Merge pull request #287 from lukaszbudnik/enhancements-to-logging

Enhancements to logging

Author: lukaszbudnik

README.md

@@ -461,7 +461,7 @@ singleScripts:
 # optional, directories of tenant SQL script which are applied always for all tenants, these are subdirectories of baseLocation
 tenantScripts:
   - tenants-scripts
-# optional, default is:
+# optional, default is 8080
 port: 8080
 # path prefix is optional and defaults to '/'
 # path prefix is used for application HTTP request routing by Application Load Balancers/Application Gateways
@@ -479,6 +479,9 @@ webHookHeaders:
   - "Authorization: Basic QWxhZGRpbjpPcGVuU2VzYW1l"
   - "Content-Type: application/json"
   - "X-Custom-Header: value1,value2"
+# optional, allows to filter logs produced by migrator, valid values are: DEBUG, INFO, ERROR, PANIC
+# defaults to INFO
+logLevel: INFO
 ```
 
 ## Env variables substitution

common/common.go

@@ -4,25 +4,41 @@ import (
 	"context"
 	"fmt"
 	"log"
+	"path/filepath"
 	"runtime"
 )
 
+const (
+	panicLevel = "PANIC"
+	errorLevel = "ERROR"
+	infoLevel  = "INFO"
+	debugLevel = "DEBUG"
+)
+
 // RequestIDKey is used together with context for setting/getting X-Request-ID
 type RequestIDKey struct{}
 
+// LogLevel
+type LogLevelKey struct{}
+
 // LogError logs error message
 func LogError(ctx context.Context, format string, a ...interface{}) string {
-	return logLevel(ctx, "ERROR", format, a...)
+	return logLevel(ctx, errorLevel, format, a...)
 }
 
 // LogInfo logs info message
 func LogInfo(ctx context.Context, format string, a ...interface{}) string {
-	return logLevel(ctx, "INFO", format, a...)
+	return logLevel(ctx, infoLevel, format, a...)
+}
+
+// LogDebug logs debug message
+func LogDebug(ctx context.Context, format string, a ...interface{}) string {
+	return logLevel(ctx, debugLevel, format, a...)
 }
 
 // LogPanic logs error message
 func LogPanic(ctx context.Context, format string, a ...interface{}) string {
-	return logLevel(ctx, "PANIC", format, a...)
+	return logLevel(ctx, panicLevel, format, a...)
 }
 
 // Log logs message with a given level with no request context
@@ -37,14 +53,22 @@ func Log(level string, format string, a ...interface{}) string {
 }
 
 func logLevel(ctx context.Context, level string, format string, a ...interface{}) string {
-	_, file, line, _ := runtime.Caller(2)
 
-	requestID := ctx.Value(RequestIDKey{})
-	message := fmt.Sprintf(format, a...)
+	logLevel := fmt.Sprintf("%v", ctx.Value(LogLevelKey{}))
 
-	log.SetFlags(log.Ldate | log.Ltime | log.Lmicroseconds | log.LUTC)
-	log.Printf("[%v:%v] %v requestId=%v %v", file, line, level, requestID, message)
-	return message
+	if shouldLogMessage(logLevel, level) {
+		requestID := ctx.Value(RequestIDKey{})
+		message := fmt.Sprintf(format, a...)
+		_, file, line, _ := runtime.Caller(2)
+		filename := filepath.Base(file)
+
+		log.SetFlags(log.Ldate | log.Ltime | log.Lmicroseconds | log.LUTC)
+		log.Printf("[%v:%v] %v requestId=%v %v", filename, line, level, requestID, message)
+
+		return message
+	}
+
+	return ""
 }
 
 // FindNthIndex finds index of nth occurance of a character c in string str
@@ -60,3 +84,27 @@ func FindNthIndex(str string, c byte, n int) int {
 	}
 	return -1
 }
+
+func shouldLogMessage(configLogLevel, targetLevel string) bool {
+	// if configLogLevel and targetLevel match then log
+	if configLogLevel == targetLevel {
+		return true
+	}
+	// if configLogLevel is debug then all messages are logged no need to check targetLevel
+	if configLogLevel == debugLevel {
+		return true
+	}
+	// if configLogLevel not set then INFO is assumed
+	// if INFO then all levels should log except of debug
+	if (len(configLogLevel) == 0 || configLogLevel == infoLevel) && targetLevel != debugLevel {
+		return true
+	}
+
+	// if logLevel is ERROR then only ERROR and PANIC are logged
+	// ERROR is covered in the beginning of method so need to check only Panic level
+	if configLogLevel == errorLevel && targetLevel == panicLevel {
+		return true
+	}
+
+	return false
+}

common/common_test.go

@@ -10,9 +10,29 @@ import (
 func newTestContext() context.Context {
 	ctx := context.TODO()
 	ctx = context.WithValue(ctx, RequestIDKey{}, "123")
+	// log level empty = default log level = INFO
+	ctx = context.WithValue(ctx, LogLevelKey{}, "")
 	return ctx
 }
 
+func newTestContextWithDebugLogLevel() context.Context {
+	ctx := newTestContext()
+	ctx = context.WithValue(ctx, LogLevelKey{}, debugLevel)
+	return ctx
+}
+
+func TestLogDebugSkip(t *testing.T) {
+	// DEBUG message will be skipped, as the default log level is INFO
+	message := LogDebug(newTestContext(), "success")
+	assert.Empty(t, message)
+}
+
+func TestLogDebug(t *testing.T) {
+	// DEBUG message will be returned, as the log level is set to DEBUG
+	message := LogDebug(newTestContextWithDebugLogLevel(), "success")
+	assert.Equal(t, "success", message)
+}
+
 func TestLogInfo(t *testing.T) {
 	message := LogInfo(newTestContext(), "success")
 	assert.Equal(t, "success", message)
@@ -42,3 +62,35 @@ func TestFindNthIndexNotFound(t *testing.T) {
 	indx := FindNthIndex("https://lukaszbudniktest.blob.core.windows.net/mycontainer", '/', 4)
 	assert.Equal(t, -1, indx)
 }
+
+func TestShouldLogMessage(t *testing.T) {
+	// default logLevel is info, should log all except of debug
+	assert.False(t, shouldLogMessage("", debugLevel))
+	assert.True(t, shouldLogMessage("", infoLevel))
+	assert.True(t, shouldLogMessage("", errorLevel))
+	assert.True(t, shouldLogMessage("", panicLevel))
+
+	// debug logLevel logs all
+	assert.True(t, shouldLogMessage(debugLevel, debugLevel))
+	assert.True(t, shouldLogMessage(debugLevel, infoLevel))
+	assert.True(t, shouldLogMessage(debugLevel, errorLevel))
+	assert.True(t, shouldLogMessage(debugLevel, panicLevel))
+
+	// info logLevel logs all except of debug
+	assert.False(t, shouldLogMessage(infoLevel, debugLevel))
+	assert.True(t, shouldLogMessage(infoLevel, infoLevel))
+	assert.True(t, shouldLogMessage(infoLevel, errorLevel))
+	assert.True(t, shouldLogMessage(infoLevel, panicLevel))
+
+	// error logLevel logs only error or panic
+	assert.False(t, shouldLogMessage(errorLevel, debugLevel))
+	assert.False(t, shouldLogMessage(errorLevel, infoLevel))
+	assert.True(t, shouldLogMessage(errorLevel, errorLevel))
+	assert.True(t, shouldLogMessage(errorLevel, panicLevel))
+
+	// panic logLevel logs only panic
+	assert.False(t, shouldLogMessage(panicLevel, debugLevel))
+	assert.False(t, shouldLogMessage(panicLevel, infoLevel))
+	assert.False(t, shouldLogMessage(panicLevel, errorLevel))
+	assert.True(t, shouldLogMessage(panicLevel, panicLevel))
+}

config/config.go

@@ -27,6 +27,7 @@ type Config struct {
 	WebHookURL        string   `yaml:"webHookURL,omitempty"`
 	WebHookHeaders    []string `yaml:"webHookHeaders,omitempty"`
 	WebHookTemplate   string   `yaml:"webHookTemplate,omitempty"`
+	LogLevel          string   `yaml:"logLevel,omitempty" validate:"logLevel"`
 }
 
 func (config Config) String() string {
@@ -54,6 +55,7 @@ func FromBytes(contents []byte) (*Config, error) {
 	}
 
 	validate := validator.New()
+	validate.RegisterValidation("logLevel", validateLogLevel)
 	if err := validate.Struct(config); err != nil {
 		return nil, err
 	}
@@ -94,3 +96,8 @@ func substituteEnvVariable(s string) string {
 	}
 	return s
 }
+
+func validateLogLevel(fl validator.FieldLevel) bool {
+	value := fl.Field().String()
+	return value == "" || value == "DEBUG" || value == "INFO" || value == "ERROR" || value == "PANIC"
+}

config/config_test.go

@@ -43,7 +43,23 @@ func TestWithEnvFromFile(t *testing.T) {
 }
 
 func TestConfigString(t *testing.T) {
-	config := &Config{"/opt/app/migrations", "postgres", "user=p dbname=db host=localhost", "select abc", "insert into table", ":tenant", []string{"ref"}, []string{"tenants"}, []string{"procedures"}, []string{}, "8181", "", "https://hooks.slack.com/services/TTT/BBB/XXX", []string{}, `{"text": "Results are: ${summary}"}`}
+	config := &Config{
+		BaseLocation:      "/opt/app/migrations",
+		Driver:            "postgres",
+		DataSource:        "user=p dbname=db host=localhost",
+		TenantSelectSQL:   "select abc",
+		TenantInsertSQL:   "insert into table",
+		SchemaPlaceHolder: ":tenant",
+		SingleMigrations:  []string{"ref"},
+		TenantMigrations:  []string{"tenants"},
+		SingleScripts:     []string{"procedures"},
+		TenantScripts:     []string{},
+		Port:              "8181",
+		PathPrefix:        "",
+		WebHookURL:        "https://hooks.slack.com/services/TTT/BBB/XXX",
+		WebHookHeaders:    []string{},
+		WebHookTemplate:   `{"text": "Results are: ${summary}"}`,
+	}
 	// check if go naming convention applies
 	expected := `baseLocation: /opt/app/migrations
 driver: postgres
@@ -81,3 +97,27 @@ func TestConfigFromWrongSyntaxFile(t *testing.T) {
 	assert.Nil(t, config)
 	assert.IsType(t, (*yaml.TypeError)(nil), err, "Should error because of wrong yaml syntax")
 }
+
+func TestCustomValidatorLogLevelError(t *testing.T) {
+	config := `name: invoicesdb1
+baseLocation: /opt/app/migrations
+driver: postgres
+dataSource: user=p dbname=db host=localhost
+tenantSelectSQL: select abc
+tenantInsertSQL: insert into table
+schemaPlaceHolder: :tenant
+singleMigrations:
+- ref
+tenantMigrations:
+- tenants
+singleScripts:
+- procedures
+port: "8181"
+webHookURL: https://hooks.slack.com/services/TTT/BBB/XXX
+webHookTemplate: '{"text": "Results are: ${summary}"}'
+logLevel: ABC`
+
+	_, err := FromBytes([]byte(config))
+	assert.NotNil(t, err)
+	assert.Contains(t, err.Error(), `Error:Field validation for 'LogLevel' failed on the 'logLevel' tag`)
+}

db/db.go

@@ -515,7 +515,7 @@ func (bc *baseConnector) applyMigrationsInTx(tx *sql.Tx, versionName string, act
 		}
 
 		for _, s := range schemas {
-			common.LogInfo(bc.ctx, "Applying migration type: %d, schema: %s, file: %s ", m.MigrationType, s, m.File)
+			common.LogDebug(bc.ctx, "Applying migration type: %d, schema: %s, file: %s ", m.MigrationType, s, m.File)
 
 			if action == types.ActionApply {
 				contents := strings.Replace(m.Contents, schemaPlaceHolder, s, -1)

loader/s3_loader.go

@@ -19,22 +19,22 @@ type s3Loader struct {
 	baseLoader
 }
 
-// GetSourceMigrations returns all migrations from AWS S3 location
-func (s3l *s3Loader) GetSourceMigrations() []types.Migration {
+func (s3l *s3Loader) newClient() *s3.S3 {
 	sess, err := session.NewSession()
 	if err != nil {
 		panic(err.Error())
 	}
-	client := s3.New(sess)
+	return s3.New(sess)
+}
+
+// GetSourceMigrations returns all migrations from AWS S3 location
+func (s3l *s3Loader) GetSourceMigrations() []types.Migration {
+	client := s3l.newClient()
 	return s3l.doGetSourceMigrations(client)
 }
 
 func (s3l *s3Loader) HealthCheck() error {
-	sess, err := session.NewSession()
-	if err != nil {
-		return err
-	}
-	client := s3.New(sess)
+	client := s3l.newClient()
 	return s3l.doHealthCheck(client)
 }
 

notifications/notifications_test.go

@@ -106,10 +106,21 @@ func TestWebHookNotifierCustomHeaders(t *testing.T) {
 
 func TestWebHookURLError(t *testing.T) {
 	config := config.Config{}
-	config.WebHookURL = "xczxcvv"
+	config.WebHookURL = "://xczxcvv/path"
 	notifier := New(context.TODO(), &config)
-	result, err := notifier.Notify(&types.Summary{})
+	_, err := notifier.Notify(&types.Summary{})
+
+	assert.NotNil(t, err)
+	assert.Contains(t, err.Error(), "missing protocol scheme")
+}
+
+func TestWebHookClientError(t *testing.T) {
+	config := config.Config{}
+	// passes URL parsing but HTTP client returns error
+	config.WebHookURL = "non-existing-server"
+	notifier := New(context.TODO(), &config)
+	_, err := notifier.Notify(&types.Summary{})
 
 	assert.NotNil(t, err)
-	assert.Equal(t, "", result)
+	assert.Contains(t, err.Error(), "unsupported protocol scheme")
 }