backend, net: log client versions (#395)

Author: djshow832

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 {

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
+}

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...)
 	}
 }
 

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
+}

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"`)
+}

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() {