b9b5e81 · typeable/oauth2-proxy

git.iko.soy/typeable/oauth2-proxy

improve request logging (closer to Apache Common Log)

commitb9b5e817fc5591dc045b7a6e30ed4d842f030f4b authorJehiah Czebotar <jehiah@gmail.com> dateThu 19 Mar 2015, 16:37 (12 years ago) parentc0160c1

6 files changed+169−7

compare with master

unifiedsplit

README.md+8 contrib/google_auth_proxy.cfg.example+4 logging_handler.go+132 main.go+3−1 oauthproxy.go+19−6 options.go+3

README.md+8

@@ -135,3 +135,11 @@ Google Auth Proxy responds directly to the following endpoints. All other endpoi

135135* /oauth2/sign_in - the login page, which also doubles as a sign out page (it clears cookies)

136136* /oauth2/start - a URL that will redirect to start the OAuth cycle

137137* /oauth2/callback - the URL used at the end of the OAuth cycle. The oauth app will be configured with this ass the callback url.

138+

139+## Logging Format

140+

141+Google Auth Proxy logs requests to stdout in a format similar to Apache Combined Log.

142+

143+```

144+<REMOTE_ADDRESS> - <user@domain.com> [19/Mar/2015:17:20:19 -0400] <HOST_HEADER> GET <UPSTREAM_HOST> "/path/" HTTP/1.1 "<USER_AGENT>" <RESPONSE_CODE> <RESPONSE_BYTES> <REQUEST_DURATION>

145+````

contrib/google_auth_proxy.cfg.example+4

@@ -13,6 +13,9 @@

1313# "http://127.0.0.1:8080/"

1414# ]

1515

16+## Log requests to stdout

17+# request_logging = true

18+

1619## pass HTTP Basic Auth, X-Forwarded-User and X-Forwarded-Email information to upstream

1720# pass_basic_auth = true

1821## pass the request Host Header to upstream

@@ -51,3 +54,4 @@

5154# cookie_expire = "168h"

5255# cookie_secure = true

5356# cookie_httponly = true

57+

logging_handler.gonew file+132

@@ -0,0 +1,132 @@

1+// largely adapted from https://github.com/gorilla/handlers/blob/master/handlers.go

2+// to add logging of request duration as last value (and drop referrer)

4+package main

6+import (

7+ "fmt"

8+ "io"

9+ "net"

10+ "net/http"

11+ "net/url"

12+ "time"

13+)

14+

15+// responseLogger is wrapper of http.ResponseWriter that keeps track of its HTTP status

16+// code and body size

17+type responseLogger struct {

18+ w http.ResponseWriter

19+ status int

20+ size int

21+ upstream string

22+ authInfo string

23+}

24+

25+func (l *responseLogger) Header() http.Header {

26+ return l.w.Header()

27+}

28+

29+func (l *responseLogger) ExtractGAPMetadata() {

30+ upstream := l.w.Header().Get("GAP-Upstream-Address")

31+ if upstream != "" {

32+ l.upstream = upstream

33+ l.w.Header().Del("GAP-Upstream-Address")

34+ }

35+ authInfo := l.w.Header().Get("GAP-Auth")

36+ if authInfo != "" {

37+ l.authInfo = authInfo

38+ l.w.Header().Del("GAP-Auth")

39+ }

40+}

41+

42+func (l *responseLogger) Write(b []byte) (int, error) {

43+ if l.status == 0 {

44+ // The status will be StatusOK if WriteHeader has not been called yet

45+ l.status = http.StatusOK

46+ }

47+ l.ExtractGAPMetadata()

48+ size, err := l.w.Write(b)

49+ l.size += size

50+ return size, err

51+}

52+

53+func (l *responseLogger) WriteHeader(s int) {

54+ l.ExtractGAPMetadata()

55+ l.w.WriteHeader(s)

56+ l.status = s

57+}

58+

59+func (l *responseLogger) Status() int {

60+ return l.status

61+}

62+

63+func (l *responseLogger) Size() int {

64+ return l.size

65+}

66+

67+// loggingHandler is the http.Handler implementation for LoggingHandlerTo and its friends

68+type loggingHandler struct {

69+ writer io.Writer

70+ handler http.Handler

71+ enabled bool

72+}

73+

74+func LoggingHandler(out io.Writer, h http.Handler, v bool) http.Handler {

75+ return loggingHandler{out, h, v}

76+}

77+

78+func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {

79+ t := time.Now()

80+ url := *req.URL

81+ logger := &responseLogger{w: w}

82+ h.handler.ServeHTTP(logger, req)

83+ if !h.enabled {

84+ return

85+ }

86+ logLine := buildLogLine(logger.authInfo, logger.upstream, req, url, t, logger.Status(), logger.Size())

87+ h.writer.Write(logLine)

88+}

89+

90+// Log entry for req similar to Apache Common Log Format.

91+// ts is the timestamp with which the entry should be logged.

92+// status, size are used to provide the response HTTP status and size.

93+func buildLogLine(username, upstream string, req *http.Request, url url.URL, ts time.Time, status int, size int) []byte {

94+ if username == "" {

95+ username = "-"

96+ }

97+ if upstream == "" {

98+ upstream = "-"

99+ }

100+ if url.User != nil && username == "-" {

101+ if name := url.User.Username(); name != "" {

102+ username = name

103+ }

104+ }

105+

106+ client := req.Header.Get("X-Real-IP")

107+ if client == "" {

108+ client = req.RemoteAddr

109+ }

110+

111+ if c, _, err := net.SplitHostPort(client); err == nil {

112+ client = c

113+ }

114+

115+ duration := float64(time.Now().Sub(ts)) / float64(time.Second)

116+

117+ logLine := fmt.Sprintf("%s - %s [%s] %s %s %s %q %s %q %d %d %0.3f\n",

118+ client,

119+ username,

120+ ts.Format("02/Jan/2006:15:04:05 -0700"),

121+ req.Host,

122+ req.Method,

123+ upstream,

124+ url.RequestURI(),

125+ req.Proto,

126+ req.UserAgent(),

127+ status,

128+ size,

129+ duration,

130+ )

131+ return []byte(logLine)

132+}

main.go+3−1

@@ -47,6 +47,8 @@ func main() {

4747 flagSet.Bool("cookie-secure", true, "set secure (HTTPS) cookie flag")

4848 flagSet.Bool("cookie-httponly", true, "set HttpOnly cookie flag")

4949

50+ flagSet.Bool("request-logging", true, "Log requests to stdout")

51+

5052 flagSet.Parse(os.Args[1:])

5153

5254 if *showVersion {

@@ -112,7 +114,7 @@ func main() {

112114 }

113115 log.Printf("listening on %s", listenAddr)

114116

115− server := &http.Server{Handler: oauthproxy}

117+ server := &http.Server{Handler: LoggingHandler(os.Stdout, oauthproxy, opts.RequestLogging)}

116118 err = server.Serve(listener)

117119 if err != nil && !strings.Contains(err.Error(), "use of closed network connection") {

118120 log.Printf("ERROR: http.Serve() - %s", err)

oauthproxy.go+19−6

@@ -42,13 +42,23 @@ type OauthProxy struct {

4242 SignInMessage string

4343 HtpasswdFile *HtpasswdFile

4444 DisplayHtpasswdForm bool

45− serveMux *http.ServeMux

45+ serveMux http.Handler

4646 PassBasicAuth bool

4747 skipAuthRegex []string

4848 compiledRegex []*regexp.Regexp

4949 templates *template.Template

5050}

5151

52+type UpstreamProxy struct {

53+ upstream string

54+ handler http.Handler

55+}

56+

57+func (u *UpstreamProxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {

58+ w.Header().Set("GAP-Upstream-Address", u.upstream)

59+ u.handler.ServeHTTP(w, r)

60+}

61+

5262func NewReverseProxy(target *url.URL) (proxy *httputil.ReverseProxy) {

5363 return httputil.NewSingleHostReverseProxy(target)

5464}

@@ -85,7 +95,7 @@ func NewOauthProxy(opts *Options, validator func(string) bool) *OauthProxy {

8595 } else {

8696 setProxyDirector(proxy)

8797 }

88− serveMux.Handle(path, proxy)

98+ serveMux.Handle(path, &UpstreamProxy{u.Host, proxy})

8999 }

90100 for _, u := range opts.CompiledRegex {

91101 log.Printf("compiled skip-auth-regex => %q", u)

@@ -338,7 +348,7 @@ func (p *OauthProxy) ManualSignIn(rw http.ResponseWriter, req *http.Request) (st

338348 }

339349 // check auth

340350 if p.HtpasswdFile.Validate(user, passwd) {

341− log.Printf("authenticated %s via manual sign in", user)

351+ log.Printf("authenticated %q via HtpasswdFile", user)

342352 return user, true

343353 }

344354 return "", false

@@ -366,7 +376,6 @@ func (p *OauthProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {

366376 if req.Header.Get("X-Real-IP") != "" {

367377 remoteAddr += fmt.Sprintf(" (%q)", req.Header.Get("X-Real-IP"))

368378 }

369− log.Printf("%s %s %s", remoteAddr, req.Method, req.URL.RequestURI())

370379

371380 var ok bool

372381 var user string

@@ -461,7 +470,6 @@ func (p *OauthProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {

461470 }

462471

463472 if !ok {

464− log.Printf("%s - invalid cookie session", remoteAddr)

465473 p.SignInPage(rw, req, 403)

466474 return

467475 }

@@ -472,6 +480,11 @@ func (p *OauthProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) {

472480 req.Header["X-Forwarded-User"] = []string{user}

473481 req.Header["X-Forwarded-Email"] = []string{email}

474482 }

483+ if email == "" {

484+ rw.Header().Set("GAP-Auth", user)

485+ } else {

486+ rw.Header().Set("GAP-Auth", email)

487+ }

475488

476489 p.serveMux.ServeHTTP(rw, req)

477490}

@@ -493,7 +506,7 @@ func (p *OauthProxy) CheckBasicAuth(req *http.Request) (string, bool) {

493506 return "", false

494507 }

495508 if p.HtpasswdFile.Validate(pair[0], pair[1]) {

496− log.Printf("authenticated %s via basic auth", pair[0])

509+ log.Printf("authenticated %q via basic auth", pair[0])

497510 return pair[0], true

498511 }

499512 return "", false

options.go+3

@@ -33,6 +33,8 @@ type Options struct {

3333 PassBasicAuth bool `flag:"pass-basic-auth" cfg:"pass_basic_auth"`

3434 PassHostHeader bool `flag:"pass-host-header" cfg:"pass_host_header"`

3535

36+ RequestLogging bool `flag:"request-logging" cfg:"request_logging"`

37+

3638 // internal values that are set after config validation

3739 redirectUrl *url.URL

3840 proxyUrls []*url.URL

@@ -49,6 +51,7 @@ func NewOptions() *Options {

4951 CookieExpire: time.Duration(168) * time.Hour,

5052 PassBasicAuth: true,

5153 PassHostHeader: true,

54+ RequestLogging: true,

5255 }

5356}

5457