github_mirrors/go-zero
1
0
Fork 0
mirror of https://github.com/zeromicro/go-zero.git synced 2025-02-02 16:28:39 +08:00
Code Issues Packages Projects Releases Wiki Activity

feat: add fields with logx methods, support using third party logging libs. (#1847)

Browse Source 
* 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
This commit is contained in:
Kevin Wan 2022-05-03 17:34:26 +08:00 committed by GitHub
parent ae2c76765c
commit ac321fc146
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
21 changed files with 1551 additions and 792 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

89
core/logx/durationlogger.go
View File

@ -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...)
}
}

136
core/logx/durationlogger_test.go
View File

@ -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())
}

17
core/logx/lesslogger_test.go
View File

@ -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"))
}

38
core/logx/logger.go Normal file
View File

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

532
core/logx/logs.go
View File

@ -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
// 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
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)
if err == nil {
return
}
msg := err.Error()
log.Print(msg)
outputText(severeLog, levelFatal, 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(' ')
}
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
func errorTextSync(msg string) {
if shallLog(ErrorLevel) {
getWriter().Error(msg)
}
}
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 infoFieldsSync(content string, fields ...LogField) {
if shallLog(InfoLevel) {
getWriter().Info(content, fields...)
}
}
func infoTextSync(msg string) {
if shallLog(InfoLevel) {
outputText(infoLog, levelInfo, msg)
}
}
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'))
getWriter().Info(msg)
}
}
@ -477,74 +338,20 @@ 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))
}
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)
})
w, err := newFileWriter(c)
if err != nil {
return err
}
SetWriter(w)
return nil
}
func setupWithVolume(c LogConf) error {
if len(c.ServiceName) == 0 {
return ErrLogServiceNameNotSet
@ -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
}

360
core/logx/logs_test.go
View File

@ -4,7 +4,6 @@ import (
"encoding/json"
"errors"
"fmt"
"io"
"io/ioutil"
"log"
"os"
@ -21,6 +20,7 @@ import (
var (
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 {

22
core/logx/logwriter.go Normal file
View File

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

7
core/logx/rotatelogger_test.go
View File

@ -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())
}

8
core/logx/syslog_test.go
View File

@ -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 {

106
core/logx/tracelogger.go
View File

@ -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
}
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...)...)
}
}

157
core/logx/tracelogger_test.go
View File

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

36
core/logx/util.go Normal file
View File

@ -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)
}

72
core/logx/util_test.go Normal file
View File

@ -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)
}
}

60
core/logx/vars.go Normal file
View File

@ -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")
)

320
core/logx/writer.go Normal file
View File

@ -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())
}
}

170
core/logx/writer_test.go Normal file
View File

@ -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")
}

11
core/proc/goroutines_test.go
View File

@ -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"))
}

12
core/proc/profile_test.go
View File

@ -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())

53
core/stores/redis/hook_test.go
View File

@ -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)
}
}

17
rest/internal/log_test.go
View File

@ -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) {

98
zrpc/internal/rpclogger_test.go
View File

@ -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)
}
}