From 1ddcb1ba2522d31a83158d723729ce43b0556fd5 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 2 Oct 2024 09:39:37 -0700 Subject: [PATCH 1/3] Mark panics in log with -500 code; also return 500 to caller if response hasn't been started yet --- http_logging.go | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/http_logging.go b/http_logging.go index 503b6fc..a4fa2b3 100644 --- a/http_logging.go +++ b/http_logging.go @@ -184,7 +184,7 @@ func (rr *ResponseRecorder) Flush() { func LogAndCall(msg string, handlerFunc http.HandlerFunc, extraAttributes ...KeyVal) http.HandlerFunc { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { // This is really 2 functions but we want to be able to change config without rewiring the middleware - if Config.CombineRequestAndResponse { + if Config.CombineRequestAndResponse { //nolint:nestif // see above comment. respRec := &ResponseRecorder{w: w, startTime: time.Now()} defer func() { if err := recover(); err != nil { @@ -192,6 +192,10 @@ func LogAndCall(msg string, handlerFunc http.HandlerFunc, extraAttributes ...Key if Log(Verbose) { s(Verbose, false, Config.JSON, "stack trace", Str("stack", string(debug.Stack()))) } + respRec.StatusCode = -500 // Marking as a panic for the log. + if respRec.ContentLength == 0 { // Nothing was written yet so we can write an error + http.Error(w, fmt.Sprintf("Internal Server Error\n%s", err), http.StatusInternalServerError) + } } attr := []KeyVal{ Int("status", respRec.StatusCode), From a475fcaeebb81c54bfb77dc2972c6f87809e5447 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 2 Oct 2024 11:05:14 -0700 Subject: [PATCH 2/3] Fix the test: needed a smarter NullWriter and make the panic in the handler and not the writer --- http_logging_test.go | 39 +++++++++++++++++++++++++++++---------- 1 file changed, 29 insertions(+), 10 deletions(-) diff --git a/http_logging_test.go b/http_logging_test.go index a9697ee..d8e48bb 100644 --- a/http_logging_test.go +++ b/http_logging_test.go @@ -46,26 +46,32 @@ func TestLogRequest(t *testing.T) { } func testHandler(w http.ResponseWriter, r *http.Request) { + if r.URL != nil && r.URL.Path == "/panicbefore" { + panic("some test handler panic before response") + } if r.URL != nil && r.URL.Path == "/tea" { w.WriteHeader(http.StatusTeapot) } w.Write([]byte("hello")) time.Sleep(100 * time.Millisecond) + if r.URL != nil && r.URL.Path == "/panicafter" { + panic("some test handler panic after response") + } } type NullHTTPWriter struct { doErr bool - doPanic bool + headers http.Header } func (n *NullHTTPWriter) Header() http.Header { - return nil + if n.headers == nil { + n.headers = make(http.Header) + } + return n.headers } func (n *NullHTTPWriter) Write(b []byte) (int, error) { - if n.doPanic { - panic("some fake http write panic") - } if n.doErr { return 0, errors.New("some fake http write error") } @@ -100,7 +106,7 @@ func TestLogAndCall(t *testing.T) { if !strings.HasPrefix(actual, expectedPrefix) { t.Errorf("unexpected:\n%s\nvs should start with:\n%s\n", actual, expectedPrefix) } - if hw.Header() != nil { + if len(hw.Header()) != 0 { t.Errorf("unexpected non nil header: %v", hw.Header()) } hr.URL = &url.URL{Path: "/tea"} @@ -123,20 +129,33 @@ func TestLogAndCall(t *testing.T) { if !strings.Contains(actual, expectedFragment) { t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment) } - n.doPanic = true + hr.URL = &url.URL{Path: "/panicafter"} n.doErr = false SetLogLevelQuiet(Verbose) b.Reset() LogAndCall("test-log-and-call4", testHandler).ServeHTTP(hw, hr) w.Flush() actual = b.String() - expectedFragment = `,"size":0,` + expectedFragment = `"status":-500,` + Config.GoroutineID = false + if !strings.Contains(actual, expectedFragment) { + t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment) + } + if !strings.Contains(actual, `{"level":"crit","msg":"panic in handler","error":"some test handler panic after response"}`) { + t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, "some test handler panic after response") + } + hr.URL = &url.URL{Path: "/panicbefore"} + b.Reset() + LogAndCall("test-log-and-call5", testHandler).ServeHTTP(hw, hr) + w.Flush() + actual = b.String() + expectedFragment = `"status":-500,` Config.GoroutineID = false if !strings.Contains(actual, expectedFragment) { t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment) } - if !strings.Contains(actual, `{"level":"crit","msg":"panic in handler","error":"some fake http write panic"`) { - t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, "some fake http write panic") + if !strings.Contains(actual, `{"level":"crit","msg":"panic in handler","error":"some test handler panic before response"}`) { + t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, "some test handler panic before response") } // restore for other tests Config.GoroutineID = true From ea8b8e8c761cc57a5cc352753c05e2b321f9d706 Mon Sep 17 00:00:00 2001 From: Laurent Demailly Date: Wed, 2 Oct 2024 11:30:44 -0700 Subject: [PATCH 3/3] Switch type for level to int8; silence gosec --- logger.go | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/logger.go b/logger.go index f27b527..2443157 100644 --- a/logger.go +++ b/logger.go @@ -43,7 +43,7 @@ import ( ) // Level is the level of logging (0 Debug -> 6 Fatal). -type Level int32 +type Level int8 // Log levels. Go can't have variable and function of the same name so we keep // medium length (Dbg,Info,Warn,Err,Crit,Fatal) names for the functions. @@ -180,6 +180,13 @@ func (l *JSONEntry) Time() time.Time { ) } +func intToLevel(i int) Level { + if i < 0 || i >= len(LevelToStrA) { + return -1 + } + return Level(i) //nolint:gosec // we just checked above. +} + //nolint:gochecknoinits // needed func init() { if !isValid(os.Stderr) { // wasm in browser case for instance @@ -190,12 +197,13 @@ func init() { JSONStringLevelToLevel = make(map[string]Level, len(LevelToJSON)-1) // -1 to not reverse info to NoLevel for l, name := range LevelToStrA { // Allow both -loglevel Verbose and -loglevel verbose ... - levelToStrM[name] = Level(l) - levelToStrM[strings.ToLower(name)] = Level(l) + lvl := intToLevel(l) + levelToStrM[name] = lvl + levelToStrM[strings.ToLower(name)] = lvl } for l, name := range LevelToJSON[0 : Fatal+1] { // Skip NoLevel // strip the quotes around - JSONStringLevelToLevel[name[1:len(name)-1]] = Level(l) + JSONStringLevelToLevel[name[1:len(name)-1]] = intToLevel(l) } log.SetFlags(log.Ltime) configFromEnv() @@ -339,7 +347,7 @@ func EnvHelp(w io.Writer) { // GetLogLevel returns the currently configured LogLevel. func GetLogLevel() Level { - return Level(atomic.LoadInt32(&levelInternal)) + return intToLevel(int(atomic.LoadInt32(&levelInternal))) } // Log returns true if a given level is currently logged.