Cleanup log handling

mraerino · mraerino · commit b4606ffaf427 · 2019-09-10T17:34:04.000+02:00
diff --git a/api/api.go b/api/api.go
@@ -73,12 +73,12 @@ func waitForTermination(log logrus.FieldLogger, done <-chan struct{}) {
 }
 
 // NewAPI instantiates a new REST API using the default version.
-func NewAPI(globalConfig *conf.GlobalConfiguration, db *gorm.DB) *API {
-	return NewAPIWithVersion(context.Background(), globalConfig, db, defaultVersion)
+func NewAPI(globalConfig *conf.GlobalConfiguration, log logrus.FieldLogger, db *gorm.DB) *API {
+	return NewAPIWithVersion(context.Background(), globalConfig, log, db, defaultVersion)
 }
 
 // NewAPIWithVersion instantiates a new REST API.
-func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfiguration, db *gorm.DB, version string) *API {
+func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfiguration, log logrus.FieldLogger, db *gorm.DB, version string) *API {
 	api := &API{
 		config:     globalConfig,
 		db:         db,
@@ -87,7 +87,7 @@ func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfigurati
 	}
 
 	xffmw, _ := xff.Default()
-	logger := newStructuredLogger(logrus.StandardLogger())
+	logger := newStructuredLogger(log)
 
 	r := newRouter()
 	r.UseBypass(xffmw.Handler)
diff --git a/api/api_test.go b/api/api_test.go
@@ -6,6 +6,7 @@ import (
 	"net/http/httptest"
 	"testing"
 
+	"github.com/sirupsen/logrus"
 	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -25,7 +26,7 @@ func TestTraceWrapper(t *testing.T) {
 
 	ctx, err := WithInstanceConfig(context.Background(), globalConfig.SMTP, config, "")
 	require.NoError(t, err)
-	api := NewAPIWithVersion(ctx, globalConfig, nil, "")
+	api := NewAPIWithVersion(ctx, globalConfig, logrus.StandardLogger(), nil, "")
 
 	server := httptest.NewServer(api.handler)
 	defer server.Close()
diff --git a/api/instance_test.go b/api/instance_test.go
@@ -25,14 +25,14 @@ type InstanceTestSuite struct {
 }
 
 func (ts *InstanceTestSuite) SetupTest() {
-	globalConfig, err := conf.LoadGlobal("test.env")
+	globalConfig, log, err := conf.LoadGlobal("test.env")
 	require.NoError(ts.T(), err)
 	globalConfig.OperatorToken = operatorToken
 	globalConfig.MultiInstanceMode = true
-	db, err := models.Connect(globalConfig)
+	db, err := models.Connect(globalConfig, log)
 	require.NoError(ts.T(), err)
 
-	api := NewAPI(globalConfig, db)
+	api := NewAPI(globalConfig, log, db)
 	ts.API = api
 
 	// Cleanup existing instance
diff --git a/api/log.go b/api/log.go
@@ -10,16 +10,16 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
-func newStructuredLogger(logger *logrus.Logger) func(next http.Handler) http.Handler {
+func newStructuredLogger(logger logrus.FieldLogger) func(next http.Handler) http.Handler {
 	return chimiddleware.RequestLogger(&structuredLogger{logger})
 }
 
 type structuredLogger struct {
-	Logger *logrus.Logger
+	Logger logrus.FieldLogger
 }
 
 func (l *structuredLogger) NewLogEntry(r *http.Request) chimiddleware.LogEntry {
-	entry := &structuredLoggerEntry{Logger: logrus.NewEntry(l.Logger)}
+	entry := &structuredLoggerEntry{Logger: l.Logger}
 	logFields := logrus.Fields{
 		"component":   "api",
 		"method":      r.Method,
diff --git a/api/middleware_test.go b/api/middleware_test.go
@@ -21,13 +21,13 @@ type MiddlewareTestSuite struct {
 }
 
 func (ts *MiddlewareTestSuite) SetupTest() {
-	globalConfig, err := conf.LoadGlobal("test.env")
+	globalConfig, log, err := conf.LoadGlobal("test.env")
 	require.NoError(ts.T(), err)
 	globalConfig.MultiInstanceMode = true
-	db, err := models.Connect(globalConfig)
+	db, err := models.Connect(globalConfig, log)
 	require.NoError(ts.T(), err)
 
-	api := NewAPI(globalConfig, db)
+	api := NewAPI(globalConfig, log, db)
 	ts.API = api
 }
 
diff --git a/api/payments_test.go b/api/payments_test.go
@@ -253,7 +253,7 @@ func TestPaymentsRefund(t *testing.T) {
 		err = signHTTPRequest(r, testAdminToken("magical-unicorn", ""), test.Config.JWT.Secret)
 		require.NoError(t, err)
 
-		NewAPIWithVersion(ctx, test.GlobalConfig, test.DB, defaultVersion).handler.ServeHTTP(w, r)
+		NewAPIWithVersion(ctx, test.GlobalConfig, logrus.StandardLogger(), test.DB, defaultVersion).handler.ServeHTTP(w, r)
 
 		rsp := new(models.Transaction)
 		extractPayload(t, http.StatusOK, w, rsp)
@@ -674,7 +674,7 @@ func TestPaymentPreauthorize(t *testing.T) {
 			globalConfig := new(conf.GlobalConfiguration)
 			ctx, err := WithInstanceConfig(context.Background(), globalConfig.SMTP, test.Config, "")
 			require.NoError(t, err)
-			NewAPIWithVersion(ctx, test.GlobalConfig, test.DB, "").handler.ServeHTTP(recorder, req)
+			NewAPIWithVersion(ctx, test.GlobalConfig, logrus.StandardLogger(), test.DB, "").handler.ServeHTTP(recorder, req)
 
 			rsp := payments.PreauthorizationResult{}
 			extractPayload(t, http.StatusOK, recorder, &rsp)
@@ -715,7 +715,7 @@ func TestPaymentPreauthorize(t *testing.T) {
 			globalConfig := new(conf.GlobalConfiguration)
 			ctx, err := WithInstanceConfig(context.Background(), globalConfig.SMTP, test.Config, "")
 			require.NoError(t, err)
-			NewAPIWithVersion(ctx, test.GlobalConfig, test.DB, "").handler.ServeHTTP(recorder, req)
+			NewAPIWithVersion(ctx, test.GlobalConfig, logrus.StandardLogger(), test.DB, "").handler.ServeHTTP(recorder, req)
 
 			rsp := payments.PreauthorizationResult{}
 			extractPayload(t, http.StatusOK, recorder, &rsp)
diff --git a/api/utils_test.go b/api/utils_test.go
@@ -55,7 +55,7 @@ func db(t *testing.T) (*gorm.DB, *conf.GlobalConfiguration, *conf.Configuration,
 	globalConfig.DB.Driver = "sqlite3"
 	globalConfig.DB.URL = f.Name()
 
-	db, err := models.Connect(globalConfig)
+	db, err := models.Connect(globalConfig, logrus.StandardLogger())
 	if err != nil {
 		assert.FailNow(t, "failed to connect to db: "+err.Error())
 	}
@@ -386,7 +386,7 @@ func (r *RouteTest) TestEndpoint(method string, url string, body io.Reader, toke
 	globalConfig := new(conf.GlobalConfiguration)
 	ctx, err := WithInstanceConfig(context.Background(), globalConfig.SMTP, r.Config, "")
 	require.NoError(r.T, err)
-	NewAPIWithVersion(ctx, r.GlobalConfig, r.DB, "").handler.ServeHTTP(recorder, req)
+	NewAPIWithVersion(ctx, r.GlobalConfig, logrus.StandardLogger(), r.DB, "").handler.ServeHTTP(recorder, req)
 
 	return recorder
 }
diff --git a/cmd/migrate_cmd.go b/cmd/migrate_cmd.go
@@ -15,8 +15,8 @@ var migrateCmd = cobra.Command{
 	},
 }
 
-func migrate(globalConfig *conf.GlobalConfiguration, config *conf.Configuration) {
-	db, err := models.Connect(globalConfig)
+func migrate(globalConfig *conf.GlobalConfiguration, log logrus.FieldLogger, config *conf.Configuration) {
+	db, err := models.Connect(globalConfig, log)
 	if err != nil {
 		logrus.Fatalf("Error opening database: %+v", err)
 	}
diff --git a/cmd/multi_cmd.go b/cmd/multi_cmd.go
@@ -18,28 +18,28 @@ var multiCmd = cobra.Command{
 }
 
 func multi(cmd *cobra.Command, args []string) {
-	globalConfig, err := conf.LoadGlobal(configFile)
+	globalConfig, log, err := conf.LoadGlobal(configFile)
 	if err != nil {
 		logrus.Fatalf("Failed to load configuration: %+v", err)
 	}
 	if globalConfig.OperatorToken == "" {
 		logrus.Fatal("Operator token secret is required")
 	}
 
-	db, err := models.Connect(globalConfig)
+	db, err := models.Connect(globalConfig, log.WithField("component", "db"))
 	if err != nil {
 		logrus.Fatalf("Error opening database: %+v", err)
 	}
 	defer db.Close()
 
-	bgDB, err := models.Connect(globalConfig)
+	bgDB, err := models.Connect(globalConfig, log.WithField("component", "db").WithField("bgdb", true))
 	if err != nil {
 		logrus.Fatalf("Error opening database: %+v", err)
 	}
 	defer bgDB.Close()
 
 	globalConfig.MultiInstanceMode = true
-	api := api.NewAPIWithVersion(context.Background(), globalConfig, db.Debug(), Version)
+	api := api.NewAPIWithVersion(context.Background(), globalConfig, log, db.Debug(), Version)
 
 	l := fmt.Sprintf("%v:%v", globalConfig.API.Host, globalConfig.API.Port)
 	logrus.Infof("GoCommerce API started on: %s", l)
diff --git a/cmd/root_cmd.go b/cmd/root_cmd.go
@@ -25,8 +25,8 @@ func RootCmd() *cobra.Command {
 	return &rootCmd
 }
 
-func execWithConfig(cmd *cobra.Command, fn func(globalConfig *conf.GlobalConfiguration, config *conf.Configuration)) {
-	globalConfig, err := conf.LoadGlobal(configFile)
+func execWithConfig(cmd *cobra.Command, fn func(globalConfig *conf.GlobalConfiguration, log logrus.FieldLogger, config *conf.Configuration)) {
+	globalConfig, log, err := conf.LoadGlobal(configFile)
 	if err != nil {
 		logrus.Fatalf("Failed to load configuration: %+v", err)
 	}
@@ -35,5 +35,5 @@ func execWithConfig(cmd *cobra.Command, fn func(globalConfig *conf.GlobalConfigu
 		logrus.Fatalf("Failed to load configuration: %+v", err)
 	}
 
-	fn(globalConfig, config)
+	fn(globalConfig, log, config)
 }
diff --git a/cmd/serve_cmd.go b/cmd/serve_cmd.go
@@ -19,29 +19,29 @@ var serveCmd = cobra.Command{
 	},
 }
 
-func serve(globalConfig *conf.GlobalConfiguration, config *conf.Configuration) {
-	db, err := models.Connect(globalConfig)
+func serve(globalConfig *conf.GlobalConfiguration, log logrus.FieldLogger, config *conf.Configuration) {
+	db, err := models.Connect(globalConfig, log.WithField("component", "db"))
 	if err != nil {
-		logrus.Fatalf("Error opening database: %+v", err)
+		log.Fatalf("Error opening database: %+v", err)
 	}
 	defer db.Close()
 
-	bgDB, err := models.Connect(globalConfig)
+	bgDB, err := models.Connect(globalConfig, log.WithField("component", "db").WithField("bgdb", true))
 	if err != nil {
-		logrus.Fatalf("Error opening database: %+v", err)
+		log.Fatalf("Error opening database: %+v", err)
 	}
 	defer bgDB.Close()
 
 	ctx, err := api.WithInstanceConfig(context.Background(), globalConfig.SMTP, config, "")
 	if err != nil {
-		logrus.Fatalf("Error loading instance config: %+v", err)
+		log.Fatalf("Error loading instance config: %+v", err)
 	}
-	api := api.NewAPIWithVersion(ctx, globalConfig, db, Version)
+	api := api.NewAPIWithVersion(ctx, globalConfig, log, db, Version)
 
 	l := fmt.Sprintf("%v:%v", globalConfig.API.Host, globalConfig.API.Port)
-	logrus.Infof("GoCommerce API started on: %s", l)
+	log.Infof("GoCommerce API started on: %s", l)
 
-	models.RunHooks(bgDB, logrus.WithField("component", "hooks"))
+	models.RunHooks(bgDB, log.WithField("component", "hooks"))
 
 	api.ListenAndServe(l)
 }
diff --git a/conf/configuration.go b/conf/configuration.go
@@ -5,6 +5,7 @@ import (
 
 	"github.com/joho/godotenv"
 	"github.com/kelseyhightower/envconfig"
+	"github.com/sirupsen/logrus"
 )
 
 // DBConfiguration holds all the database related configuration.
@@ -39,7 +40,7 @@ type GlobalConfiguration struct {
 	}
 	DB                DBConfiguration
 	Logging           LoggingConfig `envconfig:"LOG"`
-	OperatorToken     string              `split_words:"true"`
+	OperatorToken     string        `split_words:"true"`
 	MultiInstanceMode bool
 	SMTP              SMTPConfiguration `json:"smtp"`
 }
@@ -118,19 +119,20 @@ func loadEnvironment(filename string) error {
 }
 
 // LoadGlobal will construct the core config from the file
-func LoadGlobal(filename string) (*GlobalConfiguration, error) {
+func LoadGlobal(filename string) (*GlobalConfiguration, *logrus.Entry, error) {
 	if err := loadEnvironment(filename); err != nil {
-		return nil, err
+		return nil, nil, err
 	}
 
 	config := new(GlobalConfiguration)
 	if err := envconfig.Process("gocommerce", config); err != nil {
-		return nil, err
+		return nil, nil, err
 	}
-	if _, err := ConfigureLogging(&config.Logging); err != nil {
-		return nil, err
+	log, err := ConfigureLogging(&config.Logging)
+	if err != nil {
+		return nil, nil, err
 	}
-	return config, nil
+	return config, log, nil
 }
 
 // LoadConfig loads the per-instance configuration from a file
diff --git a/models/connection.go b/models/connection.go
@@ -5,10 +5,9 @@ import (
 	_ "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/dialers/mysql"
 	_ "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/dialers/postgres"
 	_ "github.com/go-sql-driver/mysql"
+	"github.com/jinzhu/gorm"
 	_ "github.com/lib/pq"
 	_ "github.com/mattn/go-sqlite3"
-
-	"github.com/jinzhu/gorm"
 	"github.com/netlify/gocommerce/conf"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
@@ -21,7 +20,7 @@ import (
 var Namespace string
 
 // Connect will connect to that storage engine
-func Connect(config *conf.GlobalConfiguration) (*gorm.DB, error) {
+func Connect(config *conf.GlobalConfiguration, log logrus.FieldLogger) (*gorm.DB, error) {
 	if config.DB.Namespace != "" {
 		Namespace = config.DB.Namespace
 	}
@@ -34,17 +33,18 @@ func Connect(config *conf.GlobalConfiguration) (*gorm.DB, error) {
 		return nil, errors.Wrap(err, "opening database connection")
 	}
 
-	if logrus.StandardLogger().Level == logrus.DebugLevel {
-		db.LogMode(true)
-	}
+	db.SetLogger(NewDBLogger(log))
+	db.LogMode(true)
 
 	err = db.DB().Ping()
 	if err != nil {
 		return nil, errors.Wrap(err, "checking database connection")
 	}
 
 	if config.DB.Automigrate {
-		if err := AutoMigrate(db); err != nil {
+		migDB := db.New()
+		migDB.SetLogger(NewDBLogger(log.WithField("task", "migration")))
+		if err := AutoMigrate(migDB); err != nil {
 			return nil, errors.Wrap(err, "migrating tables")
 		}
 	}
diff --git a/models/connection_logger.go b/models/connection_logger.go
@@ -0,0 +1,56 @@
+package models
+
+import (
+	"encoding/json"
+	"fmt"
+	"strings"
+	"time"
+
+	"github.com/sirupsen/logrus"
+)
+
+type DBLogger struct {
+	logrus.FieldLogger
+}
+
+func NewDBLogger(log logrus.FieldLogger) *DBLogger {
+	return &DBLogger{log}
+}
+
+func (dbl *DBLogger) Print(params ...interface{}) {
+	if len(params) <= 1 {
+		return
+	}
+
+	level := params[0]
+	log := dbl.WithField("gorm_level", level)
+
+	if entry, ok := dbl.FieldLogger.(*logrus.Entry); ok && entry.Logger.Level >= logrus.TraceLevel {
+		log = log.WithField("gorm_source", params[1])
+	}
+
+	if level != "sql" {
+		log.Debug(params[2:]...)
+		return
+	}
+
+	dur := params[2].(time.Duration)
+	sql := params[3].(string)
+	sqlValues := params[4].([]interface{})
+	rows := params[5].(int64)
+
+	values := ""
+	if valuesJSON, err := json.Marshal(sqlValues); err == nil {
+		values = string(valuesJSON)
+	} else {
+		values = fmt.Sprintf("%+v", sqlValues)
+	}
+
+	log.
+		WithField("dur_ns", dur.Nanoseconds()).
+		WithField("dur", dur).
+		WithField("sql", strings.ReplaceAll(sql, `"`, `'`)).
+		WithField("values", strings.ReplaceAll(values, `"`, `'`)).
+		WithField("rows", rows).
+		Debug("sql query")
+}

Original file line number	Diff line number	Diff line change
`@@ -10,16 +10,16 @@ import (`
`10`	`10`	`"github.com/sirupsen/logrus"`
`11`	`11`	`)`
`12`	`12`
`13`		`-func newStructuredLogger(logger *logrus.Logger) func(next http.Handler) http.Handler {`
	`13`	`+func newStructuredLogger(logger logrus.FieldLogger) func(next http.Handler) http.Handler {`
`14`	`14`	`return chimiddleware.RequestLogger(&structuredLogger{logger})`
`15`	`15`	`}`
`16`	`16`
`17`	`17`	`type structuredLogger struct {`
`18`		`- Logger *logrus.Logger`
	`18`	`+ Logger logrus.FieldLogger`
`19`	`19`	`}`
`20`	`20`
`21`	`21`	`func (l structuredLogger) NewLogEntry(r http.Request) chimiddleware.LogEntry {`
`22`		`- entry := &structuredLoggerEntry{Logger: logrus.NewEntry(l.Logger)}`
	`22`	`+ entry := &structuredLoggerEntry{Logger: l.Logger}`
`23`	`23`	`logFields := logrus.Fields{`
`24`	`24`	`"component": "api",`
`25`	`25`	`"method": r.Method,`
Original file line number	Diff line number	Diff line change
`@@ -21,13 +21,13 @@ type MiddlewareTestSuite struct {`
`21`	`21`	`}`
`22`	`22`
`23`	`23`	`func (ts *MiddlewareTestSuite) SetupTest() {`
`24`		`- globalConfig, err := conf.LoadGlobal("test.env")`
	`24`	`+ globalConfig, log, err := conf.LoadGlobal("test.env")`
`25`	`25`	`require.NoError(ts.T(), err)`
`26`	`26`	`globalConfig.MultiInstanceMode = true`
`27`		`- db, err := models.Connect(globalConfig)`
	`27`	`+ db, err := models.Connect(globalConfig, log)`
`28`	`28`	`require.NoError(ts.T(), err)`
`29`	`29`
`30`		`- api := NewAPI(globalConfig, db)`
	`30`	`+ api := NewAPI(globalConfig, log, db)`
`31`	`31`	`ts.API = api`
`32`	`32`	`}`
`33`	`33`
Original file line number	Diff line number	Diff line change
`@@ -15,8 +15,8 @@ var migrateCmd = cobra.Command{`
`15`	`15`	`},`
`16`	`16`	`}`
`17`	`17`
`18`		`-func migrate(globalConfig conf.GlobalConfiguration, config conf.Configuration) {`
`19`		`- db, err := models.Connect(globalConfig)`
	`18`	`+func migrate(globalConfig conf.GlobalConfiguration, log logrus.FieldLogger, config conf.Configuration) {`
	`19`	`+ db, err := models.Connect(globalConfig, log)`
`20`	`20`	`if err != nil {`
`21`	`21`	`logrus.Fatalf("Error opening database: %+v", err)`
`22`	`22`	`}`
Original file line number	Diff line number	Diff line change
`@@ -18,28 +18,28 @@ var multiCmd = cobra.Command{`
`18`	`18`	`}`
`19`	`19`
`20`	`20`	`func multi(cmd *cobra.Command, args []string) {`
`21`		`- globalConfig, err := conf.LoadGlobal(configFile)`
	`21`	`+ globalConfig, log, err := conf.LoadGlobal(configFile)`
`22`	`22`	`if err != nil {`
`23`	`23`	`logrus.Fatalf("Failed to load configuration: %+v", err)`
`24`	`24`	`}`
`25`	`25`	`if globalConfig.OperatorToken == "" {`
`26`	`26`	`logrus.Fatal("Operator token secret is required")`
`27`	`27`	`}`
`28`	`28`
`29`		`- db, err := models.Connect(globalConfig)`
	`29`	`+ db, err := models.Connect(globalConfig, log.WithField("component", "db"))`
`30`	`30`	`if err != nil {`
`31`	`31`	`logrus.Fatalf("Error opening database: %+v", err)`
`32`	`32`	`}`
`33`	`33`	`defer db.Close()`
`34`	`34`
`35`		`- bgDB, err := models.Connect(globalConfig)`
	`35`	`+ bgDB, err := models.Connect(globalConfig, log.WithField("component", "db").WithField("bgdb", true))`
`36`	`36`	`if err != nil {`
`37`	`37`	`logrus.Fatalf("Error opening database: %+v", err)`
`38`	`38`	`}`
`39`	`39`	`defer bgDB.Close()`
`40`	`40`
`41`	`41`	`globalConfig.MultiInstanceMode = true`
`42`		`- api := api.NewAPIWithVersion(context.Background(), globalConfig, db.Debug(), Version)`
	`42`	`+ api := api.NewAPIWithVersion(context.Background(), globalConfig, log, db.Debug(), Version)`
`43`	`43`
`44`	`44`	`l := fmt.Sprintf("%v:%v", globalConfig.API.Host, globalConfig.API.Port)`
`45`	`45`	`logrus.Infof("GoCommerce API started on: %s", l)`
Original file line number	Diff line number	Diff line change
`@@ -25,8 +25,8 @@ func RootCmd() *cobra.Command {`
`25`	`25`	`return &rootCmd`
`26`	`26`	`}`
`27`	`27`
`28`		`-func execWithConfig(cmd cobra.Command, fn func(globalConfig conf.GlobalConfiguration, config *conf.Configuration)) {`
`29`		`- globalConfig, err := conf.LoadGlobal(configFile)`
	`28`	`+func execWithConfig(cmd cobra.Command, fn func(globalConfig conf.GlobalConfiguration, log logrus.FieldLogger, config *conf.Configuration)) {`
	`29`	`+ globalConfig, log, err := conf.LoadGlobal(configFile)`
`30`	`30`	`if err != nil {`
`31`	`31`	`logrus.Fatalf("Failed to load configuration: %+v", err)`
`32`	`32`	`}`
`@@ -35,5 +35,5 @@ func execWithConfig(cmd cobra.Command, fn func(globalConfig conf.GlobalConfigu`
`35`	`35`	`logrus.Fatalf("Failed to load configuration: %+v", err)`
`36`	`36`	`}`
`37`	`37`
`38`		`- fn(globalConfig, config)`
	`38`	`+ fn(globalConfig, log, config)`
`39`	`39`	`}`