implemented support for logLevel, default logLevel is INFO, unified g…

…raphql and migrator error responses, added more coverage

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

@@ -10,13 +10,8 @@ import (
 	"gopkg.in/yaml.v2"
 )
 
-const (
-	defaultMigratorName = "main"
-)
-
 // Config represents Migrator's yaml configuration file
 type Config struct {
-	Name              string   `yaml:"name,omitempty" validate:"omitempty,alphanum"`
 	BaseLocation      string   `yaml:"baseLocation" validate:"required"`
 	Driver            string   `yaml:"driver" validate:"required"`
 	DataSource        string   `yaml:"dataSource" validate:"required"`
@@ -32,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 {
@@ -59,14 +55,11 @@ func FromBytes(contents []byte) (*Config, error) {
 	}
 
 	validate := validator.New()
+	validate.RegisterValidation("logLevel", validateLogLevel)
 	if err := validate.Struct(config); err != nil {
 		return nil, err
 	}
 
-	if len(config.Name) == 0 {
-		config.Name = defaultMigratorName
-	}
-
 	substituteEnvVariables(&config)
 
 	return &config, nil
@@ -103,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

@@ -13,8 +13,6 @@ import (
 func TestFromFile(t *testing.T) {
 	config, err := FromFile("../test/migrator-test.yaml")
 	assert.Nil(t, err)
-	// default migrator name
-	assert.Equal(t, defaultMigratorName, config.Name)
 	assert.Equal(t, "test/migrations", config.BaseLocation)
 	assert.Equal(t, "select name from migrator.migrator_tenants", config.TenantSelectSQL)
 	assert.Equal(t, "postgres", config.Driver)
@@ -46,7 +44,6 @@ func TestWithEnvFromFile(t *testing.T) {
 
 func TestConfigString(t *testing.T) {
 	config := &Config{
-		Name:              "invoicesdb1",
 		BaseLocation:      "/opt/app/migrations",
 		Driver:            "postgres",
 		DataSource:        "user=p dbname=db host=localhost",
@@ -64,8 +61,7 @@ func TestConfigString(t *testing.T) {
 		WebHookTemplate:   `{"text": "Results are: ${summary}"}`,
 	}
 	// check if go naming convention applies
-	expected := `name: invoicesdb1
-baseLocation: /opt/app/migrations
+	expected := `baseLocation: /opt/app/migrations
 driver: postgres
 dataSource: user=p dbname=db host=localhost
 tenantSelectSQL: select abc
@@ -101,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)

server/server.go

@@ -26,8 +26,11 @@ const (
 )
 
 type errorResponse struct {
-	ErrorMessage string      `json:"error"`
-	Details      interface{} `json:"details,omitempty"`
+	Errors []errorMessage `json:"errors"`
+}
+
+type errorMessage struct {
+	Message string `json:"message"`
 }
 
 // GetPort gets the port from config or defaultPort
@@ -50,6 +53,14 @@ func requestIDHandler() gin.HandlerFunc {
 	}
 }
 
+func logLevelHandler(config *config.Config) gin.HandlerFunc {
+	return func(c *gin.Context) {
+		ctx := context.WithValue(c.Request.Context(), common.LogLevelKey{}, config.LogLevel)
+		c.Request = c.Request.WithContext(ctx)
+		c.Next()
+	}
+}
+
 func recovery() gin.HandlerFunc {
 	return func(c *gin.Context) {
 		defer func() {
@@ -58,7 +69,8 @@ func recovery() gin.HandlerFunc {
 				if gin.IsDebugging() {
 					debug.PrintStack()
 				}
-				c.AbortWithStatusJSON(http.StatusInternalServerError, &errorResponse{err.(string), nil})
+				errorMsg := errorMessage{err.(string)}
+				c.AbortWithStatusJSON(http.StatusInternalServerError, errorResponse{Errors: []errorMessage{errorMsg}})
 			}
 		}()
 		c.Next()
@@ -107,7 +119,8 @@ func serviceHandler(c *gin.Context, config *config.Config, metrics metrics.Metri
 	}
 	if err := c.ShouldBindJSON(&params); err != nil {
 		common.LogError(c.Request.Context(), "Bad request: %v", err.Error())
-		c.AbortWithStatusJSON(http.StatusBadRequest, errorResponse{"Invalid request, please see documentation for valid JSON payload", nil})
+		errorMsg := errorMessage{"Invalid request, please see documentation for valid JSON payload"}
+		c.AbortWithStatusJSON(http.StatusBadRequest, errorResponse{Errors: []errorMessage{errorMsg}})
 		return
 	}
 
@@ -117,7 +130,12 @@ func serviceHandler(c *gin.Context, config *config.Config, metrics metrics.Metri
 	schema := graphql.MustParseSchema(data.SchemaDefinition, &data.RootResolver{Coordinator: coordinator}, opts...)
 
 	response := schema.Exec(c.Request.Context(), params.Query, params.OperationName, params.Variables)
-	c.JSON(http.StatusOK, response)
+	if response.Errors == nil {
+		c.JSON(http.StatusOK, response)
+	} else {
+		c.JSON(http.StatusInternalServerError, response)
+	}
+
 }
 
 func CreateRouterAndPrometheus(versionInfo *types.VersionInfo, config *config.Config, newCoordinator coordinator.Factory) *gin.Engine {
@@ -146,7 +164,7 @@ func CreateRouterAndPrometheus(versionInfo *types.VersionInfo, config *config.Co
 // SetupRouter setups router
 func SetupRouter(r *gin.Engine, versionInfo *types.VersionInfo, config *config.Config, metrics metrics.Metrics, newCoordinator coordinator.Factory) *gin.Engine {
 	r.HandleMethodNotAllowed = true
-	r.Use(recovery(), requestIDHandler(), requestLoggerHandler())
+	r.Use(logLevelHandler(config), recovery(), requestIDHandler(), requestLoggerHandler())
 
 	if strings.TrimSpace(config.PathPrefix) == "" {
 		config.PathPrefix = "/"