chore: improve logging for derp server mesh clients

derp/derp_server.go

@@ -697,14 +697,15 @@ func (s *Server) accept(ctx context.Context, nc Conn, brw *bufio.ReadWriter, rem
 
 	remoteIPPort, _ := netip.ParseAddrPort(remoteAddr)
 
+	canMesh := clientInfo.MeshKey != "" && clientInfo.MeshKey == s.meshKey
 	c := &sclient{
 		connNum:        connNum,
 		s:              s,
 		key:            clientKey,
 		nc:             nc,
 		br:             br,
 		bw:             bw,
-		logf:           logger.WithPrefix(s.logf, fmt.Sprintf("derp client %v%s: ", remoteAddr, clientKey.ShortString())),
+		logf:           logger.WithPrefix(s.logf, fmt.Sprintf("derp client %v%s (canMesh=%t): ", remoteAddr, clientKey.ShortString(), canMesh)),
 		done:           ctx.Done(),
 		remoteAddr:     remoteAddr,
 		remoteIPPort:   remoteIPPort,
@@ -713,7 +714,7 @@ func (s *Server) accept(ctx context.Context, nc Conn, brw *bufio.ReadWriter, rem
 		discoSendQueue: make(chan pkt, perClientSendQueueDepth),
 		sendPongCh:     make(chan [8]byte, 1),
 		peerGone:       make(chan peerGoneMsg),
-		canMesh:        clientInfo.MeshKey != "" && clientInfo.MeshKey == s.meshKey,
+		canMesh:        canMesh,
 		peerGoneLim:    rate.NewLimiter(rate.Every(time.Second), 3),
 	}
 
@@ -738,6 +739,7 @@ func (s *Server) accept(ctx context.Context, nc Conn, brw *bufio.ReadWriter, rem
 		return fmt.Errorf("send server info: %v", err)
 	}
 
+	c.logConnectivityf("client connected")
 	return c.run(ctx)
 }
 
@@ -753,6 +755,23 @@ var (
 	timeNow   = time.Now
 )
 
+// logConnectivityf logs a message at info level if the client is a mesh peer,
+// otherwise at debug level.
+//
+// Since this can result in info logging, it should only be used for sporadic
+// logging of connectivity-related events.
+func (c *sclient) logConnectivityf(format string, v ...any) {
+	// Include a prefix for ease of grepping the logs.
+	const prefix = "derper connectivity: "
+	if c.canMesh {
+		// Mesh peers have their connectivity logs logged at info level since
+		// failures are much more severe.
+		c.logf(prefix+format, v...)
+	} else {
+		c.debugLogf(prefix+format, v...)
+	}
+}
+
 // run serves the client until there's an error.
 // If the client hangs up or the server is closed, run returns nil, otherwise run returns an error.
 func (c *sclient) run(ctx context.Context) error {
@@ -765,9 +784,9 @@ func (c *sclient) run(ctx context.Context) error {
 		cancelSender()
 		if err := grp.Wait(); err != nil && !c.s.isClosed() {
 			if errors.Is(err, context.Canceled) {
-				c.debugLogf("sender canceled by reader exiting")
+				c.logConnectivityf("sender canceled by reader exiting")
 			} else {
-				c.logf("sender failed: %v", err)
+				c.logConnectivityf("sender failed: %v", err)
 			}
 		}
 	}()
@@ -776,12 +795,12 @@ func (c *sclient) run(ctx context.Context) error {
 		ft, fl, err := readFrameHeader(c.br)
 		c.debugLogf("read frame type %d len %d err %v", ft, fl, err)
 		if err != nil {
+			c.logConnectivityf("read frame header err %v", err)
 			if errors.Is(err, io.EOF) {
-				c.debugLogf("read EOF")
 				return nil
 			}
 			if c.s.isClosed() {
-				c.logf("closing; server closed")
+				c.logConnectivityf("closing; server closed")
 				return nil
 			}
 			return fmt.Errorf("client %s: readFrameHeader: %w", c.key.ShortString(), err)
@@ -804,6 +823,7 @@ func (c *sclient) run(ctx context.Context) error {
 			err = c.handleUnknownFrame(ft, fl)
 		}
 		if err != nil {
+			c.logConnectivityf("handle frame type %d len %d err %v", ft, fl, err)
 			return err
 		}
 	}