Skip to content
Permalink
Browse files

Cleanup log handling

  • Loading branch information...
mraerino committed Sep 10, 2019
1 parent 1352182 commit b4606ffaf4278c27811d99cf1e411be71902026b
@@ -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)
@@ -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()
@@ -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
@@ -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,
@@ -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
}

@@ -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)
@@ -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
}
@@ -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)
}
@@ -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)
@@ -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)
}
@@ -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)
}
@@ -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
@@ -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")
}
}
@@ -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")
}

0 comments on commit b4606ff

Please sign in to comment.
You can’t perform that action at this time.