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.

Sign up for GitHub

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

Jump to bottom

log/slog: Using SetDefault causes level and msg being rendered wrong if log called in a panic recovery middleware #64015

Closed
bentcoder opened this issue Nov 8, 2023 · 3 comments
Closed

log/slog: Using SetDefault causes level and msg being rendered wrong if log called in a panic recovery middleware #64015

bentcoder opened this issue Nov 8, 2023 · 3 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@bentcoder
Copy link

bentcoder commented Nov 8, 2023 •
edited
Loading

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

$ go version
go version go1.21.2 darwin/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='on'
GOARCH='amd64'
GOBIN=''
GOCACHE='/Users/myself/Library/Caches/go-build'
GOENV='/Users/myself/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/myself/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/myself/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/darwin_amd64'
GOVCS=''
GOVERSION='go1.21.2'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/Users/myself/dev/golang/dummy/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/4d/abc/T/go-build3296436397=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

func main() {
	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, nil))) // Or use NewTextHandler
	
	// ... register `recovery` middleware and handler
	// ... start server
}
func handler(w http.ResponseWriter, r *http.Request) {
	slog.InfoContext(r.Context(), "1")
	slog.WarnContext(r.Context(), "2")
	slog.ErrorContext(r.Context(), "3")

	panic("test")
}
func recovery(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		defer func() {
			if err := recover(); err != nil {
				slog.ErrorContext(r.Context(), "4")

				w.WriteHeader(http.StatusInternalServerError)
			}
		}()

		next.ServeHTTP(w, r)
	})
}

What did you expect to see?

After sending a test request to HTTP endpoint to simulate panic and recovery, last log looks wrong.

Note: If you also use a custom log handler that extracts and adds custom fields to logs, none of those fields appear in logs either.

{"time":"2023-11-08T20:54:17.142515Z","level":"INFO","msg":"1"}
{"time":"2023-11-08T20:54:17.142571Z","level":"WARN","msg":"2"}
{"time":"2023-11-08T20:54:17.142599Z","level":"ERROR","msg":"3"}
{"time":"2023-11-08T20:54:17.142703Z","level":"ERROR","msg":"4"}  <------- I am expecting to see this

What did you see instead?

When used NewJSONHandler.

{"time":"2023-11-08T20:54:17.142515Z","level":"INFO","msg":"1"}
{"time":"2023-11-08T20:54:17.142571Z","level":"WARN","msg":"2"}
{"time":"2023-11-08T20:54:17.142599Z","level":"ERROR","msg":"3"}
{"time":"2023-11-08T20:54:17.142703Z","level":"INFO","msg":"ERROR 4"}  <------- I got this instead

When used NewTextHandler.

time=2023-11-08T21:12:07.019Z level=INFO msg=1
time=2023-11-08T21:12:07.019Z level=WARN msg=2
time=2023-11-08T21:12:07.019Z level=ERROR msg=3
time=2023-11-08T21:12:07.019Z level=INFO msg="ERROR 4"  <------- I got this instead

As you can see above, the last log entry is not right!

If you omit slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, nil))) from main function, output seems correct for text version.

2023/11/08 21:07:12 INFO 1
2023/11/08 21:07:12 WARN 2
2023/11/08 21:07:12 ERROR 3
2023/11/08 21:07:12 ERROR 4
@seankhliao
Copy link
Member

Please include a complete reproducer.
The obvious way to attempt to reproduce it does not trigger what you're seeing.

package main

import (
	"log/slog"
	"net/http"
	"os"
)

func main() {
	slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr, nil))) // Or use NewTextHandler

	http.Handle("/", recovery(http.HandlerFunc(handler)))
	http.ListenAndServe(":8080", nil)
}

func handler(w http.ResponseWriter, r *http.Request) {
	slog.InfoContext(r.Context(), "1")
	slog.WarnContext(r.Context(), "2")
	slog.ErrorContext(r.Context(), "3")

	panic("test")
}

func recovery(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		defer func() {
			if err := recover(); err != nil {
				slog.ErrorContext(r.Context(), "4")

				w.WriteHeader(http.StatusInternalServerError)
			}
		}()

		next.ServeHTTP(w, r)
	})
}

@seankhliao seankhliao added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Nov 8, 2023
@bentcoder
Copy link
Author

Sorry, it has to be related to something I have in the app. I've tried again and it seems to be working fine.

@bentcoder
Copy link
Author

Found it. When importing golang.org/x/exp/slog in one package and log/slog in another (which is what I seem to be doing, accidentally), things get messed up.

avisiedo added a commit to avisiedo/idmsvc-backend that referenced this issue Jul 11, 2024
@avisiedo
refactor: use golang.org/x/exp/slog
3c80c86 
Use the slog experimental version to keep the
consistency cross the repository. Use different
packages could evoke the situation described at:

golang/go#64015

Signed-off-by: Alejandro Visiedo <avisiedo@redhat.com>
avisiedo added a commit to avisiedo/idmsvc-backend that referenced this issue Jul 15, 2024
@avisiedo
refactor: use golang.org/x/exp/slog
4bc303c 
Use the slog experimental version to keep the
consistency cross the repository. Use different
packages could evoke the situation described at:

golang/go#64015

Signed-off-by: Alejandro Visiedo <avisiedo@redhat.com>
avisiedo added a commit to avisiedo/idmsvc-backend that referenced this issue Jul 15, 2024
@avisiedo
refactor: use log/slog
Loading
Loading status checks…
7ce9e59 
Use the slog experimental version to keep the
consistency cross the repository. Use different
packages could evoke the situation described at:

golang/go#64015

Signed-off-by: Alejandro Visiedo <avisiedo@redhat.com>
@avisiedo avisiedo mentioned this issue Jul 15, 2024
Merged
avisiedo added a commit to avisiedo/idmsvc-backend that referenced this issue Jul 15, 2024
@avisiedo
refactor: use log/slog
Loading
Loading status checks…
eedacc4 
Use the log/slog package to keep the
consistency cross the repository. Use different
packages could evoke the situation described at:

golang/go#64015

Signed-off-by: Alejandro Visiedo <avisiedo@redhat.com>
avisiedo added a commit to avisiedo/idmsvc-backend that referenced this issue Jul 16, 2024
@avisiedo
refactor: use log/slog
Loading
Loading status checks…
d48547b 
Use the log/slog package to keep the
consistency cross the repository. Use different
packages could evoke the situation described at:

golang/go#64015

Signed-off-by: Alejandro Visiedo <avisiedo@redhat.com>
avisiedo added a commit to avisiedo/idmsvc-backend that referenced this issue Jul 23, 2024
@avisiedo
refactor: use log/slog
Loading
Loading status checks…
aa7fe44 
Use the log/slog package to keep the
consistency cross the repository. Use different
packages could evoke the situation described at:

golang/go#64015

Signed-off-by: Alejandro Visiedo <avisiedo@redhat.com>
avisiedo added a commit to avisiedo/idmsvc-backend that referenced this issue Jul 25, 2024
@avisiedo
refactor: use log/slog
Loading
Loading status checks…
c66edbd 
Use the log/slog package to keep the
consistency cross the repository. Use different
packages could evoke the situation described at:

golang/go#64015

Signed-off-by: Alejandro Visiedo <avisiedo@redhat.com>
avisiedo added a commit to podengo-project/idmsvc-backend that referenced this issue Jul 25, 2024
@avisiedo
refactor: use log/slog
Loading
Loading status checks…
1c2592f 
Use the log/slog package to keep the
consistency cross the repository. Use different
packages could evoke the situation described at:

golang/go#64015

Signed-off-by: Alejandro Visiedo <avisiedo@redhat.com>
@golang golang locked and limited conversation to collaborators Nov 7, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@gopherbot @bentcoder @seankhliao