From b46e34be728a6930434a42b7ef50767b3e5a5ed1 Mon Sep 17 00:00:00 2001 From: MisterWil Date: Sun, 10 Feb 2019 08:37:45 -0800 Subject: [PATCH 1/5] Auth and standard logging with file rolling --- Gopkg.lock | 15 +- Gopkg.toml | 4 + README.md | 62 ++++- api/api.go | 10 +- contrib/oauth2_proxy.cfg.example | 14 +- htpasswd.go | 4 +- http.go | 21 +- logger/logger.go | 447 +++++++++++++++++++++++++++++++ logging_handler.go | 92 +------ logging_handler_test.go | 8 +- main.go | 37 ++- oauthproxy.go | 57 ++-- oauthproxy_test.go | 8 +- options.go | 114 ++++++-- providers/azure.go | 6 +- providers/github.go | 17 +- providers/gitlab.go | 6 +- providers/google.go | 16 +- providers/internal_util.go | 14 +- templates.go | 11 +- validator.go | 9 +- watcher.go | 18 +- watcher_unsupported.go | 6 +- 23 files changed, 771 insertions(+), 225 deletions(-) create mode 100644 logger/logger.go diff --git a/Gopkg.lock b/Gopkg.lock index bc4c28f..f9bdf7a 100644 --- a/Gopkg.lock +++ b/Gopkg.lock @@ -87,7 +87,10 @@ [[projects]] digest = "1:3926a4ec9a4ff1a072458451aa2d9b98acd059a45b38f7335d31e06c3d6a0159" name = "github.com/stretchr/testify" - packages = ["assert"] + packages = [ + "assert", + "require", + ] pruneopts = "" revision = "69483b4bd14f5845b5a1e55bca19e954e827f1d0" version = "v1.1.4" @@ -170,6 +173,14 @@ revision = "836bfd95fecc0f1511dd66bdbf2b5b61ab8b00b6" version = "v1.2.11" +[[projects]] + digest = "1:11c58e19ff7ce22740423bb933f1ddca3bf575def40d5ac3437ec12871b1648b" + name = "gopkg.in/natefinch/lumberjack.v2" + packages = ["."] + pruneopts = "" + revision = "a96e63847dc3c67d17befa69c303767e2f84e54f" + version = "v2.1" + [[projects]] digest = "1:be4ed0a2b15944dd777a663681a39260ed05f9c4e213017ed2e2255622c8820c" name = "gopkg.in/square/go-jose.v2" @@ -192,12 +203,14 @@ "github.com/mbland/hmacauth", "github.com/mreiferson/go-options", "github.com/stretchr/testify/assert", + "github.com/stretchr/testify/require", "golang.org/x/crypto/bcrypt", "golang.org/x/oauth2", "golang.org/x/oauth2/google", "google.golang.org/api/admin/directory/v1", "google.golang.org/api/googleapi", "gopkg.in/fsnotify/fsnotify.v1", + "gopkg.in/natefinch/lumberjack.v2", ] solver-name = "gps-cdcl" solver-version = 1 diff --git a/Gopkg.toml b/Gopkg.toml index 253f154..f15d952 100644 --- 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 index 7c93bbc..524ba9b 100644 --- a/README.md +++ b/README.md @@ -185,6 +185,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 @@ -210,6 +212,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://]: or unix:// to listen on for HTTP clients (default "127.0.0.1:4180") -https-address string: : 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 -pass-access-token: pass OAuth access_token to upstream via X-Forwarded-Access-Token header -pass-authorization-header: pass OIDC IDToken to upstream via Authorization Bearer header @@ -222,7 +230,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) @@ -232,6 +240,8 @@ Usage of oauth2_proxy: -skip-auth-regex value: bypass authentication for requests path's that match (may be given multiple times) -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 @@ -361,9 +371,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: + +``` + - [19/Mar/2015:17:20:19 -0400] [] +``` + +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: ``` - [19/Mar/2015:17:20:19 -0400] GET "/path/" HTTP/1.1 "" @@ -376,7 +417,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] +``` + +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 index 56f36e6..c5d5623 100644 --- 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 index 4ea2482..8471db9 100644 --- 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 index 1fe21cd..0166e08 100644 --- 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 index 4456e39..c02f36e 100644 --- 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 @@ -47,17 +48,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 @@ -75,24 +76,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 diff --git a/logger/logger.go b/logger/logger.go new file mode 100644 index 0000000..9c9f2fe --- /dev/null +++ b/logger/logger.go @@ -0,0 +1,447 @@ +package logger + +import ( + "fmt" + "io" + "net" + "net/http" + "net/url" + "os" + "runtime" + "sync" + "text/template" + "time" +) + +type AuthStatus string + +const ( + // Default logging formats + DefaultStandardLoggingFormat = "[{{.Timestamp}}] [{{.File}}] {{.Message}}" + DefaultAuthLoggingFormat = "{{.Client}} - {{.Username}} [{{.Timestamp}}] [{{.Status}}] {{.Message}}" + DefaultRequestLoggingFormat = "{{.Client}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}" + + // Auth statuses + AuthSuccess AuthStatus = "AuthSuccess" + AuthFailure AuthStatus = "AuthFailure" + AuthError AuthStatus = "AuthError" + + // General logging config + Llongfile = 1 << iota // full file name and line number: /a/b/c/d.go:23 + Lshortfile // final file name element and line number: d.go:23. overrides Llongfile + LUTC // use UTC rather than the local time zone + LstdFlags = Lshortfile // initial values for the standard logger +) + +// These are the containers for all values that are available as variables in the logging formats. +// All values are pre-formatted strings so it is easy to use them in the format string. +type stdLogMessageData struct { + Timestamp, + File, + Message string +} + +type authLogMessageData struct { + Client, + Host, + Protocol, + RequestMethod, + Timestamp, + UserAgent, + Username, + Status, + Message string +} + +type reqLogMessageData struct { + Client, + Host, + Protocol, + RequestDuration, + RequestMethod, + RequestURI, + ResponseSize, + StatusCode, + Timestamp, + Upstream, + UserAgent, + Username string +} + +type Logger struct { + mu sync.Mutex + flag int + writer io.Writer + stdEnabled bool + authEnabled bool + reqEnabled bool + stdLogTemplate *template.Template + authTemplate *template.Template + reqTemplate *template.Template +} + +// New creates a new Standarderr Logger. +func New(flag int) *Logger { + return &Logger{ + writer: os.Stderr, + flag: flag, + stdEnabled: true, + authEnabled: true, + reqEnabled: true, + stdLogTemplate: template.Must(template.New("std-log").Parse(DefaultStandardLoggingFormat)), + authTemplate: template.Must(template.New("auth-log").Parse(DefaultAuthLoggingFormat)), + reqTemplate: template.Must(template.New("req-log").Parse(DefaultRequestLoggingFormat)), + } +} + +var std = New(LstdFlags) + +// Cheap integer to fixed-width decimal ASCII. Give a negative width to avoid zero-padding. +func itoa(buf *[]byte, i int, wid int) { + // Assemble decimal in reverse order. + var b [20]byte + bp := len(b) - 1 + for i >= 10 || wid > 1 { + wid-- + q := i / 10 + b[bp] = byte('0' + i - q*10) + bp-- + i = q + } + // i < 10 + b[bp] = byte('0' + i) + *buf = append(*buf, b[bp:]...) +} + +// Output a standard log template with a simple message. +// Write a final newline at the end of every message. +func (l *Logger) Output(calldepth int, message string) { + if !l.stdEnabled { + return + } + + now := time.Now() + file := "???:0" + + if l.flag&(Lshortfile|Llongfile) != 0 { + file = l.GetFileLineString(calldepth + 1) + } + + l.mu.Lock() + defer l.mu.Unlock() + + l.stdLogTemplate.Execute(l.writer, stdLogMessageData{ + Timestamp: FormatTimestamp(now), + File: file, + Message: message, + }) + + l.writer.Write([]byte("\n")) +} + +// Print auth details to the logger. Requires an http.Request to log details. +// Remaining arguments are handled in the manner of fmt.Sprintf. +// Writes a final newline to the end of every message. +func (l *Logger) PrintAuth(username string, req *http.Request, status AuthStatus, format string, a ...interface{}) { + if !l.authEnabled { + return + } + + now := time.Now() + + if username == "" { + username = "-" + } + + client := GetClient(req) + + l.mu.Lock() + defer l.mu.Unlock() + + l.authTemplate.Execute(l.writer, authLogMessageData{ + Client: client, + Host: req.Host, + Protocol: req.Proto, + RequestMethod: req.Method, + Timestamp: FormatTimestamp(now), + UserAgent: fmt.Sprintf("%q", req.UserAgent()), + Username: username, + Status: fmt.Sprintf("%s", status), + Message: fmt.Sprintf(format, a...), + }) + + l.writer.Write([]byte("\n")) +} + +// Print HTTP request details to the Logger. +// Writes a final newline to the end of every message. +func (l *Logger) PrintReq(username, upstream string, req *http.Request, url url.URL, ts time.Time, status int, size int) { + if !l.reqEnabled { + return + } + + duration := float64(time.Now().Sub(ts)) / float64(time.Second) + + if username == "" { + username = "-" + } + + if upstream == "" { + upstream = "-" + } + + if url.User != nil && username == "-" { + if name := url.User.Username(); name != "" { + username = name + } + } + + client := GetClient(req) + + l.mu.Lock() + defer l.mu.Unlock() + + l.reqTemplate.Execute(l.writer, reqLogMessageData{ + Client: client, + Host: req.Host, + Protocol: req.Proto, + RequestDuration: fmt.Sprintf("%0.3f", duration), + RequestMethod: req.Method, + RequestURI: fmt.Sprintf("%q", url.RequestURI()), + ResponseSize: fmt.Sprintf("%d", size), + StatusCode: fmt.Sprintf("%d", status), + Timestamp: FormatTimestamp(ts), + Upstream: upstream, + UserAgent: fmt.Sprintf("%q", req.UserAgent()), + Username: username, + }) + + l.writer.Write([]byte("\n")) +} + +// Obtains file and line number info for the standard output log +func (l *Logger) GetFileLineString(calldepth int) string { + var file string + var line int + var ok bool + + _, file, line, ok = runtime.Caller(calldepth) + if !ok { + file = "???" + line = 0 + } + + if l.flag&Lshortfile != 0 { + short := file + for i := len(file) - 1; i > 0; i-- { + if file[i] == '/' { + short = file[i+1:] + break + } + } + file = short + } + + return fmt.Sprintf("%s:%d", file, line) +} + +// Parse an HTTP request for the client/remote IP +func GetClient(req *http.Request) string { + client := req.Header.Get("X-Real-IP") + if client == "" { + client = req.RemoteAddr + } + + if c, _, err := net.SplitHostPort(client); err == nil { + client = c + } + + return client +} + +// Returns a formatted timestamp +func (l *Logger) FormatTimestamp(ts time.Time) string { + if l.flag&LUTC != 0 { + ts = ts.UTC() + } + + return ts.Format("2006/01/02 15:04:05") +} + +// Flags returns the output flags for the logger. +func (l *Logger) Flags() int { + l.mu.Lock() + defer l.mu.Unlock() + return l.flag +} + +// SetFlags sets the output flags for the logger. +func (l *Logger) SetFlags(flag int) { + l.mu.Lock() + defer l.mu.Unlock() + l.flag = flag +} + +// Set all logging enabled for the logger. +func (l *Logger) SetStandardEnabled(e bool) { + l.mu.Lock() + defer l.mu.Unlock() + l.stdEnabled = e +} + +// Set auth logging enabled for the standard logger +func (l *Logger) SetAuthEnabled(e bool) { + l.mu.Lock() + defer l.mu.Unlock() + l.authEnabled = e +} + +// Set request logging enabled for the standard logger +func (l *Logger) SetReqEnabled(e bool) { + l.mu.Lock() + defer l.mu.Unlock() + l.reqEnabled = e +} + +// Set the output template for the standard logger +func (l *Logger) SetStandardTemplate(t string) { + l.mu.Lock() + defer l.mu.Unlock() + l.stdLogTemplate = template.Must(template.New("std-log").Parse(t)) +} + +// Set the auth template for the standard logger +func (l *Logger) SetAuthTemplate(t string) { + l.mu.Lock() + defer l.mu.Unlock() + l.authTemplate = template.Must(template.New("auth-log").Parse(t)) +} + +// Set the request template for the standard logger +func (l *Logger) SetReqTemplate(t string) { + l.mu.Lock() + defer l.mu.Unlock() + l.reqTemplate = template.Must(template.New("req-log").Parse(t)) +} + +// These functions utilize the standard logger. + +// Returns a formatted timestamp for the standard logger. +func FormatTimestamp(ts time.Time) string { + return std.FormatTimestamp(ts) +} + +// Flags returns the output flags for the standard logger. +func Flags() int { + return std.Flags() +} + +// SetFlags sets the output flags for the standard logger. +func SetFlags(flag int) { + std.SetFlags(flag) +} + +// SetOutput sets the output destination for the standard logger. +func SetOutput(w io.Writer) { + std.mu.Lock() + defer std.mu.Unlock() + std.writer = w +} + +// Set output logging enabled for the standard logger +func SetStandardEnabled(e bool) { + std.SetStandardEnabled(e) +} + +// Set auth logging enabled for the standard logger +func SetAuthEnabled(e bool) { + std.SetAuthEnabled(e) +} + +// Set request logging enabled for the standard logger +func SetReqEnabled(e bool) { + std.SetReqEnabled(e) +} + +// Set the output template for the standard logger +func SetStandardTemplate(t string) { + std.SetStandardTemplate(t) +} + +// Set the auth template for the standard logger +func SetAuthTemplate(t string) { + std.SetAuthTemplate(t) +} + +// Set the request template for the standard logger +func SetReqTemplate(t string) { + std.SetReqTemplate(t) +} + +// Print calls Output to print to the standard logger. +// Arguments are handled in the manner of fmt.Print. +func Print(v ...interface{}) { + std.Output(2, fmt.Sprint(v...)) +} + +// Printf calls Output to print to the standard logger. +// Arguments are handled in the manner of fmt.Printf. +func Printf(format string, v ...interface{}) { + std.Output(2, fmt.Sprintf(format, v...)) +} + +// Println calls Output to print to the standard logger. +// Arguments are handled in the manner of fmt.Println. +func Println(v ...interface{}) { + std.Output(2, fmt.Sprintln(v...)) +} + +// Fatal is equivalent to Print() followed by a call to os.Exit(1). +func Fatal(v ...interface{}) { + std.Output(2, fmt.Sprint(v...)) + os.Exit(1) +} + +// Fatalf is equivalent to Printf() followed by a call to os.Exit(1). +func Fatalf(format string, v ...interface{}) { + std.Output(2, fmt.Sprintf(format, v...)) + os.Exit(1) +} + +// Fatalln is equivalent to Println() followed by a call to os.Exit(1). +func Fatalln(v ...interface{}) { + std.Output(2, fmt.Sprintln(v...)) + os.Exit(1) +} + +// Panic is equivalent to Print() followed by a call to panic(). +func Panic(v ...interface{}) { + s := fmt.Sprint(v...) + std.Output(2, s) + panic(s) +} + +// Panicf is equivalent to Printf() followed by a call to panic(). +func Panicf(format string, v ...interface{}) { + s := fmt.Sprintf(format, v...) + std.Output(2, s) + panic(s) +} + +// Panicln is equivalent to Println() followed by a call to panic(). +func Panicln(v ...interface{}) { + s := fmt.Sprintln(v...) + std.Output(2, s) + panic(s) +} + +// PrintAuthf writes authentication details to the standard logger. +// Arguments are handled in the manner of fmt.Printf. +func PrintAuthf(username string, req *http.Request, status AuthStatus, format string, a ...interface{}) { + std.PrintAuth(username, req, status, format, a...) +} + +// PrintAuthf writes request details to the standard logger. +func PrintReq(username, upstream string, req *http.Request, url url.URL, ts time.Time, status int, size int) { + std.PrintReq(username, upstream, req, url, ts, status, size) +} diff --git a/logging_handler.go b/logging_handler.go index d47ae58..1d38c3d 100644 --- a/logging_handler.go +++ b/logging_handler.go @@ -4,17 +4,10 @@ package main import ( - "fmt" - "io" - "net" "net/http" - "net/url" - "text/template" "time" -) -const ( - defaultRequestLoggingFormat = "{{.Client}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}" + "github.com/pusher/oauth2_proxy/logger" ) // responseLogger is wrapper of http.ResponseWriter that keeps track of its HTTP status @@ -82,93 +75,22 @@ func (l *responseLogger) Flush() { } } -// logMessageData is the container for all values that are available as variables in the request logging format. -// All values are pre-formatted strings so it is easy to use them in the format string. -type logMessageData struct { - Client, - Host, - Protocol, - RequestDuration, - RequestMethod, - RequestURI, - ResponseSize, - StatusCode, - Timestamp, - Upstream, - UserAgent, - Username string -} - // loggingHandler is the http.Handler implementation for LoggingHandlerTo and its friends type loggingHandler struct { - writer io.Writer - handler http.Handler - enabled bool - logTemplate *template.Template + handler http.Handler } // LoggingHandler provides an http.Handler which logs requests to the HTTP server -func LoggingHandler(out io.Writer, h http.Handler, v bool, requestLoggingTpl string) http.Handler { +func LoggingHandler(h http.Handler) http.Handler { return loggingHandler{ - writer: out, - handler: h, - enabled: v, - logTemplate: template.Must(template.New("request-log").Parse(requestLoggingTpl)), + handler: h, } } 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 - } - h.writeLogLine(logger.authInfo, logger.upstream, req, url, t, logger.Status(), logger.Size()) -} - -// 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 (h loggingHandler) writeLogLine(username, upstream string, req *http.Request, url url.URL, ts time.Time, status int, size int) { - 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) - - h.logTemplate.Execute(h.writer, logMessageData{ - Client: client, - Host: req.Host, - Protocol: req.Proto, - RequestDuration: fmt.Sprintf("%0.3f", duration), - RequestMethod: req.Method, - RequestURI: fmt.Sprintf("%q", url.RequestURI()), - ResponseSize: fmt.Sprintf("%d", size), - StatusCode: fmt.Sprintf("%d", status), - Timestamp: ts.Format("02/Jan/2006:15:04:05 -0700"), - Upstream: upstream, - UserAgent: fmt.Sprintf("%q", req.UserAgent()), - Username: username, - }) - - h.writer.Write([]byte("\n")) + responseLogger := &responseLogger{w: w} + h.handler.ServeHTTP(responseLogger, req) + logger.PrintReq(responseLogger.authInfo, responseLogger.upstream, req, url, t, responseLogger.Status(), responseLogger.Size()) } diff --git a/logging_handler_test.go b/logging_handler_test.go index 9717cd6..57176a8 100644 --- a/logging_handler_test.go +++ b/logging_handler_test.go @@ -7,6 +7,8 @@ import ( "net/http/httptest" "testing" "time" + + "github.com/pusher/oauth2_proxy/logger" ) func TestLoggingHandler_ServeHTTP(t *testing.T) { @@ -16,7 +18,7 @@ func TestLoggingHandler_ServeHTTP(t *testing.T) { Format, ExpectedLogMessage string }{ - {defaultRequestLoggingFormat, fmt.Sprintf("127.0.0.1 - - [%s] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n", ts.Format("02/Jan/2006:15:04:05 -0700"))}, + {logger.DefaultRequestLoggingFormat, fmt.Sprintf("127.0.0.1 - - [%s] test-server GET - \"/foo/bar\" HTTP/1.1 \"\" 200 4 0.000\n", logger.FormatTimestamp(ts))}, {"{{.RequestMethod}}", "GET\n"}, } @@ -26,7 +28,9 @@ func TestLoggingHandler_ServeHTTP(t *testing.T) { w.Write([]byte("test")) } - h := LoggingHandler(buf, http.HandlerFunc(handler), true, test.Format) + logger.SetOutput(buf) + logger.SetReqTemplate(test.Format) + h := LoggingHandler(http.HandlerFunc(handler)) r, _ := http.NewRequest("GET", "/foo/bar", nil) r.RemoteAddr = "127.0.0.1" diff --git a/main.go b/main.go index 57a6f22..8d4d16a 100644 --- a/main.go +++ b/main.go @@ -3,7 +3,6 @@ package main import ( "flag" "fmt" - "log" "os" "runtime" "strings" @@ -11,14 +10,16 @@ import ( "github.com/BurntSushi/toml" "github.com/mreiferson/go-options" + + "github.com/pusher/oauth2_proxy/logger" ) func main() { - log.SetFlags(log.Ldate | log.Ltime | log.Lshortfile) + logger.SetFlags(logger.Lshortfile) flagSet := flag.NewFlagSet("oauth2_proxy", flag.ExitOnError) emailDomains := StringArray{} - whitelistDomains := StringArray{} + whitelistandardomains := StringArray{} upstreams := StringArray{} skipAuthRegex := StringArray{} googleGroups := StringArray{} @@ -47,7 +48,7 @@ func main() { flagSet.Duration("flush-interval", time.Duration(1)*time.Second, "period between response flushing when streaming responses") flagSet.Var(&emailDomains, "email-domain", "authenticate emails with the specified domain (may be given multiple times). Use * to authenticate any email") - flagSet.Var(&whitelistDomains, "whitelist-domain", "allowed domains for redirection after authentication. Prefix domain with a . to allow subdomains (eg .example.com)") + flagSet.Var(&whitelistandardomains, "whitelist-domain", "allowed domains for redirection after authentication. Prefix domain with a . to allow subdomains (eg .example.com)") flagSet.String("azure-tenant", "common", "go to a tenant-specific or common (tenant-independent) endpoint.") flagSet.String("github-org", "", "restrict logins to members of this organisation") flagSet.String("github-team", "", "restrict logins to members of this team") @@ -71,8 +72,21 @@ 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.String("request-logging-format", defaultRequestLoggingFormat, "Template for log lines") + flagSet.String("logging-filename", "", "File to log requests to, empty for stdout") + flagSet.Int("logging-max-size", 100, "Maximum size in megabytes of the log file before rotation") + flagSet.Int("logging-max-age", 7, "Maximum number of days to retain old log files") + flagSet.Int("logging-max-backups", 0, "Maximum number of old log files to retain; 0 to disable") + flagSet.Bool("logging-local-time", true, "If the time in log files and backup filenames are local or UTC time") + flagSet.Bool("logging-compress", false, "Should rotated log files be compressed using gzip") + + flagSet.Bool("standard-logging", true, "Log standard runtime information") + flagSet.String("standard-logging-format", logger.DefaultStandardLoggingFormat, "Template for standard log lines") + + flagSet.Bool("request-logging", true, "Log HTTP requests") + flagSet.String("request-logging-format", logger.DefaultRequestLoggingFormat, "Template for HTTP request log lines") + + flagSet.Bool("auth-logging", true, "Log authentication attempts") + flagSet.String("auth-logging-format", logger.DefaultAuthLoggingFormat, "Template for authentication log lines") flagSet.String("provider", "google", "OAuth provider") flagSet.String("oidc-issuer-url", "", "OpenID Connect issuer URL (ie: https://accounts.google.com)") @@ -99,7 +113,7 @@ func main() { if *config != "" { _, err := toml.DecodeFile(*config, &cfg) if err != nil { - log.Fatalf("ERROR: failed to load config file %s - %s", *config, err) + logger.Fatalf("ERROR: failed to load config file %s - %s", *config, err) } } cfg.LoadEnvForStruct(opts) @@ -107,9 +121,10 @@ func main() { err := opts.Validate() if err != nil { - log.Printf("%s", err) + logger.Printf("%s", err) os.Exit(1) } + validator := NewValidator(opts.EmailDomains, opts.AuthenticatedEmailsFile) oauthproxy := NewOAuthProxy(opts, validator) @@ -122,16 +137,16 @@ func main() { } if opts.HtpasswdFile != "" { - log.Printf("using htpasswd file %s", opts.HtpasswdFile) + logger.Printf("using htpasswd file %s", opts.HtpasswdFile) oauthproxy.HtpasswdFile, err = NewHtpasswdFromFile(opts.HtpasswdFile) oauthproxy.DisplayHtpasswdForm = opts.DisplayHtpasswdForm if err != nil { - log.Fatalf("FATAL: unable to open %s %s", opts.HtpasswdFile, err) + logger.Fatalf("FATAL: unable to open %s %s", opts.HtpasswdFile, err) } } s := &Server{ - Handler: LoggingHandler(os.Stdout, oauthproxy, opts.RequestLogging, opts.RequestLoggingFormat), + Handler: LoggingHandler(oauthproxy), Opts: opts, } s.ListenAndServe() diff --git a/oauthproxy.go b/oauthproxy.go index ab70686..92affb6 100644 --- a/oauthproxy.go +++ b/oauthproxy.go @@ -5,7 +5,6 @@ import ( "errors" "fmt" "html/template" - "log" "net" "net/http" "net/http/httputil" @@ -16,6 +15,7 @@ import ( "github.com/mbland/hmacauth" "github.com/pusher/oauth2_proxy/cookie" + "github.com/pusher/oauth2_proxy/logger" "github.com/pusher/oauth2_proxy/providers" ) @@ -158,7 +158,7 @@ func NewOAuthProxy(opts *Options, validator func(string) bool) *OAuthProxy { switch u.Scheme { case httpScheme, httpsScheme: u.Path = "" - log.Printf("mapping path %q => upstream %q", path, u) + logger.Printf("mapping path %q => upstream %q", path, u) proxy := NewReverseProxy(u, opts.FlushInterval) if !opts.PassHostHeader { setProxyUpstreamHostHeader(proxy, u) @@ -171,7 +171,7 @@ func NewOAuthProxy(opts *Options, validator func(string) bool) *OAuthProxy { if u.Fragment != "" { path = u.Fragment } - log.Printf("mapping path %q => file system %q", path, u.Path) + logger.Printf("mapping path %q => file system %q", path, u.Path) proxy := NewFileServer(path, u.Path) serveMux.Handle(path, &UpstreamProxy{path, proxy, nil}) default: @@ -179,26 +179,26 @@ func NewOAuthProxy(opts *Options, validator func(string) bool) *OAuthProxy { } } for _, u := range opts.CompiledRegex { - log.Printf("compiled skip-auth-regex => %q", u) + logger.Printf("compiled skip-auth-regex => %q", u) } redirectURL := opts.redirectURL redirectURL.Path = fmt.Sprintf("%s/callback", opts.ProxyPrefix) - log.Printf("OAuthProxy configured for %s Client ID: %s", opts.provider.Data().ProviderName, opts.ClientID) + logger.Printf("OAuthProxy configured for %s Client ID: %s", opts.provider.Data().ProviderName, opts.ClientID) refresh := "disabled" if opts.CookieRefresh != time.Duration(0) { refresh = fmt.Sprintf("after %s", opts.CookieRefresh) } - log.Printf("Cookie settings: name:%s secure(https):%v httponly:%v expiry:%s domain:%s refresh:%s", opts.CookieName, opts.CookieSecure, opts.CookieHTTPOnly, opts.CookieExpire, opts.CookieDomain, refresh) + logger.Printf("Cookie settings: name:%s secure(https):%v httponly:%v expiry:%s domain:%s refresh:%s", opts.CookieName, opts.CookieSecure, opts.CookieHTTPOnly, opts.CookieExpire, opts.CookieDomain, refresh) var cipher *cookie.Cipher if opts.PassAccessToken || opts.SetAuthorization || opts.PassAuthorization || (opts.CookieRefresh != time.Duration(0)) { var err error cipher, err = cookie.NewCipher(secretBytes(opts.CookieSecret)) if err != nil { - log.Fatal("cookie-secret error: ", err) + logger.Fatal("cookie-secret error: ", err) } } @@ -400,7 +400,7 @@ func (p *OAuthProxy) makeCookie(req *http.Request, name string, value string, ex domain = h } if !strings.HasSuffix(domain, p.CookieDomain) { - log.Printf("Warning: request host is %q but using configured cookie domain of %q", domain, p.CookieDomain) + logger.Printf("Warning: request host is %q but using configured cookie domain of %q", domain, p.CookieDomain) } } @@ -495,7 +495,6 @@ func (p *OAuthProxy) PingPage(rw http.ResponseWriter) { // ErrorPage writes an error response func (p *OAuthProxy) ErrorPage(rw http.ResponseWriter, code int, title string, message string) { - log.Printf("ErrorPage %d %s %s", code, title, message) rw.WriteHeader(code) t := struct { Title string @@ -554,9 +553,10 @@ func (p *OAuthProxy) ManualSignIn(rw http.ResponseWriter, req *http.Request) (st } // check auth if p.HtpasswdFile.Validate(user, passwd) { - log.Printf("authenticated %q via HtpasswdFile", user) + logger.PrintAuthf(user, req, logger.AuthSuccess, "Successful authentication via HtpasswdFile") return user, true } + logger.PrintAuthf(user, req, logger.AuthFailure, "Failed authentication via HtpasswdFile; unauthorized") return "", false } @@ -652,6 +652,7 @@ func (p *OAuthProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) { func (p *OAuthProxy) SignIn(rw http.ResponseWriter, req *http.Request) { redirect, err := p.GetRedirect(req) if err != nil { + logger.Printf("Error obtaining redirect: %s", err.Error()) p.ErrorPage(rw, 500, "Internal Error", err.Error()) return } @@ -680,12 +681,14 @@ func (p *OAuthProxy) SignOut(rw http.ResponseWriter, req *http.Request) { func (p *OAuthProxy) OAuthStart(rw http.ResponseWriter, req *http.Request) { nonce, err := cookie.Nonce() if err != nil { + logger.Printf("Error obtaining nonce: %s", err.Error()) p.ErrorPage(rw, 500, "Internal Error", err.Error()) return } p.SetCSRFCookie(rw, req, nonce) redirect, err := p.GetRedirect(req) if err != nil { + logger.Printf("Error obtaining redirect: %s", err.Error()) p.ErrorPage(rw, 500, "Internal Error", err.Error()) return } @@ -701,24 +704,27 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) { // finish the oauth cycle err := req.ParseForm() if err != nil { + logger.Printf("Error while parsing OAuth callback: %s" + err.Error()) p.ErrorPage(rw, 500, "Internal Error", err.Error()) return } errorString := req.Form.Get("error") if errorString != "" { + logger.Printf("Error while parsing OAuth callback: %s ", errorString) p.ErrorPage(rw, 403, "Permission Denied", errorString) return } session, err := p.redeemCode(req.Host, req.Form.Get("code")) if err != nil { - log.Printf("%s error redeeming code %s", remoteAddr, err) + logger.Printf("Error while parsing OAuth callback: %s ", errorString) p.ErrorPage(rw, 500, "Internal Error", "Internal Error") return } s := strings.SplitN(req.Form.Get("state"), ":", 2) if len(s) != 2 { + logger.Printf("Error while parsing OAuth state; invalid length") p.ErrorPage(rw, 500, "Internal Error", "Invalid State") return } @@ -726,12 +732,13 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) { redirect := s[1] c, err := req.Cookie(p.CSRFCookieName) if err != nil { + logger.PrintAuthf(session.Email, req, logger.AuthFailure, "Failed authentication via oauth2; unable too obtain CSRF cookie") p.ErrorPage(rw, 403, "Permission Denied", err.Error()) return } p.ClearCSRFCookie(rw, req) if c.Value != nonce { - log.Printf("%s csrf token mismatch, potential attack", remoteAddr) + logger.PrintAuthf(session.Email, req, logger.AuthFailure, "Failed authentication via oauth2; csrf token mismatch, potential attack") p.ErrorPage(rw, 403, "Permission Denied", "csrf failed") return } @@ -742,16 +749,16 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) { // set cookie, or deny if p.Validator(session.Email) && p.provider.ValidateGroup(session.Email) { - log.Printf("%s authentication complete %s", remoteAddr, session) + logger.PrintAuthf(session.Email, req, logger.AuthSuccess, "Successful authentication via oauth2; %s", session) err := p.SaveSession(rw, req, session) if err != nil { - log.Printf("%s %s", remoteAddr, err) + logger.Printf("%s %s", remoteAddr, err) p.ErrorPage(rw, 500, "Internal Error", "Internal Error") return } http.Redirect(rw, req, redirect, 302) } else { - log.Printf("%s Permission Denied: %q is unauthorized", remoteAddr, session.Email) + logger.PrintAuthf(session.Email, req, logger.AuthSuccess, "Failed authentication via oauth2; unauthorized") p.ErrorPage(rw, 403, "Permission Denied", "Invalid Account") } } @@ -793,16 +800,16 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int session, sessionAge, err := p.LoadCookiedSession(req) if err != nil { - log.Printf("%s %s", remoteAddr, err) + logger.Printf("Error loading cookied session: %s", err) } if session != nil && sessionAge > p.CookieRefresh && p.CookieRefresh != time.Duration(0) { - log.Printf("%s refreshing %s old session cookie for %s (refresh after %s)", remoteAddr, sessionAge, session, p.CookieRefresh) + logger.Printf("Refreshing %s old session cookie for %s (refresh after %s)", sessionAge, session, p.CookieRefresh) saveSession = true } var ok bool if ok, err = p.provider.RefreshSessionIfNeeded(session); err != nil { - log.Printf("%s removing session. error refreshing access token %s %s", remoteAddr, err, session) + logger.Printf("%s removing session. error refreshing access token %s %s", remoteAddr, err, session) clearSession = true session = nil } else if ok { @@ -811,7 +818,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int } if session != nil && session.IsExpired() { - log.Printf("%s removing session. token expired %s", remoteAddr, session) + logger.Printf("Removing session; token expired %s", session) session = nil saveSession = false clearSession = true @@ -819,7 +826,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int if saveSession && !revalidated && session != nil && session.AccessToken != "" { if !p.provider.ValidateSessionState(session) { - log.Printf("%s removing session. error validating %s", remoteAddr, session) + logger.Printf("Removing session; error validating %s", session) saveSession = false session = nil clearSession = true @@ -827,7 +834,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int } if session != nil && session.Email != "" && !p.Validator(session.Email) { - log.Printf("%s Permission Denied: removing session %s", remoteAddr, session) + logger.Printf(session.Email, req, logger.AuthFailure, "Failed authentication via session; removing session %s", session) session = nil saveSession = false clearSession = true @@ -836,7 +843,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int if saveSession && session != nil { err = p.SaveSession(rw, req, session) if err != nil { - log.Printf("%s %s", remoteAddr, err) + logger.PrintAuthf(session.Email, req, logger.AuthError, "Save session error %s", err) return http.StatusInternalServerError } } @@ -847,9 +854,6 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int if session == nil { session, err = p.CheckBasicAuth(req) - if err != nil { - log.Printf("%s %s", remoteAddr, err) - } } if session == nil { @@ -921,9 +925,10 @@ func (p *OAuthProxy) CheckBasicAuth(req *http.Request) (*providers.SessionState, return nil, fmt.Errorf("invalid format %s", b) } if p.HtpasswdFile.Validate(pair[0], pair[1]) { - log.Printf("authenticated %q via basic auth", pair[0]) + logger.PrintAuthf(pair[0], req, logger.AuthSuccess, "Successful authentication via basic auth") return &providers.SessionState{User: pair[0]}, nil } + logger.PrintAuthf(pair[0], req, logger.AuthFailure, "Failed authentication via basic auth; not in Htpasswd file") return nil, fmt.Errorf("%s not in HtpasswdFile", pair[0]) } diff --git a/oauthproxy_test.go b/oauthproxy_test.go index 468f7b2..6bb91a0 100644 --- a/oauthproxy_test.go +++ b/oauthproxy_test.go @@ -5,7 +5,6 @@ import ( "encoding/base64" "io" "io/ioutil" - "log" "net" "net/http" "net/http/httptest" @@ -16,13 +15,14 @@ import ( "time" "github.com/mbland/hmacauth" + "github.com/pusher/oauth2_proxy/logger" "github.com/pusher/oauth2_proxy/providers" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) func init() { - log.SetFlags(log.Ldate | log.Ltime | log.Lshortfile) + logger.SetFlags(logger.Lshortfile) } @@ -185,7 +185,7 @@ func (tp *TestProvider) ValidateSessionState(session *providers.SessionState) bo func TestBasicAuthPassword(t *testing.T) { providerServer := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - log.Printf("%#v", r) + logger.Printf("%#v", r) var payload string switch r.URL.Path { case "/oauth/token": @@ -277,7 +277,7 @@ func NewPassAccessTokenTest(opts PassAccessTokenTestOptions) *PassAccessTokenTes t.providerServer = httptest.NewServer( http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - log.Printf("%#v", r) + logger.Printf("%#v", r) var payload string switch r.URL.Path { case "/oauth/token": diff --git a/options.go b/options.go index e096003..30d3c70 100644 --- a/options.go +++ b/options.go @@ -15,7 +15,9 @@ import ( oidc "github.com/coreos/go-oidc" "github.com/mbland/hmacauth" + "github.com/pusher/oauth2_proxy/logger" "github.com/pusher/oauth2_proxy/providers" + lumberjack "gopkg.in/natefinch/lumberjack.v2" ) // Options holds Configuration Options that can be set by Command Line Flag, @@ -79,8 +81,19 @@ type Options struct { Scope string `flag:"scope" cfg:"scope"` ApprovalPrompt string `flag:"approval-prompt" cfg:"approval_prompt"` - RequestLogging bool `flag:"request-logging" cfg:"request_logging"` - RequestLoggingFormat string `flag:"request-logging-format" cfg:"request_logging_format"` + // Configuration values for logging + LoggingFilename string `flag:"logging-filename" cfg:"logging_filename"` + LoggingMaxSize int `flag:"logging-max-size" cfg:"logging_max_size"` + LoggingMaxAge int `flag:"logging-max-age" cfg:"logging_max_age"` + LoggingMaxBackups int `flag:"logging-max-backups" cfg:"logging_max_backups"` + LoggingLocalTime bool `flag:"logging-local-time" cfg:"logging_local_time"` + LoggingCompress bool `flag:"logging-compress" cfg:"logging_compress"` + StandardLogging bool `flag:"standard-logging" cfg:"standard_logging"` + StandardLoggingFormat string `flag:"standard-logging-format" cfg:"standard_logging_format"` + RequestLogging bool `flag:"request-logging" cfg:"request_logging"` + RequestLoggingFormat string `flag:"request-logging-format" cfg:"request_logging_format"` + AuthLogging bool `flag:"auth-logging" cfg:"auth_logging"` + AuthLoggingFormat string `flag:"auth-logging-format" cfg:"auth_logging_format"` SignatureKey string `flag:"signature-key" cfg:"signature_key" env:"OAUTH2_PROXY_SIGNATURE_KEY"` @@ -102,26 +115,36 @@ type SignatureData struct { // NewOptions constructs a new Options with defaulted values func NewOptions() *Options { return &Options{ - ProxyPrefix: "/oauth2", - HTTPAddress: "127.0.0.1:4180", - HTTPSAddress: ":443", - DisplayHtpasswdForm: true, - CookieName: "_oauth2_proxy", - CookieSecure: true, - CookieHTTPOnly: true, - CookieExpire: time.Duration(168) * time.Hour, - CookieRefresh: time.Duration(0), - SetXAuthRequest: false, - SkipAuthPreflight: false, - PassBasicAuth: true, - PassUserHeaders: true, - PassAccessToken: false, - PassHostHeader: true, - SetAuthorization: false, - PassAuthorization: false, - ApprovalPrompt: "force", - RequestLogging: true, - RequestLoggingFormat: defaultRequestLoggingFormat, + ProxyPrefix: "/oauth2", + HTTPAddress: "127.0.0.1:4180", + HTTPSAddress: ":443", + DisplayHtpasswdForm: true, + CookieName: "_oauth2_proxy", + CookieSecure: true, + CookieHTTPOnly: true, + CookieExpire: time.Duration(168) * time.Hour, + CookieRefresh: time.Duration(0), + SetXAuthRequest: false, + SkipAuthPreflight: false, + PassBasicAuth: true, + PassUserHeaders: true, + PassAccessToken: false, + PassHostHeader: true, + SetAuthorization: false, + PassAuthorization: false, + ApprovalPrompt: "force", + LoggingFilename: "", + LoggingMaxSize: 100, + LoggingMaxAge: 7, + LoggingMaxBackups: 0, + LoggingLocalTime: true, + LoggingCompress: false, + StandardLogging: true, + StandardLoggingFormat: logger.DefaultStandardLoggingFormat, + RequestLogging: true, + RequestLoggingFormat: logger.DefaultRequestLoggingFormat, + AuthLogging: true, + AuthLoggingFormat: logger.DefaultAuthLoggingFormat, } } @@ -247,6 +270,7 @@ func (o *Options) Validate() error { msgs = parseSignatureKey(o, msgs) msgs = validateCookieName(o, msgs) + msgs = setupLogger(o, msgs) if len(msgs) != 0 { return fmt.Errorf("Invalid configuration:\n %s", @@ -345,3 +369,49 @@ func secretBytes(secret string) []byte { } return []byte(secret) } + +func setupLogger(o *Options, msgs []string) []string { + // Setup the log file + if len(o.LoggingFilename) > 0 { + // Validate that the file/dir can be written + file, err := os.OpenFile(o.LoggingFilename, os.O_WRONLY|os.O_CREATE, 0666) + if err != nil { + if os.IsPermission(err) { + return append(msgs, "unable to write to log file: "+o.LoggingFilename) + } + } + file.Close() + + logger.Printf("Redirecting logging to file: %s", o.LoggingFilename) + + logWriter := &lumberjack.Logger{ + Filename: o.LoggingFilename, + MaxSize: o.LoggingMaxSize, // megabytes + MaxAge: o.LoggingMaxAge, // days + MaxBackups: o.LoggingMaxBackups, + LocalTime: o.LoggingLocalTime, + Compress: o.LoggingCompress, + } + + logger.SetOutput(logWriter) + } + + // Supply a sanity warning to the logger if all logging is disabled + if !o.StandardLogging && !o.AuthLogging && !o.RequestLogging { + logger.Print("Warning: Logging disabled. No further logs will be shown.") + } + + // Pass configuration values to the standard logger + logger.SetStandardEnabled(o.StandardLogging) + logger.SetAuthEnabled(o.AuthLogging) + logger.SetReqEnabled(o.RequestLogging) + logger.SetStandardTemplate(o.StandardLoggingFormat) + logger.SetAuthTemplate(o.AuthLoggingFormat) + logger.SetReqTemplate(o.RequestLoggingFormat) + + if !o.LoggingLocalTime { + logger.SetFlags(logger.Flags() | logger.LUTC) + } + + return msgs +} diff --git a/providers/azure.go b/providers/azure.go index f93db40..baae38f 100644 --- a/providers/azure.go +++ b/providers/azure.go @@ -3,12 +3,12 @@ package providers import ( "errors" "fmt" - "log" "net/http" "net/url" "github.com/bitly/go-simplejson" "github.com/pusher/oauth2_proxy/api" + "github.com/pusher/oauth2_proxy/logger" ) // AzureProvider represents an Azure based Identity Provider @@ -116,12 +116,12 @@ func (p *AzureProvider) GetEmailAddress(s *SessionState) (string, error) { email, err = json.Get("userPrincipalName").String() if err != nil { - log.Printf("failed making request %s", err) + logger.Printf("failed making request %s", err) return "", err } if email == "" { - log.Printf("failed to get email address") + logger.Printf("failed to get email address") return "", err } diff --git a/providers/github.go b/providers/github.go index d39ee2b..47eebfa 100644 --- a/providers/github.go +++ b/providers/github.go @@ -4,12 +4,13 @@ import ( "encoding/json" "fmt" "io/ioutil" - "log" "net/http" "net/url" "path" "strconv" "strings" + + "github.com/pusher/oauth2_proxy/logger" ) // GitHubProvider represents an GitHub based Identity Provider @@ -116,13 +117,13 @@ func (p *GitHubProvider) hasOrg(accessToken string) (bool, error) { var presentOrgs []string for _, org := range orgs { if p.Org == org.Login { - log.Printf("Found Github Organization: %q", org.Login) + logger.Printf("Found Github Organization: %q", org.Login) return true, nil } presentOrgs = append(presentOrgs, org.Login) } - log.Printf("Missing Organization:%q in %v", p.Org, presentOrgs) + logger.Printf("Missing Organization:%q in %v", p.Org, presentOrgs) return false, nil } @@ -179,7 +180,7 @@ func (p *GitHubProvider) hasOrgAndTeam(accessToken string) (bool, error) { ts := strings.Split(p.Team, ",") for _, t := range ts { if t == team.Slug { - log.Printf("Found Github Organization:%q Team:%q (Name:%q)", team.Org.Login, team.Slug, team.Name) + logger.Printf("Found Github Organization:%q Team:%q (Name:%q)", team.Org.Login, team.Slug, team.Name) return true, nil } } @@ -187,13 +188,13 @@ func (p *GitHubProvider) hasOrgAndTeam(accessToken string) (bool, error) { } } if hasOrg { - log.Printf("Missing Team:%q from Org:%q in teams: %v", p.Team, p.Org, presentTeams) + logger.Printf("Missing Team:%q from Org:%q in teams: %v", p.Team, p.Org, presentTeams) } else { var allOrgs []string for org := range presentOrgs { allOrgs = append(allOrgs, org) } - log.Printf("Missing Organization:%q in %#v", p.Org, allOrgs) + logger.Printf("Missing Organization:%q in %#v", p.Org, allOrgs) } return false, nil } @@ -241,7 +242,7 @@ func (p *GitHubProvider) GetEmailAddress(s *SessionState) (string, error) { resp.StatusCode, endpoint.String(), body) } - log.Printf("got %d from %q %s", resp.StatusCode, endpoint.String(), body) + logger.Printf("got %d from %q %s", resp.StatusCode, endpoint.String(), body) if err := json.Unmarshal(body, &emails); err != nil { return "", fmt.Errorf("%s unmarshaling %s", err, body) @@ -291,7 +292,7 @@ func (p *GitHubProvider) GetUserName(s *SessionState) (string, error) { resp.StatusCode, endpoint.String(), body) } - log.Printf("got %d from %q %s", resp.StatusCode, endpoint.String(), body) + logger.Printf("got %d from %q %s", resp.StatusCode, endpoint.String(), body) if err := json.Unmarshal(body, &user); err != nil { return "", fmt.Errorf("%s unmarshaling %s", err, body) diff --git a/providers/gitlab.go b/providers/gitlab.go index 446727d..1962552 100644 --- a/providers/gitlab.go +++ b/providers/gitlab.go @@ -1,11 +1,11 @@ package providers import ( - "log" "net/http" "net/url" "github.com/pusher/oauth2_proxy/api" + "github.com/pusher/oauth2_proxy/logger" ) // GitLabProvider represents an GitLab based Identity Provider @@ -49,12 +49,12 @@ func (p *GitLabProvider) GetEmailAddress(s *SessionState) (string, error) { req, err := http.NewRequest("GET", p.ValidateURL.String()+"?access_token="+s.AccessToken, nil) if err != nil { - log.Printf("failed building request %s", err) + logger.Printf("failed building request %s", err) return "", err } json, err := api.Request(req) if err != nil { - log.Printf("failed making request %s", err) + logger.Printf("failed making request %s", err) return "", err } return json.Get("email").String() diff --git a/providers/google.go b/providers/google.go index feea36f..9e27aa9 100644 --- a/providers/google.go +++ b/providers/google.go @@ -8,12 +8,12 @@ import ( "fmt" "io" "io/ioutil" - "log" "net/http" "net/url" "strings" "time" + "github.com/pusher/oauth2_proxy/logger" "golang.org/x/oauth2" "golang.org/x/oauth2/google" "google.golang.org/api/admin/directory/v1" @@ -167,18 +167,18 @@ func (p *GoogleProvider) SetGroupRestriction(groups []string, adminEmail string, func getAdminService(adminEmail string, credentialsReader io.Reader) *admin.Service { data, err := ioutil.ReadAll(credentialsReader) if err != nil { - log.Fatal("can't read Google credentials file:", err) + logger.Fatal("can't read Google credentials file:", err) } conf, err := google.JWTConfigFromJSON(data, admin.AdminDirectoryUserReadonlyScope, admin.AdminDirectoryGroupReadonlyScope) if err != nil { - log.Fatal("can't load Google credentials file:", err) + logger.Fatal("can't load Google credentials file:", err) } conf.Subject = adminEmail client := conf.Client(oauth2.NoContext) adminService, err := admin.New(client) if err != nil { - log.Fatal(err) + logger.Fatal(err) } return adminService } @@ -186,7 +186,7 @@ func getAdminService(adminEmail string, credentialsReader io.Reader) *admin.Serv func userInGroup(service *admin.Service, groups []string, email string) bool { user, err := fetchUser(service, email) if err != nil { - log.Printf("error fetching user: %v", err) + logger.Printf("error fetching user: %v", err) return false } id := user.Id @@ -196,9 +196,9 @@ func userInGroup(service *admin.Service, groups []string, email string) bool { members, err := fetchGroupMembers(service, group) if err != nil { if err, ok := err.(*googleapi.Error); ok && err.Code == 404 { - log.Printf("error fetching members for group %s: group does not exist", group) + logger.Printf("error fetching members for group %s: group does not exist", group) } else { - log.Printf("error fetching group members: %v", err) + logger.Printf("error fetching group members: %v", err) return false } } @@ -273,7 +273,7 @@ func (p *GoogleProvider) RefreshSessionIfNeeded(s *SessionState) (bool, error) { origExpiration := s.ExpiresOn s.AccessToken = newToken s.ExpiresOn = time.Now().Add(duration).Truncate(time.Second) - log.Printf("refreshed access token %s (expired on %s)", s, origExpiration) + logger.Printf("refreshed access token %s (expired on %s)", s, origExpiration) return true, nil } diff --git a/providers/internal_util.go b/providers/internal_util.go index a2098d3..7144dee 100644 --- a/providers/internal_util.go +++ b/providers/internal_util.go @@ -2,11 +2,11 @@ package providers import ( "io/ioutil" - "log" "net/http" "net/url" "github.com/pusher/oauth2_proxy/api" + "github.com/pusher/oauth2_proxy/logger" ) // stripToken is a helper function to obfuscate "access_token" @@ -24,14 +24,14 @@ func stripToken(endpoint string) string { func stripParam(param, endpoint string) string { u, err := url.Parse(endpoint) if err != nil { - log.Printf("error attempting to strip %s: %s", param, err) + logger.Printf("error attempting to strip %s: %s", param, err) return endpoint } if u.RawQuery != "" { values, err := url.ParseQuery(u.RawQuery) if err != nil { - log.Printf("error attempting to strip %s: %s", param, err) + logger.Printf("error attempting to strip %s: %s", param, err) return u.String() } @@ -57,18 +57,18 @@ func validateToken(p Provider, accessToken string, header http.Header) bool { } resp, err := api.RequestUnparsedResponse(endpoint, header) if err != nil { - log.Printf("GET %s", stripToken(endpoint)) - log.Printf("token validation request failed: %s", err) + logger.Printf("GET %s", stripToken(endpoint)) + logger.Printf("token validation request failed: %s", err) return false } body, _ := ioutil.ReadAll(resp.Body) resp.Body.Close() - log.Printf("%d GET %s %s", resp.StatusCode, stripToken(endpoint), body) + logger.Printf("%d GET %s %s", resp.StatusCode, stripToken(endpoint), body) if resp.StatusCode == 200 { return true } - log.Printf("token validation request failed: status %d - %s", resp.StatusCode, body) + logger.Printf("token validation request failed: status %d - %s", resp.StatusCode, body) return false } diff --git a/templates.go b/templates.go index ec5d0b2..ec1ba87 100644 --- a/templates.go +++ b/templates.go @@ -2,18 +2,19 @@ package main import ( "html/template" - "log" "path" + + "github.com/pusher/oauth2_proxy/logger" ) func loadTemplates(dir string) *template.Template { if dir == "" { return getTemplates() } - log.Printf("using custom template directory %q", dir) + logger.Printf("using custom template directory %q", dir) t, err := template.New("").ParseFiles(path.Join(dir, "sign_in.html"), path.Join(dir, "error.html")) if err != nil { - log.Fatalf("failed parsing template %s", err) + logger.Fatalf("failed parsing template %s", err) } return t } @@ -151,7 +152,7 @@ func getTemplates() *template.Template { {{end}}`) if err != nil { - log.Fatalf("failed parsing template %s", err) + logger.Fatalf("failed parsing template %s", err) } t, err = t.Parse(`{{define "error.html"}} @@ -169,7 +170,7 @@ func getTemplates() *template.Template { {{end}}`) if err != nil { - log.Fatalf("failed parsing template %s", err) + logger.Fatalf("failed parsing template %s", err) } return t } diff --git a/validator.go b/validator.go index 67e19d3..1a5c465 100644 --- a/validator.go +++ b/validator.go @@ -3,11 +3,12 @@ package main import ( "encoding/csv" "fmt" - "log" "os" "strings" "sync/atomic" "unsafe" + + "github.com/pusher/oauth2_proxy/logger" ) // UserMap holds information from the authenticated emails file @@ -22,7 +23,7 @@ func NewUserMap(usersFile string, done <-chan bool, onUpdate func()) *UserMap { m := make(map[string]bool) atomic.StorePointer(&um.m, unsafe.Pointer(&m)) if usersFile != "" { - log.Printf("using authenticated emails file %s", usersFile) + logger.Printf("using authenticated emails file %s", usersFile) WatchForUpdates(usersFile, done, func() { um.LoadAuthenticatedEmailsFile() onUpdate() @@ -44,7 +45,7 @@ func (um *UserMap) IsValid(email string) (result bool) { func (um *UserMap) LoadAuthenticatedEmailsFile() { r, err := os.Open(um.usersFile) if err != nil { - log.Fatalf("failed opening authenticated-emails-file=%q, %s", um.usersFile, err) + logger.Fatalf("failed opening authenticated-emails-file=%q, %s", um.usersFile, err) } defer r.Close() csvReader := csv.NewReader(r) @@ -53,7 +54,7 @@ func (um *UserMap) LoadAuthenticatedEmailsFile() { csvReader.TrimLeadingSpace = true records, err := csvReader.ReadAll() if err != nil { - log.Printf("error reading authenticated-emails-file=%q, %s", um.usersFile, err) + logger.Printf("error reading authenticated-emails-file=%q, %s", um.usersFile, err) return } updated := make(map[string]bool) diff --git a/watcher.go b/watcher.go index 0ba4234..34e98d7 100644 --- a/watcher.go +++ b/watcher.go @@ -3,11 +3,11 @@ package main import ( - "log" "os" "path/filepath" "time" + "github.com/pusher/oauth2_proxy/logger" fsnotify "gopkg.in/fsnotify/fsnotify.v1" ) @@ -24,7 +24,7 @@ func WaitForReplacement(filename string, op fsnotify.Op, for { if _, err := os.Stat(filename); err == nil { if err := watcher.Add(filename); err == nil { - log.Printf("watching resumed for %s", filename) + logger.Printf("watching resumed for %s", filename) return } } @@ -37,14 +37,14 @@ func WatchForUpdates(filename string, done <-chan bool, action func()) { filename = filepath.Clean(filename) watcher, err := fsnotify.NewWatcher() if err != nil { - log.Fatal("failed to create watcher for ", filename, ": ", err) + logger.Fatal("failed to create watcher for ", filename, ": ", err) } go func() { defer watcher.Close() for { select { case _ = <-done: - log.Printf("Shutting down watcher for: %s", filename) + logger.Printf("Shutting down watcher for: %s", filename) return case event := <-watcher.Events: // On Arch Linux, it appears Chmod events precede Remove events, @@ -53,19 +53,19 @@ func WatchForUpdates(filename string, done <-chan bool, action func()) { // UserMap.LoadAuthenticatedEmailsFile()) crashes when the file // can't be opened. if event.Op&(fsnotify.Remove|fsnotify.Rename|fsnotify.Chmod) != 0 { - log.Printf("watching interrupted on event: %s", event) + logger.Printf("watching interrupted on event: %s", event) watcher.Remove(filename) WaitForReplacement(filename, event.Op, watcher) } - log.Printf("reloading after event: %s", event) + logger.Printf("reloading after event: %s", event) action() case err = <-watcher.Errors: - log.Printf("error watching %s: %s", filename, err) + logger.Printf("error watching %s: %s", filename, err) } } }() if err = watcher.Add(filename); err != nil { - log.Fatal("failed to add ", filename, " to watcher: ", err) + logger.Fatal("failed to add ", filename, " to watcher: ", err) } - log.Printf("watching %s for updates", filename) + logger.Printf("watching %s for updates", filename) } diff --git a/watcher_unsupported.go b/watcher_unsupported.go index 937f49b..1f6e3fc 100644 --- a/watcher_unsupported.go +++ b/watcher_unsupported.go @@ -2,11 +2,9 @@ package main -import ( - "log" -) +import "github.com/pusher/oauth2_proxy/logger" func WatchForUpdates(filename string, done <-chan bool, action func()) { - log.Printf("file watching not implemented on this platform") + logger.Printf("file watching not implemented on this platform") go func() { <-done }() } From 2e5c877dd18282a32a12af582f8899eb64fd2c48 Mon Sep 17 00:00:00 2001 From: MisterWil Date: Sun, 10 Feb 2019 09:01:13 -0800 Subject: [PATCH 2/5] Self code review changes --- main.go | 4 ++-- oauthproxy.go | 26 +++++++++++++------------- 2 files changed, 15 insertions(+), 15 deletions(-) diff --git a/main.go b/main.go index 8d4d16a..9445986 100644 --- a/main.go +++ b/main.go @@ -19,7 +19,7 @@ func main() { flagSet := flag.NewFlagSet("oauth2_proxy", flag.ExitOnError) emailDomains := StringArray{} - whitelistandardomains := StringArray{} + whitelistDomains := StringArray{} upstreams := StringArray{} skipAuthRegex := StringArray{} googleGroups := StringArray{} @@ -48,7 +48,7 @@ func main() { flagSet.Duration("flush-interval", time.Duration(1)*time.Second, "period between response flushing when streaming responses") flagSet.Var(&emailDomains, "email-domain", "authenticate emails with the specified domain (may be given multiple times). Use * to authenticate any email") - flagSet.Var(&whitelistandardomains, "whitelist-domain", "allowed domains for redirection after authentication. Prefix domain with a . to allow subdomains (eg .example.com)") + flagSet.Var(&whitelistDomains, "whitelist-domain", "allowed domains for redirection after authentication. Prefix domain with a . to allow subdomains (eg .example.com)") flagSet.String("azure-tenant", "common", "go to a tenant-specific or common (tenant-independent) endpoint.") flagSet.String("github-org", "", "restrict logins to members of this organisation") flagSet.String("github-team", "", "restrict logins to members of this team") diff --git a/oauthproxy.go b/oauthproxy.go index 92affb6..f4d03f9 100644 --- a/oauthproxy.go +++ b/oauthproxy.go @@ -553,10 +553,10 @@ func (p *OAuthProxy) ManualSignIn(rw http.ResponseWriter, req *http.Request) (st } // check auth if p.HtpasswdFile.Validate(user, passwd) { - logger.PrintAuthf(user, req, logger.AuthSuccess, "Successful authentication via HtpasswdFile") + logger.PrintAuthf(user, req, logger.AuthSuccess, "Authenticated via HtpasswdFile") return user, true } - logger.PrintAuthf(user, req, logger.AuthFailure, "Failed authentication via HtpasswdFile; unauthorized") + logger.PrintAuthf(user, req, logger.AuthFailure, "Invalid authentication via HtpasswdFile") return "", false } @@ -704,27 +704,27 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) { // finish the oauth cycle err := req.ParseForm() if err != nil { - logger.Printf("Error while parsing OAuth callback: %s" + err.Error()) + logger.Printf("Error while parsing OAuth2 callback: %s" + err.Error()) p.ErrorPage(rw, 500, "Internal Error", err.Error()) return } errorString := req.Form.Get("error") if errorString != "" { - logger.Printf("Error while parsing OAuth callback: %s ", errorString) + logger.Printf("Error while parsing OAuth2 callback: %s ", errorString) p.ErrorPage(rw, 403, "Permission Denied", errorString) return } session, err := p.redeemCode(req.Host, req.Form.Get("code")) if err != nil { - logger.Printf("Error while parsing OAuth callback: %s ", errorString) + logger.Printf("Error redeeming code during OAuth2 callback: %s ", errorString) p.ErrorPage(rw, 500, "Internal Error", "Internal Error") return } s := strings.SplitN(req.Form.Get("state"), ":", 2) if len(s) != 2 { - logger.Printf("Error while parsing OAuth state; invalid length") + logger.Printf("Error while parsing OAuth2 state; invalid length") p.ErrorPage(rw, 500, "Internal Error", "Invalid State") return } @@ -732,13 +732,13 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) { redirect := s[1] c, err := req.Cookie(p.CSRFCookieName) if err != nil { - logger.PrintAuthf(session.Email, req, logger.AuthFailure, "Failed authentication via oauth2; unable too obtain CSRF cookie") + logger.PrintAuthf(session.Email, req, logger.AuthFailure, "Invalid authentication via OAuth2; unable too obtain CSRF cookie") p.ErrorPage(rw, 403, "Permission Denied", err.Error()) return } p.ClearCSRFCookie(rw, req) if c.Value != nonce { - logger.PrintAuthf(session.Email, req, logger.AuthFailure, "Failed authentication via oauth2; csrf token mismatch, potential attack") + logger.PrintAuthf(session.Email, req, logger.AuthFailure, "Invalid authentication via OAuth2; csrf token mismatch, potential attack") p.ErrorPage(rw, 403, "Permission Denied", "csrf failed") return } @@ -749,7 +749,7 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) { // set cookie, or deny if p.Validator(session.Email) && p.provider.ValidateGroup(session.Email) { - logger.PrintAuthf(session.Email, req, logger.AuthSuccess, "Successful authentication via oauth2; %s", session) + logger.PrintAuthf(session.Email, req, logger.AuthSuccess, "Authenticated via OAuth2; %s", session) err := p.SaveSession(rw, req, session) if err != nil { logger.Printf("%s %s", remoteAddr, err) @@ -758,7 +758,7 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) { } http.Redirect(rw, req, redirect, 302) } else { - logger.PrintAuthf(session.Email, req, logger.AuthSuccess, "Failed authentication via oauth2; unauthorized") + logger.PrintAuthf(session.Email, req, logger.AuthSuccess, "Invalid authentication via OAuth2; unauthorized") p.ErrorPage(rw, 403, "Permission Denied", "Invalid Account") } } @@ -834,7 +834,7 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int } if session != nil && session.Email != "" && !p.Validator(session.Email) { - logger.Printf(session.Email, req, logger.AuthFailure, "Failed authentication via session; removing session %s", session) + logger.Printf(session.Email, req, logger.AuthFailure, "Invalid authentication via session; removing session %s", session) session = nil saveSession = false clearSession = true @@ -925,10 +925,10 @@ func (p *OAuthProxy) CheckBasicAuth(req *http.Request) (*providers.SessionState, return nil, fmt.Errorf("invalid format %s", b) } if p.HtpasswdFile.Validate(pair[0], pair[1]) { - logger.PrintAuthf(pair[0], req, logger.AuthSuccess, "Successful authentication via basic auth") + logger.PrintAuthf(pair[0], req, logger.AuthSuccess, "Authenticated via basic auth and HTpasswd File") return &providers.SessionState{User: pair[0]}, nil } - logger.PrintAuthf(pair[0], req, logger.AuthFailure, "Failed authentication via basic auth; not in Htpasswd file") + logger.PrintAuthf(pair[0], req, logger.AuthFailure, "Invalid authentication via basic auth; not in Htpasswd File") return nil, fmt.Errorf("%s not in HtpasswdFile", pair[0]) } From b8da1dec4a67b8226404413667c81854d162e761 Mon Sep 17 00:00:00 2001 From: MisterWil Date: Fri, 15 Feb 2019 10:07:25 -0800 Subject: [PATCH 3/5] Fixed linting errors. --- logger/logger.go | 103 +++++++++++++++++++++++++---------------------- oauthproxy.go | 5 ++- 2 files changed, 58 insertions(+), 50 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index 9c9f2fe..8e27733 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -13,24 +13,32 @@ import ( "time" ) +// AuthStatus defines the different types of auth logging that occur type AuthStatus string const ( - // Default logging formats + // DefaultStandardLoggingFormat defines the default standard log format DefaultStandardLoggingFormat = "[{{.Timestamp}}] [{{.File}}] {{.Message}}" - DefaultAuthLoggingFormat = "{{.Client}} - {{.Username}} [{{.Timestamp}}] [{{.Status}}] {{.Message}}" - DefaultRequestLoggingFormat = "{{.Client}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}" + // DefaultAuthLoggingFormat defines the default auth log format + DefaultAuthLoggingFormat = "{{.Client}} - {{.Username}} [{{.Timestamp}}] [{{.Status}}] {{.Message}}" + // DefaultRequestLoggingFormat defines the default request log format + DefaultRequestLoggingFormat = "{{.Client}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}" - // Auth statuses + // AuthSuccess indicates that an auth attempt has succeeded explicitly AuthSuccess AuthStatus = "AuthSuccess" + // AuthFailure indicates that an auth attempt has failed explicitly AuthFailure AuthStatus = "AuthFailure" - AuthError AuthStatus = "AuthError" + // AuthError indicates that an auth attempt has failed due to an error + AuthError AuthStatus = "AuthError" - // General logging config - Llongfile = 1 << iota // full file name and line number: /a/b/c/d.go:23 - Lshortfile // final file name element and line number: d.go:23. overrides Llongfile - LUTC // use UTC rather than the local time zone - LstdFlags = Lshortfile // initial values for the standard logger + // Llongfile flag to log full file name and line number: /a/b/c/d.go:23 + Llongfile = 1 << iota + // Lshortfile flag to log final file name element and line number: d.go:23. overrides Llongfile + Lshortfile + // LUTC flag to log UTC datetime rather than the local time zone + LUTC + // LstdFlags flag for initial values for the logger + LstdFlags = Lshortfile ) // These are the containers for all values that are available as variables in the logging formats. @@ -68,6 +76,11 @@ type reqLogMessageData struct { Username string } +// A Logger represents an active logging object that generates lines of +// output to an io.Writer passed through a formatter. Each logging +// operation makes a single call to the Writer's Write method. A Logger +// can be used simultaneously from multiple goroutines; it guarantees to +// serialize access to the Writer. type Logger struct { mu sync.Mutex flag int @@ -96,23 +109,6 @@ func New(flag int) *Logger { var std = New(LstdFlags) -// Cheap integer to fixed-width decimal ASCII. Give a negative width to avoid zero-padding. -func itoa(buf *[]byte, i int, wid int) { - // Assemble decimal in reverse order. - var b [20]byte - bp := len(b) - 1 - for i >= 10 || wid > 1 { - wid-- - q := i / 10 - b[bp] = byte('0' + i - q*10) - bp-- - i = q - } - // i < 10 - b[bp] = byte('0' + i) - *buf = append(*buf, b[bp:]...) -} - // Output a standard log template with a simple message. // Write a final newline at the end of every message. func (l *Logger) Output(calldepth int, message string) { @@ -139,9 +135,9 @@ func (l *Logger) Output(calldepth int, message string) { l.writer.Write([]byte("\n")) } -// Print auth details to the logger. Requires an http.Request to log details. -// Remaining arguments are handled in the manner of fmt.Sprintf. -// Writes a final newline to the end of every message. +// PrintAuth writes auth info to the logger. Requires an http.Request to +// log request details. Remaining arguments are handled in the manner of +// fmt.Sprintf. Writes a final newline to the end of every message. func (l *Logger) PrintAuth(username string, req *http.Request, status AuthStatus, format string, a ...interface{}) { if !l.authEnabled { return @@ -173,8 +169,9 @@ func (l *Logger) PrintAuth(username string, req *http.Request, status AuthStatus l.writer.Write([]byte("\n")) } -// Print HTTP request details to the Logger. -// Writes a final newline to the end of every message. +// PrintReq writes request details to the Logger using the http.Request, +// url, and timestamp of the request. Writes a final newline to the end +// of every message. func (l *Logger) PrintReq(username, upstream string, req *http.Request, url url.URL, ts time.Time, status int, size int) { if !l.reqEnabled { return @@ -219,7 +216,9 @@ func (l *Logger) PrintReq(username, upstream string, req *http.Request, url url. l.writer.Write([]byte("\n")) } -// Obtains file and line number info for the standard output log +// GetFileLineString will find the caller file and line number +// taking in to account the calldepth to iterate up the stack +// to find the non-logging call location. func (l *Logger) GetFileLineString(calldepth int) string { var file string var line int @@ -245,7 +244,7 @@ func (l *Logger) GetFileLineString(calldepth int) string { return fmt.Sprintf("%s:%d", file, line) } -// Parse an HTTP request for the client/remote IP +// GetClient parses an HTTP request for the client/remote IP address. func GetClient(req *http.Request) string { client := req.Header.Get("X-Real-IP") if client == "" { @@ -259,7 +258,7 @@ func GetClient(req *http.Request) string { return client } -// Returns a formatted timestamp +// FormatTimestamp returns a formatted timestamp. func (l *Logger) FormatTimestamp(ts time.Time) string { if l.flag&LUTC != 0 { ts = ts.UTC() @@ -282,42 +281,42 @@ func (l *Logger) SetFlags(flag int) { l.flag = flag } -// Set all logging enabled for the logger. +// SetStandardEnabled enables or disables standard logging. func (l *Logger) SetStandardEnabled(e bool) { l.mu.Lock() defer l.mu.Unlock() l.stdEnabled = e } -// Set auth logging enabled for the standard logger +// SetAuthEnabled enables or disables auth logging. func (l *Logger) SetAuthEnabled(e bool) { l.mu.Lock() defer l.mu.Unlock() l.authEnabled = e } -// Set request logging enabled for the standard logger +// SetReqEnabled enabled or disables request logging. func (l *Logger) SetReqEnabled(e bool) { l.mu.Lock() defer l.mu.Unlock() l.reqEnabled = e } -// Set the output template for the standard logger +// SetStandardTemplate sets the template for standard logging. func (l *Logger) SetStandardTemplate(t string) { l.mu.Lock() defer l.mu.Unlock() l.stdLogTemplate = template.Must(template.New("std-log").Parse(t)) } -// Set the auth template for the standard logger +// SetAuthTemplate sets the template for auth logging. func (l *Logger) SetAuthTemplate(t string) { l.mu.Lock() defer l.mu.Unlock() l.authTemplate = template.Must(template.New("auth-log").Parse(t)) } -// Set the request template for the standard logger +// SetReqTemplate sets the template for request logging. func (l *Logger) SetReqTemplate(t string) { l.mu.Lock() defer l.mu.Unlock() @@ -326,7 +325,7 @@ func (l *Logger) SetReqTemplate(t string) { // These functions utilize the standard logger. -// Returns a formatted timestamp for the standard logger. +// FormatTimestamp returns a formatted timestamp for the standard logger. func FormatTimestamp(ts time.Time) string { return std.FormatTimestamp(ts) } @@ -348,32 +347,38 @@ func SetOutput(w io.Writer) { std.writer = w } -// Set output logging enabled for the standard logger +// SetStandardEnabled enables or disables standard logging for the +// standard logger. func SetStandardEnabled(e bool) { std.SetStandardEnabled(e) } -// Set auth logging enabled for the standard logger +// SetAuthEnabled enables or disables auth logging for the standard +// logger. func SetAuthEnabled(e bool) { std.SetAuthEnabled(e) } -// Set request logging enabled for the standard logger +// SetReqEnabled enables or disables request logging for the +// standard logger. func SetReqEnabled(e bool) { std.SetReqEnabled(e) } -// Set the output template for the standard logger +// SetStandardTemplate sets the template for standard logging for +// the standard logger. func SetStandardTemplate(t string) { std.SetStandardTemplate(t) } -// Set the auth template for the standard logger +// SetAuthTemplate sets the template for auth logging for the +// standard logger. func SetAuthTemplate(t string) { std.SetAuthTemplate(t) } -// Set the request template for the standard logger +// SetReqTemplate sets the template for request logging for the +// standard logger. func SetReqTemplate(t string) { std.SetReqTemplate(t) } @@ -441,7 +446,7 @@ func PrintAuthf(username string, req *http.Request, status AuthStatus, format st std.PrintAuth(username, req, status, format, a...) } -// PrintAuthf writes request details to the standard logger. +// PrintReq writes request details to the standard logger. func PrintReq(username, upstream string, req *http.Request, url url.URL, ts time.Time, status int, size int) { std.PrintReq(username, upstream, req, url, ts, status, size) } diff --git a/oauthproxy.go b/oauthproxy.go index f4d03f9..2ea2623 100644 --- a/oauthproxy.go +++ b/oauthproxy.go @@ -854,6 +854,9 @@ func (p *OAuthProxy) Authenticate(rw http.ResponseWriter, req *http.Request) int if session == nil { session, err = p.CheckBasicAuth(req) + if err != nil { + logger.Printf("Error during basic auth validation: %s", err) + } } if session == nil { @@ -929,7 +932,7 @@ func (p *OAuthProxy) CheckBasicAuth(req *http.Request) (*providers.SessionState, return &providers.SessionState{User: pair[0]}, nil } logger.PrintAuthf(pair[0], req, logger.AuthFailure, "Invalid authentication via basic auth; not in Htpasswd File") - return nil, fmt.Errorf("%s not in HtpasswdFile", pair[0]) + return nil, nil } // isAjax checks if a request is an ajax request From 398f85c30f9f85539b55db77291992264579717c Mon Sep 17 00:00:00 2001 From: MisterWil Date: Fri, 15 Feb 2019 10:29:24 -0800 Subject: [PATCH 4/5] Updated changelog --- CHANGELOG.md | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index b72f7c1..d2a8114 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,21 @@ ## Changes since v3.1.0 +- [#52](https://github.com/pusher/oauth2_proxy/pull/52) Logging Improvements + - Implement flags to configure file logging + - `-logging-filename` Defines the filename to log to + - `-logging-max-size` Defines the maximum + - `-logging-max-age` Defines the maximum age of backups to retain + - `-logging-max-backups` Defines the maximum number of rollover log files to retain + - `-logging-compress` Defines if rollover log files should be compressed + - `-logging-local-time` Defines if logging date and time should be local or UTC + - Implement two new flags to enable or disable specific logging types + - `-standard-logging` Enables or disables standard (not request or auth) logging + - `-auth-logging` Enables or disables auth logging + - Implement two new flags to customize the logging format + - `-standard-logging-format` Sets the format for standard logging + - `-auth-logging-format` Sets the format for auth logging + # v3.1.0 ## Release highlights From 2ca2c48bd9bc199047637ad20442e6e2dff682f9 Mon Sep 17 00:00:00 2001 From: MisterWil Date: Tue, 26 Feb 2019 08:53:41 -0800 Subject: [PATCH 5/5] Added list of variables for logging formats. --- README.md | 39 +++++++++++++++++++++++++++++++++++++-- 1 file changed, 37 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index 6d0ef54..d134620 100644 --- a/README.md +++ b/README.md @@ -403,7 +403,19 @@ 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. +Available variables for auth logging: + +| Variable | Example | Description | +| --- | --- | --- | +| Client | 74.125.224.72 | The client/remote IP address. Will use the X-Real-IP header it if exists. | +| Host | domain.com | The value of the Host header. | +| Protocol | HTTP/1.0 | The request protocol. | +| RequestMethod | GET | The request method. | +| Timestamp | 19/Mar/2015:17:20:19 -0400 | The date and time of the logging event. | +| UserAgent | - | The full user agent as reported by the requesting client. | +| Username | username@email.com | The email or username of the auth request. | +| Status | AuthSuccess | The status of the auth request. See above for details. | +| Message | Authenticated via OAuth2 | The details of the auth attempt. | ### Request Log Format HTTP request logs will output by default in the below format: @@ -419,7 +431,22 @@ The default format is configured as follows: {{.Client}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}} ``` -[See `requestLogMessageData` in `logging_handler.go`](./logger/logger.go) for all available variables. +Available variables for request logging: + +| Variable | Example | Description | +| --- | --- | --- | +| Client | 74.125.224.72 | The client/remote IP address. Will use the X-Real-IP header it if exists. | +| Host | domain.com | The value of the Host header. | +| Protocol | HTTP/1.0 | The request protocol. | +| RequestDuration | 0.001 | The time in seconds that a request took to process. | +| RequestMethod | GET | The request method. | +| RequestURI | "/oauth2/auth" | The URI path of the request. | +| ResponseSize | 12 | The size in bytes of the response. | +| StatusCode | 200 | The HTTP status code of the response. | +| Timestamp | 19/Mar/2015:17:20:19 -0400 | The date and time of the logging event. | +| Upstream | - | The upstream data of the HTTP request. | +| UserAgent | - | The full user agent as reported by the requesting client. | +| Username | username@email.com | The email or username of the auth request. | ### 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: @@ -434,6 +461,14 @@ If you require a different format than that, you can configure it with the `-sta [{{.Timestamp}}] [{{.File}}] {{.Message}} ``` +Available variables for standard logging: + +| Variable | Example | Description | +| --- | --- | --- | +| Timestamp | 19/Mar/2015:17:20:19 -0400 | The date and time of the logging event. | +| File | main.go:40 | The file and line number of the logging statement. | +| Message | HTTP: listening on 127.0.0.1:4180 | The details of the log statement. | + ## Adding a new Provider Follow the examples in the [`providers` package](providers/) to define a new