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: LevelHandler example is invalid; results in a deadlock #61892

Open
ainar-g opened this issue Aug 9, 2023 · 11 comments
Open

log/slog: LevelHandler example is invalid; results in a deadlock #61892

ainar-g opened this issue Aug 9, 2023 · 11 comments
Assignees
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@ainar-g
Copy link
Contributor

ainar-g commented Aug 9, 2023

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

$ go version
go version go1.21.0 linux/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/home/ainar/.cache/go-build'
GOENV='/home/ainar/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/ainar/go/pkg/mod'
GONOPROXY='REMOVED'
GONOSUMDB='REMOVED'
GOOS='linux'
GOPATH='/home/ainar/go'
GOPRIVATE='REMOVED'
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/home/ainar/go/go1.21'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/home/ainar/go/go1.21/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.21.0'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/home/ainar/adg/AdGuardDNS/go.mod'
GOWORK='/home/ainar/adg/AdGuardDNS/go.work'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build844166527=/tmp/go-build -gno-record-gcc-switches'

What did you do?

https://go.dev/play/p/_usbsfWCk4k

What did you expect to see?

  1. The example from here to compile with the final log/slog.

  2. That example to work with the final log/slog without known deadlocks.

What did you see instead?

  1. The example had to be modified to include context.Contexts, see the code in the playground.

  2. The code still results in:

    fatal error: all goroutines are asleep - deadlock!
    
    goroutine 1 [sync.Mutex.Lock]:
    sync.runtime_SemacquireMutex(0x11?, 0x20?, 0x10?)
    	/usr/local/go-faketime/src/runtime/sema.go:77 +0x25
    sync.(*Mutex).lockSlow(0xc0000160f0)
    	/usr/local/go-faketime/src/sync/mutex.go:171 +0x15d
    sync.(*Mutex).Lock(...)
    	/usr/local/go-faketime/src/sync/mutex.go:90
    log.(*Logger).output(0xc0000160f0, 0x0, 0x0?, 0xc000050f38)
    	/usr/local/go-faketime/src/log/log.go:243 +0x427
    log.init.0.func1(0xbab699fc00000000?, {0xc00007e800?, 0x583520?, 0xc000012070?})
    	/usr/local/go-faketime/src/log/log.go:251 +0x53
    log/slog.(*defaultHandler).Handle(_, {_, _}, {{0xbab699fc00000000, 0x1, 0x583520}, {0xc000012070, 0xb}, 0x0, 0x0, ...})
    	/usr/local/go-faketime/src/log/slog/handler.go:116 +0x3b2
    main.(*LevelHandler).Handle(_, {_, _}, {{0xbab699fc00000000, 0x1, 0x583520}, {0xc000012070, 0xb}, 0x0, 0x0, ...})
    	/tmp/sandbox2273227079/levelhandler.go:39 +0x55
    log/slog.(*handlerWriter).Write(0xc000060040, {0xc000012060, 0xc, 0x7fa4a0fcb5f0?})
    	/usr/local/go-faketime/src/log/slog/logger.go:70 +0x226
    log.(*Logger).output(0xc0000160f0, 0x4ae051, 0x0?, 0xc000051750)
    	/usr/local/go-faketime/src/log/log.go:245 +0x485
    log.init.0.func1(0xbab699fc00000000?, {0xc00007e000?, 0x583520?, 0x4d0552?})
    	/usr/local/go-faketime/src/log/log.go:251 +0x53
    log/slog.(*defaultHandler).Handle(_, {_, _}, {{0xbab699fc00000000, 0x1, 0x583520}, {0x4d0552, 0x5}, 0xfffffffffffffffc, 0x4ae051, ...})
    	/usr/local/go-faketime/src/log/slog/handler.go:116 +0x3b2
    main.(*LevelHandler).Handle(_, {_, _}, {{0xbab699fc00000000, 0x1, 0x583520}, {0x4d0552, 0x5}, 0xfffffffffffffffc, 0x4ae051, ...})
    	/tmp/sandbox2273227079/levelhandler.go:39 +0x55
    log/slog.(*Logger).log(0xc0000140a0, {0x4f51f0, 0x5b0e40}, 0xfffffffffffffffc, {0x4d0552, 0x5}, {0x0, 0x0, 0x0})
    	/usr/local/go-faketime/src/log/slog/logger.go:225 +0x1e4
    log/slog.Debug({0x4d0552?, 0x0?}, {0x0?, 0x0?, 0x60?})
    	/usr/local/go-faketime/src/log/slog/logger.go:250 +0x96
    main.main()
    	/tmp/sandbox2273227079/prog.go:10 +0x131
    

    In the original issue, @jba had said that it should be possible to fix this deadlock once slog is imported into stdlib, but it seems like a test case for this example hadn't been made?

Additional information

Originally, my need for this code is from the desire to use the default plain-text handler of log/slog with debug level.

@gopherbot gopherbot added this to the Unreleased milestone Aug 9, 2023
@mknyszek
Copy link
Contributor

mknyszek commented Aug 9, 2023

CC @jba

@mknyszek mknyszek added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 9, 2023
@jba jba self-assigned this Aug 11, 2023
@jba
Copy link
Contributor

jba commented Aug 11, 2023

The deadlock is masking a deeper problem. There is an inherent circularity here.

In addition to setting slog's default handler, slog.SetDefault makes the default log.Logger use that handler.
So when you call slog.SetDefault with a handler H that contains the default handler, you're creating this situation:

  1. H calls the default handler, which calls the default log.Logger.
  2. The default log.Logger calls H.

We need to find a way to resolve that circularity while preserving existing behavior.

I'll be out for two weeks, but I'll revisit this when I return.

@jba
Copy link
Contributor

jba commented Aug 11, 2023

I lied, I'm still here.

Just to be clear, this is not about how the code is currently written. If you're thinking about how we can reorganize the code in log and log/slog to make this work (as I have been for the last couple of hours), you are on the wrong track. There is nothing to "make work"; calling slog.SetDefault with a handler that calls the default handler is asking for something impossible. You are asking for slog to behave like log to behave like slog. Maybe technically that's not impossible, but the opposite: any output (or no output) would make that true. If you look at it that way, then deadlock is a valid solution!

Until we think of a better answer (if there is one), here is a simple workaround: break the connection between log and slog. After calling slog.SetDefault, call log.SetOutput with an ordinary io.Writer. Now slog calls H, which calls the default log.Logger, which ... just writes to somewhere. No more circularity.

@ainar-g
Copy link
Contributor Author

ainar-g commented Aug 11, 2023

@jba, I very much appreciate the workaround! That works for our projects.

Should I leave the issue open until the example is fixed or is that going to be done either way when updating golang.org/x/exp/slog to match log/slog (assuming that's planned)?

@jba
Copy link
Contributor

jba commented Aug 11, 2023

Let's leave it open until we have a satisfying answer, or decide that that is impossible.

@atuleu
Copy link

atuleu commented Aug 25, 2023

I came to the same issue while just wanting to increase the level of the default slog handler.

It seems a pretty expected use case. Why not just simply add a third exported Handler, say DefaultHandler which produces the same output than log/slog. So in both use case that went to this issue we should simply call
slog.SetDefault(slog.New(os.Stdout,NewLevelHandler(slog.DebugLevel,slog.NewDefaultHandler(os.Stdout))))

In my case just discovering the package, I was expecting TextHandler to be that handler, or like in the old log that there should be an option, like log.Stdflags to make it behave like the default one, a with a few settings changes. Since I think we cannot add such an option to HandlerOption adding a new Handler that mimics the behavior of the default handler will be nice.

I also find weird to me that wrapping the slog.Default will break anything. I can think of a few project where I would like to replicate logrus.AddHook by calling slog.SetDefault(slog.New(os.Stdout,SomeWrapper(slog.Default().Handler()))). For example intercepting log records and send them through OTel.

@atuleu
Copy link

atuleu commented Aug 25, 2023

Until we think of a better answer (if there is one), here is a simple workaround: break the connection between log and slog. After calling slog.SetDefault, call log.SetOutput with an ordinary io.Writer. Now slog calls H, which calls the default log.Logger, which ... just writes to somewhere. No more circularity.

Actually it does not do the same, as it strips the leading timestamp: https://go.dev/play/p/F-4rvQ99QgV

@tgulacsi
Copy link
Contributor

@atuleu, yes, the flags has to be set, too: log.SetFlags(log.Ldate|log.Ltime)

@seankhliao seankhliao changed the title x/exp/slog: LevelHandler example is invalid; results in a deadlock log/slog: LevelHandler example is invalid; results in a deadlock Sep 2, 2023
@Minoxs
Copy link

Minoxs commented Jan 4, 2024

I found a (dirty) workaround for wrapping the default handler, which was probably unintended. More details in here: #56345 (comment)

type WrapperHandler struct {
	slog.Handler
}

func (w *WrapperHandler) Handle(ctx context.Context, record slog.Record) error {
        // doSomething()
	return w.Handler.Handle(ctx, record)
}

func main() {
  wrap := &WrapperHandler(slog.Default().Handler())
  *slog.Default() = *slog.New(wrap) // Bypass SetDefault using pointer hacks (not thread-safe obviously)
  slog.Info("TEST")  // Works just fine
}

@Minoxs
Copy link

Minoxs commented Jan 4, 2024

The deadlock is masking a deeper problem. There is an inherent circularity here.

In addition to setting slog's default handler, slog.SetDefault makes the default log.Logger use that handler. So when you call slog.SetDefault with a handler H that contains the default handler, you're creating this situation:

1. `H` calls the default handler, which calls the default `log.Logger`.

2. The default `log.Logger` calls `H`.

We need to find a way to resolve that circularity while preserving existing behavior.

I'll be out for two weeks, but I'll revisit this when I return.

If that's something too deep to change, there should be a way of setting slog's default logger without touching log's default logger, or directly changing the default handler. The comment above shows that would be enough.

Having to call slog.SetDefault() and then log.SetOutput() looks hacky (imo of course). Essentially, the way slog.SetDefault() is very unintuitive, at least it should be better documented how slog and log are intertwined, the quoted comment alone cleared up a lot of my confusion.

But also, why is slog using log.Logger on default settings? Wouldn't a definitive solution be for slog to be its own independent thing, and maybe add some function that users can explicitly call to bridge the gap between log and slog? It could be something as simple as log.SetOutput(slog.Default().Writer()).

Another possibility would be adding a With(slog.Handler) in slog.Logger to enable creating a chain of loggers to explicitly enable this behaviour without having to set a new default handler, or maybe just have the CommonHandler be public and/or configurable.

Admittedly I still haven't looked too deep into the source code, but I can imagine a dozen different ways that this can be resolved, all with their pros and cons, but it doesn't look impossible.

@3052
Copy link

3052 commented Jan 5, 2024

I can confirm the above works, thanks. needless to say its an awful hack, but I think thats more the fault of the current awkward API. here is another example:

package main

import (
   "context"
   "log/slog"
)

type debug struct {
   slog.Handler
}

func (debug) Enabled(_ context.Context, level slog.Level) bool {
   return level >= slog.LevelDebug
}

func main() {
   h := slog.Default().Handler()
   *slog.Default() = *slog.New(debug{h})
   slog.Debug("hello world")
}

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

8 participants