From 6f145bda1f84b3eceeee9f964087a92185898fbb Mon Sep 17 00:00:00 2001
From: Toni Spets <toni.spets@beeper.com>
Date: Wed, 2 Oct 2024 14:00:25 +0300
Subject: [PATCH] Log panics in HTTP routes nicely

Returns a JSON body with some details that can be used for tracing.
---
 pkg/requestlog/accesslogger.go | 122 +++++++++++++++++++++------------
 1 file changed, 77 insertions(+), 45 deletions(-)

diff --git a/pkg/requestlog/accesslogger.go b/pkg/requestlog/accesslogger.go
index bae344c..f5b2043 100644
--- a/pkg/requestlog/accesslogger.go
+++ b/pkg/requestlog/accesslogger.go
@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"encoding/json"
 	"net/http"
+	"runtime/debug"
 	"time"
 
 	"github.com/rs/zerolog"
@@ -25,58 +26,89 @@ func AccessLogger(logOptions bool) func(http.Handler) http.Handler {
 			}
 
 			start := time.Now()
-			next.ServeHTTP(crw, r)
-			requestDuration := time.Since(start)
+			defer func() {
+				requestDuration := time.Since(start)
 
-			if r.Method == http.MethodOptions && !logOptions {
-				return
-			}
+				var requestLog *zerolog.Event
+				if crw.StatusCode >= 500 {
+					requestLog = log.Error()
+				} else if crw.StatusCode >= 400 {
+					requestLog = log.Warn()
+				} else {
+					requestLog = log.Info()
+				}
 
-			var requestLog *zerolog.Event
-			if crw.StatusCode >= 500 {
-				requestLog = log.Error()
-			} else if crw.StatusCode >= 400 {
-				requestLog = log.Warn()
-			} else {
-				requestLog = log.Info()
-			}
+				// recover and log the error
+				if rcvr := recover(); rcvr != nil && rcvr != http.ErrAbortHandler {
+					crw.StatusCode = http.StatusInternalServerError
+					w.Header().Set("Content-Type", "text/plain")
+					w.WriteHeader(crw.StatusCode)
 
-			if userAgent := r.UserAgent(); userAgent != "" {
-				requestLog.Str("user_agent", userAgent)
-			}
-			if referer := r.Referer(); referer != "" {
-				requestLog.Str("referer", referer)
-			}
-			remoteAddr := r.RemoteAddr
-
-			requestLog.Str("remote_addr", remoteAddr)
-			requestLog.Str("method", r.Method)
-			requestLog.Str("proto", r.Proto)
-			requestLog.Int64("request_length", r.ContentLength)
-			requestLog.Str("host", r.Host)
-			requestLog.Str("request_uri", r.RequestURI)
-			if r.Method != http.MethodGet && r.Method != http.MethodHead {
-				requestLog.Str("request_content_type", r.Header.Get("Content-Type"))
-				if crw.RequestBody != nil {
-					logRequestMaybeJSON(requestLog, "request_body", crw.RequestBody.Bytes())
+					resp := struct {
+						Errcode   string `json:"errcode"`
+						Error     string `json:"error"`
+						RequestID string `json:"request_id"`
+						Time      string `json:"time"`
+					}{
+						Errcode: "COM.BEEPER.PANIC",
+						Error:   "Internal Server Error",
+						Time:    time.Now().UTC().Format(time.RFC3339),
+					}
+
+					if requestID, ok := hlog.IDFromRequest(r); ok {
+						resp.RequestID = requestID.String()
+					}
+
+					json.NewEncoder(w).Encode(&resp)
+
+					requestLog = log.Error()
+					requestLog.Interface("panic", rcvr)
+					requestLog.Bytes("stack", debug.Stack())
 				}
-			}
 
-			// response
-			requestLog.Int64("request_time_ms", requestDuration.Milliseconds())
-			requestLog.Int("status_code", crw.StatusCode)
-			requestLog.Int("response_length", crw.ResponseLength)
-			requestLog.Str("response_content_type", crw.Header().Get("Content-Type"))
-			if crw.ResponseBody != nil {
-				logRequestMaybeJSON(requestLog, "response_body", crw.ResponseBody.Bytes())
-			}
+				if r.Method == http.MethodOptions && !logOptions {
+					return
+				}
 
-			// don't log successful health requests
-			if r.URL.Path == "/health" && crw.StatusCode == http.StatusNoContent {
-				return
-			}
+				if userAgent := r.UserAgent(); userAgent != "" {
+					requestLog.Str("user_agent", userAgent)
+				}
+				if referer := r.Referer(); referer != "" {
+					requestLog.Str("referer", referer)
+				}
+				remoteAddr := r.RemoteAddr
 
-			requestLog.Msg("Access")
+				requestLog.Str("remote_addr", remoteAddr)
+				requestLog.Str("method", r.Method)
+				requestLog.Str("proto", r.Proto)
+				requestLog.Int64("request_length", r.ContentLength)
+				requestLog.Str("host", r.Host)
+				requestLog.Str("request_uri", r.RequestURI)
+				if r.Method != http.MethodGet && r.Method != http.MethodHead {
+					requestLog.Str("request_content_type", r.Header.Get("Content-Type"))
+					if crw.RequestBody != nil {
+						logRequestMaybeJSON(requestLog, "request_body", crw.RequestBody.Bytes())
+					}
+				}
+
+				// response
+				requestLog.Int64("request_time_ms", requestDuration.Milliseconds())
+				requestLog.Int("status_code", crw.StatusCode)
+				requestLog.Int("response_length", crw.ResponseLength)
+				requestLog.Str("response_content_type", crw.Header().Get("Content-Type"))
+				if crw.ResponseBody != nil {
+					logRequestMaybeJSON(requestLog, "response_body", crw.ResponseBody.Bytes())
+				}
+
+				// don't log successful health requests
+				if r.URL.Path == "/health" && crw.StatusCode == http.StatusNoContent {
+					return
+				}
+
+				requestLog.Msg("Access")
+			}()
+
+			next.ServeHTTP(crw, r)
 		})
 	}
 }