From 4ac06d3bbd1a00a958f498e9b9f643069a8d24e7 Mon Sep 17 00:00:00 2001 From: Caleb Doxsey Date: Fri, 29 Mar 2024 15:26:20 -0600 Subject: [PATCH] core/logging: less verbose logs (#5040) --- authorize/evaluator/evaluator.go | 2 +- cmd/pomerium/main.go | 3 --- internal/autocert/certmagic_logger.go | 6 ++++++ internal/controlplane/server.go | 4 ++-- internal/controlplane/xds.go | 4 ++-- internal/controlplane/xdsmgr/xdsmgr.go | 8 ++++---- internal/databroker/config_source.go | 6 +++--- internal/databroker/server.go | 22 +++++++++++----------- internal/identity/manager/manager.go | 2 +- internal/zero/connect-mux/service.go | 2 +- internal/zero/controller/controller.go | 2 +- internal/zero/controller/mux_log.go | 8 ++++---- internal/zero/grpcconn/client.go | 4 ++-- internal/zero/reconciler/sync.go | 2 +- pkg/cmd/pomerium/pomerium.go | 3 +++ pkg/envoy/envoy.go | 9 ++++++--- pkg/grpc/client.go | 2 +- pkg/grpc/databroker/syncer.go | 4 ++-- 18 files changed, 51 insertions(+), 42 deletions(-) diff --git a/authorize/evaluator/evaluator.go b/authorize/evaluator/evaluator.go index 5a047e8c4..243093ed6 100644 --- a/authorize/evaluator/evaluator.go +++ b/authorize/evaluator/evaluator.go @@ -191,7 +191,7 @@ func getOrCreatePolicyEvaluators( m[p.id] = p.evaluator } - log.Info(ctx). + log.Debug(ctx). Dur("duration", time.Since(now)). Int("reused-policies", reusedCount). Int("created-policies", len(cfg.Policies)-reusedCount). diff --git a/cmd/pomerium/main.go b/cmd/pomerium/main.go index 9bdd89f91..490da99f9 100644 --- a/cmd/pomerium/main.go +++ b/cmd/pomerium/main.go @@ -8,7 +8,6 @@ import ( "fmt" "github.com/rs/zerolog" - "go.uber.org/automaxprocs/maxprocs" "github.com/pomerium/pomerium/config" "github.com/pomerium/pomerium/internal/log" @@ -31,8 +30,6 @@ func main() { return } - _, _ = maxprocs.Set(maxprocs.Logger(func(s string, i ...interface{}) { log.Info(context.Background()).Msgf(s, i...) })) - ctx := context.Background() runFn := run if zero_cmd.IsManagedMode(*configFile) { diff --git a/internal/autocert/certmagic_logger.go b/internal/autocert/certmagic_logger.go index d42c6a0fe..5ab4b6045 100644 --- a/internal/autocert/certmagic_logger.go +++ b/internal/autocert/certmagic_logger.go @@ -24,6 +24,9 @@ func (c certMagicLoggerCore) With(fs []zapcore.Field) zapcore.Core { } func (c certMagicLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { + if e.Level == zap.InfoLevel { + e.Level = zap.DebugLevel + } if !c.Enabled(e.Level) { return ce } @@ -31,6 +34,9 @@ func (c certMagicLoggerCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *z } func (c certMagicLoggerCore) Write(e zapcore.Entry, fs []zapcore.Field) error { + if e.Level == zap.InfoLevel { + e.Level = zap.DebugLevel + } fs = append(c.fields, fs...) for _, f := range fs { if f.Type == zapcore.ErrorType && errors.Is(f.Interface.(error), certmagic.ErrNoOCSPServerSpecified) { diff --git a/internal/controlplane/server.go b/internal/controlplane/server.go index f80760097..3ba1da32a 100644 --- a/internal/controlplane/server.go +++ b/internal/controlplane/server.go @@ -180,7 +180,7 @@ func (srv *Server) Run(ctx context.Context) error { // start the gRPC server eg.Go(func() error { - log.Info(ctx).Str("addr", srv.GRPCListener.Addr().String()).Msg("starting control-plane gRPC server") + log.Debug(ctx).Str("addr", srv.GRPCListener.Addr().String()).Msg("starting control-plane gRPC server") return grpcutil.ServeWithGracefulStop(ctx, srv.GRPCServer, srv.GRPCListener, time.Second*5) }) @@ -199,7 +199,7 @@ func (srv *Server) Run(ctx context.Context) error { // start the HTTP server eg.Go(func() error { - log.Info(ctx). + log.Debug(ctx). Str("addr", entry.Listener.Addr().String()). Msgf("starting control-plane %s server", entry.Name) return httputil.ServeWithGracefulStop(ctx, entry.Handler, entry.Listener, time.Second*5) diff --git a/internal/controlplane/xds.go b/internal/controlplane/xds.go index e84b93908..6700467b6 100644 --- a/internal/controlplane/xds.go +++ b/internal/controlplane/xds.go @@ -26,7 +26,7 @@ func (srv *Server) buildDiscoveryResources(ctx context.Context) (map[string][]*e cfg := srv.currentConfig.Load() - log.Info(ctx).Msg("controlplane: building discovery resources") + log.Debug(ctx).Msg("controlplane: building discovery resources") eg, ctx := errgroup.WithContext(ctx) @@ -83,7 +83,7 @@ func (srv *Server) buildDiscoveryResources(ctx context.Context) (map[string][]*e return nil, err } - log.Info(ctx). + log.Debug(ctx). Int("cluster-count", len(clusterResources)). Int("listener-count", len(listenerResources)). Int("route-configuration-count", len(routeConfigurationResources)). diff --git a/internal/controlplane/xdsmgr/xdsmgr.go b/internal/controlplane/xdsmgr/xdsmgr.go index 31271b43b..fe66871db 100644 --- a/internal/controlplane/xdsmgr/xdsmgr.go +++ b/internal/controlplane/xdsmgr/xdsmgr.go @@ -107,7 +107,7 @@ func (mgr *Manager) DeltaAggregatedResources( case req.GetResponseNonce() == "": // neither an ACK or a NACK case req.GetErrorDetail() != nil: - log.Info(ctx). + log.Debug(ctx). Str("type-url", req.GetTypeUrl()). Any("error-detail", req.GetErrorDetail()). Msg("xdsmgr: nack") @@ -118,7 +118,7 @@ func (mgr *Manager) DeltaAggregatedResources( state.clientResourceVersions[resource.Name] = resource.Version } case req.GetResponseNonce() == mgr.nonce: - log.Info(ctx). + log.Debug(ctx). Str("type-url", req.GetTypeUrl()). Msg("xdsmgr: ack") // an ACK for the last response @@ -129,7 +129,7 @@ func (mgr *Manager) DeltaAggregatedResources( } default: // an ACK for a response that's not the last response - log.Info(ctx). + log.Debug(ctx). Str("type-url", req.GetTypeUrl()). Msg("xdsmgr: ack") } @@ -211,7 +211,7 @@ func (mgr *Manager) DeltaAggregatedResources( case <-ctx.Done(): return ctx.Err() case res := <-outgoing: - log.Info(ctx). + log.Debug(ctx). Str("type-url", res.GetTypeUrl()). Int("resource-count", len(res.GetResources())). Int("removed-resource-count", len(res.GetRemovedResources())). diff --git a/internal/databroker/config_source.go b/internal/databroker/config_source.go index dc2a52244..fce4d18d0 100644 --- a/internal/databroker/config_source.go +++ b/internal/databroker/config_source.go @@ -90,7 +90,7 @@ func (src *ConfigSource) rebuild(ctx context.Context, firstTime firstTime) { now := time.Now() src.mu.Lock() defer src.mu.Unlock() - log.Info(ctx).Str("lock-wait", time.Since(now).String()).Msg("databroker: rebuilding configuration") + log.Debug(ctx).Str("lock-wait", time.Since(now).String()).Msg("databroker: rebuilding configuration") cfg := src.underlyingConfig.Clone() @@ -103,7 +103,7 @@ func (src *ConfigSource) rebuild(ctx context.Context, firstTime firstTime) { log.Error(ctx).Err(err).Msg("databroker: failed to build new config") return } - log.Info(ctx).Str("elapsed", time.Since(now).String()).Msg("databroker: built new config") + log.Debug(ctx).Str("elapsed", time.Since(now).String()).Msg("databroker: built new config") src.computedConfig = cfg if !firstTime { @@ -278,7 +278,7 @@ func (src *ConfigSource) runUpdater(cfg *config.Config) { databrokerURLs = append(databrokerURLs, url.String()) } - log.Info(ctx). + log.Debug(ctx). Str("outbound_port", cfg.OutboundPort). Strs("databroker_urls", databrokerURLs). Msg("config: starting databroker config source syncer") diff --git a/internal/databroker/server.go b/internal/databroker/server.go index f2c8443cd..a9dac9e23 100644 --- a/internal/databroker/server.go +++ b/internal/databroker/server.go @@ -75,7 +75,7 @@ func (srv *Server) UpdateConfig(options ...ServerOption) { func (srv *Server) AcquireLease(ctx context.Context, req *databroker.AcquireLeaseRequest) (*databroker.AcquireLeaseResponse, error) { ctx, span := trace.StartSpan(ctx, "databroker.grpc.AcquireLease") defer span.End() - log.Info(ctx). + log.Debug(ctx). Str("name", req.GetName()). Dur("duration", req.GetDuration().AsDuration()). Msg("acquire lease") @@ -102,7 +102,7 @@ func (srv *Server) AcquireLease(ctx context.Context, req *databroker.AcquireLeas func (srv *Server) Get(ctx context.Context, req *databroker.GetRequest) (*databroker.GetResponse, error) { ctx, span := trace.StartSpan(ctx, "databroker.grpc.Get") defer span.End() - log.Info(ctx). + log.Debug(ctx). Str("type", req.GetType()). Str("id", req.GetId()). Msg("get") @@ -129,7 +129,7 @@ func (srv *Server) Get(ctx context.Context, req *databroker.GetRequest) (*databr func (srv *Server) ListTypes(ctx context.Context, _ *emptypb.Empty) (*databroker.ListTypesResponse, error) { ctx, span := trace.StartSpan(ctx, "databroker.grpc.ListTypes") defer span.End() - log.Info(ctx).Msg("list types") + log.Debug(ctx).Msg("list types") db, err := srv.getBackend() if err != nil { @@ -146,7 +146,7 @@ func (srv *Server) ListTypes(ctx context.Context, _ *emptypb.Empty) (*databroker func (srv *Server) Query(ctx context.Context, req *databroker.QueryRequest) (*databroker.QueryResponse, error) { ctx, span := trace.StartSpan(ctx, "databroker.grpc.Query") defer span.End() - log.Info(ctx). + log.Debug(ctx). Str("type", req.GetType()). Str("query", req.GetQuery()). Int64("offset", req.GetOffset()). @@ -202,7 +202,7 @@ func (srv *Server) Put(ctx context.Context, req *databroker.PutRequest) (*databr records := req.GetRecords() if len(records) == 1 { - log.Info(ctx). + log.Debug(ctx). Str("record-type", records[0].GetType()). Str("record-id", records[0].GetId()). Msg("put") @@ -211,7 +211,7 @@ func (srv *Server) Put(ctx context.Context, req *databroker.PutRequest) (*databr for _, record := range records { recordType = record.GetType() } - log.Info(ctx). + log.Debug(ctx). Int("record-count", len(records)). Str("record-type", recordType). Msg("put") @@ -241,7 +241,7 @@ func (srv *Server) Patch(ctx context.Context, req *databroker.PatchRequest) (*da records := req.GetRecords() if len(records) == 1 { - log.Info(ctx). + log.Debug(ctx). Str("record-type", records[0].GetType()). Str("record-id", records[0].GetId()). Msg("patch") @@ -250,7 +250,7 @@ func (srv *Server) Patch(ctx context.Context, req *databroker.PatchRequest) (*da for _, record := range records { recordType = record.GetType() } - log.Info(ctx). + log.Debug(ctx). Int("record-count", len(records)). Str("record-type", recordType). Msg("patch") @@ -277,7 +277,7 @@ func (srv *Server) Patch(ctx context.Context, req *databroker.PatchRequest) (*da func (srv *Server) ReleaseLease(ctx context.Context, req *databroker.ReleaseLeaseRequest) (*emptypb.Empty, error) { ctx, span := trace.StartSpan(ctx, "databroker.grpc.ReleaseLease") defer span.End() - log.Info(ctx). + log.Debug(ctx). Str("name", req.GetName()). Str("id", req.GetId()). Msg("release lease") @@ -351,7 +351,7 @@ func (srv *Server) Sync(req *databroker.SyncRequest, stream databroker.DataBroke ctx, cancel := context.WithCancel(ctx) defer cancel() - log.Info(ctx). + log.Debug(ctx). Uint64("server_version", req.GetServerVersion()). Uint64("record_version", req.GetRecordVersion()). Msg("sync") @@ -388,7 +388,7 @@ func (srv *Server) SyncLatest(req *databroker.SyncLatestRequest, stream databrok ctx, cancel := context.WithCancel(ctx) defer cancel() - log.Info(ctx). + log.Debug(ctx). Str("type", req.GetType()). Msg("sync latest") diff --git a/internal/identity/manager/manager.go b/internal/identity/manager/manager.go index 7c5837671..1ae18063f 100644 --- a/internal/identity/manager/manager.go +++ b/internal/identity/manager/manager.go @@ -127,7 +127,7 @@ func (mgr *Manager) refreshLoop(ctx context.Context, update <-chan updateRecords mgr.onUpdateRecords(ctx, msg) } - log.Info(ctx). + log.Debug(ctx). Int("sessions", mgr.sessions.Len()). Int("users", mgr.users.Len()). Msg("initial sync complete") diff --git a/internal/zero/connect-mux/service.go b/internal/zero/connect-mux/service.go index 3dbc78644..e844af045 100644 --- a/internal/zero/connect-mux/service.go +++ b/internal/zero/connect-mux/service.go @@ -80,7 +80,7 @@ func (svc *Mux) subscribeAndDispatch(ctx context.Context, onConnected func()) (e err = multierror.Append(err, svc.onDisconnected(ctx)).ErrorOrNil() }() - log.Ctx(ctx).Info().Msg("subscribed to connect service") + log.Ctx(ctx).Debug().Msg("subscribed to connect service") for { msg, err := stream.Recv() log.Ctx(ctx).Info().Interface("msg", msg).Err(err).Msg("receive") diff --git a/internal/zero/controller/controller.go b/internal/zero/controller/controller.go index 5bb958904..a2386c544 100644 --- a/internal/zero/controller/controller.go +++ b/internal/zero/controller/controller.go @@ -70,7 +70,7 @@ func (c *controller) initAPI(ctx context.Context) error { } func run(ctx context.Context, name string, runFn func(context.Context) error) error { - log.Ctx(ctx).Info().Str("name", name).Msg("starting") + log.Ctx(ctx).Debug().Str("name", name).Msg("starting") err := runFn(ctx) if err != nil && !errors.Is(err, context.Canceled) { return fmt.Errorf("%s: %w", name, err) diff --git a/internal/zero/controller/mux_log.go b/internal/zero/controller/mux_log.go index 87c3d6960..de83ad460 100644 --- a/internal/zero/controller/mux_log.go +++ b/internal/zero/controller/mux_log.go @@ -14,16 +14,16 @@ func (c *controller) RunConnectLog(ctx context.Context) error { return c.api.Watch(ctx, connect_mux.WithOnConnected(func(ctx context.Context) { - logger.Info().Msg("connected") + logger.Debug().Msg("connected") }), connect_mux.WithOnDisconnected(func(ctx context.Context) { - logger.Info().Msg("disconnected") + logger.Debug().Msg("disconnected") }), connect_mux.WithOnBootstrapConfigUpdated(func(ctx context.Context) { - logger.Info().Msg("bootstrap config updated") + logger.Debug().Msg("bootstrap config updated") }), connect_mux.WithOnBundleUpdated(func(ctx context.Context, key string) { - logger.Info().Str("key", key).Msg("bundle updated") + logger.Debug().Str("key", key).Msg("bundle updated") }), ) } diff --git a/internal/zero/grpcconn/client.go b/internal/zero/grpcconn/client.go index 1a9a5443d..492a02feb 100644 --- a/internal/zero/grpcconn/client.go +++ b/internal/zero/grpcconn/client.go @@ -91,7 +91,7 @@ func (c *client) logConnectionState(ctx context.Context, conn *grpc.ClientConn) for ctx.Err() == nil && state != connectivity.Shutdown { _ = conn.WaitForStateChange(ctx, state) state = conn.GetState() - log.Ctx(ctx).Info(). + log.Ctx(ctx).Debug(). Str("endpoint", c.config.connectionURI). Str("state", state.String()). Msg("grpc connection state") @@ -103,7 +103,7 @@ func interceptorLogger(ctx context.Context, lvl logging.Level, msg string, field switch lvl { case logging.LevelDebug: - l.Info().Msg(msg) + l.Debug().Msg(msg) case logging.LevelInfo: l.Info().Msg(msg) case logging.LevelWarn: diff --git a/internal/zero/reconciler/sync.go b/internal/zero/reconciler/sync.go index 234e41637..09cebd6f1 100644 --- a/internal/zero/reconciler/sync.go +++ b/internal/zero/reconciler/sync.go @@ -165,7 +165,7 @@ func (c *service) syncBundle(ctx context.Context, key string) error { RecordTypes: bundleRecordTypes, } - log.Ctx(ctx).Info(). + log.Ctx(ctx).Debug(). Str("bundle", key). Strs("record_types", bundleRecordTypes). Str("etag", current.ETag). diff --git a/pkg/cmd/pomerium/pomerium.go b/pkg/cmd/pomerium/pomerium.go index 3b1992798..ea9d8dd79 100644 --- a/pkg/cmd/pomerium/pomerium.go +++ b/pkg/cmd/pomerium/pomerium.go @@ -10,6 +10,7 @@ import ( "syscall" envoy_service_auth_v3 "github.com/envoyproxy/go-control-plane/envoy/service/auth/v3" + "go.uber.org/automaxprocs/maxprocs" "golang.org/x/sync/errgroup" "github.com/pomerium/pomerium/authenticate" @@ -31,6 +32,8 @@ import ( // Run runs the main pomerium application. func Run(ctx context.Context, src config.Source) error { + _, _ = maxprocs.Set(maxprocs.Logger(func(s string, i ...interface{}) { log.Debug(context.Background()).Msgf(s, i...) })) + log.Info(ctx). Str("envoy_version", files.FullVersion()). Str("version", version.FullVersion()). diff --git a/pkg/envoy/envoy.go b/pkg/envoy/envoy.go index 3d19dc26e..40951d8fa 100644 --- a/pkg/envoy/envoy.go +++ b/pkg/envoy/envoy.go @@ -76,7 +76,7 @@ func NewServer(ctx context.Context, src config.Source, builder *envoyconfig.Buil src.OnConfigChange(ctx, srv.onConfigChange) srv.onConfigChange(ctx, src.GetConfig()) - log.Info(ctx). + log.Debug(ctx). Str("path", envoyPath). Str("checksum", files.Checksum()). Msg("running envoy") @@ -122,7 +122,7 @@ func (srv *Server) update(ctx context.Context, cfg *config.Config) { } srv.options = options - log.Info(ctx).Msg("envoy: starting envoy process") + log.Debug(ctx).Msg("envoy: starting envoy process") if err := srv.run(ctx, cfg); err != nil { log.Error(ctx).Err(err).Str("service", "envoy").Msg("envoy: failed to run envoy process") return @@ -249,6 +249,9 @@ func (srv *Server) handleLogs(ctx context.Context, rc io.ReadCloser) { if x, err := zerolog.ParseLevel(logLevel); err == nil { lvl = x } + if lvl == zerolog.InfoLevel { + lvl = zerolog.DebugLevel + } if msg == "" { msg = ln } @@ -270,7 +273,7 @@ func (srv *Server) handleLogs(ctx context.Context, rc io.ReadCloser) { } func (srv *Server) monitorProcess(ctx context.Context, pid int32) { - log.Info(ctx). + log.Debug(ctx). Int32("pid", pid). Msg("envoy: start monitoring subprocess") diff --git a/pkg/grpc/client.go b/pkg/grpc/client.go index 261fe10b8..f92513408 100644 --- a/pkg/grpc/client.go +++ b/pkg/grpc/client.go @@ -55,7 +55,7 @@ func NewGRPCClientConn(ctx context.Context, opts *Options, other ...grpc.DialOpt grpc.WithInsecure(), } dialOptions = append(dialOptions, other...) - log.Info(ctx).Str("address", opts.Address).Msg("grpc: dialing") + log.Debug(ctx).Str("address", opts.Address).Msg("grpc: dialing") return grpc.DialContext(ctx, opts.Address, dialOptions...) } diff --git a/pkg/grpc/databroker/syncer.go b/pkg/grpc/databroker/syncer.go index 820fc3d31..c85e15659 100644 --- a/pkg/grpc/databroker/syncer.go +++ b/pkg/grpc/databroker/syncer.go @@ -128,7 +128,7 @@ func (syncer *Syncer) Run(ctx context.Context) error { } func (syncer *Syncer) init(ctx context.Context) error { - log.Info(ctx).Msg("initial sync") + log.Debug(ctx).Msg("initial sync") records, recordVersion, serverVersion, err := InitialSync(ctx, syncer.handler.GetDataBrokerServiceClient(), &SyncLatestRequest{ Type: syncer.cfg.typeURL, }) @@ -157,7 +157,7 @@ func (syncer *Syncer) sync(ctx context.Context) error { return fmt.Errorf("error calling sync: %w", err) } - log.Info(ctx).Msg("listening for updates") + log.Debug(ctx).Msg("listening for updates") for { res, err := stream.Recv()