Move Logging to Middleware Package (#1070)

* Use a specialized ResponseWriter in middleware * Track User & Upstream in RequestScope * Wrap responses in our custom ResponseWriter * Add tests for logging middleware * Inject upstream metadata into request scope * Use custom ResponseWriter only in logging middleware * Assume RequestScope is never nil
2026-10-05 14:11:14 +02:00 · 2021-03-06 17:27:16 +00:00
parent 220b3708fc
commit 602dac7852
16 changed files with 337 additions and 266 deletions
@@ -4,6 +4,7 @@ import (
 	"net/http"
 	"testing"

+	middlewareapi "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/apis/middleware"
 	"github.com/oauth2-proxy/oauth2-proxy/v7/pkg/logger"
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
@@ -19,6 +20,17 @@ func TestMiddlewareSuite(t *testing.T) {

 func testHandler() http.Handler {
 	return http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
+		rw.WriteHeader(200)
+		rw.Write([]byte("test"))
+	})
+}
+
+func testUpstreamHandler(upstream string) http.Handler {
+	return http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
+		scope := middlewareapi.GetRequestScope(req)
+		scope.Upstream = upstream
+
+		rw.WriteHeader(200)
 		rw.Write([]byte("test"))
 	})
 }
@@ -0,0 +1,110 @@
+package middleware
+
+import (
+	"bufio"
+	"errors"
+	"net"
+	"net/http"
+	"time"
+
+	"github.com/justinas/alice"
+	middlewareapi "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/apis/middleware"
+	"github.com/oauth2-proxy/oauth2-proxy/v7/pkg/logger"
+)
+
+// NewRequestLogger returns middleware which logs requests
+// It uses a custom ResponseWriter to track status code & response size details
+func NewRequestLogger() alice.Constructor {
+	return requestLogger
+}
+
+func requestLogger(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
+		startTime := time.Now()
+		url := *req.URL
+
+		responseLogger := &loggingResponse{ResponseWriter: rw}
+		next.ServeHTTP(responseLogger, req)
+
+		scope := middlewareapi.GetRequestScope(req)
+		// If scope is nil, this will panic.
+		// A scope should always be injected before this handler is called.
+		logger.PrintReq(
+			getUser(scope),
+			scope.Upstream,
+			req,
+			url,
+			startTime,
+			responseLogger.Status(),
+			responseLogger.Size(),
+		)
+	})
+}
+
+func getUser(scope *middlewareapi.RequestScope) string {
+	session := scope.Session
+	if session != nil {
+		if session.Email != "" {
+			return session.Email
+		}
+		return session.User
+	}
+	return ""
+}
+
+// loggingResponse is a custom http.ResponseWriter that allows tracking certain
+// details for request logging.
+type loggingResponse struct {
+	http.ResponseWriter
+
+	status int
+	size   int
+}
+
+// Write writes the response using the ResponseWriter
+func (r *loggingResponse) Write(b []byte) (int, error) {
+	if r.status == 0 {
+		// The status will be StatusOK if WriteHeader has not been called yet
+		r.status = http.StatusOK
+	}
+	size, err := r.ResponseWriter.Write(b)
+	r.size += size
+	return size, err
+}
+
+// WriteHeader writes the status code for the Response
+func (r *loggingResponse) WriteHeader(s int) {
+	r.ResponseWriter.WriteHeader(s)
+	r.status = s
+}
+
+// Hijack implements the `http.Hijacker` interface that actual ResponseWriters
+// implement to support websockets
+func (r *loggingResponse) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	if hj, ok := r.ResponseWriter.(http.Hijacker); ok {
+		return hj.Hijack()
+	}
+	return nil, nil, errors.New("http.Hijacker is not available on writer")
+}
+
+// Flush sends any buffered data to the client. Implements the `http.Flusher`
+// interface
+func (r *loggingResponse) Flush() {
+	if flusher, ok := r.ResponseWriter.(http.Flusher); ok {
+		if r.status == 0 {
+			// The status will be StatusOK if WriteHeader has not been called yet
+			r.status = http.StatusOK
+		}
+		flusher.Flush()
+	}
+}
+
+// Status returns the response status code
+func (r *loggingResponse) Status() int {
+	return r.status
+}
+
+// Size returns the response size
+func (r *loggingResponse) Size() int {
+	return r.size
+}
@@ -0,0 +1,121 @@
+package middleware
+
+import (
+	"bytes"
+	"net/http"
+	"net/http/httptest"
+
+	middlewareapi "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/apis/middleware"
+	"github.com/oauth2-proxy/oauth2-proxy/v7/pkg/apis/sessions"
+	"github.com/oauth2-proxy/oauth2-proxy/v7/pkg/logger"
+	. "github.com/onsi/ginkgo"
+	. "github.com/onsi/ginkgo/extensions/table"
+	. "github.com/onsi/gomega"
+)
+
+const RequestLoggingFormatWithoutTime = "{{.Client}} - {{.Username}} [TIMELESS] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}"
+
+var _ = Describe("Request logger suite", func() {
+	type requestLoggerTableInput struct {
+		Format             string
+		ExpectedLogMessage string
+		Path               string
+		ExcludePaths       []string
+		Upstream           string
+		Session            *sessions.SessionState
+	}
+
+	DescribeTable("when service a request",
+		func(in *requestLoggerTableInput) {
+			buf := bytes.NewBuffer(nil)
+			logger.SetOutput(buf)
+			logger.SetReqTemplate(in.Format)
+			logger.SetExcludePaths(in.ExcludePaths)
+
+			req, err := http.NewRequest("GET", in.Path, nil)
+			Expect(err).ToNot(HaveOccurred())
+			req.RemoteAddr = "127.0.0.1"
+			req.Host = "test-server"
+
+			scope := &middlewareapi.RequestScope{Session: in.Session}
+			req = middlewareapi.AddRequestScope(req, scope)
+
+			handler := NewRequestLogger()(testUpstreamHandler(in.Upstream))
+			handler.ServeHTTP(httptest.NewRecorder(), req)
+
+			Expect(buf.String()).To(Equal(in.ExpectedLogMessage))
+		},
+		Entry("standard request", &requestLoggerTableInput{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "127.0.0.1 - standard.user [TIMELESS] test-server GET standard \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{},
+			Upstream:           "standard",
+			Session:            &sessions.SessionState{User: "standard.user"},
+		}),
+		Entry("with unrelated path excluded", &requestLoggerTableInput{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "127.0.0.1 - unrelated.exclusion [TIMELESS] test-server GET unrelated \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{"/ping"},
+			Upstream:           "unrelated",
+			Session:            &sessions.SessionState{User: "unrelated.exclusion"},
+		}),
+		Entry("with path as the sole exclusion", &requestLoggerTableInput{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{"/foo/bar"},
+		}),
+		Entry("ping path", &requestLoggerTableInput{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "127.0.0.1 - mr.ping [TIMELESS] test-server GET - \"/ping\" HTTP/1.1 \"\" 200 4 0.000\n",
+			Path:               "/ping",
+			ExcludePaths:       []string{},
+			Upstream:           "",
+			Session:            &sessions.SessionState{User: "mr.ping"},
+		}),
+		Entry("ping path but excluded", &requestLoggerTableInput{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "",
+			Path:               "/ping",
+			ExcludePaths:       []string{"/ping"},
+			Upstream:           "",
+			Session:            &sessions.SessionState{User: "mr.ping"},
+		}),
+		Entry("ping path and excluded in list", &requestLoggerTableInput{
+			Format:             RequestLoggingFormatWithoutTime,
+			ExpectedLogMessage: "",
+			Path:               "/ping",
+			ExcludePaths:       []string{"/foo/bar", "/ping"},
+		}),
+		Entry("custom format", &requestLoggerTableInput{
+			Format:             "{{.RequestMethod}} {{.Username}} {{.Upstream}}",
+			ExpectedLogMessage: "GET custom.format custom\n",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{""},
+			Upstream:           "custom",
+			Session:            &sessions.SessionState{User: "custom.format"},
+		}),
+		Entry("custom format with unrelated exclusion", &requestLoggerTableInput{
+			Format:             "{{.RequestMethod}} {{.Username}} {{.Upstream}}",
+			ExpectedLogMessage: "GET custom.format custom\n",
+			Path:               "/foo/bar",
+			ExcludePaths:       []string{"/ping"},
+			Upstream:           "custom",
+			Session:            &sessions.SessionState{User: "custom.format"},
+		}),
+		Entry("custom format ping path", &requestLoggerTableInput{
+			Format:             "{{.RequestMethod}}",
+			ExpectedLogMessage: "GET\n",
+			Path:               "/ping",
+			ExcludePaths:       []string{""},
+		}),
+		Entry("custom format ping path excluded", &requestLoggerTableInput{
+			Format:             "{{.RequestMethod}}",
+			ExpectedLogMessage: "",
+			Path:               "/ping",
+			ExcludePaths:       []string{"/ping"},
+		}),
+	)
+})