Auth and standard logging with file rolling

kbabuadze · Apr 12, 2019 · 8ec025f · 8ec025f
1 parent ee4ebe5
commit 8ec025f
Showing 23 changed files with 799 additions and 200 deletions.
diff --git a/Gopkg.lock b/Gopkg.lock
diff --git a/Gopkg.toml b/Gopkg.toml
@@ -38,3 +38,7 @@
 [[constraint]]
   branch = "master"
   name = "golang.org/x/crypto"
+
+[[constraint]]
+  name = "gopkg.in/natefinch/lumberjack.v2"
+  version = "2.1.0"
diff --git a/README.md b/README.md
@@ -262,6 +262,8 @@ An example [oauth2_proxy.cfg](contrib/oauth2_proxy.cfg.example) config file is i
 ```
 Usage of oauth2_proxy:
   -approval-prompt string: OAuth approval_prompt (default "force")
+  -auth-logging: Log authentication attempts (default true)
+  -auth-logging-format string: Template for authentication log lines (see "Logging Configuration" paragraph below)
   -authenticated-emails-file string: authenticate against emails via file (one per line)
   -azure-tenant string: go to a tenant-specific or common (tenant-independent) endpoint. (default "common")
   -basic-auth-password string: the password to set when passing the HTTP Basic Auth header
@@ -290,6 +292,12 @@ Usage of oauth2_proxy:
   -htpasswd-file string: additionally authenticate against a htpasswd file. Entries must be created with "htpasswd -s" for SHA encryption
   -http-address string: [http://]<addr>:<port> or unix://<path> to listen on for HTTP clients (default "127.0.0.1:4180")
   -https-address string: <addr>:<port> to listen on for HTTPS clients (default ":443")
+  -logging-compress: Should rotated log files be compressed using gzip (default false)
+  -logging-filename string: File to log requests to, empty for stdout (default to stdout)
+  -logging-local-time: If the time in log files and backup filenames are local or UTC time (default true)
+  -logging-max-age int: Maximum number of days to retain old log files (default 7)
+  -logging-max-backups int: Maximum number of old log files to retain; 0 to disable (default 0)
+  -logging-max-size int: Maximum size in megabytes of the log file before rotation (default 100)
   -login-url string: Authentication endpoint
   -oidc-issuer-url: the OpenID Connect issuer URL. ie: "https://accounts.google.com"
   -oidc-jwks-url string: OIDC JWKS URI for token verification; required if OIDC discovery is disabled
@@ -305,7 +313,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)
+  -request-logging-format: Template for request log lines (see "Logging Configuration" 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)
@@ -316,6 +324,8 @@ Usage of oauth2_proxy:
   -skip-oidc-discovery: bypass OIDC endpoint discovery. login-url, redeem-url and oidc-jwks-url must be configured in this case
   -skip-provider-button: will skip sign-in-page to directly reach the next step: oauth/start
   -ssl-insecure-skip-verify: skip validation of certificates presented when using HTTPS
+  -standard-logging: Log standard runtime information (default true)
+  -standard-logging-format string: Template for standard log lines (see "Logging Configuration" paragraph below)
   -tls-cert string: path to certificate file
   -tls-key string: path to private key file
   -upstream value: the http url(s) of the upstream endpoint or file:// paths for static files. Routing is based on the path
@@ -446,9 +456,40 @@ following:
 - [rc3.org: Using HMAC to authenticate Web service
   requests](http://rc3.org/2011/12/02/using-hmac-to-authenticate-web-service-requests/)
 
-## Logging Format
+## Logging Configuration
 
-By default, OAuth2 Proxy logs requests to stdout in a format similar to Apache Combined Log.
+By default, OAuth2 Proxy logs all output to stdout. Logging can be configured to output to a rotating log file using the `-logging-filename` command.
+
+If logging to a file you can also configure the maximum file size (`-logging-max-size`), age (`-logging-max-age`), max backup logs (`-logging-max-backups`), and if backup logs should be compressed (`-logging-compress`).
+
+There are three different types of logging: standard, authentication, and HTTP requests. These can each be enabled or disabled with `-standard-logging`, `-auth-logging`, and `-request-logging`.
+
+Each type of logging has their own configurable format and variables. By default these formats are similar to the Apache Combined Log.
+
+### Auth Log Format
+Authentication logs are logs which are guaranteed to contain a username or email address of a user attempting to authenticate. These logs are output by default in the below format:
+
+```
+<REMOTE_ADDRESS> - <user@domain.com> [19/Mar/2015:17:20:19 -0400] [<STATUS>] <MESSAGE>
+```
+
+The status block will contain one of the below strings:
+
+- `AuthSuccess` If a user has authenticated successfully by any method
+- `AuthFailure` If the user failed to authenticate explicitly
+- `AuthError` If there was an unexpected error during authentication
+
+If you require a different format than that, you can configure it with the `-auth-logging-format` flag.
+The default format is configured as follows:
+
+```
+{{.Client}} - {{.Username}} [{{.Timestamp}}] [{{.Status}}] {{.Message}}
+```
+
+[See `authLogMessageData` in `logging_handler.go`](./logger/logger.go) for all available variables.
+
+### Request Log Format
+HTTP request logs will output by default in the below format:
 
 ```
 <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>
@@ -461,7 +502,20 @@ 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.
+[See `requestLogMessageData` in `logging_handler.go`](./logger/logger.go) for all available variables.
+
+### Standard Log Format
+All other logging that is not covered by the above two types of logging will be output in this standard logging format. This includes configuration information at startup and errors that occur outside of a session. The default format is below:
+
+```
+[19/Mar/2015:17:20:19 -0400] [main.go:40] <MESSAGE>
+```
+
+If you require a different format than that, you can configure it with the `-standard-logging-format` flag. The default format is configured as follows:
+
+```
+[{{.Timestamp}}] [{{.File}}] {{.Message}}
+```
 
 ## Adding a new Provider
 

diff --git a/api/api.go b/api/api.go
@@ -4,22 +4,22 @@ import (
 	"encoding/json"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net/http"
 
 	"github.com/bitly/go-simplejson"
+	"github.com/pusher/oauth2_proxy/logger"
 )
 
 // Request parses the request body into a simplejson.Json object
 func Request(req *http.Request) (*simplejson.Json, error) {
 	resp, err := http.DefaultClient.Do(req)
 	if err != nil {
-		log.Printf("%s %s %s", req.Method, req.URL, err)
+		logger.Printf("%s %s %s", req.Method, req.URL, err)
 		return nil, err
 	}
 	body, err := ioutil.ReadAll(resp.Body)
 	resp.Body.Close()
-	log.Printf("%d %s %s %s", resp.StatusCode, req.Method, req.URL, body)
+	logger.Printf("%d %s %s %s", resp.StatusCode, req.Method, req.URL, body)
 	if err != nil {
 		return nil, err
 	}
@@ -37,12 +37,12 @@ func Request(req *http.Request) (*simplejson.Json, error) {
 func RequestJSON(req *http.Request, v interface{}) error {
 	resp, err := http.DefaultClient.Do(req)
 	if err != nil {
-		log.Printf("%s %s %s", req.Method, req.URL, err)
+		logger.Printf("%s %s %s", req.Method, req.URL, err)
 		return err
 	}
 	body, err := ioutil.ReadAll(resp.Body)
 	resp.Body.Close()
-	log.Printf("%d %s %s %s", resp.StatusCode, req.Method, req.URL, body)
+	logger.Printf("%d %s %s %s", resp.StatusCode, req.Method, req.URL, body)
 	if err != nil {
 		return err
 	}

diff --git a/contrib/oauth2_proxy.cfg.example b/contrib/oauth2_proxy.cfg.example
@@ -18,8 +18,18 @@
 #     "http://127.0.0.1:8080/"
 # ]
 
-## Log requests to stdout
-# request_logging = true
+## Logging configuration
+#logging_filename = ""
+#logging_max_size = 100
+#logging_max_age = 7
+#logging_local_time = true
+#logging_compress = false
+#standard_logging = true
+#standard_logging_format = "[{{.Timestamp}}] [{{.File}}] {{.Message}}"
+#request_logging = true
+#request_logging_format = "{{.Client}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}"
+#auth_logging = true
+#auth_logging_format = "{{.Client}} - {{.Username}} [{{.Timestamp}}] [{{.Status}}] {{.Message}}"
 
 ## pass HTTP Basic Auth, X-Forwarded-User and X-Forwarded-Email information to upstream
 # pass_basic_auth = true

diff --git a/htpasswd.go b/htpasswd.go
@@ -5,9 +5,9 @@ import (
 	"encoding/base64"
 	"encoding/csv"
 	"io"
-	"log"
 	"os"
 
+	"github.com/pusher/oauth2_proxy/logger"
 	"golang.org/x/crypto/bcrypt"
 )
 
@@ -67,6 +67,6 @@ func (h *HtpasswdFile) Validate(user string, password string) bool {
 		return bcrypt.CompareHashAndPassword([]byte(realPassword), []byte(password)) == nil
 	}
 
-	log.Printf("Invalid htpasswd entry for %s. Must be a SHA or bcrypt entry.", user)
+	logger.Printf("Invalid htpasswd entry for %s. Must be a SHA or bcrypt entry.", user)
 	return false
 }
diff --git a/http.go b/http.go
@@ -2,11 +2,12 @@ package main
 
 import (
 	"crypto/tls"
-	"log"
 	"net"
 	"net/http"
 	"strings"
 	"time"
+
+	"github.com/pusher/oauth2_proxy/logger"
 )
 
 // Server represents an HTTP server
@@ -86,17 +87,17 @@ func (s *Server) ServeHTTP() {
 
 	listener, err := net.Listen(networkType, listenAddr)
 	if err != nil {
-		log.Fatalf("FATAL: listen (%s, %s) failed - %s", networkType, listenAddr, err)
+		logger.Fatalf("FATAL: listen (%s, %s) failed - %s", networkType, listenAddr, err)
 	}
-	log.Printf("HTTP: listening on %s", listenAddr)
+	logger.Printf("HTTP: listening on %s", listenAddr)
 
 	server := &http.Server{Handler: s.Handler}
 	err = server.Serve(listener)
 	if err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
-		log.Printf("ERROR: http.Serve() - %s", err)
+		logger.Printf("ERROR: http.Serve() - %s", err)
 	}
 
-	log.Printf("HTTP: closing %s", listener.Addr())
+	logger.Printf("HTTP: closing %s", listener.Addr())
 }
 
 // ServeHTTPS constructs a net.Listener and starts handling HTTPS requests
@@ -114,24 +115,24 @@ func (s *Server) ServeHTTPS() {
 	config.Certificates = make([]tls.Certificate, 1)
 	config.Certificates[0], err = tls.LoadX509KeyPair(s.Opts.TLSCertFile, s.Opts.TLSKeyFile)
 	if err != nil {
-		log.Fatalf("FATAL: loading tls config (%s, %s) failed - %s", s.Opts.TLSCertFile, s.Opts.TLSKeyFile, err)
+		logger.Fatalf("FATAL: loading tls config (%s, %s) failed - %s", s.Opts.TLSCertFile, s.Opts.TLSKeyFile, err)
 	}
 
 	ln, err := net.Listen("tcp", addr)
 	if err != nil {
-		log.Fatalf("FATAL: listen (%s) failed - %s", addr, err)
+		logger.Fatalf("FATAL: listen (%s) failed - %s", addr, err)
 	}
-	log.Printf("HTTPS: listening on %s", ln.Addr())
+	logger.Printf("HTTPS: listening on %s", ln.Addr())
 
 	tlsListener := tls.NewListener(tcpKeepAliveListener{ln.(*net.TCPListener)}, config)
 	srv := &http.Server{Handler: s.Handler}
 	err = srv.Serve(tlsListener)
 
 	if err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
-		log.Printf("ERROR: https.Serve() - %s", err)
+		logger.Printf("ERROR: https.Serve() - %s", err)
 	}
 
-	log.Printf("HTTPS: closing %s", tlsListener.Addr())
+	logger.Printf("HTTPS: closing %s", tlsListener.Addr())
 }
 
 // tcpKeepAliveListener sets TCP keep-alive timeouts on accepted