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

New issue

Open

opened 2026-03-07 22:08:54 +03:00 by kerem · 1 comment

kerem commented

2026-03-07 22:08:54 +03:00

Owner

Originally created by @xuyang2 on GitHub (Jul 10, 2023).
Original GitHub issue: https://github.com/hibiken/asynq/issues/684

Originally assigned to: @hibiken on GitHub.

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()
github.com/hibiken/asynq@123d560a44/scheduler.go (L223C17-L224)

Originally created by @xuyang2 on GitHub (Jul 10, 2023). Original GitHub issue: https://github.com/hibiken/asynq/issues/684 Originally assigned to: @hibiken on GitHub. 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: ```console 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: ```console 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

kerem added the

bug

label

2026-03-07 22:08:54 +03:00

kerem commented

2026-03-07 22:08:55 +03:00

Author

Owner

@xuyang2 commented on GitHub (Jul 10, 2023):

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

@xuyang2 commented on GitHub (Jul 10, 2023): 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...)) } ```

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference

starred/asynq#1355

No description provided.

Rows
Columns