DISTMYSQL-157: Improve error logging of MySQL errors

https://jira.percona.com/browse/DISTMYSQL-157

Problem:
Some error logs indicate only the error returned by the server without
the information about the server identity itself.
On the other hand there are also logs which display the server identity
together with the returned error.

Cause:
There is an utility layer implemented by golib/sqlutils which intercepts
database queries. Some queries done by orchestrator go through this
layer and some don't.
sqlutils layer in case of query error prints out the query to the stdout

Solution:
golib/sqlutils layer is not aware of the server identity it operates on.
It proxies creation of sql.DB object and then uses this object for
queries execution.

Logger interface has been introduced. golib/sqlutils client can register
its own logger which will be used instead of internal logging when the
error occurs during usage of the related sql.DB object.

Additionally, I've made the local copy of golib utility module.

Author: kamil-holubicki

go.mod

@@ -49,4 +49,5 @@ replace (
 	github.com/hashicorp/raft => github.com/openark/raft v0.0.0-20170918052300-fba9f909f7fe
 	golang.org/x/text v0.3.0 => golang.org/x/text v0.3.8
 	golang.org/x/text v0.3.7 => golang.org/x/text v0.3.8
+	github.com/openark/golib => ./go/golib
 )

go/db/db.go

@@ -21,6 +21,7 @@ import (
 	"errors"
 	"fmt"
 	"regexp"
+	"strconv"
 	"strings"
 	"sync"
 	"time"
@@ -100,7 +101,8 @@ func openTopology(host string, port int, readTimeout int) (db *sql.DB, err error
 			return nil, err
 		}
 	}
-	if db, _, err = sqlutils.GetDB(mysql_uri); err != nil {
+	sqlUtilsLogger := SqlUtilsLogger{client_context: host + ":" + strconv.Itoa(port)}
+	if db, _, err = sqlutils.GetDB(mysql_uri, sqlUtilsLogger); err != nil {
 		return nil, err
 	}
 	if config.Config.MySQLConnectionLifetimeSeconds > 0 {
@@ -123,7 +125,8 @@ func openOrchestratorMySQLGeneric() (db *sql.DB, fromCache bool, err error) {
 	if config.Config.MySQLOrchestratorUseMutualTLS {
 		uri, _ = SetupMySQLOrchestratorTLS(uri)
 	}
-	return sqlutils.GetDB(uri)
+	sqlUtilsLogger := SqlUtilsLogger{client_context: config.Config.MySQLOrchestratorHost + ":" + config.Config.MySQLOrchestratorHost}
+	return sqlutils.GetDB(uri, sqlUtilsLogger)
 }
 
 func IsSQLite() bool {
@@ -174,7 +177,7 @@ func safeMySQLURI(dsn string) string {
 func OpenOrchestrator() (db *sql.DB, err error) {
 	var fromCache bool
 	if IsSQLite() {
-		db, fromCache, err = sqlutils.GetSQLiteDB(config.Config.SQLite3DataFile)
+		db, fromCache, err = sqlutils.GetSQLiteDB(config.Config.SQLite3DataFile, nil)
 		if err == nil && !fromCache {
 			log.Debugf("Connected to orchestrator backend: sqlite on %v", config.Config.SQLite3DataFile)
 		}
@@ -191,7 +194,8 @@ func OpenOrchestrator() (db *sql.DB, err error) {
 			}
 		}
 		dsn := getMySQLURI()
-		db, fromCache, err = sqlutils.GetDB(dsn)
+		sqlUtilsLogger := SqlUtilsLogger{client_context: dsn}
+		db, fromCache, err = sqlutils.GetDB(dsn, sqlUtilsLogger)
 		if err == nil && !fromCache {
 			log.Debugf("Connected to orchestrator backend: %v", safeMySQLURI(dsn))
 

go/db/tls.go

@@ -19,6 +19,7 @@ package db
 import (
 	"crypto/tls"
 	"fmt"
+	"strconv"
 	"strings"
 	"time"
 
@@ -55,6 +56,23 @@ func init() {
 	metrics.Register("instance_tls.write_cache", writeInstanceTLSCacheCounter)
 }
 
+type SqlUtilsLogger struct {
+	client_context string
+}
+
+func (logger SqlUtilsLogger) OnError(caller_context string, query string, err error) error {
+	query = strings.Join(strings.Fields(query), " ")  // trim whitespaces
+	query = strings.Replace(query, "%", "%%", -1)  // escape %
+
+	msg := fmt.Sprintf("%+v(%+v) %+v: %+v",
+						caller_context,
+						logger.client_context,
+						query,
+						err)
+
+	return log.Errorf(msg)
+}
+
 func requiresTLS(host string, port int, mysql_uri string) bool {
 	cacheKey := fmt.Sprintf("%s:%d", host, port)
 
@@ -64,7 +82,8 @@ func requiresTLS(host string, port int, mysql_uri string) bool {
 	}
 
 	required := false
-	db, _, _ := sqlutils.GetDB(mysql_uri)
+	sqlUtilsLogger := SqlUtilsLogger{client_context: host + ":" + strconv.Itoa(port)}
+	db, _, _ := sqlutils.GetDB(mysql_uri, sqlUtilsLogger)
 	if err := db.Ping(); err != nil && (strings.Contains(err.Error(), Error3159) || strings.Contains(err.Error(), Error1045)) {
 		required = true
 	}

go/golib/go.mod

@@ -0,0 +1,3 @@
+module golib
+
+go 1.18

go/golib/log/log.go

@@ -0,0 +1,268 @@
+/*
+   Copyright 2014 Outbrain Inc.
+
+   Licensed under the Apache License, Version 2.0 (the "License");
+   you may not use this file except in compliance with the License.
+   You may obtain a copy of the License at
+
+       http://www.apache.org/licenses/LICENSE-2.0
+
+   Unless required by applicable law or agreed to in writing, software
+   distributed under the License is distributed on an "AS IS" BASIS,
+   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+   See the License for the specific language governing permissions and
+   limitations under the License.
+*/
+
+package log
+
+import (
+	"errors"
+	"fmt"
+	"log/syslog"
+	"os"
+	"runtime/debug"
+	"time"
+)
+
+// LogLevel indicates the severity of a log entry
+type LogLevel int
+
+func (this LogLevel) String() string {
+	switch this {
+	case FATAL:
+		return "FATAL"
+	case CRITICAL:
+		return "CRITICAL"
+	case ERROR:
+		return "ERROR"
+	case WARNING:
+		return "WARNING"
+	case NOTICE:
+		return "NOTICE"
+	case INFO:
+		return "INFO"
+	case DEBUG:
+		return "DEBUG"
+	}
+	return "unknown"
+}
+
+func LogLevelFromString(logLevelName string) (LogLevel, error) {
+	switch logLevelName {
+	case "FATAL":
+		return FATAL, nil
+	case "CRITICAL":
+		return CRITICAL, nil
+	case "ERROR":
+		return ERROR, nil
+	case "WARNING":
+		return WARNING, nil
+	case "NOTICE":
+		return NOTICE, nil
+	case "INFO":
+		return INFO, nil
+	case "DEBUG":
+		return DEBUG, nil
+	}
+	return 0, fmt.Errorf("Unknown LogLevel name: %+v", logLevelName)
+}
+
+const (
+	FATAL LogLevel = iota
+	CRITICAL
+	ERROR
+	WARNING
+	NOTICE
+	INFO
+	DEBUG
+)
+
+const TimeFormat = "2006-01-02 15:04:05"
+
+// globalLogLevel indicates the global level filter for all logs (only entries with level equals or higher
+// than this value will be logged)
+var globalLogLevel LogLevel = DEBUG
+var printStackTrace bool = false
+
+// syslogWriter is optional, and defaults to nil (disabled)
+var syslogLevel LogLevel = ERROR
+var syslogWriter *syslog.Writer
+
+// SetPrintStackTrace enables/disables dumping the stack upon error logging
+func SetPrintStackTrace(shouldPrintStackTrace bool) {
+	printStackTrace = shouldPrintStackTrace
+}
+
+// SetLevel sets the global log level. Only entries with level equals or higher than
+// this value will be logged
+func SetLevel(logLevel LogLevel) {
+	globalLogLevel = logLevel
+}
+
+// GetLevel returns current global log level
+func GetLevel() LogLevel {
+	return globalLogLevel
+}
+
+// EnableSyslogWriter enables, if possible, writes to syslog. These will execute _in addition_ to normal logging
+func EnableSyslogWriter(tag string) (err error) {
+	syslogWriter, err = syslog.New(syslog.LOG_ERR, tag)
+	if err != nil {
+		syslogWriter = nil
+	}
+	return err
+}
+
+// SetSyslogLevel sets the minimal syslog level. Only entries with level equals or higher than
+// this value will be logged. However, this is also capped by the global log level. That is,
+// messages with lower level than global-log-level will be discarded at any case.
+func SetSyslogLevel(logLevel LogLevel) {
+	syslogLevel = logLevel
+}
+
+// logFormattedEntry nicely formats and emits a log entry
+func logFormattedEntry(logLevel LogLevel, message string, args ...interface{}) string {
+	if logLevel > globalLogLevel {
+		return ""
+	}
+	// if TZ env variable is set, update the timestamp timezone
+	localizedTime := time.Now()
+	tzLocation := os.Getenv("TZ")
+	if tzLocation != "" {
+		location, err := time.LoadLocation(tzLocation)
+		if err == nil { // if invalid tz location was provided, just leave it as the default
+			localizedTime = time.Now().In(location)
+		}
+	}
+
+	msgArgs := fmt.Sprintf(message, args...)
+	entryString := fmt.Sprintf("%s %s %s", localizedTime.Format(TimeFormat), logLevel, msgArgs)
+	fmt.Fprintln(os.Stderr, entryString)
+
+	if syslogWriter != nil {
+		go func() error {
+			if logLevel > syslogLevel {
+				return nil
+			}
+			switch logLevel {
+			case FATAL:
+				return syslogWriter.Emerg(msgArgs)
+			case CRITICAL:
+				return syslogWriter.Crit(msgArgs)
+			case ERROR:
+				return syslogWriter.Err(msgArgs)
+			case WARNING:
+				return syslogWriter.Warning(msgArgs)
+			case NOTICE:
+				return syslogWriter.Notice(msgArgs)
+			case INFO:
+				return syslogWriter.Info(msgArgs)
+			case DEBUG:
+				return syslogWriter.Debug(msgArgs)
+			}
+			return nil
+		}()
+	}
+	return entryString
+}
+
+// logEntry emits a formatted log entry
+func logEntry(logLevel LogLevel, message string, args ...interface{}) string {
+	entryString := message
+	for _, s := range args {
+		entryString += fmt.Sprintf(" %s", s)
+	}
+	return logFormattedEntry(logLevel, entryString)
+}
+
+// logErrorEntry emits a log entry based on given error object
+func logErrorEntry(logLevel LogLevel, err error) error {
+	if err == nil {
+		// No error
+		return nil
+	}
+	entryString := fmt.Sprintf("%+v", err)
+	logEntry(logLevel, entryString)
+	if printStackTrace {
+		debug.PrintStack()
+	}
+	return err
+}
+
+func Debug(message string, args ...interface{}) string {
+	return logEntry(DEBUG, message, args...)
+}
+
+func Debugf(message string, args ...interface{}) string {
+	return logFormattedEntry(DEBUG, message, args...)
+}
+
+func Info(message string, args ...interface{}) string {
+	return logEntry(INFO, message, args...)
+}
+
+func Infof(message string, args ...interface{}) string {
+	return logFormattedEntry(INFO, message, args...)
+}
+
+func Notice(message string, args ...interface{}) string {
+	return logEntry(NOTICE, message, args...)
+}
+
+func Noticef(message string, args ...interface{}) string {
+	return logFormattedEntry(NOTICE, message, args...)
+}
+
+func Warning(message string, args ...interface{}) error {
+	return errors.New(logEntry(WARNING, message, args...))
+}
+
+func Warningf(message string, args ...interface{}) error {
+	return errors.New(logFormattedEntry(WARNING, message, args...))
+}
+
+func Error(message string, args ...interface{}) error {
+	return errors.New(logEntry(ERROR, message, args...))
+}
+
+func Errorf(message string, args ...interface{}) error {
+	return errors.New(logFormattedEntry(ERROR, message, args...))
+}
+
+func Errore(err error) error {
+	return logErrorEntry(ERROR, err)
+}
+
+func Critical(message string, args ...interface{}) error {
+	return errors.New(logEntry(CRITICAL, message, args...))
+}
+
+func Criticalf(message string, args ...interface{}) error {
+	return errors.New(logFormattedEntry(CRITICAL, message, args...))
+}
+
+func Criticale(err error) error {
+	return logErrorEntry(CRITICAL, err)
+}
+
+// Fatal emits a FATAL level entry and exists the program
+func Fatal(message string, args ...interface{}) error {
+	logEntry(FATAL, message, args...)
+	os.Exit(1)
+	return errors.New(logEntry(CRITICAL, message, args...))
+}
+
+// Fatalf emits a FATAL level entry and exists the program
+func Fatalf(message string, args ...interface{}) error {
+	logFormattedEntry(FATAL, message, args...)
+	os.Exit(1)
+	return errors.New(logFormattedEntry(CRITICAL, message, args...))
+}
+
+// Fatale emits a FATAL level entry and exists the program
+func Fatale(err error) error {
+	logErrorEntry(FATAL, err)
+	os.Exit(1)
+	return err
+}