hibiken / asynq

Simple, reliable, and efficient distributed task queue in Go
MIT License
9.65k stars 696 forks source link

[BUG] The call stack depth of Logger.Infof() and Logger.Info() should be the same #684

Open xuyang2 opened 1 year ago

xuyang2 commented 1 year ago

The call stack depth of Infof() and Info() should be the same,otherwise the logger cannot use the same callerSkip number to get the file and line number of the code that calls the logger.

Step to produce: wrap a zap.Logger,pass it to asynq.NewScheduler(), start the Scheduler

// asynqlog/asynqlog.go
package asynqlog

import (
    "github.com/hibiken/asynq"
    "go.uber.org/zap"
)

// var _ asynq.Logger = slog.Logger(nil)

var _ asynq.Logger = (*zap.SugaredLogger)(nil)
var _ asynq.Logger = (*Logger)(nil)

func Wrap(logger *zap.Logger) asynq.Logger {
    l := logger.WithOptions(zap.AddCallerSkip(2)).Sugar()
    return &Logger{l: l}
}

type Logger struct {
    l asynq.Logger
}

func (l *Logger) Debug(args ...interface{}) {
    l.l.Debug(args...)
}

func (l *Logger) Info(args ...interface{}) {
    l.l.Info(args...)
}

func (l *Logger) Warn(args ...interface{}) {
    l.l.Warn(args...)
}

func (l *Logger) Error(args ...interface{}) {
    l.l.Error(args...)
}

func (l *Logger) Fatal(args ...interface{}) {
    l.l.Fatal(args...)
}

expected output:

2023-07-10T10:50:06.790+0800    INFO    asynq@v0.23.1/scheduler.go:228    Scheduler starting
2023-07-10T10:50:06.790+0800    INFO    asynq@v0.23.1/scheduler.go:229    Scheduler timezone is set to Asia/Shanghai

actual output:

2023-07-10T10:50:06.790+0800    INFO    asynq@v0.23.1/scheduler.go:228    Scheduler starting
2023-07-10T10:50:06.790+0800    INFO    log/log.go:191  Scheduler timezone is set to Asia/Shanghai

Cause: Logger.Infof() calls Logger.Info() https://github.com/hibiken/asynq/blob/123d560a4488fad0998a90f46cada46e3849b20d/scheduler.go#L223C17-L224

xuyang2 commented 1 year ago

I think this can be fixed by a little copying: ( And checking with canLogAt() before fmt.Sprintf() can also improve performance )

func (l *Logger) Info(args ...interface{}) {
    if !l.canLogAt(InfoLevel) {
        return
    }
    l.base.Info(args...)
}

func (l *Logger) Infof(format string, args ...interface{}) {
    if !l.canLogAt(InfoLevel) {
        return
    }
    l.base.Info(fmt.Sprintf(format, args...))
    // l.Info(fmt.Sprintf(format, args...))
}