Merge pull request #19 from kamil-holubicki/DISTMYSQL-157

DISTMYSQL-157: Improve error logging of MySQL errors

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