diff --git a/derp/derp_server.go b/derp/derp_server.go index 9af356d45e11c..3021241094d27 100644 --- a/derp/derp_server.go +++ b/derp/derp_server.go @@ -697,6 +697,7 @@ 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, @@ -704,7 +705,7 @@ func (s *Server) accept(ctx context.Context, nc Conn, brw *bufio.ReadWriter, rem 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 } }