router, backend: refine some logs (#259)

pkg/manager/router/router.go

@@ -78,6 +78,7 @@ type RedirectableConn interface {
 	Redirect(addr string)
 	GetRedirectingAddr() string
 	NotifyBackendStatus(status BackendStatus)
+	ConnectionID() uint64
 }
 
 // backendWrapper contains the connections on the backend.

pkg/manager/router/router_score.go

@@ -289,16 +289,16 @@ func (router *ScoreBasedRouter) OnBackendChanged(backends map[string]BackendStat
 	for addr, status := range backends {
 		be := router.lookupBackend(addr, true)
 		if be == nil && status != StatusCannotConnect {
-			router.logger.Info("find new backend", zap.String("addr", addr),
-				zap.String("status", status.String()))
+			router.logger.Info("update backend", zap.String("backend_addr", addr),
+				zap.String("prev_status", "none"), zap.String("cur_status", status.String()))
 			router.backends.PushBack(&backendWrapper{
 				status:   status,
 				addr:     addr,
 				connList: glist.New[*connWrapper](),
 			})
 		} else if be != nil {
 			backend := be.Value
-			router.logger.Info("update backend", zap.String("addr", addr),
+			router.logger.Info("update backend", zap.String("backend_addr", addr),
 				zap.String("prev_status", backend.status.String()), zap.String("cur_status", status.String()))
 			backend.status = status
 			if !router.removeBackendIfEmpty(be) {
@@ -367,8 +367,11 @@ func (router *ScoreBasedRouter) rebalance(maxNum int) {
 		if ce == nil {
 			break
 		}
-		router.removeConn(busiestEle, ce)
 		conn := ce.Value
+		router.logger.Info("begin redirect connection", zap.Uint64("connID", conn.ConnectionID()),
+			zap.String("from", busiestBackend.addr), zap.String("to", idlestBackend.addr),
+			zap.Int("from_score", busiestBackend.score()), zap.Int("to_score", idlestBackend.score()))
+		router.removeConn(busiestEle, ce)
 		conn.phase = phaseRedirectNotify
 		conn.lastRedirect = curTime
 		router.addConn(idlestEle, conn)

pkg/proxy/backend/authenticator.go

@@ -200,7 +200,7 @@ func (auth *Authenticator) handshakeFirstTime(logger *zap.Logger, cctx ConnConte
 		// but TiDB does not send all of its supported capabilities
 		// thus we must ignore server capabilities
 		// however, I will log something
-		logger.Info("backend does not support capabilities from proxy", zap.Stringer("common", common), zap.Stringer("proxy", proxyCapability^common), zap.Stringer("backend", backendCapability^common))
+		logger.Debug("backend does not support capabilities from proxy", zap.Stringer("common", common), zap.Stringer("proxy", proxyCapability^common), zap.Stringer("backend", backendCapability^common))
 	}
 
 	// forward client handshake resp

pkg/proxy/backend/backend_conn_mgr.go

@@ -229,12 +229,12 @@ func (mgr *BackendConnManager) getBackendIO(cctx ConnContext, auth *Authenticato
 			if err = selector.Succeed(mgr); err != nil {
 				// Bad luck: the backend has been recycled or shut down just after the selector returns it.
 				if ignoredErr := cn.Close(); ignoredErr != nil {
-					mgr.logger.Error("close backend connection failed", zap.String("addr", addr), zap.Error(ignoredErr))
+					mgr.logger.Error("close backend connection failed", zap.String("backend_addr", addr), zap.Error(ignoredErr))
 				}
 				return nil, err
 			}
 
-			mgr.logger.Info("connected to backend", zap.String("addr", addr))
+			mgr.logger.Info("connected to backend", zap.String("backend_addr", addr))
 			// NOTE: should use DNS name as much as possible
 			// Usually certs are signed with domain instead of IP addrs
 			// And `RemoteAddr()` will return IP addr
@@ -443,7 +443,7 @@ func (mgr *BackendConnManager) tryRedirect(ctx context.Context) {
 		if errors.Is(rs.err, net.ErrClosed) || pnet.IsDisconnectError(rs.err) || errors.Is(rs.err, os.ErrDeadlineExceeded) {
 			mgr.quitSource = SrcBackendQuit
 			if ignoredErr := mgr.clientIO.GracefulClose(); ignoredErr != nil {
-				mgr.logger.Warn("graceful close client IO error", zap.Stringer("addr", mgr.clientIO.RemoteAddr()), zap.Error(ignoredErr))
+				mgr.logger.Warn("graceful close client IO error", zap.Stringer("client_addr", mgr.clientIO.RemoteAddr()), zap.Error(ignoredErr))
 			}
 		}
 		return
@@ -558,7 +558,7 @@ func (mgr *BackendConnManager) tryGracefulClose(ctx context.Context) {
 	mgr.quitSource = SrcProxyQuit
 	// Closing clientIO will cause the whole connection to be closed.
 	if err := mgr.clientIO.GracefulClose(); err != nil {
-		mgr.logger.Warn("graceful close client IO error", zap.Stringer("addr", mgr.clientIO.RemoteAddr()), zap.Error(err))
+		mgr.logger.Warn("graceful close client IO error", zap.Stringer("client_addr", mgr.clientIO.RemoteAddr()), zap.Error(err))
 	}
 	mgr.closeStatus.Store(statusClosing)
 }
@@ -573,11 +573,11 @@ func (mgr *BackendConnManager) checkBackendActive() {
 	defer mgr.processLock.Unlock()
 	backendIO := mgr.backendIO.Load()
 	if !backendIO.IsPeerActive() {
-		mgr.logger.Info("backend connection is closed, close client connection", zap.Stringer("client", mgr.clientIO.RemoteAddr()),
-			zap.Stringer("backend", backendIO.RemoteAddr()))
+		mgr.logger.Info("backend connection is closed, close client connection",
+			zap.Stringer("client_addr", mgr.clientIO.RemoteAddr()), zap.Stringer("backend_addr", backendIO.RemoteAddr()))
 		mgr.quitSource = SrcBackendQuit
 		if err := mgr.clientIO.GracefulClose(); err != nil {
-			mgr.logger.Warn("graceful close client IO error", zap.Stringer("addr", mgr.clientIO.RemoteAddr()), zap.Error(err))
+			mgr.logger.Warn("graceful close client IO error", zap.Stringer("client_addr", mgr.clientIO.RemoteAddr()), zap.Error(err))
 		}
 		mgr.closeStatus.Store(statusClosing)
 	}
@@ -669,7 +669,7 @@ func (mgr *BackendConnManager) Close() error {
 		// Just notify it with the current address.
 		if len(addr) > 0 {
 			if err := eventReceiver.OnConnClosed(addr, mgr); err != nil {
-				mgr.logger.Error("close connection error", zap.String("addr", addr), zap.NamedError("notify_err", err))
+				mgr.logger.Error("close connection error", zap.String("client_addr", addr), zap.NamedError("notify_err", err))
 			}
 		}
 	}
@@ -695,7 +695,7 @@ func (mgr *BackendConnManager) setKeepAlive(cfg config.KeepAlive) {
 		return
 	}
 	if err := backendIO.SetKeepalive(cfg); err != nil {
-		mgr.logger.Warn("failed to set keepalive", zap.Error(err), zap.Stringer("backend", backendIO.RemoteAddr()))
+		mgr.logger.Warn("failed to set keepalive", zap.Stringer("backend_addr", backendIO.RemoteAddr()), zap.Error(err))
 	}
 }
 

pkg/proxy/client/client_conn.go

@@ -69,7 +69,7 @@ clean:
 	switch src {
 	case backend.SrcClientQuit, backend.SrcClientErr, backend.SrcProxyQuit:
 	default:
-		cc.logger.Info(msg, zap.Error(err), zap.Stringer("quit source", src))
+		cc.logger.Info(msg, zap.String("backend_addr", cc.connMgr.ServerAddr()), zap.Stringer("quit source", src), zap.Error(err))
 	}
 }
 

pkg/proxy/proxy.go

@@ -145,18 +145,18 @@ func (s *SQLServer) onConn(ctx context.Context, conn net.Conn) {
 	// 'maxConns == 0' => unlimited connections
 	if maxConns != 0 && conns >= maxConns {
 		s.mu.Unlock()
-		s.logger.Warn("too many connections", zap.Uint64("max connections", maxConns), zap.String("addr", conn.RemoteAddr().Network()), zap.Error(conn.Close()))
+		s.logger.Warn("too many connections", zap.Uint64("max connections", maxConns), zap.String("client_addr", conn.RemoteAddr().Network()), zap.Error(conn.Close()))
 		return
 	}
 	if s.mu.inShutdown {
 		s.mu.Unlock()
-		s.logger.Warn("in shutdown", zap.String("addr", conn.RemoteAddr().Network()), zap.Error(conn.Close()))
+		s.logger.Warn("in shutdown", zap.String("client_addr", conn.RemoteAddr().Network()), zap.Error(conn.Close()))
 		return
 	}
 
 	connID := s.mu.connID
 	s.mu.connID++
-	logger := s.logger.With(zap.Uint64("connID", connID), zap.String("remoteAddr", conn.RemoteAddr().String()))
+	logger := s.logger.With(zap.Uint64("connID", connID), zap.String("client_addr", conn.RemoteAddr().String()))
 	clientConn := client.NewClientConnection(logger.Named("conn"), conn, s.certMgr.ServerTLS(), s.certMgr.SQLTLS(),
 		s.hsHandler, connID, &backend.BCConfig{
 			ProxyProtocol:      s.mu.proxyProtocol,