add BodyFn option to logger for request-body transforms

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

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

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 "<truncated:" + body + ">"
+		}
+		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, "<truncated:01234>"},
+	}
+
+	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) {

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) {