From cb9f66cbb1e34c6966d8f1f3160d5057c36c33c2 Mon Sep 17 00:00:00 2001 From: Umputun Date: Thu, 16 Jul 2026 16:01:27 -0500 Subject: [PATCH 1/3] feat: add BodyFn option to logger for request body transform Add logger.BodyFn(func(body string, truncated bool) string) Option, a transform applied to the request body before logging, e.g. to mask credentials. It runs only when body logging is enabled (WithBody); the transform receives the body capped at MaxBodySize plus a truncated flag and fully owns the logged output, so it can emit a marker for a partial body it can't safely process. The logger still collapses the result to a single line to prevent log injection, and the read stays bounded by MaxBodySize. --- README.md | 2 ++ logger/logger.go | 19 +++++++--- logger/logger_test.go | 83 +++++++++++++++++++++++++++++++++++++++++++ logger/options.go | 14 ++++++++ 4 files changed, 114 insertions(+), 4 deletions(-) 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..e17e259 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 } @@ -226,15 +227,25 @@ func (l *Middleware) getBody(r *http.Request) string { // https://golang.org/pkg/net/http/#Handler r.Body = io.NopCloser(reader) + // 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. without a transform the body is logged as read, with the + // "..." marker appended when it was truncated. + switch { + case l.bodyFn != nil: + body = l.bodyFn(body, hasMore) + case hasMore: + body += "..." + } + + // always collapse to a single line, regardless of the transform, so an + // embedded newline in the body can't forge additional log lines. if body != "" { body = strings.ReplaceAll(body, "\n", " ") body = reMultWhtsp.ReplaceAllString(body, " ") } - if hasMore { - body += "..." - } - return body } diff --git a/logger/logger_test.go b/logger/logger_test.go index f3c2a95..f55eb39 100644 --- a/logger/logger_test.go +++ b/logger/logger_test.go @@ -300,6 +300,89 @@ func TestGetBody(t *testing.T) { assert.Equal(t, "body", body) } +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"}, + {"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 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 TestPeek(t *testing.T) { cases := []struct { body string diff --git a/logger/options.go b/logger/options.go index b0e4199..69eed07 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); 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) { From 30487d06bec3e757553bec42e0f20f53d60a79ba Mon Sep 17 00:00:00 2001 From: Umputun Date: Thu, 16 Jul 2026 16:23:18 -0500 Subject: [PATCH 2/3] fix: make logger robust to crafted request-body content Two log-output defects on the body-logging path, surfaced while reviewing the BodyFn change but predating it: - the single-line collapse only neutralized LF; a lone CR (and VT, FF, NEL, U+2028, U+2029) survived, so a crafted body could forge extra log records. Collapse every line-break character before the whitespace-run pass. - the rendered line was passed to Logf as the format string, so a '%' in a body or URL was interpreted as a format verb (e.g. %!s(MISSING)). Pass it as an argument instead. Also add the missing nil-BodyFn default-path test plus CR/Unicode-separator and percent-in-body regression tests. --- logger/logger.go | 19 ++++++++++++++++--- logger/logger_test.go | 37 +++++++++++++++++++++++++++++++++++++ 2 files changed, 53 insertions(+), 3 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index e17e259..b120780 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -132,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) @@ -209,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 "" @@ -240,9 +253,9 @@ func (l *Middleware) getBody(r *http.Request) string { } // always collapse to a single line, regardless of the transform, so an - // embedded newline in the body can't forge additional log lines. + // embedded line break in the body can't forge additional log lines. if body != "" { - body = strings.ReplaceAll(body, "\n", " ") + body = lineBreaks.Replace(body) body = reMultWhtsp.ReplaceAllString(body, " ") } diff --git a/logger/logger_test.go b/logger/logger_test.go index f55eb39..5795004 100644 --- a/logger/logger_test.go +++ b/logger/logger_test.go @@ -298,6 +298,18 @@ 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) { @@ -320,6 +332,8 @@ func TestGetBodyBodyFn(t *testing.T) { {"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, ""}, } @@ -383,6 +397,29 @@ func TestLoggerBodyFn(t *testing.T) { 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) { cases := []struct { body string From d15cf8e37900bd3c9a3fc4abb356fd6e07606c22 Mon Sep 17 00:00:00 2001 From: Umputun Date: Thu, 16 Jul 2026 16:32:45 -0500 Subject: [PATCH 3/3] fix: skip empty-body transform and correct Apache Combined log format Two review follow-ups on the logger: - getBody no longer calls bodyFn for an empty request body - there is nothing to transform, and a transform returning a marker for empty input would otherwise log content for bodyless requests. - formatApacheCombined closed the request quote after the URL, emitting "METHOD URL" PROTO" instead of the correct "METHOD URL PROTO". Move the space so the protocol stays inside the quoted request field, and fix the test that had asserted the malformed line. --- logger/logger.go | 9 +++++---- logger/logger_test.go | 16 +++++++++++++++- logger/options.go | 6 +++--- 3 files changed, 23 insertions(+), 8 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index b120780..d79e88a 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -192,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)) @@ -243,10 +243,11 @@ func (l *Middleware) getBody(r *http.Request) string { // 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. without a transform the body is logged as read, with the - // "..." marker appended when it was truncated. + // 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: + case l.bodyFn != nil && body != "": body = l.bodyFn(body, hasMore) case hasMore: body += "..." diff --git a/logger/logger_test.go b/logger/logger_test.go index 5795004..5796f4c 100644 --- a/logger/logger_test.go +++ b/logger/logger_test.go @@ -361,6 +361,20 @@ func TestGetBodyBodyFnNoWithBody(t *testing.T) { 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) @@ -524,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 69eed07..8156e0d 100644 --- a/logger/options.go +++ b/logger/options.go @@ -50,9 +50,9 @@ 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); 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 +// 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