Refactor response writer & access logger (#33323)

And add comments & tests

Author: wxiaoguang

routers/common/middleware.go

@@ -43,14 +43,18 @@ func ProtocolMiddlewares() (handlers []any) {
 
 func RequestContextHandler() func(h http.Handler) http.Handler {
 	return func(next http.Handler) http.Handler {
-		return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) {
-			profDesc := fmt.Sprintf("%s: %s", req.Method, req.RequestURI)
+		return http.HandlerFunc(func(respOrig http.ResponseWriter, req *http.Request) {
+			// this response writer might not be the same as the one in context.Base.Resp
+			// because there might be a "gzip writer" in the middle, so the "written size" here is the compressed size
+			respWriter := context.WrapResponseWriter(respOrig)
+
+			profDesc := fmt.Sprintf("HTTP: %s %s", req.Method, req.RequestURI)
 			ctx, finished := reqctx.NewRequestContext(req.Context(), profDesc)
 			defer finished()
 
 			defer func() {
 				if err := recover(); err != nil {
-					RenderPanicErrorPage(resp, req, err) // it should never panic
+					RenderPanicErrorPage(respWriter, req, err) // it should never panic
 				}
 			}()
 
@@ -62,7 +66,7 @@ func RequestContextHandler() func(h http.Handler) http.Handler {
 					_ = req.MultipartForm.RemoveAll() // remove the temp files buffered to tmp directory
 				}
 			})
-			next.ServeHTTP(context.WrapResponseWriter(resp), req)
+			next.ServeHTTP(respWriter, req)
 		})
 	}
 }

services/context/access_log.go

@@ -18,13 +18,14 @@ import (
 	"code.gitea.io/gitea/modules/web/middleware"
 )
 
-type routerLoggerOptions struct {
-	req            *http.Request
+type accessLoggerTmplData struct {
 	Identity       *string
 	Start          *time.Time
-	ResponseWriter http.ResponseWriter
-	Ctx            map[string]any
-	RequestID      *string
+	ResponseWriter struct {
+		Status, Size int
+	}
+	Ctx       map[string]any
+	RequestID *string
 }
 
 const keyOfRequestIDInTemplate = ".RequestID"
@@ -51,51 +52,65 @@ func parseRequestIDFromRequestHeader(req *http.Request) string {
 	return requestID
 }
 
+type accessLogRecorder struct {
+	logger        log.BaseLogger
+	logTemplate   *template.Template
+	needRequestID bool
+}
+
+func (lr *accessLogRecorder) record(start time.Time, respWriter ResponseWriter, req *http.Request) {
+	var requestID string
+	if lr.needRequestID {
+		requestID = parseRequestIDFromRequestHeader(req)
+	}
+
+	reqHost, _, err := net.SplitHostPort(req.RemoteAddr)
+	if err != nil {
+		reqHost = req.RemoteAddr
+	}
+
+	identity := "-"
+	data := middleware.GetContextData(req.Context())
+	if signedUser, ok := data[middleware.ContextDataKeySignedUser].(*user_model.User); ok {
+		identity = signedUser.Name
+	}
+	buf := bytes.NewBuffer([]byte{})
+	tmplData := accessLoggerTmplData{
+		Identity: &identity,
+		Start:    &start,
+		Ctx: map[string]any{
+			"RemoteAddr": req.RemoteAddr,
+			"RemoteHost": reqHost,
+			"Req":        req,
+		},
+		RequestID: &requestID,
+	}
+	tmplData.ResponseWriter.Status = respWriter.Status()
+	tmplData.ResponseWriter.Size = respWriter.WrittenSize()
+	err = lr.logTemplate.Execute(buf, tmplData)
+	if err != nil {
+		log.Error("Could not execute access logger template: %v", err.Error())
+	}
+
+	lr.logger.Log(1, log.INFO, "%s", buf.String())
+}
+
+func newAccessLogRecorder() *accessLogRecorder {
+	return &accessLogRecorder{
+		logger:        log.GetLogger("access"),
+		logTemplate:   template.Must(template.New("log").Parse(setting.Log.AccessLogTemplate)),
+		needRequestID: len(setting.Log.RequestIDHeaders) > 0 && strings.Contains(setting.Log.AccessLogTemplate, keyOfRequestIDInTemplate),
+	}
+}
+
 // AccessLogger returns a middleware to log access logger
 func AccessLogger() func(http.Handler) http.Handler {
-	logger := log.GetLogger("access")
-	needRequestID := len(setting.Log.RequestIDHeaders) > 0 && strings.Contains(setting.Log.AccessLogTemplate, keyOfRequestIDInTemplate)
-	logTemplate, _ := template.New("log").Parse(setting.Log.AccessLogTemplate)
+	recorder := newAccessLogRecorder()
 	return func(next http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 			start := time.Now()
-
-			var requestID string
-			if needRequestID {
-				requestID = parseRequestIDFromRequestHeader(req)
-			}
-
-			reqHost, _, err := net.SplitHostPort(req.RemoteAddr)
-			if err != nil {
-				reqHost = req.RemoteAddr
-			}
-
 			next.ServeHTTP(w, req)
-			rw := w.(ResponseWriter)
-
-			identity := "-"
-			data := middleware.GetContextData(req.Context())
-			if signedUser, ok := data[middleware.ContextDataKeySignedUser].(*user_model.User); ok {
-				identity = signedUser.Name
-			}
-			buf := bytes.NewBuffer([]byte{})
-			err = logTemplate.Execute(buf, routerLoggerOptions{
-				req:            req,
-				Identity:       &identity,
-				Start:          &start,
-				ResponseWriter: rw,
-				Ctx: map[string]any{
-					"RemoteAddr": req.RemoteAddr,
-					"RemoteHost": reqHost,
-					"Req":        req,
-				},
-				RequestID: &requestID,
-			})
-			if err != nil {
-				log.Error("Could not execute access logger template: %v", err.Error())
-			}
-
-			logger.Info("%s", buf.String())
+			recorder.record(start, w.(ResponseWriter), req)
 		})
 	}
 }

services/context/access_log_test.go

@@ -0,0 +1,75 @@
+// Copyright 2025 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package context
+
+import (
+	"fmt"
+	"net/http"
+	"net/url"
+	"testing"
+	"time"
+
+	"code.gitea.io/gitea/modules/log"
+	"code.gitea.io/gitea/modules/setting"
+
+	"github.com/stretchr/testify/assert"
+)
+
+type testAccessLoggerMock struct {
+	logs []string
+}
+
+func (t *testAccessLoggerMock) Log(skip int, level log.Level, format string, v ...any) {
+	t.logs = append(t.logs, fmt.Sprintf(format, v...))
+}
+
+func (t *testAccessLoggerMock) GetLevel() log.Level {
+	return log.INFO
+}
+
+type testAccessLoggerResponseWriterMock struct{}
+
+func (t testAccessLoggerResponseWriterMock) Header() http.Header {
+	return nil
+}
+
+func (t testAccessLoggerResponseWriterMock) Before(f func(ResponseWriter)) {}
+
+func (t testAccessLoggerResponseWriterMock) WriteHeader(statusCode int) {}
+
+func (t testAccessLoggerResponseWriterMock) Write(bytes []byte) (int, error) {
+	return 0, nil
+}
+
+func (t testAccessLoggerResponseWriterMock) Flush() {}
+
+func (t testAccessLoggerResponseWriterMock) WrittenStatus() int {
+	return http.StatusOK
+}
+
+func (t testAccessLoggerResponseWriterMock) Status() int {
+	return t.WrittenStatus()
+}
+
+func (t testAccessLoggerResponseWriterMock) WrittenSize() int {
+	return 123123
+}
+
+func TestAccessLogger(t *testing.T) {
+	setting.Log.AccessLogTemplate = `{{.Ctx.RemoteHost}} - {{.Identity}} {{.Start.Format "[02/Jan/2006:15:04:05 -0700]" }} "{{.Ctx.Req.Method}} {{.Ctx.Req.URL.RequestURI}} {{.Ctx.Req.Proto}}" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} "{{.Ctx.Req.Referer}}" "{{.Ctx.Req.UserAgent}}"`
+	recorder := newAccessLogRecorder()
+	mockLogger := &testAccessLoggerMock{}
+	recorder.logger = mockLogger
+	req := &http.Request{
+		RemoteAddr: "remote-addr",
+		Method:     "GET",
+		Proto:      "https",
+		URL:        &url.URL{Path: "/path"},
+	}
+	req.Header = http.Header{}
+	req.Header.Add("Referer", "referer")
+	req.Header.Add("User-Agent", "user-agent")
+	recorder.record(time.Date(2000, 1, 2, 3, 4, 5, 0, time.UTC), &testAccessLoggerResponseWriterMock{}, req)
+	assert.Equal(t, []string{`remote-addr - - [02/Jan/2000:03:04:05 +0000] "GET /path https" 200 123123 "referer" "user-agent"`}, mockLogger.logs)
+}

services/context/response.go

@@ -15,27 +15,26 @@ type ResponseWriter interface {
 	http.Flusher
 	web_types.ResponseStatusProvider
 
-	Before(func(ResponseWriter))
-
-	Status() int // used by access logger template
-	Size() int   // used by access logger template
+	Before(fn func(ResponseWriter))
+	Status() int
+	WrittenSize() int
 }
 
-var _ ResponseWriter = &Response{}
+var _ ResponseWriter = (*Response)(nil)
 
 // Response represents a response
 type Response struct {
 	http.ResponseWriter
 	written        int
 	status         int
-	befores        []func(ResponseWriter)
+	beforeFuncs    []func(ResponseWriter)
 	beforeExecuted bool
 }
 
 // Write writes bytes to HTTP endpoint
 func (r *Response) Write(bs []byte) (int, error) {
 	if !r.beforeExecuted {
-		for _, before := range r.befores {
+		for _, before := range r.beforeFuncs {
 			before(r)
 		}
 		r.beforeExecuted = true
@@ -51,18 +50,14 @@ func (r *Response) Write(bs []byte) (int, error) {
 	return size, nil
 }
 
-func (r *Response) Status() int {
-	return r.status
-}
-
-func (r *Response) Size() int {
+func (r *Response) WrittenSize() int {
 	return r.written
 }
 
 // WriteHeader write status code
 func (r *Response) WriteHeader(statusCode int) {
 	if !r.beforeExecuted {
-		for _, before := range r.befores {
+		for _, before := range r.beforeFuncs {
 			before(r)
 		}
 		r.beforeExecuted = true
@@ -80,24 +75,26 @@ func (r *Response) Flush() {
 	}
 }
 
+// Status returns status code written
+// TODO: use WrittenStatus instead
+func (r *Response) Status() int {
+	return r.status
+}
+
 // WrittenStatus returned status code written
 func (r *Response) WrittenStatus() int {
 	return r.status
 }
 
 // Before allows for a function to be called before the ResponseWriter has been written to. This is
 // useful for setting headers or any other operations that must happen before a response has been written.
-func (r *Response) Before(f func(ResponseWriter)) {
-	r.befores = append(r.befores, f)
+func (r *Response) Before(fn func(ResponseWriter)) {
+	r.beforeFuncs = append(r.beforeFuncs, fn)
 }
 
 func WrapResponseWriter(resp http.ResponseWriter) *Response {
 	if v, ok := resp.(*Response); ok {
 		return v
 	}
-	return &Response{
-		ResponseWriter: resp,
-		status:         0,
-		befores:        make([]func(ResponseWriter), 0),
-	}
+	return &Response{ResponseWriter: resp}
 }