diff --git a/core/logx/config.go b/core/logx/config.go index be09ae3a9116..8c0b8987d44d 100644 --- a/core/logx/config.go +++ b/core/logx/config.go @@ -3,10 +3,11 @@ package logx // A LogConf is a logging config. type LogConf struct { ServiceName string `json:",optional"` - Mode string `json:",default=console,options=console|file|volume"` + Mode string `json:",default=console,options=[console,file,volume]"` + Encoding string `json:",default=json,options=[json,plain]"` TimeFormat string `json:",optional"` Path string `json:",default=logs"` - Level string `json:",default=info,options=info|error|severe"` + Level string `json:",default=info,options=[info,error,severe]"` Compress bool `json:",optional"` KeepDays int `json:",optional"` StackCooldownMillis int `json:",default=100"` diff --git a/core/logx/durationlogger.go b/core/logx/durationlogger.go index 92df85fc1339..ab26a0a6c31b 100644 --- a/core/logx/durationlogger.go +++ b/core/logx/durationlogger.go @@ -79,10 +79,15 @@ func (l *durationLogger) WithDuration(duration time.Duration) Logger { } func (l *durationLogger) write(writer io.Writer, level string, val interface{}) { - outputJson(writer, &durationLogger{ - Timestamp: getTimestamp(), - Level: level, - Content: val, - Duration: l.Duration, - }) + switch encoding { + case plainEncodingType: + writePlainAny(writer, level, val, l.Duration) + default: + outputJson(writer, &durationLogger{ + Timestamp: getTimestamp(), + Level: level, + Content: val, + Duration: l.Duration, + }) + } } diff --git a/core/logx/durationlogger_test.go b/core/logx/durationlogger_test.go index b916c2b5d2d6..96eba091e378 100644 --- a/core/logx/durationlogger_test.go +++ b/core/logx/durationlogger_test.go @@ -37,6 +37,19 @@ func TestWithDurationInfo(t *testing.T) { assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) } +func TestWithDurationInfoConsole(t *testing.T) { + old := encoding + encoding = plainEncodingType + defer func() { + encoding = old + }() + + var builder strings.Builder + log.SetOutput(&builder) + WithDuration(time.Second).Info("foo") + assert.True(t, strings.Contains(builder.String(), "ms"), builder.String()) +} + func TestWithDurationInfof(t *testing.T) { var builder strings.Builder log.SetOutput(&builder) diff --git a/core/logx/logs.go b/core/logx/logs.go index de3f7c5bce82..5eb232dee23f 100644 --- a/core/logx/logs.go +++ b/core/logx/logs.go @@ -1,6 +1,7 @@ package logx import ( + "bytes" "encoding/json" "errors" "fmt" @@ -31,6 +32,15 @@ const ( SevereLevel ) +const ( + jsonEncodingType = iota + plainEncodingType + + jsonEncoding = "json" + plainEncoding = "plain" + plainEncodingSep = '\t' +) + const ( accessFilename = "access.log" errorFilename = "error.log" @@ -65,6 +75,7 @@ var ( timeFormat = "2006-01-02T15:04:05.000Z07" writeConsole bool logLevel uint32 + encoding = jsonEncodingType // use uint32 for atomic operations disableStat uint32 infoLog io.WriteCloser @@ -124,6 +135,12 @@ func SetUp(c LogConf) error { if len(c.TimeFormat) > 0 { timeFormat = c.TimeFormat } + switch c.Encoding { + case plainEncoding: + encoding = plainEncodingType + default: + encoding = jsonEncodingType + } switch c.Mode { case consoleMode: @@ -407,21 +424,31 @@ func infoTextSync(msg string) { } func outputAny(writer io.Writer, level string, val interface{}) { - info := logEntry{ - Timestamp: getTimestamp(), - Level: level, - Content: val, + switch encoding { + case plainEncodingType: + writePlainAny(writer, level, val) + default: + info := logEntry{ + Timestamp: getTimestamp(), + Level: level, + Content: val, + } + outputJson(writer, info) } - outputJson(writer, info) } func outputText(writer io.Writer, level, msg string) { - info := logEntry{ - Timestamp: getTimestamp(), - Level: level, - Content: msg, + switch encoding { + case plainEncodingType: + writePlainText(writer, level, msg) + default: + info := logEntry{ + Timestamp: getTimestamp(), + Level: level, + Content: msg, + } + outputJson(writer, info) } - outputJson(writer, info) } func outputError(writer io.Writer, msg string, callDepth int) { @@ -565,6 +592,62 @@ func statSync(msg string) { } } +func writePlainAny(writer io.Writer, level string, val interface{}, fields ...string) { + switch v := val.(type) { + case string: + writePlainText(writer, level, v, fields...) + case error: + writePlainText(writer, level, v.Error(), fields...) + case fmt.Stringer: + writePlainText(writer, level, v.String(), fields...) + default: + var buf bytes.Buffer + buf.WriteString(getTimestamp()) + buf.WriteByte(plainEncodingSep) + buf.WriteString(level) + for _, item := range fields { + buf.WriteByte(plainEncodingSep) + buf.WriteString(item) + } + buf.WriteByte(plainEncodingSep) + if err := json.NewEncoder(&buf).Encode(val); err != nil { + log.Println(err.Error()) + return + } + buf.WriteByte('\n') + if atomic.LoadUint32(&initialized) == 0 || writer == nil { + log.Println(buf.String()) + return + } + + if _, err := writer.Write(buf.Bytes()); err != nil { + log.Println(err.Error()) + } + } +} + +func writePlainText(writer io.Writer, level, msg string, fields ...string) { + var buf bytes.Buffer + buf.WriteString(getTimestamp()) + buf.WriteByte(plainEncodingSep) + buf.WriteString(level) + for _, item := range fields { + buf.WriteByte(plainEncodingSep) + buf.WriteString(item) + } + buf.WriteByte(plainEncodingSep) + buf.WriteString(msg) + buf.WriteByte('\n') + if atomic.LoadUint32(&initialized) == 0 || writer == nil { + log.Println(buf.String()) + return + } + + if _, err := writer.Write(buf.Bytes()); err != nil { + log.Println(err.Error()) + } +} + type logWriter struct { logger *log.Logger } diff --git a/core/logx/logs_test.go b/core/logx/logs_test.go index 03c77fcc96b5..29d647c24782 100644 --- a/core/logx/logs_test.go +++ b/core/logx/logs_test.go @@ -141,6 +141,78 @@ func TestStructedLogInfov(t *testing.T) { }) } +func TestStructedLogInfoConsoleAny(t *testing.T) { + doTestStructedLogConsole(t, func(writer io.WriteCloser) { + infoLog = writer + }, func(v ...interface{}) { + old := encoding + encoding = plainEncodingType + defer func() { + encoding = old + }() + + Infov(v) + }) +} + +func TestStructedLogInfoConsoleAnyString(t *testing.T) { + doTestStructedLogConsole(t, func(writer io.WriteCloser) { + infoLog = writer + }, func(v ...interface{}) { + old := encoding + encoding = plainEncodingType + defer func() { + encoding = old + }() + + Infov(fmt.Sprint(v...)) + }) +} + +func TestStructedLogInfoConsoleAnyError(t *testing.T) { + doTestStructedLogConsole(t, func(writer io.WriteCloser) { + infoLog = writer + }, func(v ...interface{}) { + old := encoding + encoding = plainEncodingType + defer func() { + encoding = old + }() + + Infov(errors.New(fmt.Sprint(v...))) + }) +} + +func TestStructedLogInfoConsoleAnyStringer(t *testing.T) { + doTestStructedLogConsole(t, func(writer io.WriteCloser) { + infoLog = writer + }, func(v ...interface{}) { + old := encoding + encoding = plainEncodingType + defer func() { + encoding = old + }() + + Infov(ValStringer{ + val: fmt.Sprint(v...), + }) + }) +} + +func TestStructedLogInfoConsoleText(t *testing.T) { + doTestStructedLogConsole(t, func(writer io.WriteCloser) { + infoLog = writer + }, func(v ...interface{}) { + old := encoding + encoding = plainEncodingType + defer func() { + encoding = old + }() + + Info(fmt.Sprint(v...)) + }) +} + func TestStructedLogSlow(t *testing.T) { doTestStructedLog(t, levelSlow, func(writer io.WriteCloser) { slowLog = writer @@ -432,6 +504,17 @@ func doTestStructedLog(t *testing.T, level string, setup func(writer io.WriteClo assert.True(t, strings.Contains(val, message)) } +func doTestStructedLogConsole(t *testing.T, setup func(writer io.WriteCloser), + write func(...interface{})) { + const message = "hello there" + writer := new(mockWriter) + setup(writer) + atomic.StoreUint32(&initialized, 1) + write(message) + println(writer.String()) + assert.True(t, strings.Contains(writer.String(), message)) +} + func testSetLevelTwiceWithMode(t *testing.T, mode string) { SetUp(LogConf{ Mode: mode, @@ -456,3 +539,11 @@ func testSetLevelTwiceWithMode(t *testing.T, mode string) { ErrorStackf(message) assert.Equal(t, 0, writer.builder.Len()) } + +type ValStringer struct { + val string +} + +func (v ValStringer) String() string { + return v.val +} diff --git a/core/logx/tracelogger.go b/core/logx/tracelogger.go index 53c4ef470ce7..e2702d51571b 100644 --- a/core/logx/tracelogger.go +++ b/core/logx/tracelogger.go @@ -77,16 +77,24 @@ func (l *traceLogger) WithDuration(duration time.Duration) Logger { } func (l *traceLogger) write(writer io.Writer, level string, val interface{}) { - outputJson(writer, &traceLogger{ - logEntry: logEntry{ - Timestamp: getTimestamp(), - Level: level, - Duration: l.Duration, - Content: val, - }, - Trace: traceIdFromContext(l.ctx), - Span: spanIdFromContext(l.ctx), - }) + traceID := traceIdFromContext(l.ctx) + spanID := spanIdFromContext(l.ctx) + + switch encoding { + case plainEncodingType: + writePlainAny(writer, level, val, l.Duration, traceID, spanID) + default: + outputJson(writer, &traceLogger{ + logEntry: logEntry{ + Timestamp: getTimestamp(), + Level: level, + Duration: l.Duration, + Content: val, + }, + Trace: traceID, + Span: spanID, + }) + } } // WithContext sets ctx to log, for keeping tracing information. diff --git a/core/logx/tracelogger_test.go b/core/logx/tracelogger_test.go index 52363497cb05..7da8d0dd63e7 100644 --- a/core/logx/tracelogger_test.go +++ b/core/logx/tracelogger_test.go @@ -82,6 +82,37 @@ func TestTraceInfo(t *testing.T) { assert.True(t, strings.Contains(buf.String(), spanKey)) } +func TestTraceInfoConsole(t *testing.T) { + old := encoding + encoding = plainEncodingType + defer func() { + encoding = old + }() + + var buf mockWriter + atomic.StoreUint32(&initialized, 1) + infoLog = newLogWriter(log.New(&buf, "", flags)) + otp := otel.GetTracerProvider() + tp := sdktrace.NewTracerProvider(sdktrace.WithSampler(sdktrace.AlwaysSample())) + otel.SetTracerProvider(tp) + defer otel.SetTracerProvider(otp) + + ctx, _ := tp.Tracer("foo").Start(context.Background(), "bar") + l := WithContext(ctx).(*traceLogger) + SetLevel(InfoLevel) + l.WithDuration(time.Second).Info(testlog) + assert.True(t, strings.Contains(buf.String(), traceIdFromContext(ctx))) + assert.True(t, strings.Contains(buf.String(), spanIdFromContext(ctx))) + buf.Reset() + l.WithDuration(time.Second).Infof(testlog) + assert.True(t, strings.Contains(buf.String(), traceIdFromContext(ctx))) + assert.True(t, strings.Contains(buf.String(), spanIdFromContext(ctx))) + buf.Reset() + l.WithDuration(time.Second).Infov(testlog) + assert.True(t, strings.Contains(buf.String(), traceIdFromContext(ctx))) + assert.True(t, strings.Contains(buf.String(), spanIdFromContext(ctx))) +} + func TestTraceSlow(t *testing.T) { var buf mockWriter atomic.StoreUint32(&initialized, 1) diff --git a/rest/handler/loghandler.go b/rest/handler/loghandler.go index 0cf9b3e8f48f..f9b0a8729ab1 100644 --- a/rest/handler/loghandler.go +++ b/rest/handler/loghandler.go @@ -160,9 +160,9 @@ func dumpRequest(r *http.Request) string { func logBrief(r *http.Request, code int, timer *utils.ElapsedTimer, logs *internal.LogCollector) { var buf bytes.Buffer duration := timer.Duration() - logger := logx.WithContext(r.Context()) - buf.WriteString(fmt.Sprintf("[HTTP] %s - %d - %s - %s - %s - %s", - r.Method, code, r.RequestURI, httpx.GetRemoteAddr(r), r.UserAgent(), timex.ReprOfDuration(duration))) + logger := logx.WithContext(r.Context()).WithDuration(duration) + buf.WriteString(fmt.Sprintf("[HTTP] %s - %d - %s - %s - %s", + r.Method, code, r.RequestURI, httpx.GetRemoteAddr(r), r.UserAgent())) if duration > slowThreshold.Load() { logger.Slowf("[HTTP] %s - %d - %s - %s - %s - slowcall(%s)", r.Method, code, r.RequestURI, httpx.GetRemoteAddr(r), r.UserAgent(), timex.ReprOfDuration(duration))