diff --git a/log/formatters.go b/log/formatters.go index 0c8688e..3a8bf9a 100644 --- a/log/formatters.go +++ b/log/formatters.go @@ -2,6 +2,7 @@ package log import ( "bytes" + "encoding/json" "fmt" "path/filepath" "strings" @@ -64,3 +65,61 @@ func shortPath(pathIn string) string { return strings.Join(resultToks, string(filepath.Separator)) } + +type JSONFormatter struct{} + +var DefaultJSONFieldKeys = []string{"level", "timestamp", "caller", "message"} + +func (jf *JSONFormatter) Format(entry *logrus.Entry) ([]byte, error) { + data := make(logrus.Fields, len(entry.Data)+4) + for k, v := range entry.Data { + if strings.HasPrefix(k, "saaskit.") { + continue + } + + switch v := v.(type) { + case error: + // Otherwise errors are ignored by `encoding/json` + // https://github.com/sirupsen/logrus/issues/137 + data[k] = v.Error() + default: + data[k] = v + } + } + + // Configure default fields. + prefixDefaultFieldClashes(data) + data["timestamp"] = entry.Time.Format("2006/01/02 15:04:05") + data["level"] = entry.Level.String() + data["message"] = entry.Message + if entry.Caller != nil { + data["caller"] = fmt.Sprintf("%s:%d", shortPath(entry.Caller.File), entry.Caller.Line) + } + + var b *bytes.Buffer + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } + + encoder := json.NewEncoder(b) + encoder.SetEscapeHTML(true) + if err := encoder.Encode(data); err != nil { + return nil, fmt.Errorf("failed to marshal fields to JSON: %w", err) + } + + return b.Bytes(), nil +} + +// prefixDefaultFieldClashes adds a prefix to the keys in data that clash +// with the keys in DefaultJSONFieldKeys to prevent them from being overwritten. +func prefixDefaultFieldClashes(data logrus.Fields) { + for _, fieldKey := range DefaultJSONFieldKeys { + if _, ok := data[fieldKey]; ok { + data["fields."+fieldKey] = data[fieldKey] + // Delete the original non-prefixed key. + delete(data, fieldKey) + } + } +} diff --git a/log/log.go b/log/log.go index 38117e2..eafb007 100644 --- a/log/log.go +++ b/log/log.go @@ -12,14 +12,15 @@ import ( "github.com/sirupsen/logrus" ) -var ( - Log Logger -) +var Log Logger type LogOptions struct { LogLevel string BugsnagKey string AppVersion string + + // UseJSONFormatter will use JSONFormatter, default is ConsoleFormatter. + UseJSONFormatter bool } func InitLog(opts *LogOptions) { @@ -33,14 +34,18 @@ func InitLog(opts *LogOptions) { } } - Log.SetFormatter(&ConsoleFormatter{}) - Log.logger.AddHook(&CallerHook{}) if opts == nil { return } + if opts.UseJSONFormatter { + Log.SetFormatter(&JSONFormatter{}) + } else { + Log.SetFormatter(&ConsoleFormatter{}) + } + if opts.LogLevel != "" { lvl, err := logrus.ParseLevel(opts.LogLevel) if err == nil { @@ -74,6 +79,7 @@ func InitLog(opts *LogOptions) { func WithField(key string, value interface{}) *logrus.Entry { return Log.WithField(key, value) } + func WithFields(fields logrus.Fields) *logrus.Entry { return Log.WithFields(fields) } @@ -81,6 +87,7 @@ func WithFields(fields logrus.Fields) *logrus.Entry { func Debug(args ...interface{}) { Log.Debug(args...) } + func Debugf(format string, args ...interface{}) { Log.Debugf(format, args...) } @@ -88,6 +95,7 @@ func Debugf(format string, args ...interface{}) { func Info(args ...interface{}) { Log.Info(args...) } + func Infof(format string, args ...interface{}) { Log.Infof(format, args...) } @@ -95,12 +103,15 @@ func Infof(format string, args ...interface{}) { func Warning(args ...interface{}) { Log.WithFields(getSaaskitError(args, 1)).Warning(args...) } + func Warningf(format string, args ...interface{}) { Log.WithFields(getSaaskitErrorf(format, args, 1)).Warningf(format, args...) } + func Warn(args ...interface{}) { Log.WithFields(getSaaskitError(args, 1)).Warning(args...) } + func Warnf(format string, args ...interface{}) { Log.WithFields(getSaaskitErrorf(format, args, 1)).Warningf(format, args...) } @@ -108,6 +119,7 @@ func Warnf(format string, args ...interface{}) { func Error(args ...interface{}) { Log.WithFields(getSaaskitError(args, 1)).Error(args...) } + func Errorf(format string, args ...interface{}) { // NOTE: this must support the %w wrap verb since vandoor uses it err := fmt.Errorf(format, args...) @@ -117,6 +129,7 @@ func Errorf(format string, args ...interface{}) { func Fatal(args ...interface{}) { Log.WithFields(getSaaskitError(args, 1)).Fatal(args...) } + func Fatalf(format string, args ...interface{}) { Log.WithFields(getSaaskitErrorf(format, args, 1)).Fatalf(format, args...) } diff --git a/log/log_test.go b/log/log_test.go index 982ddd1..68805a1 100644 --- a/log/log_test.go +++ b/log/log_test.go @@ -43,23 +43,60 @@ func TestFilterEvents(t *testing.T) { func TestCallerHook(t *testing.T) { param.Init(nil) - - h := &CallerHook{} + log := newLogger() + log.AddHook(&CallerHook{}) out := bytes.NewBuffer(nil) - log := newLogger() log.SetOutput(out) - log.logger.AddHook(h) - log.SetFormatter(&ConsoleFormatter{}) - log.Error("test 1") - assert.Contains(t, out.String(), "testing.go:") + validateFunc := func(formatter logrus.Formatter) { + if _, ok := formatter.(*JSONFormatter); ok { + assert.Contains(t, out.String(), "caller", "testing.go:") + } else { + assert.Contains(t, out.String(), "testing.go:") + } - out = bytes.NewBuffer(nil) - log.SetOutput(out) + out.Reset() + } + + for _, formatter := range []logrus.Formatter{ + &ConsoleFormatter{}, &JSONFormatter{}, + } { + t.Run(fmt.Sprintf("%T", formatter), func(t *testing.T) { + log.SetFormatter(formatter) + + log.Error("test 1") + validateFunc(formatter) + + log.WithField("test", "test").WithField("test2", "test2").Info("test 2") + validateFunc(formatter) + }) + } +} + +func TestPrefixFieldClashes(t *testing.T) { + param.Init(nil) + Log = newLogger() + + out := bytes.NewBuffer(nil) + Log.SetOutput(out) + Log.SetFormatter(&JSONFormatter{}) - log.WithField("test", "test").WithField("test2", "test2").Error("test 2") - assert.Contains(t, out.String(), "testing.go:") + Log.AddHook(&CallerHook{}) + + Log.WithFields(logrus.Fields{ + "level": "test", + "message": "test", + "timestamp": "test", + "caller": "test", + }).Info("super awesome test") + + assert.Contains(t, out.String(), `"fields.level":"test"`) + assert.Contains(t, out.String(), `"fields.message":"test"`) + assert.Contains(t, out.String(), `"fields.timestamp":"test"`) + assert.Contains(t, out.String(), `"fields.caller":"test"`) + assert.Contains(t, out.String(), `"level":"info"`) + assert.Contains(t, out.String(), `"message":"super awesome test"`) } func TestSaaskitError(t *testing.T) { @@ -85,25 +122,30 @@ func TestSaaskitError(t *testing.T) { }, } for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - out := bytes.NewBuffer(nil) - Log.SetOutput(out) - - h := &hook{} - Log.AddHook(h) - - Error(tt.args...) - - require.Len(t, h.entries, 1) - require.Contains(t, h.entries[0].Data, "saaskit.error") - if bugsnagErr, ok := h.entries[0].Data["saaskit.error"].(*errors.Error); ok { - assert.IsType(t, tt.wantErrType, bugsnagErr.Err) - firstLine := strings.Split(string(bugsnagErr.Stack()), "\n")[0] - assert.Contains(t, firstLine, "log_test.go:") - } else { - assert.IsType(t, tt.wantErrType, h.entries[0].Data["saaskit.error"]) - } - }) + for _, formatter := range []logrus.Formatter{ + &ConsoleFormatter{}, &JSONFormatter{}, + } { + t.Run(fmt.Sprintf("%s %T", tt.name, formatter), func(t *testing.T) { + out := bytes.NewBuffer(nil) + Log.SetOutput(out) + Log.SetFormatter(formatter) + + h := &hook{} + Log.AddHook(h) + + Error(tt.args...) + + require.Len(t, h.entries, 1) + require.Contains(t, h.entries[0].Data, "saaskit.error") + if bugsnagErr, ok := h.entries[0].Data["saaskit.error"].(*errors.Error); ok { + assert.IsType(t, tt.wantErrType, bugsnagErr.Err) + firstLine := strings.Split(string(bugsnagErr.Stack()), "\n")[0] + assert.Contains(t, firstLine, "log_test.go:") + } else { + assert.IsType(t, tt.wantErrType, h.entries[0].Data["saaskit.error"]) + } + }) + } } } @@ -127,25 +169,30 @@ func TestSaaskitErrorf(t *testing.T) { }, } for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - out := bytes.NewBuffer(nil) - Log.SetOutput(out) - - h := &hook{} - Log.AddHook(h) - - Errorf(tt.format, tt.args...) - - require.Len(t, h.entries, 1) - require.Contains(t, h.entries[0].Data, "saaskit.error") - if bugsnagErr, ok := h.entries[0].Data["saaskit.error"].(*errors.Error); ok { - assert.IsType(t, tt.wantErrType, bugsnagErr.Err) - firstLine := strings.Split(string(bugsnagErr.Stack()), "\n")[0] - assert.Contains(t, firstLine, "log_test.go:") - } else { - assert.IsType(t, tt.wantErrType, h.entries[0].Data["saaskit.error"]) - } - }) + for _, formatter := range []logrus.Formatter{ + &ConsoleFormatter{}, &JSONFormatter{}, + } { + t.Run(fmt.Sprintf("%s %T", tt.name, formatter), func(t *testing.T) { + out := bytes.NewBuffer(nil) + Log.SetOutput(out) + Log.SetFormatter(formatter) + + h := &hook{} + Log.AddHook(h) + + Errorf(tt.format, tt.args...) + + require.Len(t, h.entries, 1) + require.Contains(t, h.entries[0].Data, "saaskit.error") + if bugsnagErr, ok := h.entries[0].Data["saaskit.error"].(*errors.Error); ok { + assert.IsType(t, tt.wantErrType, bugsnagErr.Err) + firstLine := strings.Split(string(bugsnagErr.Stack()), "\n")[0] + assert.Contains(t, firstLine, "log_test.go:") + } else { + assert.IsType(t, tt.wantErrType, h.entries[0].Data["saaskit.error"]) + } + }) + } } } @@ -170,8 +217,7 @@ func (h *hook) Levels() []logrus.Level { var _ error = myError{} -type myError struct { -} +type myError struct{} func (e myError) Error() string { return "my error"