Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

log/slog: slog.SetDefault side effects log.Print is not respecting level #57396

Closed
mkungla opened this issue Dec 19, 2022 · 1 comment
Closed

Comments

@mkungla
Copy link
Contributor

mkungla commented Dec 19, 2022

What version of Go are you using (go version)?

$ go version
go version go1.20rc1 linux/amd64

Does this issue reproduce with the latest release?

-

What did you do?

// Handle handles the Record.
// It will only be called if Enabled returns true.
// Handle methods that produce output should observe the following rules:
//   - If r.Time is the zero time, ignore the time.
//   - If an Attr's key is the empty string, ignore the Attr.
Handle(r Record) error

It will only be called if Enabled returns true.

That is misleading, there is no checks for Enabled on available handlers which call directly commonHandler.handle. commonHandler.handler does not have enabled check. This check is performed by Logger call chain using Logger.logDepth where enabled is checked.

That can lead some undesired side effects; e.g.

slog.SetDefault(slog.New(slog.HandlerOptions{
  Level: slog.LevelWarn,
}.NewTextHandler(os.Stdout)))

slog.Info("slog.Info: that is ignored as it should")
slog.Warn("slog.Warn: that is logged as it should", "info.enabled", slog.Default().Enabled(slog.LevelInfo))
log.Print("log.Print: did not expect to see that in logs")

slog.Default().Handler().Handle(
  slog.NewRecord(
    time.Now(),
    slog.LevelInfo,
    "call.Handle: I guess thats ok if that is printed always",
    0, 
    nil,
))

What did you expect to see?

No info logs.

What did you see instead?

time=2022-12-19T22:13:49.033+02:00 level=WARN msg="slog.Warn: that is logged as it should" info.enabled=false
time=2022-12-19T22:13:49.033+02:00 level=INFO msg="log.Print: did not expect to see that in logs"
time=2022-12-19T22:13:49.033+02:00 level=INFO msg="call.Handle: I guess thats ok if that is printed always"

Primarly it conserns log.Output set by func SetDefault(l *Logger)

// It is used to link the default log.Logger to the default slog.Logger.
func (w *handlerWriter) Write(buf []byte) (int, error) {
  ...
  r := NewRecord(time.Now(), LevelInfo, string(buf), depth, nil)
  return origLen, w.h.Handle(r)
}

So shouldn't this handlerWriter call have something like

func (w *handlerWriter) Write(buf []byte) (int, error) {
  if !w.h.Enabled(LevelInfo) {
    return 0, nil
  }
  ...
}

or should Handle implementation do this check?

Originally posted by @mkungla in #56345 (comment)

@seankhliao
Copy link
Member

please use the original thread

@seankhliao seankhliao closed this as not planned Won't fix, can't repro, duplicate, stale Dec 19, 2022
@golang golang locked and limited conversation to collaborators Dec 19, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants