diff --git a/http_logging.go b/http_logging.go index beef0e1..1a234a2 100644 --- a/http_logging.go +++ b/http_logging.go @@ -135,6 +135,23 @@ func (rr *ResponseRecorder) WriteHeader(code int) { //nolint:revive // name is fine. func LogAndCall(msg string, hf http.HandlerFunc, extraAttributes ...KeyVal) http.HandlerFunc { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if Config.CombineRequestAndResponse { + rr := &ResponseRecorder{w: w, startTime: time.Now()} + defer func() { + if err := recover(); err != nil { + S(Critical, "panic in handler", Any("error", err)) + } + attr := []KeyVal{ + Int("status", rr.StatusCode), + Int64("size", rr.ContentLength), + Int64("microsec", time.Since(rr.startTime).Microseconds()), + } + attr = append(attr, extraAttributes...) + LogRequest(r, msg, attr...) + }() + hf(rr, r) + return + } LogRequest(r, msg, extraAttributes...) rr := &ResponseRecorder{w: w, startTime: time.Now()} hf(rr, r) diff --git a/http_logging_test.go b/http_logging_test.go index 866cad2..15454f2 100644 --- a/http_logging_test.go +++ b/http_logging_test.go @@ -46,17 +46,23 @@ func testHandler(w http.ResponseWriter, r *http.Request) { if r.URL != nil && r.URL.Path == "/tea" { w.WriteHeader(http.StatusTeapot) } - time.Sleep(100 * time.Millisecond) w.Write([]byte("hello")) + time.Sleep(100 * time.Millisecond) } -type NullHTTPWriter struct{ doErr bool } +type NullHTTPWriter struct { + doErr bool + doPanic bool +} func (n *NullHTTPWriter) Header() http.Header { return nil } func (n *NullHTTPWriter) Write(b []byte) (int, error) { + if n.doPanic { + panic("some fake http write panic") + } if n.doErr { return 0, fmt.Errorf("some fake http write error") } @@ -89,21 +95,38 @@ func TestLogAndCall(t *testing.T) { } hr.URL = &url.URL{Path: "/tea"} b.Reset() + Config.CombineRequestAndResponse = true // single line test LogAndCall("test-log-and-call2", testHandler).ServeHTTP(hw, hr) w.Flush() actual = b.String() - if !strings.Contains(actual, ":418,") { - t.Errorf("unexpected:\n%s\nvs should contain tea pot code.", actual) + //nolint: lll + expectedPrefix = `{"level":"info","msg":"test-log-and-call2","method":"","url":{"Scheme":"","Opaque":"","User":null,"Host":"","Path":"/tea","RawPath":"","OmitHost":false,"ForceQuery":false,"RawQuery":"","Fragment":"","RawFragment":""},"proto":"","remote_addr":"","host":"","header.x-forwarded-proto":"","header.x-forwarded-for":"","user-agent":"","status":418,"size":5,"microsec":1` + if !strings.HasPrefix(actual, expectedPrefix) { + t.Errorf("unexpected:\n%s\nvs should start with:\n%s\n", actual, expectedPrefix) } b.Reset() n.doErr = true LogAndCall("test-log-and-call3", testHandler).ServeHTTP(hw, hr) w.Flush() actual = b.String() - expectedFragment := `"test-log-and-call3","status":500,"size":0,"microsec":` + expectedFragment := `"user-agent":"","status":500,"size":0,"microsec":1` if !strings.Contains(actual, expectedFragment) { t.Errorf("unexpected:\n%s\nvs should contain error:\n%s\n", actual, expectedFragment) } + n.doPanic = true + n.doErr = false + b.Reset() + LogAndCall("test-log-and-call4", testHandler).ServeHTTP(hw, hr) + w.Flush() + actual = b.String() + expectedFragment = `,"size":0,` + 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") + } } func TestLogResponseOnHTTPResponse(t *testing.T) {