improve request logging (closer to Apache Common Log)

Author: jehiah

README.md

@@ -135,3 +135,11 @@ Google Auth Proxy responds directly to the following endpoints. All other endpoi
 * /oauth2/sign_in - the login page, which also doubles as a sign out page (it clears cookies)
 * /oauth2/start - a URL that will redirect to start the OAuth cycle
 * /oauth2/callback - the URL used at the end of the OAuth cycle. The oauth app will be configured with this ass the callback url.
+
+## Logging Format
+
+Google Auth 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>
+````

contrib/google_auth_proxy.cfg.example

@@ -13,6 +13,9 @@
 #     "http://127.0.0.1:8080/"
 # ]
 
+## Log requests to stdout
+# request_logging = true
+
 ## pass HTTP Basic Auth, X-Forwarded-User and X-Forwarded-Email information to upstream
 # pass_basic_auth = true
 ## pass the request Host Header to upstream
@@ -51,3 +54,4 @@
 # cookie_expire = "168h"
 # cookie_secure = true
 # cookie_httponly = true
+

logging_handler.go

@@ -0,0 +1,132 @@
+// largely adapted from https://github.com/gorilla/handlers/blob/master/handlers.go
+// to add logging of request duration as last value (and drop referrer)
+
+package main
+
+import (
+	"fmt"
+	"io"
+	"net"
+	"net/http"
+	"net/url"
+	"time"
+)
+
+// responseLogger is wrapper of http.ResponseWriter that keeps track of its HTTP status
+// code and body size
+type responseLogger struct {
+	w        http.ResponseWriter
+	status   int
+	size     int
+	upstream string
+	authInfo string
+}
+
+func (l *responseLogger) Header() http.Header {
+	return l.w.Header()
+}
+
+func (l *responseLogger) ExtractGAPMetadata() {
+	upstream := l.w.Header().Get("GAP-Upstream-Address")
+	if upstream != "" {
+		l.upstream = upstream
+		l.w.Header().Del("GAP-Upstream-Address")
+	}
+	authInfo := l.w.Header().Get("GAP-Auth")
+	if authInfo != "" {
+		l.authInfo = authInfo
+		l.w.Header().Del("GAP-Auth")
+	}
+}
+
+func (l *responseLogger) Write(b []byte) (int, error) {
+	if l.status == 0 {
+		// The status will be StatusOK if WriteHeader has not been called yet
+		l.status = http.StatusOK
+	}
+	l.ExtractGAPMetadata()
+	size, err := l.w.Write(b)
+	l.size += size
+	return size, err
+}
+
+func (l *responseLogger) WriteHeader(s int) {
+	l.ExtractGAPMetadata()
+	l.w.WriteHeader(s)
+	l.status = s
+}
+
+func (l *responseLogger) Status() int {
+	return l.status
+}
+
+func (l *responseLogger) Size() int {
+	return l.size
+}
+
+// loggingHandler is the http.Handler implementation for LoggingHandlerTo and its friends
+type loggingHandler struct {
+	writer  io.Writer
+	handler http.Handler
+	enabled bool
+}
+
+func LoggingHandler(out io.Writer, h http.Handler, v bool) http.Handler {
+	return loggingHandler{out, h, v}
+}
+
+func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
+	t := time.Now()
+	url := *req.URL
+	logger := &responseLogger{w: w}
+	h.handler.ServeHTTP(logger, req)
+	if !h.enabled {
+		return
+	}
+	logLine := buildLogLine(logger.authInfo, logger.upstream, req, url, t, logger.Status(), logger.Size())
+	h.writer.Write(logLine)
+}
+
+// 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 {
+	if username == "" {
+		username = "-"
+	}
+	if upstream == "" {
+		upstream = "-"
+	}
+	if url.User != nil && username == "-" {
+		if name := url.User.Username(); name != "" {
+			username = name
+		}
+	}
+
+	client := req.Header.Get("X-Real-IP")
+	if client == "" {
+		client = req.RemoteAddr
+	}
+
+	if c, _, err := net.SplitHostPort(client); err == nil {
+		client = c
+	}
+
+	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)
+}

main.go

@@ -47,6 +47,8 @@ func main() {
 	flagSet.Bool("cookie-secure", true, "set secure (HTTPS) cookie flag")
 	flagSet.Bool("cookie-httponly", true, "set HttpOnly cookie flag")
 
+	flagSet.Bool("request-logging", true, "Log requests to stdout")
+
 	flagSet.Parse(os.Args[1:])
 
 	if *showVersion {
@@ -112,7 +114,7 @@ func main() {
 	}
 	log.Printf("listening on %s", listenAddr)
 
-	server := &http.Server{Handler: oauthproxy}
+	server := &http.Server{Handler: LoggingHandler(os.Stdout, oauthproxy, opts.RequestLogging)}
 	err = server.Serve(listener)
 	if err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
 		log.Printf("ERROR: http.Serve() - %s", err)

oauthproxy.go

@@ -42,13 +42,23 @@ type OauthProxy struct {
 	SignInMessage       string
 	HtpasswdFile        *HtpasswdFile
 	DisplayHtpasswdForm bool
-	serveMux            *http.ServeMux
+	serveMux            http.Handler
 	PassBasicAuth       bool
 	skipAuthRegex       []string
 	compiledRegex       []*regexp.Regexp
 	templates           *template.Template
 }
 
+type UpstreamProxy struct {
+	upstream string
+	handler  http.Handler
+}
+
+func (u *UpstreamProxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	w.Header().Set("GAP-Upstream-Address", u.upstream)
+	u.handler.ServeHTTP(w, r)
+}
+
 func NewReverseProxy(target *url.URL) (proxy *httputil.ReverseProxy) {
 	return httputil.NewSingleHostReverseProxy(target)
 }
@@ -85,7 +95,7 @@ func NewOauthProxy(opts *Options, validator func(string) bool) *OauthProxy {
 		} else {
 			setProxyDirector(proxy)
 		}
-		serveMux.Handle(path, proxy)
+		serveMux.Handle(path, &UpstreamProxy{u.Host, proxy})
 	}
 	for _, u := range opts.CompiledRegex {
 		log.Printf("compiled skip-auth-regex => %q", u)
@@ -338,7 +348,7 @@ func (p *OauthProxy) ManualSignIn(rw http.ResponseWriter, req *http.Request) (st
 	}
 	// check auth
 	if p.HtpasswdFile.Validate(user, passwd) {
-		log.Printf("authenticated %s via manual sign in", user)
+		log.Printf("authenticated %q via HtpasswdFile", user)
 		return user, true
 	}
 	return "", false
@@ -366,7 +376,6 @@ func (p *OauthProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
 	if req.Header.Get("X-Real-IP") != "" {
 		remoteAddr += fmt.Sprintf(" (%q)", req.Header.Get("X-Real-IP"))
 	}
-	log.Printf("%s %s %s", remoteAddr, req.Method, req.URL.RequestURI())
 
 	var ok bool
 	var user string
@@ -461,7 +470,6 @@ func (p *OauthProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
 	}
 
 	if !ok {
-		log.Printf("%s - invalid cookie session", remoteAddr)
 		p.SignInPage(rw, req, 403)
 		return
 	}
@@ -472,6 +480,11 @@ func (p *OauthProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
 		req.Header["X-Forwarded-User"] = []string{user}
 		req.Header["X-Forwarded-Email"] = []string{email}
 	}
+	if email == "" {
+		rw.Header().Set("GAP-Auth", user)
+	} else {
+		rw.Header().Set("GAP-Auth", email)
+	}
 
 	p.serveMux.ServeHTTP(rw, req)
 }
@@ -493,7 +506,7 @@ func (p *OauthProxy) CheckBasicAuth(req *http.Request) (string, bool) {
 		return "", false
 	}
 	if p.HtpasswdFile.Validate(pair[0], pair[1]) {
-		log.Printf("authenticated %s via basic auth", pair[0])
+		log.Printf("authenticated %q via basic auth", pair[0])
 		return pair[0], true
 	}
 	return "", false

options.go

@@ -33,6 +33,8 @@ type Options struct {
 	PassBasicAuth  bool     `flag:"pass-basic-auth" cfg:"pass_basic_auth"`
 	PassHostHeader bool     `flag:"pass-host-header" cfg:"pass_host_header"`
 
+	RequestLogging bool `flag:"request-logging" cfg:"request_logging"`
+
 	// internal values that are set after config validation
 	redirectUrl   *url.URL
 	proxyUrls     []*url.URL
@@ -49,6 +51,7 @@ func NewOptions() *Options {
 		CookieExpire:        time.Duration(168) * time.Hour,
 		PassBasicAuth:       true,
 		PassHostHeader:      true,
+		RequestLogging:      true,
 	}
 }