diff --git a/README.md b/README.md index cd27cf4..c263f6e 100644 --- a/README.md +++ b/README.md @@ -92,6 +92,8 @@ Logs request, request handling time and response. Log record fields in order of _remote IP can be masked with user defined function_ +_request body can be transformed before logging with a user-defined function (`BodyFn`), e.g. to mask credentials. It only runs when body logging is on (`WithBody`), and receives the body along with a `truncated` flag that is set when the body exceeded `MaxBodySize` - the function can use it to emit a marker instead of logging a partial body it can't safely process_ + example: `019/03/05 17:26:12.976 [INFO] GET - /api/v1/find?site=remark - 8e228e9cfece - 200 (115) - 4.47784618s` ### Recoverer middleware diff --git a/logger/logger.go b/logger/logger.go index e2eaa3c..d79e88a 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -26,6 +26,7 @@ type Middleware struct { ipFn func(ip string) string userFn func(r *http.Request) (string, error) subjFn func(r *http.Request) (string, error) + bodyFn func(body string, truncated bool) string log Backend apacheCombined bool } @@ -131,7 +132,7 @@ func (l *Middleware) Handler(next http.Handler) http.Handler { body: body, } - l.log.Logf(formater(r, p)) + l.log.Logf("%s", formater(r, p)) }() next.ServeHTTP(ww, r) @@ -191,7 +192,7 @@ func (l *Middleware) formatApacheCombined(r *http.Request, p *logParts) string { bld.WriteString(p.method) bld.WriteString(" ") bld.WriteString(p.rawURL) - bld.WriteString(`" `) + bld.WriteString(" ") bld.WriteString(r.Proto) bld.WriteString(`" `) bld.WriteString(strconv.Itoa(p.statusCode)) @@ -208,6 +209,19 @@ func (l *Middleware) formatApacheCombined(r *http.Request, p *logParts) string { var reMultWhtsp = regexp.MustCompile(`[\s\p{Zs}]{2,}`) +// lineBreaks maps every character that can start a new line to a space, so a body +// can't forge extra log records. reMultWhtsp only collapses runs of two or more, so +// a lone CR or a Unicode line separator would otherwise slip through. +var lineBreaks = strings.NewReplacer( + "\n", " ", // LF + "\r", " ", // CR + "\v", " ", // vertical tab + "\f", " ", // form feed + "\u0085", " ", // NEL + "\u2028", " ", // line separator + "\u2029", " ", // paragraph separator +) + func (l *Middleware) getBody(r *http.Request) string { if !l.logBody { return "" @@ -226,13 +240,24 @@ func (l *Middleware) getBody(r *http.Request) string { // https://golang.org/pkg/net/http/#Handler r.Body = io.NopCloser(reader) - if body != "" { - body = strings.ReplaceAll(body, "\n", " ") - body = reMultWhtsp.ReplaceAllString(body, " ") + // the transform owns the logged body: it receives the body (capped at + // maxBodySize) and a flag telling it whether more was dropped, and decides + // how to render it - mask values, summarize, or emit a marker for a + // truncated body. an empty body has nothing to transform, so it is left + // alone. without a transform the body is logged as read, with the "..." + // marker appended when it was truncated. + switch { + case l.bodyFn != nil && body != "": + body = l.bodyFn(body, hasMore) + case hasMore: + body += "..." } - if hasMore { - body += "..." + // always collapse to a single line, regardless of the transform, so an + // embedded line break in the body can't forge additional log lines. + if body != "" { + body = lineBreaks.Replace(body) + body = reMultWhtsp.ReplaceAllString(body, " ") } return body diff --git a/logger/logger_test.go b/logger/logger_test.go index f3c2a95..5796f4c 100644 --- a/logger/logger_test.go +++ b/logger/logger_test.go @@ -298,6 +298,140 @@ func TestGetBody(t *testing.T) { l = New(WithBody) body = l.getBody(req) assert.Equal(t, "body", body) + + // nil transform reproduces the default path, including the truncation marker + reqTrunc, err := http.NewRequest("POST", "http://example.com/", strings.NewReader("0123456789abc")) + require.NoError(t, err) + l = New(WithBody, MaxBodySize(5), BodyFn(nil)) + assert.Equal(t, "01234...", l.getBody(reqTrunc)) + + // a lone carriage return in the raw body is collapsed to a space (single-line guarantee) + reqCR, err := http.NewRequest("POST", "http://example.com/", strings.NewReader("a\rb")) + require.NoError(t, err) + l = New(WithBody) + assert.Equal(t, "a b", l.getBody(reqCR)) +} + +func TestGetBodyBodyFn(t *testing.T) { + // arbitrary (non-json) transform: upper-cases a whole body, or wraps a + // truncated one with its flag - exercises both the transform and the flag + fn := func(body string, truncated bool) string { + if truncated { + return "" + } + return strings.ToUpper(body) + } + + tests := []struct { + name string + body string + maxBodySize int + want string + }{ + {"transforms body", "hello world", 1024, "HELLO WORLD"}, + {"plain text, not json", "just text, no braces", 1024, "JUST TEXT, NO BRACES"}, + {"empty body", "", 1024, ""}, + {"collapses transform newlines", "a\nb", 1024, "A B"}, + {"collapses lone carriage return", "a\rb", 1024, "A B"}, + {"collapses unicode line separator", "a\u2028b", 1024, "A B"}, + {"truncated flag set", "0123456789abc", 5, ""}, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + req, err := http.NewRequest("POST", "http://example.com/", strings.NewReader(tt.body)) + require.NoError(t, err) + l := New(WithBody, MaxBodySize(tt.maxBodySize), BodyFn(fn)) + assert.Equal(t, tt.want, l.getBody(req)) + }) + } +} + +func TestGetBodyBodyFnNoWithBody(t *testing.T) { + called := false + fn := func(string, bool) string { + called = true + return "should not appear" + } + req, err := http.NewRequest("POST", "http://example.com/", strings.NewReader("hello")) + require.NoError(t, err) + + l := New(BodyFn(fn)) // no WithBody, body logging disabled + assert.Equal(t, "", l.getBody(req)) + assert.False(t, called, "bodyFn must not run when body logging is disabled") +} + +func TestGetBodyBodyFnSkipsEmpty(t *testing.T) { + called := false + fn := func(string, bool) string { + called = true + return "should not appear" // non-empty even for empty input + } + req, err := http.NewRequest("GET", "http://example.com/", http.NoBody) + require.NoError(t, err) + + l := New(WithBody, BodyFn(fn)) + assert.Equal(t, "", l.getBody(req)) + assert.False(t, called, "bodyFn must not run on an empty body") +} + +func TestLoggerBodyFn(t *testing.T) { + handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + body, err := io.ReadAll(r.Body) + require.NoError(t, err) + // downstream handler still receives the original, unmasked body + assert.Equal(t, `{"user":"alice","password":"secret"}`, string(body)) + _, err = w.Write([]byte("ok")) + require.NoError(t, err) + }) + + // plain-string masker, deliberately not json-aware, to show the transform + // need not parse the body + masker := func(body string, truncated bool) string { + if truncated { + return "[body too large]" + } + return strings.ReplaceAll(body, "secret", "****") + } + + lb := &mockLgr{} + l := New(Prefix("[INFO] REST"), WithBody, Log(lb), BodyFn(masker)) + ts := httptest.NewServer(l.Handler(handler)) + defer ts.Close() + + resp, err := http.Post(ts.URL+"/login", "application/json", + bytes.NewBufferString(`{"user":"alice","password":"secret"}`)) + require.NoError(t, err) + defer resp.Body.Close() // nolint + assert.Equal(t, 200, resp.StatusCode) + + s := lb.buf.String() + t.Log(s) + assert.Contains(t, s, `{"user":"alice","password":"****"}`) + assert.NotContains(t, s, "secret") +} + +func TestLoggerBodyWithPercent(t *testing.T) { + handler := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + _, err := w.Write([]byte("ok")) + require.NoError(t, err) + }) + + lb := &mockLgr{} + l := New(Prefix("[INFO] REST"), WithBody, Log(lb)) + ts := httptest.NewServer(l.Handler(handler)) + defer ts.Close() + + // a body with a percent verb must be logged verbatim, not treated as a format directive + resp, err := http.Post(ts.URL+"/blah", "", bytes.NewBufferString("a%sb 100%done")) + require.NoError(t, err) + defer resp.Body.Close() // nolint + assert.Equal(t, 200, resp.StatusCode) + + s := lb.buf.String() + t.Log(s) + assert.Contains(t, s, "a%sb 100%done") + assert.NotContains(t, s, "MISSING") } func TestPeek(t *testing.T) { @@ -404,7 +538,7 @@ func TestLoggerApacheCombined(t *testing.T) { s := lb.buf.String() t.Log(s) assert.True(t, strings.HasPrefix(s, "127.0.0.1!masked - user [")) - assert.True(t, strings.HasSuffix(s, ` "POST /blah?key=val&password=********&var=123" HTTP/1.1" 200 9 "" "Go-http-client/1.1"`), s) + assert.True(t, strings.HasSuffix(s, ` "POST /blah?key=val&password=********&var=123 HTTP/1.1" 200 9 "" "Go-http-client/1.1"`), s) } func TestAnonymizeIP(t *testing.T) { diff --git a/logger/options.go b/logger/options.go index b0e4199..8156e0d 100644 --- a/logger/options.go +++ b/logger/options.go @@ -49,6 +49,20 @@ func SubjFn(subjFn func(r *http.Request) (string, error)) Option { } } +// BodyFn sets a transform applied to the request body before it is logged, e.g. to +// mask secrets. It only runs when body logging is enabled (see WithBody) and the +// body is non-empty; if bodyFn is nil the body is logged unchanged. bodyFn receives +// the body (capped at MaxBodySize) and a truncated flag that is true when the body was longer than +// MaxBodySize and got cut short - a masker can use it to emit a marker instead of +// risking a pass-through of a partial body it cannot parse. The returned string is +// what gets logged, so bodyFn owns the content; the logger still collapses it to a +// single line to keep one log record per request. +func BodyFn(bodyFn func(body string, truncated bool) string) Option { + return func(l *Middleware) { + l.bodyFn = bodyFn + } +} + // ApacheCombined sets format to Apache Combined Log. // See http://httpd.apache.org/docs/2.2/logs.html#combined func ApacheCombined(l *Middleware) {