Make logger configurable per connection

Author: frozenbonito

AUTHORS

@@ -95,6 +95,7 @@ Stan Putrya <root.vagner at gmail.com>
 Stanley Gunawan <gunawan.stanley at gmail.com>
 Steven Hartland <steven.hartland at multiplay.co.uk>
 Tan Jinhua <312841925 at qq.com>
+Tetsuro Aoki <t.aoki1130 at gmail.com>
 Thomas Wodarek <wodarekwebpage at gmail.com>
 Tim Ruffles <timruffles at gmail.com>
 Tom Jenkinson <tom at tjenkinson.me>

README.md

@@ -279,6 +279,16 @@ Note that this sets the location for time.Time values but does not change MySQL'
 
 Please keep in mind, that param values must be [url.QueryEscape](https://golang.org/pkg/net/url/#QueryEscape)'ed. Alternatively you can manually replace the `/` with `%2F`. For example `US/Pacific` would be `loc=US%2FPacific`.
 
+##### `logging`
+
+```
+Type:           bool / string
+Valid Values:   true, false, <name>
+Default:        true
+```
+
+`logging=false` disables logging. You can use a custom logger after registering it with [`mysql.RegisterLogger`](https://godoc.org/github.com/go-sql-driver/mysql#RegisterLogger).
+
 ##### `maxAllowedPacket`
 ```
 Type:          decimal number

auth.go

@@ -291,7 +291,7 @@ func (mc *mysqlConn) auth(authData []byte, plugin string) ([]byte, error) {
 		return enc, err
 
 	default:
-		errLog.Print("unknown auth plugin:", plugin)
+		mc.errLog().Print("unknown auth plugin:", plugin)
 		return nil, ErrUnknownPlugin
 	}
 }

connection.go

@@ -105,7 +105,7 @@ func (mc *mysqlConn) Begin() (driver.Tx, error) {
 
 func (mc *mysqlConn) begin(readOnly bool) (driver.Tx, error) {
 	if mc.closed.Load() {
-		errLog.Print(ErrInvalidConn)
+		mc.errLog().Print(ErrInvalidConn)
 		return nil, driver.ErrBadConn
 	}
 	var q string
@@ -147,7 +147,7 @@ func (mc *mysqlConn) cleanup() {
 		return
 	}
 	if err := mc.netConn.Close(); err != nil {
-		errLog.Print(err)
+		mc.errLog().Print(err)
 	}
 }
 
@@ -163,14 +163,14 @@ func (mc *mysqlConn) error() error {
 
 func (mc *mysqlConn) Prepare(query string) (driver.Stmt, error) {
 	if mc.closed.Load() {
-		errLog.Print(ErrInvalidConn)
+		mc.errLog().Print(ErrInvalidConn)
 		return nil, driver.ErrBadConn
 	}
 	// Send command
 	err := mc.writeCommandPacketStr(comStmtPrepare, query)
 	if err != nil {
 		// STMT_PREPARE is safe to retry.  So we can return ErrBadConn here.
-		errLog.Print(err)
+		mc.errLog().Print(err)
 		return nil, driver.ErrBadConn
 	}
 
@@ -204,7 +204,7 @@ func (mc *mysqlConn) interpolateParams(query string, args []driver.Value) (strin
 	buf, err := mc.buf.takeCompleteBuffer()
 	if err != nil {
 		// can not take the buffer. Something must be wrong with the connection
-		errLog.Print(err)
+		mc.errLog().Print(err)
 		return "", ErrInvalidConn
 	}
 	buf = buf[:0]
@@ -296,7 +296,7 @@ func (mc *mysqlConn) interpolateParams(query string, args []driver.Value) (strin
 
 func (mc *mysqlConn) Exec(query string, args []driver.Value) (driver.Result, error) {
 	if mc.closed.Load() {
-		errLog.Print(ErrInvalidConn)
+		mc.errLog().Print(ErrInvalidConn)
 		return nil, driver.ErrBadConn
 	}
 	if len(args) != 0 {
@@ -357,7 +357,7 @@ func (mc *mysqlConn) Query(query string, args []driver.Value) (driver.Rows, erro
 
 func (mc *mysqlConn) query(query string, args []driver.Value) (*textRows, error) {
 	if mc.closed.Load() {
-		errLog.Print(ErrInvalidConn)
+		mc.errLog().Print(ErrInvalidConn)
 		return nil, driver.ErrBadConn
 	}
 	if len(args) != 0 {
@@ -451,7 +451,7 @@ func (mc *mysqlConn) finish() {
 // Ping implements driver.Pinger interface
 func (mc *mysqlConn) Ping(ctx context.Context) (err error) {
 	if mc.closed.Load() {
-		errLog.Print(ErrInvalidConn)
+		mc.errLog().Print(ErrInvalidConn)
 		return driver.ErrBadConn
 	}
 
@@ -648,3 +648,10 @@ func (mc *mysqlConn) ResetSession(ctx context.Context) error {
 func (mc *mysqlConn) IsValid() bool {
 	return !mc.closed.Load()
 }
+
+func (mc *mysqlConn) errLog() Logger {
+	if mc.cfg.Logger != nil {
+		return mc.cfg.Logger
+	}
+	return defaultLogger
+}

connection_test.go

@@ -179,6 +179,7 @@ func TestPingErrInvalidConn(t *testing.T) {
 		buf:              newBuffer(nc),
 		maxAllowedPacket: defaultMaxAllowedPacket,
 		closech:          make(chan struct{}),
+		cfg:              NewConfig(),
 	}
 
 	err := ms.Ping(context.Background())

connector.go

@@ -92,7 +92,7 @@ func (c *connector) Connect(ctx context.Context) (driver.Conn, error) {
 	authResp, err := mc.auth(authData, plugin)
 	if err != nil {
 		// try the default auth plugin, if using the requested plugin failed
-		errLog.Print("could not use requested auth plugin '"+plugin+"': ", err.Error())
+		c.errLog().Print("could not use requested auth plugin '"+plugin+"': ", err.Error())
 		plugin = defaultAuthPlugin
 		authResp, err = mc.auth(authData, plugin)
 		if err != nil {
@@ -144,3 +144,10 @@ func (c *connector) Connect(ctx context.Context) (driver.Conn, error) {
 func (c *connector) Driver() driver.Driver {
 	return &MySQLDriver{}
 }
+
+func (c *connector) errLog() Logger {
+	if c.cfg.Logger != nil {
+		return c.cfg.Logger
+	}
+	return defaultLogger
+}

driver_test.go

@@ -1995,7 +1995,7 @@ func TestInsertRetrieveEscapedData(t *testing.T) {
 func TestUnixSocketAuthFail(t *testing.T) {
 	runTests(t, dsn, func(dbt *DBTest) {
 		// Save the current logger so we can restore it.
-		oldLogger := errLog
+		oldLogger := defaultLogger
 
 		// Set a new logger so we can capture its output.
 		buffer := bytes.NewBuffer(make([]byte, 0, 64))

dsn.go

@@ -50,6 +50,8 @@ type Config struct {
 	Timeout          time.Duration     // Dial timeout
 	ReadTimeout      time.Duration     // I/O read timeout
 	WriteTimeout     time.Duration     // I/O write timeout
+	LoggingConfig    string            // Logging configuration
+	Logger           Logger            // Logger
 
 	AllowAllFiles            bool // Allow all files to be used with LOAD DATA LOCAL INFILE
 	AllowCleartextPasswords  bool // Allows the cleartext client side plugin
@@ -153,6 +155,20 @@ func (cfg *Config) normalize() error {
 		}
 	}
 
+	if cfg.Logger == nil {
+		switch cfg.LoggingConfig {
+		case "true", "":
+			// use default logger
+		case "false":
+			cfg.Logger = defaultNopLogger
+		default:
+			cfg.Logger = getLogger(cfg.LoggingConfig)
+			if cfg.Logger == nil {
+				return errors.New("invalid value / unknown logger name: " + cfg.LoggingConfig)
+			}
+		}
+	}
+
 	return nil
 }
 
@@ -282,6 +298,10 @@ func (cfg *Config) FormatDSN() string {
 		writeDSNParam(&buf, &hasParam, "maxAllowedPacket", strconv.Itoa(cfg.MaxAllowedPacket))
 	}
 
+	if len(cfg.LoggingConfig) > 0 {
+		writeDSNParam(&buf, &hasParam, "logging", url.QueryEscape(cfg.LoggingConfig))
+	}
+
 	// other params
 	if cfg.Params != nil {
 		var params []string
@@ -554,6 +574,23 @@ func parseDSNParams(cfg *Config, params string) (err error) {
 			if err != nil {
 				return
 			}
+
+		case "logging":
+			boolValue, isBool := readBool(value)
+			if isBool {
+				if boolValue {
+					cfg.LoggingConfig = "true"
+				} else {
+					cfg.LoggingConfig = "false"
+				}
+			} else {
+				name, err := url.QueryUnescape(value)
+				if err != nil {
+					return fmt.Errorf("invalid value for logger name: %v", err)
+				}
+				cfg.LoggingConfig = name
+			}
+
 		default:
 			// lazy init
 			if cfg.Params == nil {

dsn_test.go

@@ -11,7 +11,9 @@ package mysql
 import (
 	"crypto/tls"
 	"fmt"
+	"log"
 	"net/url"
+	"os"
 	"reflect"
 	"testing"
 	"time"
@@ -33,14 +35,14 @@ var testDSNs = []struct {
 	"user@unix(/path/to/socket)/dbname?charset=utf8",
 	&Config{User: "user", Net: "unix", Addr: "/path/to/socket", DBName: "dbname", Params: map[string]string{"charset": "utf8"}, Collation: "utf8mb4_general_ci", Loc: time.UTC, MaxAllowedPacket: defaultMaxAllowedPacket, AllowNativePasswords: true, CheckConnLiveness: true},
 }, {
-	"user:password@tcp(localhost:5555)/dbname?charset=utf8&tls=true",
-	&Config{User: "user", Passwd: "password", Net: "tcp", Addr: "localhost:5555", DBName: "dbname", Params: map[string]string{"charset": "utf8"}, Collation: "utf8mb4_general_ci", Loc: time.UTC, MaxAllowedPacket: defaultMaxAllowedPacket, AllowNativePasswords: true, CheckConnLiveness: true, TLSConfig: "true"},
+	"user:password@tcp(localhost:5555)/dbname?charset=utf8&tls=true&logging=false",
+	&Config{User: "user", Passwd: "password", Net: "tcp", Addr: "localhost:5555", DBName: "dbname", Params: map[string]string{"charset": "utf8"}, Collation: "utf8mb4_general_ci", Loc: time.UTC, MaxAllowedPacket: defaultMaxAllowedPacket, AllowNativePasswords: true, CheckConnLiveness: true, TLSConfig: "true", LoggingConfig: "false"},
 }, {
-	"user:password@tcp(localhost:5555)/dbname?charset=utf8mb4,utf8&tls=skip-verify",
-	&Config{User: "user", Passwd: "password", Net: "tcp", Addr: "localhost:5555", DBName: "dbname", Params: map[string]string{"charset": "utf8mb4,utf8"}, Collation: "utf8mb4_general_ci", Loc: time.UTC, MaxAllowedPacket: defaultMaxAllowedPacket, AllowNativePasswords: true, CheckConnLiveness: true, TLSConfig: "skip-verify"},
+	"user:password@tcp(localhost:5555)/dbname?charset=utf8mb4,utf8&tls=skip-verify&logging=testLogger",
+	&Config{User: "user", Passwd: "password", Net: "tcp", Addr: "localhost:5555", DBName: "dbname", Params: map[string]string{"charset": "utf8mb4,utf8"}, Collation: "utf8mb4_general_ci", Loc: time.UTC, MaxAllowedPacket: defaultMaxAllowedPacket, AllowNativePasswords: true, CheckConnLiveness: true, TLSConfig: "skip-verify", LoggingConfig: "testLogger"},
 }, {
-	"user:password@/dbname?loc=UTC&timeout=30s&readTimeout=1s&writeTimeout=1s&allowAllFiles=1&clientFoundRows=true&allowOldPasswords=TRUE&collation=utf8mb4_unicode_ci&maxAllowedPacket=16777216&tls=false&allowCleartextPasswords=true&parseTime=true&rejectReadOnly=true",
-	&Config{User: "user", Passwd: "password", Net: "tcp", Addr: "127.0.0.1:3306", DBName: "dbname", Collation: "utf8mb4_unicode_ci", Loc: time.UTC, TLSConfig: "false", AllowCleartextPasswords: true, AllowNativePasswords: true, Timeout: 30 * time.Second, ReadTimeout: time.Second, WriteTimeout: time.Second, AllowAllFiles: true, AllowOldPasswords: true, CheckConnLiveness: true, ClientFoundRows: true, MaxAllowedPacket: 16777216, ParseTime: true, RejectReadOnly: true},
+	"user:password@/dbname?loc=UTC&timeout=30s&readTimeout=1s&writeTimeout=1s&allowAllFiles=1&clientFoundRows=true&allowOldPasswords=TRUE&collation=utf8mb4_unicode_ci&maxAllowedPacket=16777216&tls=false&allowCleartextPasswords=true&parseTime=true&rejectReadOnly=true&logging=true",
+	&Config{User: "user", Passwd: "password", Net: "tcp", Addr: "127.0.0.1:3306", DBName: "dbname", Collation: "utf8mb4_unicode_ci", Loc: time.UTC, TLSConfig: "false", AllowCleartextPasswords: true, AllowNativePasswords: true, Timeout: 30 * time.Second, ReadTimeout: time.Second, WriteTimeout: time.Second, LoggingConfig: "true", AllowAllFiles: true, AllowOldPasswords: true, CheckConnLiveness: true, ClientFoundRows: true, MaxAllowedPacket: 16777216, ParseTime: true, RejectReadOnly: true},
 }, {
 	"user:password@/dbname?allowNativePasswords=false&checkConnLiveness=false&maxAllowedPacket=0&allowFallbackToPlaintext=true",
 	&Config{User: "user", Passwd: "password", Net: "tcp", Addr: "127.0.0.1:3306", DBName: "dbname", Collation: "utf8mb4_general_ci", Loc: time.UTC, MaxAllowedPacket: 0, AllowFallbackToPlaintext: true, AllowNativePasswords: false, CheckConnLiveness: false},
@@ -75,6 +77,10 @@ var testDSNs = []struct {
 }
 
 func TestDSNParser(t *testing.T) {
+	logger := log.New(os.Stderr, "", log.LstdFlags)
+	RegisterLogger("testLogger", logger)
+	defer DeregisterLogger("testLogger")
+
 	for i, tst := range testDSNs {
 		cfg, err := ParseDSN(tst.in)
 		if err != nil {
@@ -83,6 +89,7 @@ func TestDSNParser(t *testing.T) {
 
 		// pointer not static
 		cfg.TLS = nil
+		cfg.Logger = nil
 
 		if !reflect.DeepEqual(cfg, tst.out) {
 			t.Errorf("%d. ParseDSN(%q) mismatch:\ngot  %+v\nwant %+v", i, tst.in, cfg, tst.out)
@@ -112,6 +119,10 @@ func TestDSNParserInvalid(t *testing.T) {
 }
 
 func TestDSNReformat(t *testing.T) {
+	logger := log.New(os.Stderr, "", log.LstdFlags)
+	RegisterLogger("testLogger", logger)
+	defer DeregisterLogger("testLogger")
+
 	for i, tst := range testDSNs {
 		dsn1 := tst.in
 		cfg1, err := ParseDSN(dsn1)
@@ -268,6 +279,93 @@ func TestDSNWithCustomTLSQueryEscape(t *testing.T) {
 	}
 }
 
+func TestDSNWithCustomLogger(t *testing.T) {
+	baseDSN := "User:password@tcp(localhost:5555)/dbname?logging="
+
+	t.Run("custom logger is registered", func(tt *testing.T) {
+		logger := log.New(os.Stderr, "", log.LstdFlags)
+
+		RegisterLogger("testKey", logger)
+		defer DeregisterLogger("testKey")
+
+		tst := baseDSN + "testKey"
+
+		cfg, err := ParseDSN(tst)
+		if err != nil {
+			tt.Fatal(err.Error())
+		}
+
+		if cfg.LoggingConfig != "testKey" {
+			tt.Errorf("unexpected cfg.LoggingConfig value: %q", cfg.LoggingConfig)
+		}
+		if cfg.Logger != logger {
+			tt.Error("logger pointer doesn't match")
+		}
+	})
+
+	t.Run("custom logger is missing", func(tt *testing.T) {
+		tst := baseDSN + "invalid_name"
+
+		cfg, err := ParseDSN(tst)
+		if err == nil {
+			tt.Errorf("invalid name in DSN (%s) but did not error. Got config: %#v", tst, cfg)
+		}
+	})
+}
+
+func TestDSNLoggingConfig(t *testing.T) {
+	t.Run("logging=true", func(tt *testing.T) {
+		dsn := "User:password@tcp(localhost:5555)/dbname?logging=true"
+
+		cfg, err := ParseDSN(dsn)
+		if err != nil {
+			tt.Fatal(err.Error())
+		}
+
+		if cfg.LoggingConfig != "true" {
+			tt.Errorf("unexpected cfg.LoggingConfig value: %q", cfg.LoggingConfig)
+		}
+		if cfg.Logger != nil {
+			tt.Error("cfg.Logger should be nil")
+		}
+	})
+
+	t.Run("logging=false", func(tt *testing.T) {
+		dsn := "User:password@tcp(localhost:5555)/dbname?logging=false"
+
+		cfg, err := ParseDSN(dsn)
+		if err != nil {
+			tt.Fatal(err.Error())
+		}
+
+		if cfg.LoggingConfig != "false" {
+			tt.Errorf("unexpected cfg.LoggingConfig value: %q", cfg.LoggingConfig)
+		}
+		if cfg.Logger != defaultNopLogger {
+			tt.Error("logger pointer doesn't match")
+		}
+	})
+}
+
+func TestDSNWithCustomLoggerQueryEscape(t *testing.T) {
+	const name = "&%!:"
+	dsn := "User:password@tcp(localhost:5555)/dbname?logging=" + url.QueryEscape(name)
+
+	logger := log.New(os.Stderr, "", log.LstdFlags)
+
+	RegisterLogger(name, logger)
+	defer DeregisterTLSConfig(name)
+
+	cfg, err := ParseDSN(dsn)
+	if err != nil {
+		t.Fatal(err.Error())
+	}
+
+	if cfg.Logger != logger {
+		t.Error("logger pointer doesn't match")
+	}
+}
+
 func TestDSNUnsafeCollation(t *testing.T) {
 	_, err := ParseDSN("/dbname?collation=gbk_chinese_ci&interpolateParams=true")
 	if err != errInvalidDSNUnsafeCollation {