Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: implement console plain output for debug logs #1456

Merged
merged 3 commits into from
Jan 17, 2022
Merged
Show file tree
Hide file tree
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Next Next commit
feat: implement console plain output for debug logs
  • Loading branch information
kevwan committed Jan 16, 2022
commit 1411bce68cc8dd49c0594ea567c8414f33dfd35a
5 changes: 3 additions & 2 deletions core/logx/config.go
Original file line number Diff line number Diff line change
Expand Up @@ -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,console]"`
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"`
Expand Down
17 changes: 11 additions & 6 deletions core/logx/durationlogger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 consoleEncodingType:
writeConsoleAny(writer, level, val, l.Duration)
default:
outputJson(writer, &durationLogger{
Timestamp: getTimestamp(),
Level: level,
Content: val,
Duration: l.Duration,
})
}
}
13 changes: 13 additions & 0 deletions core/logx/durationlogger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 = consoleEncodingType
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)
Expand Down
103 changes: 93 additions & 10 deletions core/logx/logs.go
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
package logx

import (
"bytes"
"encoding/json"
"errors"
"fmt"
Expand Down Expand Up @@ -31,6 +32,15 @@ const (
SevereLevel
)

const (
jsonEncodingType = iota
consoleEncodingType

consoleEncoding = "console"
jsonEncoding = "json"
consoleEncodingSep = '\t'
)

const (
accessFilename = "access.log"
errorFilename = "error.log"
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -124,6 +135,12 @@ func SetUp(c LogConf) error {
if len(c.TimeFormat) > 0 {
timeFormat = c.TimeFormat
}
switch c.Encoding {
case consoleEncoding:
encoding = consoleEncodingType
default:
encoding = jsonEncodingType
}

switch c.Mode {
case consoleMode:
Expand Down Expand Up @@ -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 consoleEncodingType:
writeConsoleAny(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 consoleEncodingType:
writeConsoleText(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) {
Expand Down Expand Up @@ -565,6 +592,62 @@ func statSync(msg string) {
}
}

func writeConsoleAny(writer io.Writer, level string, val interface{}, fields ...string) {
switch v := val.(type) {
case string:
writeConsoleText(writer, level, v, fields...)
case error:
writeConsoleText(writer, level, v.Error(), fields...)
case fmt.Stringer:
writeConsoleText(writer, level, v.String(), fields...)
default:
var buf bytes.Buffer
buf.WriteString(getTimestamp())
buf.WriteByte(consoleEncodingSep)
buf.WriteString(level)
for _, item := range fields {
buf.WriteByte(consoleEncodingSep)
buf.WriteString(item)
}
buf.WriteByte(consoleEncodingSep)
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 writeConsoleText(writer io.Writer, level, msg string, fields ...string) {
var buf bytes.Buffer
buf.WriteString(getTimestamp())
buf.WriteByte(consoleEncodingSep)
buf.WriteString(level)
for _, item := range fields {
buf.WriteByte(consoleEncodingSep)
buf.WriteString(item)
}
buf.WriteByte(consoleEncodingSep)
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
}
Expand Down
91 changes: 91 additions & 0 deletions core/logx/logs_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 = consoleEncodingType
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 = consoleEncodingType
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 = consoleEncodingType
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 = consoleEncodingType
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 = consoleEncodingType
defer func() {
encoding = old
}()

Info(fmt.Sprint(v...))
})
}

func TestStructedLogSlow(t *testing.T) {
doTestStructedLog(t, levelSlow, func(writer io.WriteCloser) {
slowLog = writer
Expand Down Expand Up @@ -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,
Expand All @@ -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
}
28 changes: 18 additions & 10 deletions core/logx/tracelogger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 consoleEncodingType:
writeConsoleAny(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.
Expand Down
31 changes: 31 additions & 0 deletions core/logx/tracelogger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 = consoleEncodingType
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)
Expand Down
Loading