From ac321fc146c47a978738d758057ac0a04e0b2b98 Mon Sep 17 00:00:00 2001 From: Kevin Wan Date: Tue, 3 May 2022 17:34:26 +0800 Subject: [PATCH] feat: add fields with logx methods, support using third party logging libs. (#1847) * backup * simplify * chore: remove unused pool * chore: fix lint errors * chore: use strings.Builder instead of bytes.Buffer * test: add more tests * chore: fix reviewdog * test: fix data race * feat: make logger customizable * chore: fix reviewdog * test: fix fails * chore: fix set writer twice * chore: use context instead of golang.org context * chore: specify uint32 for level types --- core/logx/durationlogger.go | 93 +++--- core/logx/durationlogger_test.go | 136 ++++++-- core/logx/lesslogger_test.go | 17 +- core/logx/logger.go | 38 +++ core/logx/logs.go | 538 ++++++++----------------------- core/logx/logs_test.go | 364 ++++++++++++++------- core/logx/logwriter.go | 22 ++ core/logx/rotatelogger_test.go | 7 + core/logx/syslog_test.go | 8 +- core/logx/tracelogger.go | 112 ++++--- core/logx/tracelogger_test.go | 157 +++++---- core/logx/util.go | 36 +++ core/logx/util_test.go | 72 +++++ core/logx/vars.go | 60 ++++ core/logx/writer.go | 320 ++++++++++++++++++ core/logx/writer_test.go | 170 ++++++++++ core/proc/goroutines_test.go | 11 +- core/proc/profile_test.go | 12 +- core/stores/redis/hook_test.go | 53 +-- rest/internal/log_test.go | 17 +- zrpc/internal/rpclogger_test.go | 98 +++--- 21 files changed, 1550 insertions(+), 791 deletions(-) create mode 100644 core/logx/logger.go create mode 100644 core/logx/logwriter.go create mode 100644 core/logx/util.go create mode 100644 core/logx/util_test.go create mode 100644 core/logx/vars.go create mode 100644 core/logx/writer.go create mode 100644 core/logx/writer_test.go diff --git a/core/logx/durationlogger.go b/core/logx/durationlogger.go index 7108a939..bf51d342 100644 --- a/core/logx/durationlogger.go +++ b/core/logx/durationlogger.go @@ -1,18 +1,13 @@ package logx import ( + "context" "fmt" - "io" - "sync/atomic" "time" "github.com/zeromicro/go-zero/core/timex" ) -const durationCallerDepth = 3 - -type durationLogger logEntry - // WithDuration returns a Logger which logs the given duration. func WithDuration(d time.Duration) Logger { return &durationLogger{ @@ -20,57 +15,62 @@ func WithDuration(d time.Duration) Logger { } } +type durationLogger logEntry + func (l *durationLogger) Error(v ...interface{}) { - if shallLog(ErrorLevel) { - l.write(errorLog, levelError, formatWithCaller(fmt.Sprint(v...), durationCallerDepth)) - } + l.err(fmt.Sprint(v...)) } func (l *durationLogger) Errorf(format string, v ...interface{}) { - if shallLog(ErrorLevel) { - l.write(errorLog, levelError, formatWithCaller(fmt.Sprintf(format, v...), durationCallerDepth)) - } + l.err(fmt.Sprintf(format, v...)) } func (l *durationLogger) Errorv(v interface{}) { - if shallLog(ErrorLevel) { - l.write(errorLog, levelError, v) - } + l.err(v) +} + +func (l *durationLogger) Errorw(msg string, fields ...LogField) { + l.err(msg, fields...) } func (l *durationLogger) Info(v ...interface{}) { - if shallLog(InfoLevel) { - l.write(infoLog, levelInfo, fmt.Sprint(v...)) - } + l.info(fmt.Sprint(v...)) } func (l *durationLogger) Infof(format string, v ...interface{}) { - if shallLog(InfoLevel) { - l.write(infoLog, levelInfo, fmt.Sprintf(format, v...)) - } + l.info(fmt.Sprintf(format, v...)) } func (l *durationLogger) Infov(v interface{}) { - if shallLog(InfoLevel) { - l.write(infoLog, levelInfo, v) - } + l.info(v) +} + +func (l *durationLogger) Infow(msg string, fields ...LogField) { + l.info(msg, fields...) } func (l *durationLogger) Slow(v ...interface{}) { - if shallLog(ErrorLevel) { - l.write(slowLog, levelSlow, fmt.Sprint(v...)) - } + l.slow(fmt.Sprint(v...)) } func (l *durationLogger) Slowf(format string, v ...interface{}) { - if shallLog(ErrorLevel) { - l.write(slowLog, levelSlow, fmt.Sprintf(format, v...)) - } + l.slow(fmt.Sprintf(format, v...)) } func (l *durationLogger) Slowv(v interface{}) { - if shallLog(ErrorLevel) { - l.write(slowLog, levelSlow, v) + l.slow(v) +} + +func (l *durationLogger) Sloww(msg string, fields ...LogField) { + l.slow(msg, fields...) +} + +func (l *durationLogger) WithContext(ctx context.Context) Logger { + return &traceLogger{ + ctx: ctx, + logEntry: logEntry{ + Duration: l.Duration, + }, } } @@ -79,16 +79,23 @@ func (l *durationLogger) WithDuration(duration time.Duration) Logger { return l } -func (l *durationLogger) write(writer io.Writer, level string, val interface{}) { - switch atomic.LoadUint32(&encoding) { - case plainEncodingType: - writePlainAny(writer, level, val, l.Duration) - default: - outputJson(writer, &durationLogger{ - Timestamp: getTimestamp(), - Level: level, - Content: val, - Duration: l.Duration, - }) +func (l *durationLogger) err(v interface{}, fields ...LogField) { + if shallLog(ErrorLevel) { + fields = append(fields, Field(durationKey, l.Duration)) + getWriter().Error(v, fields...) + } +} + +func (l *durationLogger) info(v interface{}, fields ...LogField) { + if shallLog(InfoLevel) { + fields = append(fields, Field(durationKey, l.Duration)) + getWriter().Info(v, fields...) + } +} + +func (l *durationLogger) slow(v interface{}, fields ...LogField) { + if shallLog(ErrorLevel) { + fields = append(fields, Field(durationKey, l.Duration)) + getWriter().Slow(v, fields...) } } diff --git a/core/logx/durationlogger_test.go b/core/logx/durationlogger_test.go index 4cebf448..b1f1af0d 100644 --- a/core/logx/durationlogger_test.go +++ b/core/logx/durationlogger_test.go @@ -1,41 +1,62 @@ package logx import ( - "log" + "context" "strings" "sync/atomic" "testing" "time" "github.com/stretchr/testify/assert" + "go.opentelemetry.io/otel" + sdktrace "go.opentelemetry.io/otel/sdk/trace" ) func TestWithDurationError(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Error("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) } func TestWithDurationErrorf(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Errorf("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) } func TestWithDurationErrorv(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Errorv("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) +} + +func TestWithDurationErrorw(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + WithDuration(time.Second).Errorw("foo", Field("foo", "bar")) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) + assert.True(t, strings.Contains(w.String(), "foo"), w.String()) + assert.True(t, strings.Contains(w.String(), "bar"), w.String()) } func TestWithDurationInfo(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Info("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) } func TestWithDurationInfoConsole(t *testing.T) { @@ -45,43 +66,96 @@ func TestWithDurationInfoConsole(t *testing.T) { atomic.StoreUint32(&encoding, old) }() - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + o := writer.Swap(w) + defer writer.Store(o) + WithDuration(time.Second).Info("foo") - assert.True(t, strings.Contains(builder.String(), "ms"), builder.String()) + assert.True(t, strings.Contains(w.String(), "ms"), w.String()) } func TestWithDurationInfof(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Infof("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) } func TestWithDurationInfov(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Infov("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) +} + +func TestWithDurationInfow(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + WithDuration(time.Second).Infow("foo", Field("foo", "bar")) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) + assert.True(t, strings.Contains(w.String(), "foo"), w.String()) + assert.True(t, strings.Contains(w.String(), "bar"), w.String()) +} + +func TestWithDurationWithContextInfow(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + 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") + WithDuration(time.Second).WithContext(ctx).Infow("foo", Field("foo", "bar")) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) + assert.True(t, strings.Contains(w.String(), "foo"), w.String()) + assert.True(t, strings.Contains(w.String(), "bar"), w.String()) + assert.True(t, strings.Contains(w.String(), "trace"), w.String()) + assert.True(t, strings.Contains(w.String(), "span"), w.String()) } func TestWithDurationSlow(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Slow("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) } func TestWithDurationSlowf(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).WithDuration(time.Hour).Slowf("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) } func TestWithDurationSlowv(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).WithDuration(time.Hour).Slowv("foo") - assert.True(t, strings.Contains(builder.String(), "duration"), builder.String()) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) +} + +func TestWithDurationSloww(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + WithDuration(time.Second).WithDuration(time.Hour).Sloww("foo", Field("foo", "bar")) + assert.True(t, strings.Contains(w.String(), "duration"), w.String()) + assert.True(t, strings.Contains(w.String(), "foo"), w.String()) + assert.True(t, strings.Contains(w.String(), "bar"), w.String()) } diff --git a/core/logx/lesslogger_test.go b/core/logx/lesslogger_test.go index 32f25fdb..3d615753 100644 --- a/core/logx/lesslogger_test.go +++ b/core/logx/lesslogger_test.go @@ -1,7 +1,6 @@ package logx import ( - "log" "strings" "testing" @@ -9,23 +8,27 @@ import ( ) func TestLessLogger_Error(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + l := NewLessLogger(500) for i := 0; i < 100; i++ { l.Error("hello") } - assert.Equal(t, 1, strings.Count(builder.String(), "\n")) + assert.Equal(t, 1, strings.Count(w.String(), "\n")) } func TestLessLogger_Errorf(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + l := NewLessLogger(500) for i := 0; i < 100; i++ { l.Errorf("hello") } - assert.Equal(t, 1, strings.Count(builder.String(), "\n")) + assert.Equal(t, 1, strings.Count(w.String(), "\n")) } diff --git a/core/logx/logger.go b/core/logx/logger.go new file mode 100644 index 00000000..2d48af47 --- /dev/null +++ b/core/logx/logger.go @@ -0,0 +1,38 @@ +package logx + +import ( + "context" + "time" +) + +// A Logger represents a logger. +type Logger interface { + // Error logs a message at error level. + Error(...interface{}) + // Errorf logs a message at error level. + Errorf(string, ...interface{}) + // Errorv logs a message at error level. + Errorv(interface{}) + // Errorw logs a message at error level. + Errorw(string, ...LogField) + // Info logs a message at info level. + Info(...interface{}) + // Infof logs a message at info level. + Infof(string, ...interface{}) + // Infov logs a message at info level. + Infov(interface{}) + // Infow logs a message at info level. + Infow(string, ...LogField) + // Slow logs a message at slow level. + Slow(...interface{}) + // Slowf logs a message at slow level. + Slowf(string, ...interface{}) + // Slowv logs a message at slow level. + Slowv(interface{}) + // Sloww logs a message at slow level. + Sloww(string, ...LogField) + // WithContext returns a new logger with the given context. + WithContext(context.Context) Logger + // WithDuration returns a new logger with the given duration. + WithDuration(time.Duration) Logger +} diff --git a/core/logx/logs.go b/core/logx/logs.go index 817dc513..23ec33f2 100644 --- a/core/logx/logs.go +++ b/core/logx/logs.go @@ -1,93 +1,29 @@ package logx import ( - "bytes" - "encoding/json" - "errors" "fmt" "io" - "io/ioutil" "log" "os" "path" - "runtime" "runtime/debug" - "strconv" - "strings" - "sync" "sync/atomic" "time" - "github.com/zeromicro/go-zero/core/iox" "github.com/zeromicro/go-zero/core/sysx" - "github.com/zeromicro/go-zero/core/timex" ) -const ( - // InfoLevel logs everything - InfoLevel = iota - // ErrorLevel includes errors, slows, stacks - ErrorLevel - // SevereLevel only log severe messages - SevereLevel -) - -const ( - jsonEncodingType = iota - plainEncodingType - - jsonEncoding = "json" - plainEncoding = "plain" - plainEncodingSep = '\t' -) - -const ( - accessFilename = "access.log" - errorFilename = "error.log" - severeFilename = "severe.log" - slowFilename = "slow.log" - statFilename = "stat.log" - - consoleMode = "console" - volumeMode = "volume" - - levelAlert = "alert" - levelInfo = "info" - levelError = "error" - levelSevere = "severe" - levelFatal = "fatal" - levelSlow = "slow" - levelStat = "stat" - - backupFileDelimiter = "-" - callerInnerDepth = 5 - flags = 0x0 -) +const callerDepth = 5 var ( - // ErrLogPathNotSet is an error that indicates the log path is not set. - ErrLogPathNotSet = errors.New("log path must be set") - // ErrLogNotInitialized is an error that log is not initialized. - ErrLogNotInitialized = errors.New("log not initialized") - // ErrLogServiceNameNotSet is an error that indicates that the service name is not set. - ErrLogServiceNameNotSet = errors.New("log service name must be set") - - timeFormat = "2006-01-02T15:04:05.000Z07:00" - writeConsole bool - logLevel uint32 - encoding uint32 = jsonEncodingType + timeFormat = "2006-01-02T15:04:05.000Z07:00" + logLevel uint32 + encoding uint32 = jsonEncodingType // use uint32 for atomic operations disableStat uint32 - infoLog io.WriteCloser - errorLog io.WriteCloser - severeLog io.WriteCloser - slowLog io.WriteCloser - statLog io.WriteCloser - stackLog io.Writer - - once sync.Once - initialized uint32 - options logOptions + + options logOptions + writer = new(atomicWriter) ) type ( @@ -95,109 +31,37 @@ type ( Timestamp string `json:"@timestamp"` Level string `json:"level"` Duration string `json:"duration,omitempty"` + Caller string `json:"caller,omitempty"` Content interface{} `json:"content"` } + logEntryWithFields map[string]interface{} + logOptions struct { gzipEnabled bool logStackCooldownMills int keepDays int } + // LogField is a key-value pair that will be added to the log entry. + LogField struct { + Key string + Value interface{} + } + // LogOption defines the method to customize the logging. LogOption func(options *logOptions) - - // A Logger represents a logger. - Logger interface { - Error(...interface{}) - Errorf(string, ...interface{}) - Errorv(interface{}) - Info(...interface{}) - Infof(string, ...interface{}) - Infov(interface{}) - Slow(...interface{}) - Slowf(string, ...interface{}) - Slowv(interface{}) - WithDuration(time.Duration) Logger - } ) -// MustSetup sets up logging with given config c. It exits on error. -func MustSetup(c LogConf) { - Must(SetUp(c)) -} - -// SetUp sets up the logx. If already set up, just return nil. -// we allow SetUp to be called multiple times, because for example -// we need to allow different service frameworks to initialize logx respectively. -// the same logic for SetUp -func SetUp(c LogConf) error { - if len(c.TimeFormat) > 0 { - timeFormat = c.TimeFormat - } - switch c.Encoding { - case plainEncoding: - atomic.StoreUint32(&encoding, plainEncodingType) - default: - atomic.StoreUint32(&encoding, jsonEncodingType) - } - - switch c.Mode { - case consoleMode: - setupWithConsole(c) - return nil - case volumeMode: - return setupWithVolume(c) - default: - return setupWithFiles(c) - } -} - // Alert alerts v in alert level, and the message is written to error log. func Alert(v string) { - outputText(errorLog, levelAlert, v) + getWriter().Alert(v) } // Close closes the logging. func Close() error { - if writeConsole { - return nil - } - - if atomic.LoadUint32(&initialized) == 0 { - return ErrLogNotInitialized - } - - atomic.StoreUint32(&initialized, 0) - - if infoLog != nil { - if err := infoLog.Close(); err != nil { - return err - } - } - - if errorLog != nil { - if err := errorLog.Close(); err != nil { - return err - } - } - - if severeLog != nil { - if err := severeLog.Close(); err != nil { - return err - } - } - - if slowLog != nil { - if err := slowLog.Close(); err != nil { - return err - } - } - - if statLog != nil { - if err := statLog.Close(); err != nil { - return err - } + if w := writer.Swap(nil); w != nil { + return w.(io.Closer).Close() } return nil @@ -205,16 +69,7 @@ func Close() error { // Disable disables the logging. func Disable() { - once.Do(func() { - atomic.StoreUint32(&initialized, 1) - - infoLog = iox.NopCloser(ioutil.Discard) - errorLog = iox.NopCloser(ioutil.Discard) - severeLog = iox.NopCloser(ioutil.Discard) - slowLog = iox.NopCloser(ioutil.Discard) - statLog = iox.NopCloser(ioutil.Discard) - stackLog = ioutil.Discard - }) + writer.Store(nopWriter{}) } // DisableStat disables the stat logs. @@ -224,22 +79,12 @@ func DisableStat() { // Error writes v into error log. func Error(v ...interface{}) { - ErrorCaller(1, v...) -} - -// ErrorCaller writes v with context into error log. -func ErrorCaller(callDepth int, v ...interface{}) { - errorTextSync(fmt.Sprint(v...), callDepth+callerInnerDepth) -} - -// ErrorCallerf writes v with context in format into error log. -func ErrorCallerf(callDepth int, format string, v ...interface{}) { - errorTextSync(fmt.Errorf(format, v...).Error(), callDepth+callerInnerDepth) + errorTextSync(fmt.Sprint(v...)) } // Errorf writes v with format into error log. func Errorf(format string, v ...interface{}) { - ErrorCallerf(1, format, v...) + errorTextSync(fmt.Errorf(format, v...).Error()) } // ErrorStack writes v along with call stack into error log. @@ -260,6 +105,21 @@ func Errorv(v interface{}) { errorAnySync(v) } +// Errorw writes msg along with fields into error log. +func Errorw(msg string, fields ...LogField) { + errorFieldsSync(msg, fields...) +} + +// Field returns a LogField for the given key and value. +func Field(key string, value interface{}) LogField { + switch val := value.(type) { + case time.Duration: + return LogField{Key: key, Value: fmt.Sprint(val)} + default: + return LogField{Key: key, Value: val} + } +} + // Info writes v into access log. func Info(v ...interface{}) { infoTextSync(fmt.Sprint(v...)) @@ -275,14 +135,32 @@ func Infov(v interface{}) { infoAnySync(v) } +// Infow writes msg along with fields into access log. +func Infow(msg string, fields ...LogField) { + infoFieldsSync(msg, fields...) +} + // Must checks if err is nil, otherwise logs the error and exits. func Must(err error) { - if err != nil { - msg := formatWithCaller(err.Error(), 3) - log.Print(msg) - outputText(severeLog, levelFatal, msg) - os.Exit(1) + if err == nil { + return } + + msg := err.Error() + log.Print(msg) + getWriter().Severe(msg) + os.Exit(1) +} + +// MustSetup sets up logging with given config c. It exits on error. +func MustSetup(c LogConf) { + Must(SetUp(c)) +} + +// Reset clears the writer and resets the log level. +func Reset() Writer { + SetLevel(InfoLevel) + return writer.Swap(nil) } // SetLevel sets the logging level. It can be used to suppress some logs. @@ -290,6 +168,43 @@ func SetLevel(level uint32) { atomic.StoreUint32(&logLevel, level) } +// SetWriter sets the logging writer. It can be used to customize the logging. +// Call Reset before calling SetWriter again. +func SetWriter(w Writer) { + if writer.Load() == nil { + writer.Store(w) + } +} + +// SetUp sets up the logx. If already set up, just return nil. +// we allow SetUp to be called multiple times, because for example +// we need to allow different service frameworks to initialize logx respectively. +// the same logic for SetUp +func SetUp(c LogConf) error { + setupLogLevel(c) + + if len(c.TimeFormat) > 0 { + timeFormat = c.TimeFormat + } + + switch c.Encoding { + case plainEncoding: + atomic.StoreUint32(&encoding, plainEncodingType) + default: + atomic.StoreUint32(&encoding, jsonEncodingType) + } + + switch c.Mode { + case consoleMode: + setupWithConsole() + return nil + case volumeMode: + return setupWithVolume(c) + default: + return setupWithFiles(c) + } +} + // Severe writes v into severe log. func Severe(v ...interface{}) { severeSync(fmt.Sprint(v...)) @@ -315,6 +230,11 @@ func Slowv(v interface{}) { slowAnySync(v) } +// Sloww writes msg along with fields into slow log. +func Sloww(msg string, fields ...LogField) { + slowFieldsSync(msg, fields...) +} + // Stat writes v into stat log. func Stat(v ...interface{}) { statSync(fmt.Sprint(v...)) @@ -357,52 +277,30 @@ func createOutput(path string) (io.WriteCloser, error) { func errorAnySync(v interface{}) { if shallLog(ErrorLevel) { - outputAny(errorLog, levelError, v) + getWriter().Error(v) } } -func errorTextSync(msg string, callDepth int) { +func errorFieldsSync(content string, fields ...LogField) { if shallLog(ErrorLevel) { - outputError(errorLog, msg, callDepth) + getWriter().Error(content, fields...) } } -func formatWithCaller(msg string, callDepth int) string { - var buf strings.Builder - - caller := getCaller(callDepth) - if len(caller) > 0 { - buf.WriteString(caller) - buf.WriteByte(' ') +func errorTextSync(msg string) { + if shallLog(ErrorLevel) { + getWriter().Error(msg) } - - buf.WriteString(msg) - - return buf.String() } -func getCaller(callDepth int) string { - var buf strings.Builder - - _, file, line, ok := runtime.Caller(callDepth) - if ok { - short := file - for i := len(file) - 1; i > 0; i-- { - if file[i] == '/' { - short = file[i+1:] - break - } - } - buf.WriteString(short) - buf.WriteByte(':') - buf.WriteString(strconv.Itoa(line)) +func getWriter() Writer { + w := writer.Load() + if w == nil { + w = newConsoleWriter() + writer.Store(w) } - return buf.String() -} - -func getTimestamp() string { - return timex.Time().Format(timeFormat) + return w } func handleOptions(opts []LogOption) { @@ -413,56 +311,19 @@ func handleOptions(opts []LogOption) { func infoAnySync(val interface{}) { if shallLog(InfoLevel) { - outputAny(infoLog, levelInfo, val) + getWriter().Info(val) } } -func infoTextSync(msg string) { +func infoFieldsSync(content string, fields ...LogField) { if shallLog(InfoLevel) { - outputText(infoLog, levelInfo, msg) + getWriter().Info(content, fields...) } } -func outputAny(writer io.Writer, level string, val interface{}) { - switch atomic.LoadUint32(&encoding) { - case plainEncodingType: - writePlainAny(writer, level, val) - default: - info := logEntry{ - Timestamp: getTimestamp(), - Level: level, - Content: val, - } - outputJson(writer, info) - } -} - -func outputText(writer io.Writer, level, msg string) { - switch atomic.LoadUint32(&encoding) { - case plainEncodingType: - writePlainText(writer, level, msg) - default: - info := logEntry{ - Timestamp: getTimestamp(), - Level: level, - Content: msg, - } - outputJson(writer, info) - } -} - -func outputError(writer io.Writer, msg string, callDepth int) { - content := formatWithCaller(msg, callDepth) - outputText(writer, levelError, content) -} - -func outputJson(writer io.Writer, info interface{}) { - if content, err := json.Marshal(info); err != nil { - log.Println(err.Error()) - } else if atomic.LoadUint32(&initialized) == 0 || writer == nil { - log.Println(string(content)) - } else { - writer.Write(append(content, '\n')) +func infoTextSync(msg string) { + if shallLog(InfoLevel) { + getWriter().Info(msg) } } @@ -477,72 +338,18 @@ func setupLogLevel(c LogConf) { } } -func setupWithConsole(c LogConf) { - once.Do(func() { - atomic.StoreUint32(&initialized, 1) - writeConsole = true - setupLogLevel(c) - - infoLog = newLogWriter(log.New(os.Stdout, "", flags)) - errorLog = newLogWriter(log.New(os.Stderr, "", flags)) - severeLog = newLogWriter(log.New(os.Stderr, "", flags)) - slowLog = newLogWriter(log.New(os.Stderr, "", flags)) - stackLog = newLessWriter(errorLog, options.logStackCooldownMills) - statLog = infoLog - }) +func setupWithConsole() { + SetWriter(newConsoleWriter()) } func setupWithFiles(c LogConf) error { - var opts []LogOption - var err error - - if len(c.Path) == 0 { - return ErrLogPathNotSet - } - - opts = append(opts, WithCooldownMillis(c.StackCooldownMillis)) - if c.Compress { - opts = append(opts, WithGzip()) - } - if c.KeepDays > 0 { - opts = append(opts, WithKeepDays(c.KeepDays)) + w, err := newFileWriter(c) + if err != nil { + return err } - accessFile := path.Join(c.Path, accessFilename) - errorFile := path.Join(c.Path, errorFilename) - severeFile := path.Join(c.Path, severeFilename) - slowFile := path.Join(c.Path, slowFilename) - statFile := path.Join(c.Path, statFilename) - - once.Do(func() { - atomic.StoreUint32(&initialized, 1) - handleOptions(opts) - setupLogLevel(c) - - if infoLog, err = createOutput(accessFile); err != nil { - return - } - - if errorLog, err = createOutput(errorFile); err != nil { - return - } - - if severeLog, err = createOutput(severeFile); err != nil { - return - } - - if slowLog, err = createOutput(slowFile); err != nil { - return - } - - if statLog, err = createOutput(statFile); err != nil { - return - } - - stackLog = newLessWriter(errorLog, options.logStackCooldownMills) - }) - - return err + SetWriter(w) + return nil } func setupWithVolume(c LogConf) error { @@ -556,7 +363,7 @@ func setupWithVolume(c LogConf) error { func severeSync(msg string) { if shallLog(SevereLevel) { - outputText(severeLog, levelSevere, fmt.Sprintf("%s\n%s", msg, string(debug.Stack()))) + getWriter().Severe(fmt.Sprintf("%s\n%s", msg, string(debug.Stack()))) } } @@ -570,99 +377,30 @@ func shallLogStat() bool { func slowAnySync(v interface{}) { if shallLog(ErrorLevel) { - outputAny(slowLog, levelSlow, v) + getWriter().Slow(v) + } +} + +func slowFieldsSync(content string, fields ...LogField) { + if shallLog(ErrorLevel) { + getWriter().Slow(content, fields...) } } func slowTextSync(msg string) { if shallLog(ErrorLevel) { - outputText(slowLog, levelSlow, msg) + getWriter().Slow(msg) } } func stackSync(msg string) { if shallLog(ErrorLevel) { - outputText(stackLog, levelError, fmt.Sprintf("%s\n%s", msg, string(debug.Stack()))) + getWriter().Stack(fmt.Sprintf("%s\n%s", msg, string(debug.Stack()))) } } func statSync(msg string) { if shallLogStat() && shallLog(InfoLevel) { - outputText(statLog, levelStat, msg) + getWriter().Stat(msg) } } - -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 -} - -func newLogWriter(logger *log.Logger) logWriter { - return logWriter{ - logger: logger, - } -} - -func (lw logWriter) Close() error { - return nil -} - -func (lw logWriter) Write(data []byte) (int, error) { - lw.logger.Print(string(data)) - return len(data), nil -} diff --git a/core/logx/logs_test.go b/core/logx/logs_test.go index 7ab86c52..36cfef2d 100644 --- a/core/logx/logs_test.go +++ b/core/logx/logs_test.go @@ -4,7 +4,6 @@ import ( "encoding/json" "errors" "fmt" - "io" "io/ioutil" "log" "os" @@ -19,8 +18,9 @@ import ( ) var ( - s = []byte("Sending #11 notification (id: 1451875113812010473) in #1 connection") - pool = make(chan []byte, 1) + s = []byte("Sending #11 notification (id: 1451875113812010473) in #1 connection") + pool = make(chan []byte, 1) + _ Writer = (*mockWriter)(nil) ) type mockWriter struct { @@ -28,10 +28,46 @@ type mockWriter struct { builder strings.Builder } -func (mw *mockWriter) Write(data []byte) (int, error) { +func (mw *mockWriter) Alert(v interface{}) { mw.lock.Lock() defer mw.lock.Unlock() - return mw.builder.Write(data) + output(&mw.builder, levelAlert, v) +} + +func (mw *mockWriter) Error(v interface{}, fields ...LogField) { + mw.lock.Lock() + defer mw.lock.Unlock() + output(&mw.builder, levelError, v, fields...) +} + +func (mw *mockWriter) Info(v interface{}, fields ...LogField) { + mw.lock.Lock() + defer mw.lock.Unlock() + output(&mw.builder, levelInfo, v, fields...) +} + +func (mw *mockWriter) Severe(v interface{}) { + mw.lock.Lock() + defer mw.lock.Unlock() + output(&mw.builder, levelSevere, v) +} + +func (mw *mockWriter) Slow(v interface{}, fields ...LogField) { + mw.lock.Lock() + defer mw.lock.Unlock() + output(&mw.builder, levelSlow, v, fields...) +} + +func (mw *mockWriter) Stack(v interface{}) { + mw.lock.Lock() + defer mw.lock.Unlock() + output(&mw.builder, levelError, v) +} + +func (mw *mockWriter) Stat(v interface{}, fields ...LogField) { + mw.lock.Lock() + defer mw.lock.Unlock() + output(&mw.builder, levelStat, v, fields...) } func (mw *mockWriter) Close() error { @@ -57,94 +93,130 @@ func (mw *mockWriter) String() string { } func TestFileLineFileMode(t *testing.T) { - writer := new(mockWriter) - errorLog = writer - atomic.StoreUint32(&initialized, 1) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + file, line := getFileLine() Error("anything") - assert.True(t, writer.Contains(fmt.Sprintf("%s:%d", file, line+1))) + assert.True(t, w.Contains(fmt.Sprintf("%s:%d", file, line+1))) - writer.Reset() file, line = getFileLine() Errorf("anything %s", "format") - assert.True(t, writer.Contains(fmt.Sprintf("%s:%d", file, line+1))) + assert.True(t, w.Contains(fmt.Sprintf("%s:%d", file, line+1))) } func TestFileLineConsoleMode(t *testing.T) { - writer := new(mockWriter) - writeConsole = true - errorLog = newLogWriter(log.New(writer, "[ERROR] ", flags)) - atomic.StoreUint32(&initialized, 1) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + file, line := getFileLine() Error("anything") - assert.True(t, writer.Contains(fmt.Sprintf("%s:%d", file, line+1))) + assert.True(t, w.Contains(fmt.Sprintf("%s:%d", file, line+1))) - writer.Reset() + w.Reset() file, line = getFileLine() Errorf("anything %s", "format") - assert.True(t, writer.Contains(fmt.Sprintf("%s:%d", file, line+1))) + assert.True(t, w.Contains(fmt.Sprintf("%s:%d", file, line+1))) } func TestStructedLogAlert(t *testing.T) { - doTestStructedLog(t, levelAlert, func(writer io.WriteCloser) { - errorLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelAlert, w, func(v ...interface{}) { Alert(fmt.Sprint(v...)) }) } func TestStructedLogError(t *testing.T) { - doTestStructedLog(t, levelError, func(writer io.WriteCloser) { - errorLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelError, w, func(v ...interface{}) { Error(v...) }) } func TestStructedLogErrorf(t *testing.T) { - doTestStructedLog(t, levelError, func(writer io.WriteCloser) { - errorLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelError, w, func(v ...interface{}) { Errorf("%s", fmt.Sprint(v...)) }) } func TestStructedLogErrorv(t *testing.T) { - doTestStructedLog(t, levelError, func(writer io.WriteCloser) { - errorLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelError, w, func(v ...interface{}) { Errorv(fmt.Sprint(v...)) }) } +func TestStructedLogErrorw(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelError, w, func(v ...interface{}) { + Errorw(fmt.Sprint(v...), Field("foo", "bar")) + }) +} + func TestStructedLogInfo(t *testing.T) { - doTestStructedLog(t, levelInfo, func(writer io.WriteCloser) { - infoLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelInfo, w, func(v ...interface{}) { Info(v...) }) } func TestStructedLogInfof(t *testing.T) { - doTestStructedLog(t, levelInfo, func(writer io.WriteCloser) { - infoLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelInfo, w, func(v ...interface{}) { Infof("%s", fmt.Sprint(v...)) }) } func TestStructedLogInfov(t *testing.T) { - doTestStructedLog(t, levelInfo, func(writer io.WriteCloser) { - infoLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelInfo, w, func(v ...interface{}) { Infov(fmt.Sprint(v...)) }) } +func TestStructedLogInfow(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelInfo, w, func(v ...interface{}) { + Infow(fmt.Sprint(v...), Field("foo", "bar")) + }) +} + func TestStructedLogInfoConsoleAny(t *testing.T) { - doTestStructedLogConsole(t, func(writer io.WriteCloser) { - infoLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogConsole(t, w, func(v ...interface{}) { old := atomic.LoadUint32(&encoding) atomic.StoreUint32(&encoding, plainEncodingType) defer func() { @@ -156,9 +228,11 @@ func TestStructedLogInfoConsoleAny(t *testing.T) { } func TestStructedLogInfoConsoleAnyString(t *testing.T) { - doTestStructedLogConsole(t, func(writer io.WriteCloser) { - infoLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogConsole(t, w, func(v ...interface{}) { old := atomic.LoadUint32(&encoding) atomic.StoreUint32(&encoding, plainEncodingType) defer func() { @@ -170,9 +244,11 @@ func TestStructedLogInfoConsoleAnyString(t *testing.T) { } func TestStructedLogInfoConsoleAnyError(t *testing.T) { - doTestStructedLogConsole(t, func(writer io.WriteCloser) { - infoLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogConsole(t, w, func(v ...interface{}) { old := atomic.LoadUint32(&encoding) atomic.StoreUint32(&encoding, plainEncodingType) defer func() { @@ -184,9 +260,11 @@ func TestStructedLogInfoConsoleAnyError(t *testing.T) { } func TestStructedLogInfoConsoleAnyStringer(t *testing.T) { - doTestStructedLogConsole(t, func(writer io.WriteCloser) { - infoLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogConsole(t, w, func(v ...interface{}) { old := atomic.LoadUint32(&encoding) atomic.StoreUint32(&encoding, plainEncodingType) defer func() { @@ -200,9 +278,11 @@ func TestStructedLogInfoConsoleAnyStringer(t *testing.T) { } func TestStructedLogInfoConsoleText(t *testing.T) { - doTestStructedLogConsole(t, func(writer io.WriteCloser) { - infoLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLogConsole(t, w, func(v ...interface{}) { old := atomic.LoadUint32(&encoding) atomic.StoreUint32(&encoding, plainEncodingType) defer func() { @@ -214,69 +294,94 @@ func TestStructedLogInfoConsoleText(t *testing.T) { } func TestStructedLogSlow(t *testing.T) { - doTestStructedLog(t, levelSlow, func(writer io.WriteCloser) { - slowLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelSlow, w, func(v ...interface{}) { Slow(v...) }) } func TestStructedLogSlowf(t *testing.T) { - doTestStructedLog(t, levelSlow, func(writer io.WriteCloser) { - slowLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelSlow, w, func(v ...interface{}) { Slowf(fmt.Sprint(v...)) }) } func TestStructedLogSlowv(t *testing.T) { - doTestStructedLog(t, levelSlow, func(writer io.WriteCloser) { - slowLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelSlow, w, func(v ...interface{}) { Slowv(fmt.Sprint(v...)) }) } +func TestStructedLogSloww(t *testing.T) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelSlow, w, func(v ...interface{}) { + Sloww(fmt.Sprint(v...), Field("foo", time.Second)) + }) +} + func TestStructedLogStat(t *testing.T) { - doTestStructedLog(t, levelStat, func(writer io.WriteCloser) { - statLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelStat, w, func(v ...interface{}) { Stat(v...) }) } func TestStructedLogStatf(t *testing.T) { - doTestStructedLog(t, levelStat, func(writer io.WriteCloser) { - statLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelStat, w, func(v ...interface{}) { Statf(fmt.Sprint(v...)) }) } func TestStructedLogSevere(t *testing.T) { - doTestStructedLog(t, levelSevere, func(writer io.WriteCloser) { - severeLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelSevere, w, func(v ...interface{}) { Severe(v...) }) } func TestStructedLogSeveref(t *testing.T) { - doTestStructedLog(t, levelSevere, func(writer io.WriteCloser) { - severeLog = writer - }, func(v ...interface{}) { + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + doTestStructedLog(t, levelSevere, w, func(v ...interface{}) { Severef(fmt.Sprint(v...)) }) } func TestStructedLogWithDuration(t *testing.T) { const message = "hello there" - writer := new(mockWriter) - infoLog = writer - atomic.StoreUint32(&initialized, 1) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Info(message) var entry logEntry - if err := json.Unmarshal([]byte(writer.builder.String()), &entry); err != nil { + if err := json.Unmarshal([]byte(w.builder.String()), &entry); err != nil { t.Error(err) } assert.Equal(t, levelInfo, entry.Level) @@ -287,11 +392,12 @@ func TestStructedLogWithDuration(t *testing.T) { func TestSetLevel(t *testing.T) { SetLevel(ErrorLevel) const message = "hello there" - writer := new(mockWriter) - infoLog = writer - atomic.StoreUint32(&initialized, 1) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + Info(message) - assert.Equal(t, 0, writer.builder.Len()) + assert.Equal(t, 0, w.builder.Len()) } func TestSetLevelTwiceWithMode(t *testing.T) { @@ -300,29 +406,35 @@ func TestSetLevelTwiceWithMode(t *testing.T) { "console", "volumn", } + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + for _, mode := range testModes { - testSetLevelTwiceWithMode(t, mode) + testSetLevelTwiceWithMode(t, mode, w) } } func TestSetLevelWithDuration(t *testing.T) { SetLevel(ErrorLevel) const message = "hello there" - writer := new(mockWriter) - infoLog = writer - atomic.StoreUint32(&initialized, 1) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + WithDuration(time.Second).Info(message) - assert.Equal(t, 0, writer.builder.Len()) + assert.Equal(t, 0, w.builder.Len()) } func TestErrorfWithWrappedError(t *testing.T) { SetLevel(ErrorLevel) const message = "there" - writer := new(mockWriter) - errorLog = writer - atomic.StoreUint32(&initialized, 1) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + Errorf("hello %w", errors.New(message)) - assert.True(t, strings.Contains(writer.builder.String(), "hello there")) + assert.True(t, strings.Contains(w.builder.String(), "hello there")) } func TestMustNil(t *testing.T) { @@ -330,6 +442,11 @@ func TestMustNil(t *testing.T) { } func TestSetup(t *testing.T) { + defer func() { + SetLevel(InfoLevel) + atomic.StoreUint32(&encoding, jsonEncodingType) + }() + MustSetup(LogConf{ ServiceName: "any", Mode: "console", @@ -344,6 +461,17 @@ func TestSetup(t *testing.T) { Mode: "volume", Path: os.TempDir(), }) + MustSetup(LogConf{ + ServiceName: "any", + Mode: "console", + TimeFormat: timeFormat, + }) + MustSetup(LogConf{ + ServiceName: "any", + Mode: "console", + Encoding: plainEncoding, + }) + assert.NotNil(t, setupWithVolume(LogConf{})) assert.NotNil(t, setupWithFiles(LogConf{})) assert.Nil(t, setupWithFiles(LogConf{ @@ -364,6 +492,8 @@ func TestSetup(t *testing.T) { _, err := createOutput("") assert.NotNil(t, err) Disable() + SetLevel(InfoLevel) + atomic.StoreUint32(&encoding, jsonEncodingType) } func TestDisable(t *testing.T) { @@ -373,7 +503,6 @@ func TestDisable(t *testing.T) { WithKeepDays(1)(&opt) WithGzip()(&opt) assert.Nil(t, Close()) - writeConsole = false assert.Nil(t, Close()) } @@ -381,11 +510,20 @@ func TestDisableStat(t *testing.T) { DisableStat() const message = "hello there" - writer := new(mockWriter) - statLog = writer - atomic.StoreUint32(&initialized, 1) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) Stat(message) - assert.Equal(t, 0, writer.builder.Len()) + assert.Equal(t, 0, w.builder.Len()) +} + +func TestSetWriter(t *testing.T) { + Reset() + SetWriter(nopWriter{}) + assert.NotNil(t, writer.Load()) + assert.True(t, writer.Load() == nopWriter{}) + SetWriter(new(mockWriter)) + assert.True(t, writer.Load() == nopWriter{}) } func TestWithGzip(t *testing.T) { @@ -487,15 +625,12 @@ func put(b []byte) { } } -func doTestStructedLog(t *testing.T, level string, setup func(writer io.WriteCloser), - write func(...interface{})) { +func doTestStructedLog(t *testing.T, level string, w *mockWriter, write func(...interface{})) { const message = "hello there" - writer := new(mockWriter) - setup(writer) - atomic.StoreUint32(&initialized, 1) write(message) + fmt.Println(w.String()) var entry logEntry - if err := json.Unmarshal([]byte(writer.builder.String()), &entry); err != nil { + if err := json.Unmarshal([]byte(w.String()), &entry); err != nil { t.Error(err) } assert.Equal(t, level, entry.Level) @@ -504,18 +639,14 @@ 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{})) { +func doTestStructedLogConsole(t *testing.T, w *mockWriter, 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)) + assert.True(t, strings.Contains(w.String(), message)) } -func testSetLevelTwiceWithMode(t *testing.T, mode string) { +func testSetLevelTwiceWithMode(t *testing.T, mode string, w *mockWriter) { + writer.Store(nil) SetUp(LogConf{ Mode: mode, Level: "error", @@ -527,17 +658,14 @@ func testSetLevelTwiceWithMode(t *testing.T, mode string) { Path: "/dev/null", }) const message = "hello there" - writer := new(mockWriter) - infoLog = writer - atomic.StoreUint32(&initialized, 1) Info(message) - assert.Equal(t, 0, writer.builder.Len()) + assert.Equal(t, 0, w.builder.Len()) Infof(message) - assert.Equal(t, 0, writer.builder.Len()) + assert.Equal(t, 0, w.builder.Len()) ErrorStack(message) - assert.Equal(t, 0, writer.builder.Len()) + assert.Equal(t, 0, w.builder.Len()) ErrorStackf(message) - assert.Equal(t, 0, writer.builder.Len()) + assert.Equal(t, 0, w.builder.Len()) } type ValStringer struct { diff --git a/core/logx/logwriter.go b/core/logx/logwriter.go new file mode 100644 index 00000000..2f9cafd8 --- /dev/null +++ b/core/logx/logwriter.go @@ -0,0 +1,22 @@ +package logx + +import "log" + +type logWriter struct { + logger *log.Logger +} + +func newLogWriter(logger *log.Logger) logWriter { + return logWriter{ + logger: logger, + } +} + +func (lw logWriter) Close() error { + return nil +} + +func (lw logWriter) Write(data []byte) (int, error) { + lw.logger.Print(string(data)) + return len(data), nil +} diff --git a/core/logx/rotatelogger_test.go b/core/logx/rotatelogger_test.go index b09d148f..5bb1d58f 100644 --- a/core/logx/rotatelogger_test.go +++ b/core/logx/rotatelogger_test.go @@ -120,7 +120,14 @@ func TestRotateLoggerWrite(t *testing.T) { os.Remove(filepath.Base(logger.getBackupFilename()) + ".gz") }() } + // the following write calls cannot be changed to Write, because of DATA RACE. logger.write([]byte(`foo`)) rule.rotatedTime = time.Now().Add(-time.Hour * 24).Format(dateFormat) logger.write([]byte(`bar`)) + logger.Close() + logger.write([]byte(`baz`)) +} + +func TestLogWriterClose(t *testing.T) { + assert.Nil(t, newLogWriter(nil).Close()) } diff --git a/core/logx/syslog_test.go b/core/logx/syslog_test.go index d2a4fd29..780f346d 100644 --- a/core/logx/syslog_test.go +++ b/core/logx/syslog_test.go @@ -29,16 +29,16 @@ func TestRedirector(t *testing.T) { } func captureOutput(f func()) string { - writer := new(mockWriter) - infoLog = writer - atomic.StoreUint32(&initialized, 1) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) prevLevel := atomic.LoadUint32(&logLevel) SetLevel(InfoLevel) f() SetLevel(prevLevel) - return writer.builder.String() + return w.builder.String() } func getContent(jsonStr string) string { diff --git a/core/logx/tracelogger.go b/core/logx/tracelogger.go index 647f3dff..896bf21d 100644 --- a/core/logx/tracelogger.go +++ b/core/logx/tracelogger.go @@ -3,73 +3,79 @@ package logx import ( "context" "fmt" - "io" - "sync/atomic" "time" "github.com/zeromicro/go-zero/core/timex" "go.opentelemetry.io/otel/trace" ) +// WithContext sets ctx to log, for keeping tracing information. +func WithContext(ctx context.Context) Logger { + return &traceLogger{ + ctx: ctx, + } +} + type traceLogger struct { logEntry - Trace string `json:"trace,omitempty"` - Span string `json:"span,omitempty"` - ctx context.Context + ctx context.Context } func (l *traceLogger) Error(v ...interface{}) { - if shallLog(ErrorLevel) { - l.write(errorLog, levelError, formatWithCaller(fmt.Sprint(v...), durationCallerDepth)) - } + l.err(fmt.Sprint(v...)) } func (l *traceLogger) Errorf(format string, v ...interface{}) { - if shallLog(ErrorLevel) { - l.write(errorLog, levelError, formatWithCaller(fmt.Sprintf(format, v...), durationCallerDepth)) - } + l.err(fmt.Sprintf(format, v...)) } func (l *traceLogger) Errorv(v interface{}) { - if shallLog(ErrorLevel) { - l.write(errorLog, levelError, v) - } + l.err(fmt.Sprint(v)) +} + +func (l *traceLogger) Errorw(msg string, fields ...LogField) { + l.err(msg, fields...) } func (l *traceLogger) Info(v ...interface{}) { - if shallLog(InfoLevel) { - l.write(infoLog, levelInfo, fmt.Sprint(v...)) - } + l.info(fmt.Sprint(v...)) } func (l *traceLogger) Infof(format string, v ...interface{}) { - if shallLog(InfoLevel) { - l.write(infoLog, levelInfo, fmt.Sprintf(format, v...)) - } + l.info(fmt.Sprintf(format, v...)) } func (l *traceLogger) Infov(v interface{}) { - if shallLog(InfoLevel) { - l.write(infoLog, levelInfo, v) - } + l.info(v) +} + +func (l *traceLogger) Infow(msg string, fields ...LogField) { + l.info(msg, fields...) } func (l *traceLogger) Slow(v ...interface{}) { - if shallLog(ErrorLevel) { - l.write(slowLog, levelSlow, fmt.Sprint(v...)) - } + l.slow(fmt.Sprint(v...)) } func (l *traceLogger) Slowf(format string, v ...interface{}) { - if shallLog(ErrorLevel) { - l.write(slowLog, levelSlow, fmt.Sprintf(format, v...)) - } + l.slow(fmt.Sprintf(format, v...)) } func (l *traceLogger) Slowv(v interface{}) { - if shallLog(ErrorLevel) { - l.write(slowLog, levelSlow, v) + l.slow(v) +} + +func (l *traceLogger) Sloww(msg string, fields ...LogField) { + l.slow(msg, fields...) +} + +func (l *traceLogger) WithContext(ctx context.Context) Logger { + if ctx == nil { + return l } + + l.ctx = ctx + return l } func (l *traceLogger) WithDuration(duration time.Duration) Logger { @@ -77,31 +83,37 @@ func (l *traceLogger) WithDuration(duration time.Duration) Logger { return l } -func (l *traceLogger) write(writer io.Writer, level string, val interface{}) { +func (l *traceLogger) buildFields(fields ...LogField) []LogField { + if len(l.Duration) > 0 { + fields = append(fields, Field(durationKey, l.Duration)) + } traceID := traceIdFromContext(l.ctx) + if len(traceID) > 0 { + fields = append(fields, Field(traceKey, traceID)) + } spanID := spanIdFromContext(l.ctx) + if len(spanID) > 0 { + fields = append(fields, Field(spanKey, spanID)) + } - switch atomic.LoadUint32(&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, - }) + return fields +} + +func (l *traceLogger) err(v interface{}, fields ...LogField) { + if shallLog(ErrorLevel) { + getWriter().Error(v, l.buildFields(fields...)...) } } -// WithContext sets ctx to log, for keeping tracing information. -func WithContext(ctx context.Context) Logger { - return &traceLogger{ - ctx: ctx, +func (l *traceLogger) info(v interface{}, fields ...LogField) { + if shallLog(InfoLevel) { + getWriter().Info(v, l.buildFields(fields...)...) + } +} + +func (l *traceLogger) slow(v interface{}, fields ...LogField) { + if shallLog(ErrorLevel) { + getWriter().Slow(v, l.buildFields(fields...)...) } } diff --git a/core/logx/tracelogger_test.go b/core/logx/tracelogger_test.go index 3fa4d2ed..5a141493 100644 --- a/core/logx/tracelogger_test.go +++ b/core/logx/tracelogger_test.go @@ -2,7 +2,8 @@ package logx import ( "context" - "log" + "encoding/json" + "fmt" "strings" "sync/atomic" "testing" @@ -13,73 +14,79 @@ import ( sdktrace "go.opentelemetry.io/otel/sdk/trace" ) -const ( - traceKey = "trace" - spanKey = "span" -) - func TestTraceLog(t *testing.T) { - var buf mockWriter - atomic.StoreUint32(&initialized, 1) + SetLevel(InfoLevel) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + 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") - WithContext(ctx).(*traceLogger).write(&buf, levelInfo, testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) + WithContext(ctx).Info(testlog) + validate(t, w.String(), true, true) } func TestTraceError(t *testing.T) { - var buf mockWriter - atomic.StoreUint32(&initialized, 1) - errorLog = newLogWriter(log.New(&buf, "", flags)) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) otp := otel.GetTracerProvider() tp := sdktrace.NewTracerProvider(sdktrace.WithSampler(sdktrace.AlwaysSample())) otel.SetTracerProvider(tp) defer otel.SetTracerProvider(otp) + l := WithContext(context.Background()) ctx, _ := tp.Tracer("foo").Start(context.Background(), "bar") - l := WithContext(ctx).(*traceLogger) + var nilCtx context.Context + l = l.WithContext(nilCtx) + l = l.WithContext(ctx) SetLevel(InfoLevel) l.WithDuration(time.Second).Error(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) - buf.Reset() + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Errorf(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) - buf.Reset() + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Errorv(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) + fmt.Println(w.String()) + validate(t, w.String(), true, true) + w.Reset() + l.WithDuration(time.Second).Errorw(testlog, Field("foo", "bar")) + validate(t, w.String(), true, true) + assert.True(t, strings.Contains(w.String(), "foo"), w.String()) + assert.True(t, strings.Contains(w.String(), "bar"), w.String()) } func TestTraceInfo(t *testing.T) { - var buf mockWriter - atomic.StoreUint32(&initialized, 1) - infoLog = newLogWriter(log.New(&buf, "", flags)) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + 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) + l := WithContext(ctx) SetLevel(InfoLevel) l.WithDuration(time.Second).Info(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) - buf.Reset() + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Infof(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) - buf.Reset() + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Infov(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) + validate(t, w.String(), true, true) + w.Reset() + l.WithDuration(time.Second).Infow(testlog, Field("foo", "bar")) + validate(t, w.String(), true, true) + assert.True(t, strings.Contains(w.String(), "foo"), w.String()) + assert.True(t, strings.Contains(w.String(), "bar"), w.String()) } func TestTraceInfoConsole(t *testing.T) { @@ -89,66 +96,80 @@ func TestTraceInfoConsole(t *testing.T) { atomic.StoreUint32(&encoding, old) }() - var buf mockWriter - atomic.StoreUint32(&initialized, 1) - infoLog = newLogWriter(log.New(&buf, "", flags)) + w := new(mockWriter) + o := writer.Swap(w) + defer writer.Store(o) + 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) + l := WithContext(ctx) 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() + validate(t, w.String(), true, true) + w.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() + validate(t, w.String(), true, true) + w.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))) + validate(t, w.String(), true, true) } func TestTraceSlow(t *testing.T) { - var buf mockWriter - atomic.StoreUint32(&initialized, 1) - slowLog = newLogWriter(log.New(&buf, "", flags)) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + 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) + l := WithContext(ctx) SetLevel(InfoLevel) l.WithDuration(time.Second).Slow(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) - buf.Reset() + assert.True(t, strings.Contains(w.String(), traceKey)) + assert.True(t, strings.Contains(w.String(), spanKey)) + w.Reset() l.WithDuration(time.Second).Slowf(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) - buf.Reset() + fmt.Println("buf:", w.String()) + validate(t, w.String(), true, true) + w.Reset() l.WithDuration(time.Second).Slowv(testlog) - assert.True(t, strings.Contains(buf.String(), traceKey)) - assert.True(t, strings.Contains(buf.String(), spanKey)) + validate(t, w.String(), true, true) + w.Reset() + l.WithDuration(time.Second).Sloww(testlog, Field("foo", "bar")) + validate(t, w.String(), true, true) + assert.True(t, strings.Contains(w.String(), "foo"), w.String()) + assert.True(t, strings.Contains(w.String(), "bar"), w.String()) } func TestTraceWithoutContext(t *testing.T) { - var buf mockWriter - atomic.StoreUint32(&initialized, 1) - infoLog = newLogWriter(log.New(&buf, "", flags)) - l := WithContext(context.Background()).(*traceLogger) + w := new(mockWriter) + old := writer.Swap(w) + defer writer.Store(old) + + l := WithContext(context.Background()) SetLevel(InfoLevel) l.WithDuration(time.Second).Info(testlog) - assert.False(t, strings.Contains(buf.String(), traceKey)) - assert.False(t, strings.Contains(buf.String(), spanKey)) - buf.Reset() + validate(t, w.String(), false, false) + w.Reset() l.WithDuration(time.Second).Infof(testlog) - assert.False(t, strings.Contains(buf.String(), traceKey)) - assert.False(t, strings.Contains(buf.String(), spanKey)) + validate(t, w.String(), false, false) +} + +func validate(t *testing.T, body string, expectedTrace, expectedSpan bool) { + var val mockValue + assert.Nil(t, json.Unmarshal([]byte(body), &val)) + assert.Equal(t, expectedTrace, len(val.Trace) > 0) + assert.Equal(t, expectedSpan, len(val.Span) > 0) +} + +type mockValue struct { + Trace string `json:"trace"` + Span string `json:"span"` } diff --git a/core/logx/util.go b/core/logx/util.go new file mode 100644 index 00000000..0adc5a38 --- /dev/null +++ b/core/logx/util.go @@ -0,0 +1,36 @@ +package logx + +import ( + "fmt" + "runtime" + "strings" + + "github.com/zeromicro/go-zero/core/timex" +) + +func getCaller(callDepth int) string { + _, file, line, ok := runtime.Caller(callDepth) + if !ok { + return "" + } + + return prettyCaller(file, line) +} + +func getTimestamp() string { + return timex.Time().Format(timeFormat) +} + +func prettyCaller(file string, line int) string { + idx := strings.LastIndexByte(file, '/') + if idx < 0 { + return fmt.Sprintf("%s:%d", file, line) + } + + idx = strings.LastIndexByte(file[:idx], '/') + if idx < 0 { + return fmt.Sprintf("%s:%d", file, line) + } + + return fmt.Sprintf("%s:%d", file[idx+1:], line) +} diff --git a/core/logx/util_test.go b/core/logx/util_test.go new file mode 100644 index 00000000..eef3a40d --- /dev/null +++ b/core/logx/util_test.go @@ -0,0 +1,72 @@ +package logx + +import ( + "path/filepath" + "runtime" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func TestGetCaller(t *testing.T) { + _, file, _, _ := runtime.Caller(0) + assert.Contains(t, getCaller(1), filepath.Base(file)) + assert.True(t, len(getCaller(1<<10)) == 0) +} + +func TestGetTimestamp(t *testing.T) { + ts := getTimestamp() + tm, err := time.Parse(timeFormat, ts) + assert.Nil(t, err) + assert.True(t, time.Since(tm) < time.Minute) +} + +func TestPrettyCaller(t *testing.T) { + tests := []struct { + name string + file string + line int + want string + }{ + { + name: "regular", + file: "logx_test.go", + line: 123, + want: "logx_test.go:123", + }, + { + name: "relative", + file: "adhoc/logx_test.go", + line: 123, + want: "adhoc/logx_test.go:123", + }, + { + name: "long path", + file: "github.com/zeromicro/go-zero/core/logx/util_test.go", + line: 12, + want: "logx/util_test.go:12", + }, + { + name: "local path", + file: "/Users/kevin/go-zero/core/logx/util_test.go", + line: 1234, + want: "logx/util_test.go:1234", + }, + } + + for _, test := range tests { + test := test + t.Run(test.name, func(t *testing.T) { + assert.Equal(t, test.want, prettyCaller(test.file, test.line)) + }) + } +} + +func BenchmarkGetCaller(b *testing.B) { + b.ReportAllocs() + + for i := 0; i < b.N; i++ { + getCaller(1) + } +} diff --git a/core/logx/vars.go b/core/logx/vars.go new file mode 100644 index 00000000..4229556c --- /dev/null +++ b/core/logx/vars.go @@ -0,0 +1,60 @@ +package logx + +import "errors" + +const ( + // InfoLevel logs everything + InfoLevel uint32 = iota + // ErrorLevel includes errors, slows, stacks + ErrorLevel + // SevereLevel only log severe messages + SevereLevel +) + +const ( + jsonEncodingType = iota + plainEncodingType + + jsonEncoding = "json" + plainEncoding = "plain" + plainEncodingSep = '\t' +) + +const ( + accessFilename = "access.log" + errorFilename = "error.log" + severeFilename = "severe.log" + slowFilename = "slow.log" + statFilename = "stat.log" + + consoleMode = "console" + volumeMode = "volume" + + levelAlert = "alert" + levelInfo = "info" + levelError = "error" + levelSevere = "severe" + levelFatal = "fatal" + levelSlow = "slow" + levelStat = "stat" + + backupFileDelimiter = "-" + flags = 0x0 +) + +const ( + callerKey = "caller" + contentKey = "content" + durationKey = "duration" + levelKey = "level" + spanKey = "span" + timestampKey = "@timestamp" + traceKey = "trace" +) + +var ( + // ErrLogPathNotSet is an error that indicates the log path is not set. + ErrLogPathNotSet = errors.New("log path must be set") + // ErrLogServiceNameNotSet is an error that indicates that the service name is not set. + ErrLogServiceNameNotSet = errors.New("log service name must be set") +) diff --git a/core/logx/writer.go b/core/logx/writer.go new file mode 100644 index 00000000..75f8b4af --- /dev/null +++ b/core/logx/writer.go @@ -0,0 +1,320 @@ +package logx + +import ( + "encoding/json" + "fmt" + "io" + "log" + "os" + "path" + "strings" + "sync" + "sync/atomic" +) + +type ( + Writer interface { + Alert(v interface{}) + Close() error + Error(v interface{}, fields ...LogField) + Info(v interface{}, fields ...LogField) + Severe(v interface{}) + Slow(v interface{}, fields ...LogField) + Stack(v interface{}) + Stat(v interface{}, fields ...LogField) + } + + atomicWriter struct { + writer Writer + lock sync.RWMutex + } + + concreteWriter struct { + infoLog io.WriteCloser + errorLog io.WriteCloser + severeLog io.WriteCloser + slowLog io.WriteCloser + statLog io.WriteCloser + stackLog io.Writer + } +) + +// NewWriter creates a new Writer with the given io.Writer. +func NewWriter(w io.Writer) Writer { + lw := newLogWriter(log.New(w, "", flags)) + + return &concreteWriter{ + infoLog: lw, + errorLog: lw, + severeLog: lw, + slowLog: lw, + statLog: lw, + stackLog: lw, + } +} + +func (w *atomicWriter) Load() Writer { + w.lock.RLock() + defer w.lock.RUnlock() + return w.writer +} + +func (w *atomicWriter) Store(v Writer) { + w.lock.Lock() + w.writer = v + w.lock.Unlock() +} + +func (w *atomicWriter) Swap(v Writer) Writer { + w.lock.Lock() + old := w.writer + w.writer = v + w.lock.Unlock() + return old +} + +func newConsoleWriter() Writer { + outLog := newLogWriter(log.New(os.Stdout, "", flags)) + errLog := newLogWriter(log.New(os.Stderr, "", flags)) + return &concreteWriter{ + infoLog: outLog, + errorLog: errLog, + severeLog: errLog, + slowLog: errLog, + stackLog: newLessWriter(errLog, options.logStackCooldownMills), + statLog: outLog, + } +} + +func newFileWriter(c LogConf) (Writer, error) { + var err error + var opts []LogOption + var infoLog io.WriteCloser + var errorLog io.WriteCloser + var severeLog io.WriteCloser + var slowLog io.WriteCloser + var statLog io.WriteCloser + var stackLog io.Writer + + if len(c.Path) == 0 { + return nil, ErrLogPathNotSet + } + + opts = append(opts, WithCooldownMillis(c.StackCooldownMillis)) + if c.Compress { + opts = append(opts, WithGzip()) + } + if c.KeepDays > 0 { + opts = append(opts, WithKeepDays(c.KeepDays)) + } + + accessFile := path.Join(c.Path, accessFilename) + errorFile := path.Join(c.Path, errorFilename) + severeFile := path.Join(c.Path, severeFilename) + slowFile := path.Join(c.Path, slowFilename) + statFile := path.Join(c.Path, statFilename) + + handleOptions(opts) + setupLogLevel(c) + + if infoLog, err = createOutput(accessFile); err != nil { + return nil, err + } + + if errorLog, err = createOutput(errorFile); err != nil { + return nil, err + } + + if severeLog, err = createOutput(severeFile); err != nil { + return nil, err + } + + if slowLog, err = createOutput(slowFile); err != nil { + return nil, err + } + + if statLog, err = createOutput(statFile); err != nil { + return nil, err + } + + stackLog = newLessWriter(errorLog, options.logStackCooldownMills) + + return &concreteWriter{ + infoLog: infoLog, + errorLog: errorLog, + severeLog: severeLog, + slowLog: slowLog, + statLog: statLog, + stackLog: stackLog, + }, nil +} + +func (w *concreteWriter) Alert(v interface{}) { + output(w.errorLog, levelAlert, v) +} + +func (w *concreteWriter) Close() error { + if err := w.infoLog.Close(); err != nil { + return err + } + + if err := w.errorLog.Close(); err != nil { + return err + } + + if err := w.severeLog.Close(); err != nil { + return err + } + + if err := w.slowLog.Close(); err != nil { + return err + } + + return w.statLog.Close() +} + +func (w *concreteWriter) Error(v interface{}, fields ...LogField) { + output(w.errorLog, levelError, v, fields...) +} + +func (w *concreteWriter) Info(v interface{}, fields ...LogField) { + output(w.infoLog, levelInfo, v, fields...) +} + +func (w *concreteWriter) Severe(v interface{}) { + output(w.severeLog, levelFatal, v) +} + +func (w *concreteWriter) Slow(v interface{}, fields ...LogField) { + output(w.slowLog, levelSlow, v, fields...) +} + +func (w *concreteWriter) Stack(v interface{}) { + output(w.stackLog, levelError, v) +} + +func (w *concreteWriter) Stat(v interface{}, fields ...LogField) { + output(w.statLog, levelStat, v, fields...) +} + +type nopWriter struct{} + +func (n nopWriter) Alert(_ interface{}) { +} + +func (n nopWriter) Close() error { + return nil +} + +func (n nopWriter) Error(_ interface{}, _ ...LogField) { +} + +func (n nopWriter) Info(_ interface{}, _ ...LogField) { +} + +func (n nopWriter) Severe(_ interface{}) { +} + +func (n nopWriter) Slow(_ interface{}, _ ...LogField) { +} + +func (n nopWriter) Stack(_ interface{}) { +} + +func (n nopWriter) Stat(_ interface{}, _ ...LogField) { +} + +func buildFields(fields ...LogField) []string { + var items []string + + for _, field := range fields { + items = append(items, fmt.Sprintf("%s=%v", field.Key, field.Value)) + } + + return items +} + +func output(writer io.Writer, level string, val interface{}, fields ...LogField) { + fields = append(fields, Field(callerKey, getCaller(callerDepth))) + + switch atomic.LoadUint32(&encoding) { + case plainEncodingType: + writePlainAny(writer, level, val, buildFields(fields...)...) + default: + entry := make(logEntryWithFields) + for _, field := range fields { + entry[field.Key] = field.Value + } + entry[timestampKey] = getTimestamp() + entry[levelKey] = level + entry[contentKey] = val + writeJson(writer, entry) + } +} + +func writeJson(writer io.Writer, info interface{}) { + if content, err := json.Marshal(info); err != nil { + log.Println(err.Error()) + } else if writer == nil { + log.Println(string(content)) + } else { + writer.Write(append(content, '\n')) + } +} + +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 strings.Builder + buf.WriteString(getTimestamp()) + buf.WriteByte(plainEncodingSep) + buf.WriteString(level) + buf.WriteByte(plainEncodingSep) + if err := json.NewEncoder(&buf).Encode(val); err != nil { + log.Println(err.Error()) + return + } + + for _, item := range fields { + buf.WriteByte(plainEncodingSep) + buf.WriteString(item) + } + buf.WriteByte('\n') + if writer == nil { + log.Println(buf.String()) + return + } + + if _, err := fmt.Fprint(writer, buf.String()); err != nil { + log.Println(err.Error()) + } + } +} + +func writePlainText(writer io.Writer, level, msg string, fields ...string) { + var buf strings.Builder + buf.WriteString(getTimestamp()) + buf.WriteByte(plainEncodingSep) + buf.WriteString(level) + buf.WriteByte(plainEncodingSep) + buf.WriteString(msg) + for _, item := range fields { + buf.WriteByte(plainEncodingSep) + buf.WriteString(item) + } + buf.WriteByte('\n') + if writer == nil { + log.Println(buf.String()) + return + } + + if _, err := fmt.Fprint(writer, buf.String()); err != nil { + log.Println(err.Error()) + } +} diff --git a/core/logx/writer_test.go b/core/logx/writer_test.go new file mode 100644 index 00000000..6d96808c --- /dev/null +++ b/core/logx/writer_test.go @@ -0,0 +1,170 @@ +package logx + +import ( + "bytes" + "encoding/json" + "errors" + "log" + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestNewWriter(t *testing.T) { + const literal = "foo bar" + var buf bytes.Buffer + w := NewWriter(&buf) + w.Info(literal) + assert.Contains(t, buf.String(), literal) +} + +func TestConsoleWriter(t *testing.T) { + var buf bytes.Buffer + w := newConsoleWriter() + lw := newLogWriter(log.New(&buf, "", 0)) + w.(*concreteWriter).errorLog = lw + w.Alert("foo bar 1") + var val mockedEntry + if err := json.Unmarshal(buf.Bytes(), &val); err != nil { + t.Fatal(err) + } + assert.Equal(t, levelAlert, val.Level) + assert.Equal(t, "foo bar 1", val.Content) + + buf.Reset() + w.(*concreteWriter).errorLog = lw + w.Error("foo bar 2") + if err := json.Unmarshal(buf.Bytes(), &val); err != nil { + t.Fatal(err) + } + assert.Equal(t, levelError, val.Level) + assert.Equal(t, "foo bar 2", val.Content) + + buf.Reset() + w.(*concreteWriter).infoLog = lw + w.Info("foo bar 3") + if err := json.Unmarshal(buf.Bytes(), &val); err != nil { + t.Fatal(err) + } + assert.Equal(t, levelInfo, val.Level) + assert.Equal(t, "foo bar 3", val.Content) + + buf.Reset() + w.(*concreteWriter).severeLog = lw + w.Severe("foo bar 4") + if err := json.Unmarshal(buf.Bytes(), &val); err != nil { + t.Fatal(err) + } + assert.Equal(t, levelFatal, val.Level) + assert.Equal(t, "foo bar 4", val.Content) + + buf.Reset() + w.(*concreteWriter).slowLog = lw + w.Slow("foo bar 5") + if err := json.Unmarshal(buf.Bytes(), &val); err != nil { + t.Fatal(err) + } + assert.Equal(t, levelSlow, val.Level) + assert.Equal(t, "foo bar 5", val.Content) + + buf.Reset() + w.(*concreteWriter).statLog = lw + w.Stat("foo bar 6") + if err := json.Unmarshal(buf.Bytes(), &val); err != nil { + t.Fatal(err) + } + assert.Equal(t, levelStat, val.Level) + assert.Equal(t, "foo bar 6", val.Content) + + w.(*concreteWriter).infoLog = hardToCloseWriter{} + assert.NotNil(t, w.Close()) + w.(*concreteWriter).infoLog = easyToCloseWriter{} + w.(*concreteWriter).errorLog = hardToCloseWriter{} + assert.NotNil(t, w.Close()) + w.(*concreteWriter).errorLog = easyToCloseWriter{} + w.(*concreteWriter).severeLog = hardToCloseWriter{} + assert.NotNil(t, w.Close()) + w.(*concreteWriter).severeLog = easyToCloseWriter{} + w.(*concreteWriter).slowLog = hardToCloseWriter{} + assert.NotNil(t, w.Close()) + w.(*concreteWriter).slowLog = easyToCloseWriter{} + w.(*concreteWriter).statLog = hardToCloseWriter{} + assert.NotNil(t, w.Close()) + w.(*concreteWriter).statLog = easyToCloseWriter{} +} + +func TestNopWriter(t *testing.T) { + assert.NotPanics(t, func() { + var w nopWriter + w.Alert("foo") + w.Error("foo") + w.Info("foo") + w.Severe("foo") + w.Stack("foo") + w.Stat("foo") + w.Slow("foo") + w.Close() + }) +} + +func TestWriteJson(t *testing.T) { + var buf bytes.Buffer + log.SetOutput(&buf) + writeJson(nil, "foo") + assert.Contains(t, buf.String(), "foo") + buf.Reset() + writeJson(nil, make(chan int)) + assert.Contains(t, buf.String(), "unsupported type") +} + +func TestWritePlainAny(t *testing.T) { + var buf bytes.Buffer + log.SetOutput(&buf) + writePlainAny(nil, levelInfo, "foo") + assert.Contains(t, buf.String(), "foo") + + buf.Reset() + writePlainAny(nil, levelInfo, make(chan int)) + assert.Contains(t, buf.String(), "unsupported type") + writePlainAny(nil, levelInfo, 100) + assert.Contains(t, buf.String(), "100") + + buf.Reset() + writePlainAny(hardToWriteWriter{}, levelInfo, 100) + assert.Contains(t, buf.String(), "write error") + + buf.Reset() + writePlainAny(hardToWriteWriter{}, levelInfo, "foo") + assert.Contains(t, buf.String(), "write error") +} + +type mockedEntry struct { + Level string `json:"level"` + Content string `json:"content"` +} + +type easyToCloseWriter struct{} + +func (h easyToCloseWriter) Write(_ []byte) (_ int, _ error) { + return +} + +func (h easyToCloseWriter) Close() error { + return nil +} + +type hardToCloseWriter struct{} + +func (h hardToCloseWriter) Write(_ []byte) (_ int, _ error) { + return +} + +func (h hardToCloseWriter) Close() error { + return errors.New("close error") +} + +type hardToWriteWriter struct{} + +func (h hardToWriteWriter) Write(_ []byte) (_ int, _ error) { + return 0, errors.New("write error") +} diff --git a/core/proc/goroutines_test.go b/core/proc/goroutines_test.go index 4a4685d8..9464fba9 100644 --- a/core/proc/goroutines_test.go +++ b/core/proc/goroutines_test.go @@ -1,16 +1,23 @@ package proc import ( - "log" "strings" "testing" "github.com/stretchr/testify/assert" + "github.com/zeromicro/go-zero/core/logx" ) func TestDumpGoroutines(t *testing.T) { var buf strings.Builder - log.SetOutput(&buf) + w := logx.NewWriter(&buf) + o := logx.Reset() + logx.SetWriter(w) + defer func() { + logx.Reset() + logx.SetWriter(o) + }() + dumpGoroutines() assert.True(t, strings.Contains(buf.String(), ".dump")) } diff --git a/core/proc/profile_test.go b/core/proc/profile_test.go index a5353a59..eb89ceee 100644 --- a/core/proc/profile_test.go +++ b/core/proc/profile_test.go @@ -1,16 +1,24 @@ package proc import ( - "log" "strings" "testing" "github.com/stretchr/testify/assert" + "github.com/zeromicro/go-zero/core/logx" ) func TestProfile(t *testing.T) { var buf strings.Builder - log.SetOutput(&buf) + w := logx.NewWriter(&buf) + o := logx.Reset() + logx.SetWriter(w) + + defer func() { + logx.Reset() + logx.SetWriter(o) + }() + profiler := StartProfile() // start again should not work assert.NotNil(t, StartProfile()) diff --git a/core/stores/redis/hook_test.go b/core/stores/redis/hook_test.go index 696b7d7a..2c634f61 100644 --- a/core/stores/redis/hook_test.go +++ b/core/stores/redis/hook_test.go @@ -9,6 +9,7 @@ import ( red "github.com/go-redis/redis/v8" "github.com/stretchr/testify/assert" + "github.com/zeromicro/go-zero/core/logx" ztrace "github.com/zeromicro/go-zero/core/trace" tracesdk "go.opentelemetry.io/otel/trace" ) @@ -44,10 +45,8 @@ func TestHookProcessCase2(t *testing.T) { Sampler: 1.0, }) - writer := log.Writer() - var buf strings.Builder - log.SetOutput(&buf) - defer log.SetOutput(writer) + w, restore := injectLog() + defer restore() ctx, err := durationHook.BeforeProcess(context.Background(), nil) if err != nil { @@ -58,9 +57,9 @@ func TestHookProcessCase2(t *testing.T) { time.Sleep(slowThreshold.Load() + time.Millisecond) assert.Nil(t, durationHook.AfterProcess(ctx, red.NewCmd(context.Background(), "foo", "bar"))) - assert.True(t, strings.Contains(buf.String(), "slow")) - assert.True(t, strings.Contains(buf.String(), "trace")) - assert.True(t, strings.Contains(buf.String(), "span")) + assert.True(t, strings.Contains(w.String(), "slow")) + assert.True(t, strings.Contains(w.String(), "trace")) + assert.True(t, strings.Contains(w.String(), "span")) } func TestHookProcessCase3(t *testing.T) { @@ -110,10 +109,8 @@ func TestHookProcessPipelineCase2(t *testing.T) { Sampler: 1.0, }) - writer := log.Writer() - var buf strings.Builder - log.SetOutput(&buf) - defer log.SetOutput(writer) + w, restore := injectLog() + defer restore() ctx, err := durationHook.BeforeProcessPipeline(context.Background(), nil) if err != nil { @@ -126,34 +123,30 @@ func TestHookProcessPipelineCase2(t *testing.T) { assert.Nil(t, durationHook.AfterProcessPipeline(ctx, []red.Cmder{ red.NewCmd(context.Background(), "foo", "bar"), })) - assert.True(t, strings.Contains(buf.String(), "slow")) - assert.True(t, strings.Contains(buf.String(), "trace")) - assert.True(t, strings.Contains(buf.String(), "span")) + assert.True(t, strings.Contains(w.String(), "slow")) + assert.True(t, strings.Contains(w.String(), "trace")) + assert.True(t, strings.Contains(w.String(), "span")) } func TestHookProcessPipelineCase3(t *testing.T) { - writer := log.Writer() - var buf strings.Builder - log.SetOutput(&buf) - defer log.SetOutput(writer) + w, restore := injectLog() + defer restore() assert.Nil(t, durationHook.AfterProcessPipeline(context.Background(), []red.Cmder{ red.NewCmd(context.Background()), })) - assert.True(t, buf.Len() == 0) + assert.True(t, len(w.String()) == 0) } func TestHookProcessPipelineCase4(t *testing.T) { - writer := log.Writer() - var buf strings.Builder - log.SetOutput(&buf) - defer log.SetOutput(writer) + w, restore := injectLog() + defer restore() ctx := context.WithValue(context.Background(), startTimeKey, "foo") assert.Nil(t, durationHook.AfterProcessPipeline(ctx, []red.Cmder{ red.NewCmd(context.Background()), })) - assert.True(t, buf.Len() == 0) + assert.True(t, len(w.String()) == 0) } func TestHookProcessPipelineCase5(t *testing.T) { @@ -166,3 +159,15 @@ func TestHookProcessPipelineCase5(t *testing.T) { assert.Nil(t, durationHook.AfterProcessPipeline(ctx, nil)) assert.True(t, buf.Len() == 0) } + +func injectLog() (r *strings.Builder, restore func()) { + var buf strings.Builder + w := logx.NewWriter(&buf) + o := logx.Reset() + logx.SetWriter(w) + + return &buf, func() { + logx.Reset() + logx.SetWriter(o) + } +} diff --git a/rest/internal/log_test.go b/rest/internal/log_test.go index 03a9ee2f..9344dc51 100644 --- a/rest/internal/log_test.go +++ b/rest/internal/log_test.go @@ -2,13 +2,13 @@ package internal import ( "context" - "log" "net/http" "net/http/httptest" "strings" "testing" "github.com/stretchr/testify/assert" + "github.com/zeromicro/go-zero/core/logx" ) func TestInfo(t *testing.T) { @@ -25,16 +25,23 @@ func TestInfo(t *testing.T) { } func TestError(t *testing.T) { - var writer strings.Builder - log.SetOutput(&writer) + var buf strings.Builder + w := logx.NewWriter(&buf) + o := logx.Reset() + logx.SetWriter(w) + + defer func() { + logx.Reset() + logx.SetWriter(o) + }() + req := httptest.NewRequest(http.MethodGet, "http://localhost", nil) Error(req, "first") Errorf(req, "second %s", "third") - val := writer.String() + val := buf.String() assert.True(t, strings.Contains(val, "first")) assert.True(t, strings.Contains(val, "second")) assert.True(t, strings.Contains(val, "third")) - assert.True(t, strings.Contains(val, "\n")) } func TestContextKey_String(t *testing.T) { diff --git a/zrpc/internal/rpclogger_test.go b/zrpc/internal/rpclogger_test.go index ac87f53d..1c504343 100644 --- a/zrpc/internal/rpclogger_test.go +++ b/zrpc/internal/rpclogger_test.go @@ -1,109 +1,121 @@ package internal import ( - "log" "strings" "testing" "github.com/stretchr/testify/assert" + "github.com/zeromicro/go-zero/core/logx" ) const content = "foo" func TestLoggerError(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Error(content) - assert.Contains(t, builder.String(), content) + assert.Contains(t, w.String(), content) } func TestLoggerErrorf(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Errorf(content) - assert.Contains(t, builder.String(), content) + assert.Contains(t, w.String(), content) } func TestLoggerErrorln(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Errorln(content) - assert.Contains(t, builder.String(), content) + assert.Contains(t, w.String(), content) } func TestLoggerFatal(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Fatal(content) - assert.Contains(t, builder.String(), content) + assert.Contains(t, w.String(), content) } func TestLoggerFatalf(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Fatalf(content) - assert.Contains(t, builder.String(), content) + assert.Contains(t, w.String(), content) } func TestLoggerFatalln(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Fatalln(content) - assert.Contains(t, builder.String(), content) + assert.Contains(t, w.String(), content) } func TestLoggerInfo(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Info(content) - assert.Empty(t, builder.String()) + assert.Empty(t, w.String()) } func TestLoggerInfof(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Infof(content) - assert.Empty(t, builder.String()) + assert.Empty(t, w.String()) } func TestLoggerWarning(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Warning(content) - assert.Empty(t, builder.String()) + assert.Empty(t, w.String()) } func TestLoggerInfoln(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Infoln(content) - assert.Empty(t, builder.String()) + assert.Empty(t, w.String()) } func TestLoggerWarningf(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Warningf(content) - assert.Empty(t, builder.String()) + assert.Empty(t, w.String()) } func TestLoggerWarningln(t *testing.T) { - var builder strings.Builder - log.SetOutput(&builder) + w, restore := injectLog() + defer restore() + logger := new(Logger) logger.Warningln(content) - assert.Empty(t, builder.String()) + assert.Empty(t, w.String()) } func TestLogger_V(t *testing.T) { @@ -113,3 +125,15 @@ func TestLogger_V(t *testing.T) { // grpclog.infoLog assert.False(t, logger.V(0)) } + +func injectLog() (r *strings.Builder, restore func()) { + var buf strings.Builder + w := logx.NewWriter(&buf) + o := logx.Reset() + logx.SetWriter(w) + + return &buf, func() { + logx.Reset() + logx.SetWriter(o) + } +}