Skip to content
This repository has been archived by the owner on Jan 24, 2019. It is now read-only.

Commit

Permalink
improve request logging (closer to Apache Common Log)
Browse files Browse the repository at this point in the history
  • Loading branch information
jehiah committed Mar 19, 2015
1 parent c0160c1 commit 62885e8
Show file tree
Hide file tree
Showing 4 changed files with 153 additions and 7 deletions.
8 changes: 8 additions & 0 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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>
````
125 changes: 125 additions & 0 deletions logging_handler.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,125 @@
// 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
}

func LoggingHandler(out io.Writer, h http.Handler) http.Handler {
return loggingHandler{out, h}
}

func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
t := time.Now()
logger := &responseLogger{w: w}
url := *req.URL
h.handler.ServeHTTP(logger, req)
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, _, err := net.SplitHostPort(req.RemoteAddr)

if err != nil {
client = req.RemoteAddr
}

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)
}
2 changes: 1 addition & 1 deletion main.go
Original file line number Diff line number Diff line change
Expand Up @@ -112,7 +112,7 @@ func main() {
}
log.Printf("listening on %s", listenAddr)

server := &http.Server{Handler: oauthproxy}
server := &http.Server{Handler: LoggingHandler(os.Stdout, oauthproxy)}
err = server.Serve(listener)
if err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
log.Printf("ERROR: http.Serve() - %s", err)
Expand Down
25 changes: 19 additions & 6 deletions oauthproxy.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
}
Expand All @@ -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)
}
Expand All @@ -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
Expand Down

0 comments on commit 62885e8

Please sign in to comment.