Mark panics in log with -500 code; also return 500 to caller if response hasn't been started yet (#70)

ldemailly · web-flow · commit e9a4588681ff · 2024-10-02T11:46:05.000-07:00
* Mark panics in log with -500 code; also return 500 to caller if response hasn't been started yet

* Fix the test: needed a smarter NullWriter and make the panic in the handler and not the writer

* Switch type for level to int8; silence gosec
diff --git a/http_logging.go b/http_logging.go
@@ -184,14 +184,18 @@ 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 {
 					s(Critical, false, Config.JSON, "panic in handler", Any("error", err))
 					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),
diff --git 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
diff --git 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.
