From b9b5e817fc5591dc045b7a6e30ed4d842f030f4b Mon Sep 17 00:00:00 2001 From: Jehiah Czebotar Date: Thu, 19 Mar 2015 16:37:16 -0400 Subject: [PATCH] improve request logging (closer to Apache Common Log) --- README.md | 8 ++ contrib/google_auth_proxy.cfg.example | 4 + logging_handler.go | 132 ++++++++++++++++++++++++++ main.go | 4 +- oauthproxy.go | 25 +++-- options.go | 3 + 6 files changed, 169 insertions(+), 7 deletions(-) create mode 100644 logging_handler.go diff --git a/README.md b/README.md index c2bfcdd..524de2d 100644 --- a/README.md +++ b/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. + +``` + - [19/Mar/2015:17:20:19 -0400] GET "/path/" HTTP/1.1 "" +```` diff --git a/contrib/google_auth_proxy.cfg.example b/contrib/google_auth_proxy.cfg.example index b42c40f..cf4ff06 100644 --- a/contrib/google_auth_proxy.cfg.example +++ b/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 + diff --git a/logging_handler.go b/logging_handler.go new file mode 100644 index 0000000..17fca97 --- /dev/null +++ b/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) +} diff --git a/main.go b/main.go index 93e590e..05e05e7 100644 --- a/main.go +++ b/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) diff --git a/oauthproxy.go b/oauthproxy.go index a45e2c7..5c181ff 100644 --- a/oauthproxy.go +++ b/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 diff --git a/options.go b/options.go index 98a0680..eb099ac 100644 --- a/options.go +++ b/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, } }