reduce log spam (#31208)

lib/auth/grpcserver.go

@@ -229,7 +229,9 @@ func (g *GRPCServer) CreateAuditStream(stream authpb.AuthService_CreateAuditStre
 
 	closeStream := func(eventStream apievents.Stream) {
 		if err := eventStream.Close(auth.CloseContext()); err != nil {
-			g.WithError(err).Warningf("Failed to flush close the stream.")
+			if auth.CloseContext().Err() == nil {
+				g.WithError(err).Warn("Failed to flush close the stream.")
+			}
 		} else {
 			g.Debugf("Flushed and closed the stream.")
 		}
@@ -241,7 +243,9 @@ func (g *GRPCServer) CreateAuditStream(stream authpb.AuthService_CreateAuditStre
 			return nil
 		}
 		if err != nil {
-			g.WithError(err).Debugf("Failed to receive stream request.")
+			if stream.Context().Err() == nil {
+				g.WithError(err).Debug("Failed to receive stream request.")
+			}
 			return trace.Wrap(err)
 		}
 		if create := request.GetCreateStream(); create != nil {

lib/auth/middleware.go

@@ -760,7 +760,6 @@ func ClientCertPool(client AccessCache, clusterName string, caTypes ...types.Cer
 			if err != nil {
 				return nil, 0, trace.Wrap(err)
 			}
-			log.Debugf("ClientCertPool -> %v", CertInfo(cert))
 			pool.AddCert(cert)
 
 			// Each subject in the list gets a separate 2-byte length prefix.

lib/auth/server_info.go

@@ -53,7 +53,7 @@ func (s *Server) ReconcileServerInfos(ctx context.Context) error {
 			select {
 			case <-clock.After(timeBetweenBatches):
 			case <-ctx.Done():
-				return trace.Wrap(ctx.Err())
+				return nil
 			}
 		}
 
@@ -65,7 +65,7 @@ func (s *Server) ReconcileServerInfos(ctx context.Context) error {
 		select {
 		case <-clock.After(timeBetweenReconciliationLoops):
 		case <-ctx.Done():
-			return trace.Wrap(ctx.Err())
+			return nil
 		}
 	}
 }

lib/authz/permissions.go

@@ -1145,7 +1145,7 @@ func ConvertAuthorizerError(ctx context.Context, log logrus.FieldLogger, err err
 		// unaltered so that they know to reauthenticate with a valid key.
 		return trace.Unwrap(err)
 	default:
-		log.Warn(trace.DebugReport(err))
+		log.WithError(err).Warn("Suppressing unknown authz error.")
 	}
 	return trace.AccessDenied("access denied")
 }

lib/cache/cache.go

@@ -969,7 +969,7 @@ func (c *Cache) update(ctx context.Context, retry retryutils.Retry) {
 			return
 		}
 		if err != nil {
-			c.Logger.WithError(err).Warn("Re-init the cache on error")
+			c.Logger.Warnf("Re-init the cache on error: %v", err)
 		}
 
 		// events cache should be closed as well

lib/client/api.go

@@ -4552,7 +4552,7 @@ func connectToSSHAgent() agent.ExtendedAgent {
 	socketPath := os.Getenv(teleport.SSHAuthSock)
 	conn, err := agentconn.Dial(socketPath)
 	if err != nil {
-		log.WithError(err).Errorf("[KEY AGENT] Unable to connect to SSH agent on socket: %q.", socketPath)
+		log.Warnf("[KEY AGENT] Unable to connect to SSH agent on socket %q: %v", socketPath, err)
 		return nil
 	}
 

lib/events/emitter.go

@@ -95,6 +95,9 @@ func (a *AsyncEmitter) forward() {
 		case event := <-a.eventsCh:
 			err := a.cfg.Inner.EmitAuditEvent(a.ctx, event)
 			if err != nil {
+				if a.ctx.Err() != nil {
+					return
+				}
 				log.WithError(err).Errorf("Failed to emit audit event.")
 			}
 		}

lib/events/session_writer.go

@@ -450,6 +450,10 @@ func (a *SessionWriter) processEvents() {
 				a.log.Debugf("Recovered stream in %v.", time.Since(start))
 			}
 		case <-a.stream.Done():
+			if a.closeCtx.Err() != nil {
+				// don't attempt recovery if we're closing
+				return
+			}
 			a.log.Debugf("Stream was closed by the server, attempting to recover.")
 			if err := a.recoverStream(); err != nil {
 				a.log.WithError(err).Warningf("Failed to recover stream.")

lib/multiplexer/tls.go

@@ -123,11 +123,11 @@ func (l *TLSListener) Serve() error {
 		}
 		if utils.IsUseOfClosedNetworkError(err) {
 			<-l.context.Done()
-			return trace.Wrap(err, "listener is closed")
+			return nil
 		}
 		select {
 		case <-l.context.Done():
-			return trace.Wrap(net.ErrClosed, "listener is closed")
+			return nil
 		case <-time.After(5 * time.Second):
 		}
 	}

lib/reversetunnel/agent.go

@@ -490,7 +490,7 @@ func (a *agent) handleGlobalRequests(ctx context.Context, requests <-chan *ssh.R
 				}
 			}
 		case <-ctx.Done():
-			return trace.Wrap(ctx.Err())
+			return nil
 		}
 	}
 }
@@ -535,7 +535,7 @@ func (a *agent) handleDrainChannels() error {
 
 		select {
 		case <-a.ctx.Done():
-			return trace.Wrap(a.ctx.Err())
+			return nil
 		// Signal once when the drain context is canceled to ensure we unblock
 		// to call drainWG.Done().
 		case <-drainSignal:
@@ -595,7 +595,7 @@ func (a *agent) handleChannels() error {
 		select {
 		// need to exit:
 		case <-a.ctx.Done():
-			return trace.Wrap(a.ctx.Err())
+			return nil
 		// new discovery request channel
 		case nch := <-a.discoveryC:
 			if nch == nil {

lib/reversetunnel/agentpool.go

@@ -250,8 +250,9 @@ func (p *AgentPool) Start() error {
 
 	p.wg.Add(1)
 	go func() {
-		err := p.run()
-		p.log.WithError(err).Warn("Agent pool exited.")
+		if err := p.run(); err != nil {
+			p.log.WithError(err).Warn("Agent pool exited.")
+		}
 
 		p.cancel()
 		p.wg.Done()
@@ -262,15 +263,13 @@ func (p *AgentPool) Start() error {
 // run connects agents until the agent pool context is done.
 func (p *AgentPool) run() error {
 	for {
-		if p.ctx.Err() != nil {
-			return trace.Wrap(p.ctx.Err())
-		}
-
 		agent, err := p.connectAgent(p.ctx, p.events)
 		if err != nil {
-			// "proxy already claimed" is a fairly benign error, we should not
-			// spam the log with stack traces for it
-			if isProxyAlreadyClaimed(err) {
+			if p.ctx.Err() != nil {
+				return nil
+			} else if isProxyAlreadyClaimed(err) {
+				// "proxy already claimed" is a fairly benign error, we should not
+				// spam the log with stack traces for it
 				p.log.Debugf("Failed to connect agent: %v.", err)
 			} else {
 				p.log.WithError(err).Debugf("Failed to connect agent.")
@@ -282,7 +281,9 @@ func (p *AgentPool) run() error {
 		}
 
 		err = p.waitForBackoff(p.ctx, p.events)
-		if err != nil {
+		if p.ctx.Err() != nil {
+			return nil
+		} else if err != nil {
 			p.log.WithError(err).Debugf("Failed to wait for backoff.")
 		}
 	}
@@ -392,7 +393,7 @@ func (p *AgentPool) waitForBackoff(ctx context.Context, events <-chan Agent) err
 	for {
 		select {
 		case <-ctx.Done():
-			return trace.Wrap(ctx.Err())
+			return nil
 		case <-p.backoff.After():
 			p.backoff.Inc()
 			return nil

lib/reversetunnel/localsite.go

@@ -615,7 +615,6 @@ func (s *localSite) getConn(params reversetunnelclient.DialParams) (conn net.Con
 
 		return newMetricConn(conn, dt, dialStart, s.srv.Clock), true, nil
 	}
-	s.log.WithError(tunnelErr).WithField("address", dreq.Address).Debug("Error occurred while dialing through a tunnel.")
 
 	if s.tryProxyPeering(params) {
 		s.log.Info("Dialing over peer proxy")
@@ -625,7 +624,6 @@ func (s *localSite) getConn(params reversetunnelclient.DialParams) (conn net.Con
 		if peerErr == nil {
 			return newMetricConn(conn, dialTypePeer, dialStart, s.srv.Clock), true, nil
 		}
-		s.log.WithError(peerErr).WithField("address", dreq.Address).Debug("Error occurred while dialing over peer proxy.")
 	}
 
 	err = trace.NewAggregate(tunnelErr, peerErr)
@@ -649,7 +647,7 @@ func (s *localSite) getConn(params reversetunnelclient.DialParams) (conn net.Con
 	conn, directErr = dialer.DialTimeout(s.srv.Context, params.To.Network(), params.To.String(), apidefaults.DefaultIOTimeout)
 	if directErr != nil {
 		directMsg := getTunnelErrorMessage(params, "direct dial", directErr)
-		s.log.WithError(directErr).WithField("address", params.To.String()).Debug("Error occurred while dialing directly.")
+		s.log.WithField("address", params.To.String()).Debugf("All attempted dial methods failed. tunnel=%q, peer=%q, direct=%q", tunnelErr, peerErr, directErr)
 		aggregateErr := trace.NewAggregate(tunnelErr, peerErr, directErr)
 		return nil, false, trace.ConnectionProblem(aggregateErr, directMsg)
 	}

lib/service/service.go

@@ -2726,6 +2726,10 @@ func (process *TeleportProcess) initSSH() error {
 		// Block and wait while the node is running.
 		event, err := process.WaitForEvent(process.ExitContext(), TeleportExitEvent)
 		if err != nil {
+			if process.ExitContext().Err() != nil {
+				// doing a very un-graceful exit
+				return nil
+			}
 			return trace.Wrap(err)
 		}
 

lib/service/supervisor.go

@@ -283,7 +283,9 @@ func (s *LocalSupervisor) serve(srv Service) {
 			if err == ErrTeleportExited {
 				l.Info("Teleport process has shut down.")
 			} else {
-				l.WithError(err).Warning("Teleport process has exited with error.")
+				if s.ExitContext().Err() == nil {
+					l.WithError(err).Warning("Teleport process has exited with error.")
+				}
 				s.BroadcastEvent(Event{
 					Name:    ServiceExitedWithErrorEvent,
 					Payload: ExitEventPayload{Service: srv, Error: err},

lib/services/local/headlessauthn_watcher.go

@@ -156,7 +156,6 @@ func (h *HeadlessAuthenticationWatcher) runWatchLoop(ctx context.Context) {
 			h.Log.Warningf("Restarting watch on error after waiting %v. Error: %v.", t.Sub(startedWaiting), err)
 			h.retry.Inc()
 		case <-ctx.Done():
-			h.Log.WithError(ctx.Err()).Debugf("Context closed with err. Returning from watch loop.")
 			return
 		case <-h.closed:
 			h.Log.Debug("Watcher closed. Returning from watch loop.")

lib/srv/alpnproxy/proxy.go

@@ -313,7 +313,7 @@ func (p *Proxy) Serve(ctx context.Context) error {
 	for {
 		clientConn, err := p.cfg.Listener.Accept()
 		if err != nil {
-			if utils.IsOKNetworkError(err) || trace.IsConnectionProblem(err) {
+			if utils.IsOKNetworkError(err) || trace.IsConnectionProblem(err) || ctx.Err() != nil {
 				return nil
 			}
 			return trace.Wrap(err)

lib/srv/heartbeatv2.go

@@ -86,7 +86,9 @@ func NewSSHServerHeartbeat(cfg SSHServerHeartbeatConfig) (*HeartbeatV2, error) {
 			go func() {
 				meta, err := inner.getMetadata(ctx)
 				if err != nil {
-					log.Warnf("Failed to get metadata: %v", err)
+					if ctx.Err() == nil {
+						log.Warnf("Failed to get metadata: %v", err)
+					}
 				} else if meta != nil && meta.CloudMetadata != nil {
 					// Set the metadata immediately to give the heartbeat
 					// a chance to use it.