From b4ed5f390bfb5afa3b9b515fadfe0ff2ef90dc3c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?S=C3=A9bastien=20GLON?= Date: Mon, 30 Jan 2023 14:58:33 +0100 Subject: [PATCH] Feat(Logging): create new JSON logger MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Sébastien GLON --- src/jobservice/logger/backend/db_logger.go | 2 +- src/jobservice/logger/backend/file_logger.go | 2 +- src/jobservice/logger/backend/std_logger.go | 2 +- src/lib/log/formatter.go | 13 +++++ src/lib/log/jsonformatter.go | 60 ++++++++++++++++++++ src/lib/log/logger.go | 30 ++++------ src/lib/log/logger_test.go | 55 ++++++++++++++++-- src/lib/log/record.go | 22 ++++--- src/lib/log/textformatter.go | 22 ++++++- src/pkg/audit/forward.go | 2 +- 10 files changed, 170 insertions(+), 40 deletions(-) create mode 100644 src/lib/log/jsonformatter.go diff --git a/src/jobservice/logger/backend/db_logger.go b/src/jobservice/logger/backend/db_logger.go index a1832bb8c8b..1192a51e10e 100644 --- a/src/jobservice/logger/backend/db_logger.go +++ b/src/jobservice/logger/backend/db_logger.go @@ -26,7 +26,7 @@ func NewDBLogger(key string, level string, depth int) (*DBLogger, error) { bw := bufio.NewWriter(buffer) logLevel := parseLevel(level) - backendLogger := log.New(bw, log.NewTextFormatter(), logLevel, depth) + backendLogger := log.New(bw, log.NewFormatter(), logLevel, depth) return &DBLogger{ backendLogger: backendLogger, diff --git a/src/jobservice/logger/backend/file_logger.go b/src/jobservice/logger/backend/file_logger.go index 6ec12f7ab3c..9a2cb27534b 100644 --- a/src/jobservice/logger/backend/file_logger.go +++ b/src/jobservice/logger/backend/file_logger.go @@ -21,7 +21,7 @@ func NewFileLogger(level string, logPath string, depth int) (*FileLogger, error) return nil, err } logLevel := parseLevel(level) - backendLogger := log.New(f, log.NewTextFormatter(), logLevel, depth) + backendLogger := log.New(f, log.NewFormatter(), logLevel, depth) return &FileLogger{ backendLogger: backendLogger, diff --git a/src/jobservice/logger/backend/std_logger.go b/src/jobservice/logger/backend/std_logger.go index d51cbba20f3..f5e1851e0d5 100644 --- a/src/jobservice/logger/backend/std_logger.go +++ b/src/jobservice/logger/backend/std_logger.go @@ -26,7 +26,7 @@ func NewStdOutputLogger(level string, output string, depth int) *StdOutputLogger if output == StdErr { logStream = os.Stderr } - backendLogger := log.New(logStream, log.NewTextFormatter(), logLevel, depth) + backendLogger := log.New(logStream, log.NewFormatter(), logLevel, depth) return &StdOutputLogger{ backendLogger: backendLogger, diff --git a/src/lib/log/formatter.go b/src/lib/log/formatter.go index 67fb04e387e..a2155d7ac1f 100644 --- a/src/lib/log/formatter.go +++ b/src/lib/log/formatter.go @@ -14,7 +14,20 @@ package log +import "os" + // Formatter formats records in different ways: text, json, etc. type Formatter interface { Format(*Record) ([]byte, error) } + +// NewTextFormatter returns a TextFormatter, the format of time is time.RFC3339 +func NewFormatter() Formatter { + switch os.Getenv("LOG_FORMAT") { + case "json": + return NewJsonFormatter() + default: + return NewTextFormatter() + } + +} diff --git a/src/lib/log/jsonformatter.go b/src/lib/log/jsonformatter.go new file mode 100644 index 00000000000..b5ad1445f7c --- /dev/null +++ b/src/lib/log/jsonformatter.go @@ -0,0 +1,60 @@ +// Copyright Project Harbor Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package log + +import ( + "encoding/json" + "fmt" + "time" +) + +// JsonFormatter represents a kind of formatter that formats the logs as plain text +type JsonFormatter struct { + // timeFormat string +} + +// NewTextFormatter returns a TextFormatter, the format of time is time.RFC3339 +func NewJsonFormatter() Formatter { + return &JsonFormatter{ + // timeFormat: defaultTimeFormat, + } +} + +// Format formats the logs as "time [level] line message" +func (t *JsonFormatter) Format(r *Record) (b []byte, err error) { + // s := fmt.Sprintf("%s [%s] ", r.Time.Format(t.timeFormat), r.Lvl.string()) + b, err = json.Marshal(r) + if err != nil { + fmt.Println(err) + return + } + + return +} + +// // SetTimeFormat sets time format of JsonFormatter if the parameter fmt is not null +// func (t *JsonFormatter) SetTimeFormat(fmt string) { +// if len(fmt) != 0 { +// t.timeFormat = fmt +// } +// } + +func (c RecordTime) MarshalJSON() ([]byte, error) { + return []byte(`"` + time.Time(c).Format(time.RFC3339) + `"`), nil +} + +func (l Level) MarshalJSON() (b []byte, err error) { + return []byte(`"` + l.string() + `"`), nil +} diff --git a/src/lib/log/logger.go b/src/lib/log/logger.go index 04bd1b2b987..ea6523673f2 100644 --- a/src/lib/log/logger.go +++ b/src/lib/log/logger.go @@ -26,7 +26,7 @@ import ( ) // NOTE: the default depth for the logger is 3 so that we can get the correct file and line when use the logger to log message -var logger = New(os.Stdout, NewTextFormatter(), WarningLevel, 3) +var logger = New(os.Stdout, NewFormatter(), WarningLevel, 3) const srcSeparator = "harbor" + string(os.PathSeparator) + "src" @@ -141,7 +141,6 @@ func (l *Logger) WithFields(fields Fields) *Logger { } r.fields = copyFields - r.fieldsStr = "[" + strings.Join(parts, " ") + "]" } return r @@ -198,7 +197,7 @@ func (l *Logger) output(record *Record) (err error) { // Debug ... func (l *Logger) Debug(v ...interface{}) { if l.lvl <= DebugLevel { - record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), DebugLevel) + record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), DebugLevel, l.fields) _ = l.output(record) } } @@ -206,7 +205,7 @@ func (l *Logger) Debug(v ...interface{}) { // Debugf ... func (l *Logger) Debugf(format string, v ...interface{}) { if l.lvl <= DebugLevel { - record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), DebugLevel) + record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), DebugLevel, l.fields) _ = l.output(record) } } @@ -214,7 +213,7 @@ func (l *Logger) Debugf(format string, v ...interface{}) { // Info ... func (l *Logger) Info(v ...interface{}) { if l.lvl <= InfoLevel { - record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), InfoLevel) + record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), InfoLevel, l.fields) _ = l.output(record) } } @@ -222,7 +221,7 @@ func (l *Logger) Info(v ...interface{}) { // Infof ... func (l *Logger) Infof(format string, v ...interface{}) { if l.lvl <= InfoLevel { - record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), InfoLevel) + record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), InfoLevel, l.fields) _ = l.output(record) } } @@ -230,7 +229,7 @@ func (l *Logger) Infof(format string, v ...interface{}) { // Warning ... func (l *Logger) Warning(v ...interface{}) { if l.lvl <= WarningLevel { - record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), WarningLevel) + record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), WarningLevel, l.fields) _ = l.output(record) } } @@ -238,7 +237,7 @@ func (l *Logger) Warning(v ...interface{}) { // Warningf ... func (l *Logger) Warningf(format string, v ...interface{}) { if l.lvl <= WarningLevel { - record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), WarningLevel) + record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), WarningLevel, l.fields) _ = l.output(record) } } @@ -246,7 +245,7 @@ func (l *Logger) Warningf(format string, v ...interface{}) { // Error ... func (l *Logger) Error(v ...interface{}) { if l.lvl <= ErrorLevel { - record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), ErrorLevel) + record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), ErrorLevel, l.fields) _ = l.output(record) } } @@ -254,7 +253,7 @@ func (l *Logger) Error(v ...interface{}) { // Errorf ... func (l *Logger) Errorf(format string, v ...interface{}) { if l.lvl <= ErrorLevel { - record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), ErrorLevel) + record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), ErrorLevel, l.fields) _ = l.output(record) } } @@ -262,7 +261,7 @@ func (l *Logger) Errorf(format string, v ...interface{}) { // Fatal ... func (l *Logger) Fatal(v ...interface{}) { if l.lvl <= FatalLevel { - record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), FatalLevel) + record := NewRecord(time.Now(), fmt.Sprint(v...), l.getLine(), FatalLevel, l.fields) _ = l.output(record) } os.Exit(1) @@ -271,7 +270,7 @@ func (l *Logger) Fatal(v ...interface{}) { // Fatalf ... func (l *Logger) Fatalf(format string, v ...interface{}) { if l.lvl <= FatalLevel { - record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), FatalLevel) + record := NewRecord(time.Now(), fmt.Sprintf(format, v...), l.getLine(), FatalLevel, l.fields) _ = l.output(record) } os.Exit(1) @@ -287,13 +286,6 @@ func (l *Logger) getLine() string { if !l.skipLine { str = line(l.callDepth) } - - str = str + l.fieldsStr - - if str != "" { - str = str + ":" - } - return str } diff --git a/src/lib/log/logger_test.go b/src/lib/log/logger_test.go index 502abc76c6e..d81ebb0676f 100644 --- a/src/lib/log/logger_test.go +++ b/src/lib/log/logger_test.go @@ -30,7 +30,7 @@ func contains(t *testing.T, str string, lvl string, line, msg string) bool { return strings.Contains(str, lvl) && strings.Contains(str, line) && strings.Contains(str, msg) } -func TestSetx(t *testing.T) { +func TestTextSetx(t *testing.T) { logger := New(nil, nil, WarningLevel) logger.SetOutput(os.Stdout) fmt := NewTextFormatter() @@ -50,17 +50,37 @@ func TestSetx(t *testing.T) { } } +func TestJsonSetx(t *testing.T) { + logger := New(nil, nil, WarningLevel) + logger.SetOutput(os.Stdout) + fmt := NewJsonFormatter() + logger.setFormatter(fmt) + logger.setLevel(DebugLevel) + + if logger.out != os.Stdout { + t.Errorf("unexpected outer: %v != %v", logger.out, os.Stdout) + } + + if logger.fmtter != fmt { + t.Errorf("unexpected formatter: %v != %v", logger.fmtter, fmt) + } + + if logger.lvl != DebugLevel { + t.Errorf("unexpected log level: %v != %v", logger.lvl, DebugLevel) + } +} + func TestWithFields(t *testing.T) { buf := enter() defer exit() - logger.WithFields(Fields{"action": "create"}).Info(message) + logger.WithFields(Fields{"action": "create", "field2": "value2"}).Info(message) str := buf.String() var ( expectedLevel = InfoLevel.string() - expectLine = `[action="create"]` + expectLine = `[action="create" field2="value2"]` expectMsg = "message" ) @@ -168,7 +188,7 @@ func TestWarningf(t *testing.T) { func TestError(t *testing.T) { var ( expectedLevel = ErrorLevel.string() - expectLine = "logger_test.go:178" + expectLine = "logger_test.go:198" expectMsg = "message" ) @@ -186,7 +206,7 @@ func TestError(t *testing.T) { func TestErrorf(t *testing.T) { var ( expectedLevel = ErrorLevel.string() - expectLine = "logger_test.go:196" + expectLine = "logger_test.go:216" expectMsg = "message" ) @@ -204,7 +224,7 @@ func TestErrorf(t *testing.T) { func TestDefaultLoggerErrorf(t *testing.T) { var ( expectedLevel = ErrorLevel.string() - expectLine = "logger_test.go:214" + expectLine = "logger_test.go:234" expectMsg = "message" ) @@ -219,6 +239,29 @@ func TestDefaultLoggerErrorf(t *testing.T) { } } +func TestJsonFormatWithFields(t *testing.T) { + var ( + expectedLevel = InfoLevel.string() + expectLine = `{"action":"create"}` + expectMsg = "message" + ) + + logger := New(nil, nil, InfoLevel) + b := make([]byte, 0, 32) + buf := bytes.NewBuffer(b) + logger.SetOutput(buf) + + fmt := NewJsonFormatter() + logger.setFormatter(fmt) + logger.WithFields(Fields{"action": "create"}).Info(message) + + str := buf.String() + + if !contains(t, str, expectedLevel, expectLine, expectMsg) { + t.Errorf("unexpected message: %s, expected level: %s, expected line: %s, expected message: %s", str, expectedLevel, expectLine, expectMsg) + } +} + func enter() *bytes.Buffer { b := make([]byte, 0, 32) buf := bytes.NewBuffer(b) diff --git a/src/lib/log/record.go b/src/lib/log/record.go index b8b5febc8b9..ff0e97329dd 100644 --- a/src/lib/log/record.go +++ b/src/lib/log/record.go @@ -20,18 +20,22 @@ import ( // Record holds information about log type Record struct { - Time time.Time // time when the log produced - Msg string // content of the log - Line string // in which file and line that the log produced - Lvl Level // level of the log + Time RecordTime // time when the log produced + Msg string // content of the log + Line string // in which file and line that the log produced + Lvl Level `json:"level"` // level of the log + Fields map[string]interface{} } +type RecordTime time.Time + // NewRecord creates a record according to the arguments provided and returns it -func NewRecord(time time.Time, msg, line string, lvl Level) *Record { +func NewRecord(time time.Time, msg, line string, lvl Level, fields map[string]interface{}) *Record { return &Record{ - Time: time, - Msg: msg, - Line: line, - Lvl: lvl, + Time: RecordTime(time), + Msg: msg, + Line: line, + Lvl: lvl, + Fields: fields, } } diff --git a/src/lib/log/textformatter.go b/src/lib/log/textformatter.go index 457d940c2ba..700e9f5e190 100644 --- a/src/lib/log/textformatter.go +++ b/src/lib/log/textformatter.go @@ -15,6 +15,7 @@ package log import ( + "bytes" "fmt" "time" ) @@ -27,7 +28,7 @@ type TextFormatter struct { } // NewTextFormatter returns a TextFormatter, the format of time is time.RFC3339 -func NewTextFormatter() *TextFormatter { +func NewTextFormatter() Formatter { return &TextFormatter{ timeFormat: defaultTimeFormat, } @@ -35,11 +36,15 @@ func NewTextFormatter() *TextFormatter { // Format formats the logs as "time [level] line message" func (t *TextFormatter) Format(r *Record) (b []byte, err error) { - s := fmt.Sprintf("%s [%s] ", r.Time.Format(t.timeFormat), r.Lvl.string()) + s := fmt.Sprintf("%s [%s] ", (time.Time(r.Time)).Format(t.timeFormat), r.Lvl.string()) if len(r.Line) != 0 { s = s + r.Line + " " } + if len(r.Fields) != 0 { + s = s + mapToString(r.Fields) + + } if len(r.Msg) != 0 { s = s + r.Msg @@ -60,3 +65,16 @@ func (t *TextFormatter) SetTimeFormat(fmt string) { t.timeFormat = fmt } } + +func mapToString(m map[string]interface{}) string { + b := new(bytes.Buffer) + b.WriteByte('[') + for key, value := range m { + if b.Len() > 1 { + b.WriteByte(' ') + } + fmt.Fprintf(b, "%s=\"%s\"", key, value) + } + b.WriteByte(']') + return b.String() +} diff --git a/src/pkg/audit/forward.go b/src/pkg/audit/forward.go index b2b8f61309e..3567f632595 100644 --- a/src/pkg/audit/forward.go +++ b/src/pkg/audit/forward.go @@ -45,7 +45,7 @@ func (a *LoggerManager) Init(ctx context.Context, logEndpoint string) { w = os.Stdout a.initialized = false } - a.remoteLogger = log.New(w, log.NewTextFormatter(), log.InfoLevel, 3) + a.remoteLogger = log.New(w, log.NewFormatter(), log.InfoLevel, 3) a.remoteLogger.SetFallback(log.DefaultLogger()) }