diff --git a/pkg/proxy/backend/authenticator.go b/pkg/proxy/backend/authenticator.go index 85122cac..6b035f8f 100644 --- a/pkg/proxy/backend/authenticator.go +++ b/pkg/proxy/backend/authenticator.go @@ -411,6 +411,12 @@ func (auth *Authenticator) updateCurrentDB(db string) { auth.dbname = db } +func (auth *Authenticator) ConnInfo() []zap.Field { + fields := pnet.Attr2ZapFields(auth.attrs) + fields = append(fields, zap.Stringer("capability", auth.capability), zap.Bool("proxy-protocol", auth.proxyProtocol)) + return fields +} + func setCompress(packetIO *pnet.PacketIO, capability pnet.Capability, zstdLevel int) error { algorithm := pnet.CompressionNone if capability&pnet.ClientCompress > 0 { diff --git a/pkg/proxy/backend/backend_conn_mgr.go b/pkg/proxy/backend/backend_conn_mgr.go index d63ba91e..bfe9c58c 100644 --- a/pkg/proxy/backend/backend_conn_mgr.go +++ b/pkg/proxy/backend/backend_conn_mgr.go @@ -216,7 +216,6 @@ func (mgr *BackendConnManager) getBackendIO(cctx ConnContext, auth *Authenticato return nil, errors.Wrapf(err, "dial backend %s error", 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 @@ -640,7 +639,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("client_addr", addr), zap.NamedError("notify_err", err)) + mgr.logger.Error("close connection error", zap.String("backend_addr", addr), zap.NamedError("notify_err", err)) } } } @@ -695,3 +694,13 @@ func (mgr *BackendConnManager) resetQuitSource() { func (mgr *BackendConnManager) UpdateLogger(fields ...zap.Field) { mgr.logger = mgr.logger.With(fields...) } + +// ConnInfo returns detailed info of the connection, which should not be logged too many times. +func (mgr *BackendConnManager) ConnInfo() []zap.Field { + var fields []zap.Field + if mgr.authenticator != nil { + fields = mgr.authenticator.ConnInfo() + } + fields = append(fields, zap.String("backend_addr", mgr.ServerAddr())) + return fields +} diff --git a/pkg/proxy/client/client_conn.go b/pkg/proxy/client/client_conn.go index 9b1dcdec..a2fc4f50 100644 --- a/pkg/proxy/client/client_conn.go +++ b/pkg/proxy/client/client_conn.go @@ -49,6 +49,7 @@ func (cc *ClientConnection) Run(ctx context.Context) { msg = "new connection failed" goto clean } + cc.logger.Info("connected to backend", cc.connMgr.ConnInfo()...) if err = cc.processMsg(ctx); err != nil { msg = "fails to relay the connection" goto clean @@ -59,7 +60,9 @@ clean: switch src { case backend.SrcClientQuit, backend.SrcClientErr, backend.SrcProxyQuit: default: - cc.logger.Warn(msg, zap.String("backend_addr", cc.connMgr.ServerAddr()), zap.Stringer("quit source", src), zap.Error(err)) + fields := cc.connMgr.ConnInfo() + fields = append(fields, zap.Stringer("quit source", src), zap.Error(err)) + cc.logger.Warn(msg, fields...) } } diff --git a/pkg/proxy/net/mysql.go b/pkg/proxy/net/mysql.go index 5cd928d4..d9b56f56 100644 --- a/pkg/proxy/net/mysql.go +++ b/pkg/proxy/net/mysql.go @@ -13,6 +13,7 @@ import ( "github.com/pingcap/tidb/parser/mysql" "github.com/pingcap/tiproxy/lib/util/errors" "github.com/siddontang/go/hack" + "go.uber.org/zap" ) const ( @@ -431,3 +432,32 @@ func IsResultSetOKPacket(firstByte byte, length int) bool { func IsErrorPacket(firstByte byte) bool { return firstByte == ErrHeader.Byte() } + +// The connection attribute names that are logged. +// https://dev.mysql.com/doc/mysql-perfschema-excerpt/8.2/en/performance-schema-connection-attribute-tables.html +const ( + AttrNameClientVersion = "_client_version" // libmysqlclient & Connector/C++ & Connector/J & Connector/Net & Connector/Python + AttrNameClientName1 = "_client_name" // libmysqlclient & Connector/C++ & Connector/J & Connector/Python & mysqlnd + AttrNameClientName2 = "_program_name" // Connector/Net + AttrNameProgramName = "program_name" // MySQL Client & MySQL Shell +) + +// Attr2ZapFields converts connection attributes to log fields. +// We only pick some of them because others may be too sensitive to be logged. +func Attr2ZapFields(attrs map[string]string) []zap.Field { + fields := make([]zap.Field, 0, 3) + if attrs != nil { + if version, ok := attrs[AttrNameClientVersion]; ok { + fields = append(fields, zap.String("client_version", version)) + } + if name, ok := attrs[AttrNameClientName1]; ok { + fields = append(fields, zap.String("client_name", name)) + } else if name, ok := attrs[AttrNameClientName2]; ok { + fields = append(fields, zap.String("client_name", name)) + } + if name, ok := attrs[AttrNameProgramName]; ok { + fields = append(fields, zap.String("program_name", name)) + } + } + return fields +} diff --git a/pkg/proxy/net/mysql_test.go b/pkg/proxy/net/mysql_test.go index 56f4dbe0..d777b62a 100644 --- a/pkg/proxy/net/mysql_test.go +++ b/pkg/proxy/net/mysql_test.go @@ -6,6 +6,7 @@ package net import ( "testing" + "github.com/pingcap/tiproxy/lib/util/logger" "github.com/stretchr/testify/require" ) @@ -46,3 +47,17 @@ func TestChangeUserReq(t *testing.T) { _, err = ParseChangeUser(b, capability) require.NoError(t, err) } + +func TestLogAttrs(t *testing.T) { + attrs := map[string]string{ + AttrNameClientVersion: "8.1.0", + AttrNameClientName1: "libmysql", + AttrNameProgramName: "mysql", + } + lg, text := logger.CreateLoggerForTest(t) + lg.Info("connection info", Attr2ZapFields(attrs)...) + str := text.String() + require.Contains(t, str, `"client_version": "8.1.0"`) + require.Contains(t, str, `"client_name": "libmysql"`) + require.Contains(t, str, `"program_name": "mysql"`) +} diff --git a/pkg/proxy/proxy.go b/pkg/proxy/proxy.go index 9a61472a..3ba25b44 100644 --- a/pkg/proxy/proxy.go +++ b/pkg/proxy/proxy.go @@ -158,7 +158,7 @@ func (s *SQLServer) onConn(ctx context.Context, conn net.Conn, addr string) { connID := s.mu.connID s.mu.connID++ logger := s.logger.With(zap.Uint64("connID", connID), zap.String("client_addr", conn.RemoteAddr().String()), - zap.Bool("proxy-protocol", s.mu.proxyProtocol), zap.String("addr", addr)) + zap.String("addr", addr)) clientConn := client.NewClientConnection(logger.Named("conn"), conn, s.certMgr.ServerTLS(), s.certMgr.SQLTLS(), s.hsHandler, connID, addr, &backend.BCConfig{ ProxyProtocol: s.mu.proxyProtocol, @@ -168,9 +168,9 @@ func (s *SQLServer) onConn(ctx context.Context, conn net.Conn, addr string) { ConnBufferSize: s.mu.connBufferSize, }) s.mu.clients[connID] = clientConn + logger.Info("new connection", zap.Bool("proxy-protocol", s.mu.proxyProtocol)) s.mu.Unlock() - logger.Info("new connection") metrics.ConnGauge.Inc() defer func() {