Fix access log (#14475)

Fix #14121, #14478.

The `AccessLog` middleware has to be after `Contexter` or `APIContexter` so that we can get `LoginUserName` if possible.
And also there is a **BREAK** change that it removed internal API access log.

Author: lunny

modules/auth/sso/oauth2.go

@@ -12,6 +12,7 @@ import (
 
 	"code.gitea.io/gitea/models"
 	"code.gitea.io/gitea/modules/log"
+	"code.gitea.io/gitea/modules/middlewares"
 	"code.gitea.io/gitea/modules/timeutil"
 )
 
@@ -121,7 +122,7 @@ func (o *OAuth2) VerifyAuthData(req *http.Request, w http.ResponseWriter, store
 		return nil
 	}
 
-	if isInternalPath(req) || !isAPIPath(req) && !isAttachmentDownload(req) {
+	if middlewares.IsInternalPath(req) || !middlewares.IsAPIPath(req) && !isAttachmentDownload(req) {
 		return nil
 	}
 

modules/auth/sso/sso.go

@@ -94,16 +94,6 @@ func SessionUser(sess SessionStore) *models.User {
 	return user
 }
 
-// isAPIPath returns true if the specified URL is an API path
-func isAPIPath(req *http.Request) bool {
-	return strings.HasPrefix(req.URL.Path, "/api/")
-}
-
-// isInternalPath returns true if the specified URL is an internal API path
-func isInternalPath(req *http.Request) bool {
-	return strings.HasPrefix(req.URL.Path, "/api/internal/")
-}
-
 // isAttachmentDownload check if request is a file download (GET) with URL to an attachment
 func isAttachmentDownload(req *http.Request) bool {
 	return strings.HasPrefix(req.URL.Path, "/attachments/") && req.Method == "GET"

modules/auth/sso/sspi_windows.go

@@ -12,6 +12,7 @@ import (
 	"code.gitea.io/gitea/models"
 	"code.gitea.io/gitea/modules/base"
 	"code.gitea.io/gitea/modules/log"
+	"code.gitea.io/gitea/modules/middlewares"
 	"code.gitea.io/gitea/modules/setting"
 	"code.gitea.io/gitea/modules/templates"
 
@@ -135,7 +136,7 @@ func (s *SSPI) VerifyAuthData(req *http.Request, w http.ResponseWriter, store Da
 	}
 
 	// Make sure requests to API paths and PWA resources do not create a new session
-	if !isAPIPath(req) && !isAttachmentDownload(req) {
+	if !middlewares.IsAPIPath(req) && !isAttachmentDownload(req) {
 		handleSignIn(w, req, sess, user)
 	}
 
@@ -166,9 +167,9 @@ func (s *SSPI) shouldAuthenticate(req *http.Request) (shouldAuth bool) {
 		} else if req.FormValue("auth_with_sspi") == "1" {
 			shouldAuth = true
 		}
-	} else if isInternalPath(req) {
+	} else if middlewares.IsInternalPath(req) {
 		shouldAuth = false
-	} else if isAPIPath(req) || isAttachmentDownload(req) {
+	} else if middlewares.IsAPIPath(req) || isAttachmentDownload(req) {
 		shouldAuth = true
 	}
 	return

modules/context/access_log.go

@@ -0,0 +1,60 @@
+// Copyright 2020 The Gitea Authors. All rights reserved.
+// Use of this source code is governed by a MIT-style
+// license that can be found in the LICENSE file.
+
+package context
+
+import (
+	"bytes"
+	"html/template"
+	"net/http"
+	"time"
+
+	"code.gitea.io/gitea/modules/log"
+	"code.gitea.io/gitea/modules/setting"
+)
+
+type routerLoggerOptions struct {
+	req            *http.Request
+	Identity       *string
+	Start          *time.Time
+	ResponseWriter http.ResponseWriter
+	Ctx            map[string]interface{}
+}
+
+// AccessLogger returns a middleware to log access logger
+func AccessLogger() func(http.Handler) http.Handler {
+	logger := log.GetLogger("access")
+	logTemplate, _ := template.New("log").Parse(setting.AccessLogTemplate)
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+			start := time.Now()
+			next.ServeHTTP(w, req)
+			identity := "-"
+			if val := SignedUserName(req); val != "" {
+				identity = val
+			}
+			rw := w.(ResponseWriter)
+
+			buf := bytes.NewBuffer([]byte{})
+			err := logTemplate.Execute(buf, routerLoggerOptions{
+				req:            req,
+				Identity:       &identity,
+				Start:          &start,
+				ResponseWriter: rw,
+				Ctx: map[string]interface{}{
+					"RemoteAddr": req.RemoteAddr,
+					"Req":        req,
+				},
+			})
+			if err != nil {
+				log.Error("Could not set up chi access logger: %v", err.Error())
+			}
+
+			err = logger.SendLog(log.INFO, "", "", 0, buf.String(), "")
+			if err != nil {
+				log.Error("Could not set up chi access logger: %v", err.Error())
+			}
+		})
+	}
+}

modules/context/context.go

@@ -485,6 +485,31 @@ func GetContext(req *http.Request) *Context {
 	return req.Context().Value(contextKey).(*Context)
 }
 
+// SignedUserName returns signed user's name via context
+func SignedUserName(req *http.Request) string {
+	if middlewares.IsInternalPath(req) {
+		return ""
+	}
+	if middlewares.IsAPIPath(req) {
+		ctx, ok := req.Context().Value(apiContextKey).(*APIContext)
+		if ok {
+			v := ctx.Data["SignedUserName"]
+			if res, ok := v.(string); ok {
+				return res
+			}
+		}
+	} else {
+		ctx, ok := req.Context().Value(contextKey).(*Context)
+		if ok {
+			v := ctx.Data["SignedUserName"]
+			if res, ok := v.(string); ok {
+				return res
+			}
+		}
+	}
+	return ""
+}
+
 func getCsrfOpts() CsrfOptions {
 	return CsrfOptions{
 		Secret:         setting.SecretKey,

modules/context/response.go

@@ -12,6 +12,7 @@ type ResponseWriter interface {
 	Flush()
 	Status() int
 	Before(func(ResponseWriter))
+	Size() int
 }
 
 var (
@@ -21,11 +22,17 @@ var (
 // Response represents a response
 type Response struct {
 	http.ResponseWriter
+	written        int
 	status         int
 	befores        []func(ResponseWriter)
 	beforeExecuted bool
 }
 
+// Size return written size
+func (r *Response) Size() int {
+	return r.written
+}
+
 // Write writes bytes to HTTP endpoint
 func (r *Response) Write(bs []byte) (int, error) {
 	if !r.beforeExecuted {
@@ -35,8 +42,9 @@ func (r *Response) Write(bs []byte) (int, error) {
 		r.beforeExecuted = true
 	}
 	size, err := r.ResponseWriter.Write(bs)
+	r.written += size
 	if err != nil {
-		return 0, err
+		return size, err
 	}
 	if r.status == 0 {
 		r.WriteHeader(200)

modules/middlewares/request.go

@@ -0,0 +1,20 @@
+// Copyright 2020 The Gitea Authors. All rights reserved.
+// Use of this source code is governed by a MIT-style
+// license that can be found in the LICENSE file.
+
+package middlewares
+
+import (
+	"net/http"
+	"strings"
+)
+
+// IsAPIPath returns true if the specified URL is an API path
+func IsAPIPath(req *http.Request) bool {
+	return strings.HasPrefix(req.URL.Path, "/api/")
+}
+
+// IsInternalPath returns true if the specified URL is an internal API path
+func IsInternalPath(req *http.Request) bool {
+	return strings.HasPrefix(req.URL.Path, "/api/internal/")
+}

routers/api/v1/api.go

@@ -553,6 +553,11 @@ func Routes() *web.Route {
 		}))
 	}
 	m.Use(context.APIContexter())
+
+	if setting.EnableAccessLog {
+		m.Use(context.AccessLogger())
+	}
+
 	m.Use(context.ToggleAPI(&context.ToggleOptions{
 		SignInRequired: setting.Service.RequireSignInView,
 	}))

routers/routes/base.go

@@ -5,15 +5,13 @@
 package routes
 
 import (
-	"bytes"
 	"errors"
 	"fmt"
 	"io"
 	"net/http"
 	"os"
 	"path"
 	"strings"
-	"text/template"
 	"time"
 
 	"code.gitea.io/gitea/modules/auth/sso"
@@ -28,57 +26,6 @@ import (
 	"gitea.com/go-chi/session"
 )
 
-type routerLoggerOptions struct {
-	req            *http.Request
-	Identity       *string
-	Start          *time.Time
-	ResponseWriter http.ResponseWriter
-}
-
-// SignedUserName returns signed user's name via context
-func SignedUserName(req *http.Request) string {
-	ctx := context.GetContext(req)
-	if ctx != nil {
-		v := ctx.Data["SignedUserName"]
-		if res, ok := v.(string); ok {
-			return res
-		}
-	}
-	return ""
-}
-
-func accessLogger() func(http.Handler) http.Handler {
-	logger := log.GetLogger("access")
-	logTemplate, _ := template.New("log").Parse(setting.AccessLogTemplate)
-	return func(next http.Handler) http.Handler {
-		return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
-			start := time.Now()
-			next.ServeHTTP(w, req)
-			identity := "-"
-			if val := SignedUserName(req); val != "" {
-				identity = val
-			}
-			rw := w
-
-			buf := bytes.NewBuffer([]byte{})
-			err := logTemplate.Execute(buf, routerLoggerOptions{
-				req:            req,
-				Identity:       &identity,
-				Start:          &start,
-				ResponseWriter: rw,
-			})
-			if err != nil {
-				log.Error("Could not set up chi access logger: %v", err.Error())
-			}
-
-			err = logger.SendLog(log.INFO, "", "", 0, buf.String(), "")
-			if err != nil {
-				log.Error("Could not set up chi access logger: %v", err.Error())
-			}
-		})
-	}
-}
-
 // LoggerHandler is a handler that will log the routing to the default gitea log
 func LoggerHandler(level log.Level) func(next http.Handler) http.Handler {
 	return func(next http.Handler) http.Handler {

routers/routes/web.go

@@ -88,10 +88,6 @@ func commonMiddlewares() []func(http.Handler) http.Handler {
 			next.ServeHTTP(resp, req)
 		})
 	})
-
-	if setting.EnableAccessLog {
-		handlers = append(handlers, accessLogger())
-	}
 	return handlers
 }
 
@@ -168,6 +164,10 @@ func WebRoutes() *web.Route {
 	r.Use(context.Contexter())
 	// Removed: SetAutoHead allow a get request redirect to head if get method is not exist
 
+	if setting.EnableAccessLog {
+		r.Use(context.AccessLogger())
+	}
+
 	r.Use(user.GetNotificationCount)
 	r.Use(repo.GetActiveStopwatch)
 	r.Use(func(ctx *context.Context) {