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
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

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
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
2 participants
@bentcoder @seankhliao