feat: implement console plain output for debug logs (#1456)

* feat: implement console plain output for debug logs

* chore: rename console encoding to plain

* chore: refactor names

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"`

core/logx/durationlogger.go

@@ -79,6 +79,10 @@ func (l *durationLogger) WithDuration(duration time.Duration) Logger {
 }
 
 func (l *durationLogger) write(writer io.Writer, level string, val interface{}) {
+	switch encoding {
+	case plainEncodingType:
+		writePlainAny(writer, level, val, l.Duration)
+	default:
 		outputJson(writer, &durationLogger{
 			Timestamp: getTimestamp(),
 			Level:     level,
@@ -86,3 +90,4 @@ func (l *durationLogger) write(writer io.Writer, level string, val interface{})
 			Duration:  l.Duration,
 		})
 	}
+}

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)

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,6 +424,10 @@ func infoTextSync(msg string) {
 }
 
 func outputAny(writer io.Writer, level string, val interface{}) {
+	switch encoding {
+	case plainEncodingType:
+		writePlainAny(writer, level, val)
+	default:
 		info := logEntry{
 			Timestamp: getTimestamp(),
 			Level:     level,
@@ -414,8 +435,13 @@ func outputAny(writer io.Writer, level string, val interface{}) {
 		}
 		outputJson(writer, info)
 	}
+}
 
 func outputText(writer io.Writer, level, msg string) {
+	switch encoding {
+	case plainEncodingType:
+		writePlainText(writer, level, msg)
+	default:
 		info := logEntry{
 			Timestamp: getTimestamp(),
 			Level:     level,
@@ -423,6 +449,7 @@ func outputText(writer io.Writer, level, msg string) {
 		}
 		outputJson(writer, info)
 	}
+}
 
 func outputError(writer io.Writer, msg string, callDepth int) {
 	content := formatWithCaller(msg, callDepth)
@@ -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
 }

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
+}

core/logx/tracelogger.go

@@ -77,6 +77,13 @@ func (l *traceLogger) WithDuration(duration time.Duration) Logger {
 }
 
 func (l *traceLogger) write(writer io.Writer, level string, val interface{}) {
+	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(),
@@ -84,10 +91,11 @@ func (l *traceLogger) write(writer io.Writer, level string, val interface{}) {
 				Duration:  l.Duration,
 				Content:   val,
 			},
-		Trace: traceIdFromContext(l.ctx),
+			Trace: traceID,
-		Span:  spanIdFromContext(l.ctx),
+			Span:  spanID,
 		})
 	}
+}
 
 // WithContext sets ctx to log, for keeping tracing information.
 func WithContext(ctx context.Context) Logger {

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)

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())
+	logger := logx.WithContext(r.Context()).WithDuration(duration)
-	buf.WriteString(fmt.Sprintf("[HTTP] %s - %d - %s - %s - %s - %s",
+	buf.WriteString(fmt.Sprintf("[HTTP] %s - %d - %s - %s - %s",
-		r.Method, code, r.RequestURI, httpx.GetRemoteAddr(r), r.UserAgent(), timex.ReprOfDuration(duration)))
+		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))