Merge pull request #423 from Jimdo/configure_accesslog_format

Make Request Logging Format Configurable

Author: talam

README.md

@@ -210,6 +210,7 @@ Usage of oauth2_proxy:
   -redeem-url string: Token redemption endpoint
   -redirect-url string: the OAuth Redirect URL. ie: "https://internalapp.yourcompany.com/oauth2/callback"
   -request-logging: Log requests to stdout (default true)
+  -request-logging-format: Template for request log lines (see "Logging Format" paragraph below)
   -resource string: The resource that is protected (Azure AD only)
   -scope string: OAuth scope specification
   -set-xauthrequest: set X-Auth-Request-User and X-Auth-Request-Email response headers (useful in Nginx auth_request mode)
@@ -347,12 +348,21 @@ following:
 
 ## Logging Format
 
-OAuth2 Proxy logs requests to stdout in a format similar to Apache Combined Log.
+By default, OAuth2 Proxy logs requests to stdout in a format similar to Apache Combined Log.
 
 ```
 <REMOTE_ADDRESS> - <[email protected]> [19/Mar/2015:17:20:19 -0400] <HOST_HEADER> GET <UPSTREAM_HOST> "/path/" HTTP/1.1 "<USER_AGENT>" <RESPONSE_CODE> <RESPONSE_BYTES> <REQUEST_DURATION>
 ```
 
+If you require a different format than that, you can configure it with the `-request-logging-format` flag.
+The default format is configured as follows:
+
+```
+{{.Client}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}
+```
+
+[See `logMessageData` in `logging_handler.go`](./logging_handler.go) for all available variables.
+
 ## Adding a new Provider
 
 Follow the examples in the [`providers` package](providers/) to define a new

logging_handler.go

@@ -9,9 +9,14 @@ import (
 	"net"
 	"net/http"
 	"net/url"
+	"text/template"
 	"time"
 )
 
+const (
+	defaultRequestLoggingFormat = "{{.Client}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}"
+)
+
 // responseLogger is wrapper of http.ResponseWriter that keeps track of its HTTP status
 // code and body size
 type responseLogger struct {
@@ -64,15 +69,38 @@ func (l *responseLogger) Size() int {
 	return l.size
 }
 
+// logMessageData is the container for all values that are available as variables in the request logging format.
+// All values are pre-formatted strings so it is easy to use them in the format string.
+type logMessageData struct {
+	Client,
+	Host,
+	Protocol,
+	RequestDuration,
+	RequestMethod,
+	RequestURI,
+	ResponseSize,
+	StatusCode,
+	Timestamp,
+	Upstream,
+	UserAgent,
+	Username string
+}
+
 // loggingHandler is the http.Handler implementation for LoggingHandlerTo and its friends
 type loggingHandler struct {
-	writer  io.Writer
-	handler http.Handler
-	enabled bool
+	writer      io.Writer
+	handler     http.Handler
+	enabled     bool
+	logTemplate *template.Template
 }
 
-func LoggingHandler(out io.Writer, h http.Handler, v bool) http.Handler {
-	return loggingHandler{out, h, v}
+func LoggingHandler(out io.Writer, h http.Handler, v bool, requestLoggingTpl string) http.Handler {
+	return loggingHandler{
+		writer:      out,
+		handler:     h,
+		enabled:     v,
+		logTemplate: template.Must(template.New("request-log").Parse(requestLoggingTpl)),
+	}
 }
 
 func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
@@ -83,14 +111,13 @@ func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 	if !h.enabled {
 		return
 	}
-	logLine := buildLogLine(logger.authInfo, logger.upstream, req, url, t, logger.Status(), logger.Size())
-	h.writer.Write(logLine)
+	h.writeLogLine(logger.authInfo, logger.upstream, req, url, t, logger.Status(), logger.Size())
 }
 
 // Log entry for req similar to Apache Common Log Format.
 // ts is the timestamp with which the entry should be logged.
 // status, size are used to provide the response HTTP status and size.
-func buildLogLine(username, upstream string, req *http.Request, url url.URL, ts time.Time, status int, size int) []byte {
+func (h loggingHandler) writeLogLine(username, upstream string, req *http.Request, url url.URL, ts time.Time, status int, size int) {
 	if username == "" {
 		username = "-"
 	}
@@ -114,19 +141,20 @@ func buildLogLine(username, upstream string, req *http.Request, url url.URL, ts
 
 	duration := float64(time.Now().Sub(ts)) / float64(time.Second)
 
-	logLine := fmt.Sprintf("%s - %s [%s] %s %s %s %q %s %q %d %d %0.3f\n",
-		client,
-		username,
-		ts.Format("02/Jan/2006:15:04:05 -0700"),
-		req.Host,
-		req.Method,
-		upstream,
-		url.RequestURI(),
-		req.Proto,
-		req.UserAgent(),
-		status,
-		size,
-		duration,
-	)
-	return []byte(logLine)
+	h.logTemplate.Execute(h.writer, logMessageData{
+		Client:          client,
+		Host:            req.Host,
+		Protocol:        req.Proto,
+		RequestDuration: fmt.Sprintf("%0.3f", duration),
+		RequestMethod:   req.Method,
+		RequestURI:      fmt.Sprintf("%q", url.RequestURI()),
+		ResponseSize:    fmt.Sprintf("%d", size),
+		StatusCode:      fmt.Sprintf("%d", status),
+		Timestamp:       ts.Format("02/Jan/2006:15:04:05 -0700"),
+		Upstream:        upstream,
+		UserAgent:       fmt.Sprintf("%q", req.UserAgent()),
+		Username:        username,
+	})
+
+	h.writer.Write([]byte("\n"))
 }

logging_handler_test.go

@@ -0,0 +1,42 @@
+package main
+
+import (
+	"bytes"
+	"fmt"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+	"time"
+)
+
+func TestLoggingHandler_ServeHTTP(t *testing.T) {
+	ts := time.Now()
+
+	tests := []struct {
+		Format,
+		ExpectedLogMessage string
+	}{
+		{defaultRequestLoggingFormat, fmt.Sprintf("127.0.0.1 - - [%s] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n", ts.Format("02/Jan/2006:15:04:05 -0700"))},
+		{"{{.RequestMethod}}", "GET\n"},
+	}
+
+	for _, test := range tests {
+		buf := bytes.NewBuffer(nil)
+		handler := func(w http.ResponseWriter, req *http.Request) {
+			w.Write([]byte("test"))
+		}
+
+		h := LoggingHandler(buf, http.HandlerFunc(handler), true, test.Format)
+
+		r, _ := http.NewRequest("GET", "/foo/bar", nil)
+		r.RemoteAddr = "127.0.0.1"
+		r.Host = "test-server"
+
+		h.ServeHTTP(httptest.NewRecorder(), r)
+
+		actual := buf.String()
+		if actual != test.ExpectedLogMessage {
+			t.Errorf("Log message was\n%s\ninstead of expected \n%s", actual, test.ExpectedLogMessage)
+		}
+	}
+}

main.go

@@ -67,6 +67,7 @@ func main() {
 	flagSet.Bool("cookie-httponly", true, "set HttpOnly cookie flag")
 
 	flagSet.Bool("request-logging", true, "Log requests to stdout")
+	flagSet.String("request-logging-format", defaultRequestLoggingFormat, "Template for log lines")
 
 	flagSet.String("provider", "google", "OAuth provider")
 	flagSet.String("oidc-issuer-url", "", "OpenID Connect issuer URL (ie: https://accounts.google.com)")
@@ -125,7 +126,7 @@ func main() {
 	}
 
 	s := &Server{
-		Handler: LoggingHandler(os.Stdout, oauthproxy, opts.RequestLogging),
+		Handler: LoggingHandler(os.Stdout, oauthproxy, opts.RequestLogging, opts.RequestLoggingFormat),
 		Opts:    opts,
 	}
 	s.ListenAndServe()

options.go

@@ -74,7 +74,8 @@ type Options struct {
 	Scope             string `flag:"scope" cfg:"scope"`
 	ApprovalPrompt    string `flag:"approval-prompt" cfg:"approval_prompt"`
 
-	RequestLogging bool `flag:"request-logging" cfg:"request_logging"`
+	RequestLogging       bool   `flag:"request-logging" cfg:"request_logging"`
+	RequestLoggingFormat string `flag:"request-logging-format" cfg:"request_logging_format"`
 
 	SignatureKey string `flag:"signature-key" cfg:"signature_key" env:"OAUTH2_PROXY_SIGNATURE_KEY"`
 
@@ -94,23 +95,24 @@ type SignatureData struct {
 
 func NewOptions() *Options {
 	return &Options{
-		ProxyPrefix:         "/oauth2",
-		HttpAddress:         "127.0.0.1:4180",
-		HttpsAddress:        ":443",
-		DisplayHtpasswdForm: true,
-		CookieName:          "_oauth2_proxy",
-		CookieSecure:        true,
-		CookieHttpOnly:      true,
-		CookieExpire:        time.Duration(168) * time.Hour,
-		CookieRefresh:       time.Duration(0),
-		SetXAuthRequest:     false,
-		SkipAuthPreflight:   false,
-		PassBasicAuth:       true,
-		PassUserHeaders:     true,
-		PassAccessToken:     false,
-		PassHostHeader:      true,
-		ApprovalPrompt:      "force",
-		RequestLogging:      true,
+		ProxyPrefix:          "/oauth2",
+		HttpAddress:          "127.0.0.1:4180",
+		HttpsAddress:         ":443",
+		DisplayHtpasswdForm:  true,
+		CookieName:           "_oauth2_proxy",
+		CookieSecure:         true,
+		CookieHttpOnly:       true,
+		CookieExpire:         time.Duration(168) * time.Hour,
+		CookieRefresh:        time.Duration(0),
+		SetXAuthRequest:      false,
+		SkipAuthPreflight:    false,
+		PassBasicAuth:        true,
+		PassUserHeaders:      true,
+		PassAccessToken:      false,
+		PassHostHeader:       true,
+		ApprovalPrompt:       "force",
+		RequestLogging:       true,
+		RequestLoggingFormat: defaultRequestLoggingFormat,
 	}
 }