Merge pull request #136 from snabble/panic_stack

Log stacktrace on panic in log middleware

Author: J-Rocke

.travis.yml

@@ -1,12 +1,12 @@
 language: go
 go:
-- 1.21.x
+  - 1.22.x
 before_install:
-- go install honnef.co/go/tools/cmd/staticcheck@latest
+  - go install honnef.co/go/tools/cmd/staticcheck@latest
 script:
-- go vet github.com/snabble/go-logging/...
-- go test --cover github.com/snabble/go-logging/...
-- staticcheck ./...
+  - go vet github.com/snabble/go-logging/...
+  - go test --cover github.com/snabble/go-logging/...
+  - staticcheck ./...
 
 notifications:
   email: false
@@ -17,4 +17,4 @@ notifications:
       - secure: LNfAWkWtOCKxkcaZEoh2k3zBHpZaI0Ty+VKumDuzpU2m3NYH7AxDgrFAJLZOGdAyBvMtV2K8STSVQWTLA3lNmU5m7WVFKm17J58jle3tsk2gvYIMsGOsKFy+MSmjMm4HH1NSdkFwYrAQeSvZjEywQ5qv/geJwDvIEsuppA5JCCZ6xG1GgjcptUoiSVQn7sNgz5IHCI99RjUjeRvvPlTRqFTBd4JcQvZ46jkKGccQ10+KsH1AfQ/Ay8Ns0LJKEhsmivOgakdjpSgMjnsiWhAstLoKMI/W7kCd7fP/ff8btI+zhMby75kVdgsUTnbN15Dkr8Najf6LPQ47MfFYunKTDEZhZSdXt5C0N9DwD8BpOlnzeYlmyQ3gphoF5R2a279QNIMAaOO6DUAJpcFGvsiRkjz7VRlBzZFXHNr4Sk1D+JHzISHEM1llW/m01jeEtA6TFx0raaX95To0ygl4if+WmjmfJFDrlVJUhAVxRG7ERGG1KvBzrM43Gv4L3QQr8i5Anlntbba4DfSvP5KWQAdX3JWo7feQEktH/waZ4OzKbPqGQZ5jxBhG35Sz/2o/6nUebUlaDJjMahUrddpPGcp1xlKhF5QMTK/o9kYOEy+AmYsTthAMziq41BGwTqqgqUwaLDdUOrmC3cEZWOt5spwJjzOu7FQqlu9qXXjayzsPEbg=
 env:
   global:
-  - GOPRIVATE="github.com/snabble/*"
+    - GOPRIVATE="github.com/snabble/*"

go.mod

@@ -1,8 +1,8 @@
 module github.com/snabble/go-logging/v2
 
-go 1.21
+go 1.22
 
-toolchain go1.21.1
+toolchain go1.22.0
 
 require (
 	github.com/sirupsen/logrus v1.9.3

helper.go

@@ -101,8 +101,13 @@ func isHealthRequest(r *http.Request) bool {
 }
 
 // AccessError logs an error while accessing
-func AccessError(r *http.Request, start time.Time, err error) {
+func AccessError(r *http.Request, start time.Time, err error, stack []byte) {
 	e := createAccessEntry(r, start, 0, err)
+
+	if stack != nil {
+		e = e.WithField("stack", string(stack))
+	}
+
 	e.Errorf("ERROR ->%v %v", r.Method, r.URL.Path)
 }
 

log_middleware.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"regexp"
 	"runtime"
+	"runtime/debug"
 	"strings"
 	"time"
 
@@ -77,7 +78,7 @@ func (mw *LogMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 				AccessAborted(r, start)
 				return
 			}
-			AccessError(r, start, fmt.Errorf("PANIC (%v): %v", identifyLogOrigin(), rec))
+			AccessError(r, start, fmt.Errorf("PANIC (%v): %v", identifyLogOrigin(), rec), debug.Stack())
 		}
 	}()
 

log_middleware_test.go

@@ -89,8 +89,9 @@ func Test_LogMiddleware_Panic(t *testing.T) {
 
 	assert.Contains(t, data.Error, "Test_LogMiddleware_Panic.func1")
 	assert.Contains(t, data.Error, "some")
-	assert.Equal(t, data.Message, "ERROR ->GET /foo")
-	assert.Equal(t, data.Level, "error")
+	assert.Equal(t, "ERROR ->GET /foo", data.Message)
+	assert.Equal(t, "error", data.Level)
+	assert.NotZero(t, data.Stack)
 }
 
 func Test_LogMiddleware_Panic_ErrAbortHandler(t *testing.T) {
@@ -112,8 +113,8 @@ func Test_LogMiddleware_Panic_ErrAbortHandler(t *testing.T) {
 
 	data := logRecordFromBuffer(b)
 
-	assert.Equal(t, data.Message, "ABORTED ->GET /foo")
-	assert.Equal(t, data.Level, "info")
+	assert.Equal(t, "ABORTED ->GET /foo", data.Message)
+	assert.Equal(t, "info", data.Level)
 }
 
 func Test_LogMiddleware_Log_implicit200(t *testing.T) {
@@ -135,7 +136,7 @@ func Test_LogMiddleware_Log_implicit200(t *testing.T) {
 	data := logRecordFromBuffer(b)
 	a.Equal("", data.Error)
 	a.Equal("200 ->GET /foo", data.Message)
-	a.Equal(200, data.ResponseStatus)
+	a.Equal(http.StatusOK, data.ResponseStatus)
 	a.Equal("info", data.Level)
 }
 
@@ -225,7 +226,7 @@ func Test_LogMiddleware_Log_404(t *testing.T) {
 	data := logRecordFromBuffer(b)
 	a.Equal("", data.Error)
 	a.Equal("404 ->GET /foo", data.Message)
-	a.Equal(404, data.ResponseStatus)
+	a.Equal(http.StatusNotFound, data.ResponseStatus)
 	a.Equal("warning", data.Level)
 }
 

logger_test.go

@@ -32,6 +32,7 @@ type logRecord struct {
 	UserAgent      string            `json:"User_Agent"`
 	SpanID         string            `json:"span"`
 	TraceID        string            `json:"trace"`
+	Stack          string            `json:"stack"`
 }
 
 func Test_Logger_Set(t *testing.T) {
@@ -215,12 +216,13 @@ func Test_Logger_Access_ErrorCases(t *testing.T) {
 
 	// when an error is logged
 	b.Reset()
-	AccessError(r, time.Now(), errors.New("oops"))
+	AccessError(r, time.Now(), errors.New("oops"), []byte("__stacktrace__"))
 	// then: all fields match
 	data = logRecordFromBuffer(b)
 	a.Equal("error", data.Level)
 	a.Equal("oops", data.Error)
 	a.Equal("ERROR ->GET /foo", data.Message)
+	a.Equal("__stacktrace__", data.Stack)
 }
 
 func Test_Logger_LifecycleStart(t *testing.T) {