diff --git a/CHANGELOG.md b/CHANGELOG.md index 320ba697..2c15ade4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,8 +2,13 @@ ## Release Highlights +- Logging now uses Go's `log/slog`, adding configurable log levels and optional structured JSON output while keeping text output as the default. + ## Important Notes +- The new `--logging-level` flag controls log verbosity with `debug`, `info`, `warn`, and `error` levels. +- The new `--logging-format` flag supports `text` and `json`; `text` remains the default, and existing text template options continue to apply to text output. + ## Breaking Changes ## Changes since v7.15.2 diff --git a/contrib/oauth2-proxy.cfg.example b/contrib/oauth2-proxy.cfg.example index 866a2a0f..1365cf62 100644 --- a/contrib/oauth2-proxy.cfg.example +++ b/contrib/oauth2-proxy.cfg.example @@ -23,14 +23,18 @@ ## Logging configuration #logging_level = "info" -#logging_format = "json" +#logging_format = "text" #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}}" #auth_logging = true +#auth_logging_format = "{{.Client}} - {{.RequestID}} - {{.Username}} [{{.Timestamp}}] [{{.Status}}] {{.Message}}" #request_logging = true +#request_logging_format = "{{.Client}} - {{.RequestID}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}" ## pass HTTP Basic Auth, X-Forwarded-User and X-Forwarded-Email information to upstream # pass_basic_auth = true diff --git a/docs/docs/configuration/overview.md b/docs/docs/configuration/overview.md index 55d07134..f62b0764 100644 --- a/docs/docs/configuration/overview.md +++ b/docs/docs/configuration/overview.md @@ -152,22 +152,26 @@ Provider specific options can be found on their respective subpages. ### Logging Options -| Flag / Config Field | Type | Description | Default | -| ---------------------------------------------------------------- | ------ | ---------------------------------------------------------------------------- | ------------------------ | -| flag: `--logging-level`
toml: `logging_level` | string | Log level: `debug`, `info`, `warn`, `error` | `"info"` | -| flag: `--logging-format`
toml: `logging_format` | string | Log format: `json`, `text` | `"json"` | -| flag: `--auth-logging`
toml: `auth_logging` | bool | Log authentication attempts | true | -| flag: `--request-logging`
toml: `request_logging` | bool | Log HTTP requests | true | -| flag: `--errors-to-info-log`
toml: `errors_to_info_log` | bool | Redirect error-level logging to the standard log channel instead of stderr | false | -| flag: `--exclude-logging-path`
toml: `exclude_logging_paths` | string | Comma separated list of paths to exclude from logging, e.g. `"/ping,/path2"` | `""` (no paths excluded) | -| flag: `--silence-ping-logging`
toml: `silence_ping_logging` | bool | Disable logging of requests to ping & ready endpoints | false | -| flag: `--request-id-header`
toml: `request_id_header` | string | Request header to use as the request ID in logging | `"X-Request-Id"` | -| flag: `--logging-filename`
toml: `logging_filename` | string | File to log requests to, empty for `stdout` | `""` (stdout) | -| flag: `--logging-max-size`
toml: `logging_max_size` | int | Maximum size in megabytes of the log file before rotation | 100 | -| flag: `--logging-max-age`
toml: `logging_max_age` | int | Maximum number of days to retain old log files | 7 | -| flag: `--logging-max-backups`
toml: `logging_max_backups` | int | Maximum number of old log files to retain; 0 to disable | 0 | -| flag: `--logging-local-time`
toml: `logging_local_time` | bool | Use local time in log files and backup filenames instead of UTC | true (local time) | -| flag: `--logging-compress`
toml: `logging_compress` | bool | Should rotated log files be compressed using gzip | false | +| Flag / Config Field | Type | Description | Default | +| --------------------------------------------------------------------- | ------ | ---------------------------------------------------------------------------- | --------------------------------------------------- | +| flag: `--logging-level`
toml: `logging_level` | string | Log level: `debug`, `info`, `warn`, `error` | `"info"` | +| flag: `--logging-format`
toml: `logging_format` | string | Log format: `text`, `json` | `"text"` | +| flag: `--auth-logging-format`
toml: `auth_logging_format` | string | Template for authentication log lines when `logging_format` is `text` | see [Logging Configuration](#logging-configuration) | +| flag: `--auth-logging`
toml: `auth_logging` | bool | Log authentication attempts | true | +| flag: `--request-logging-format`
toml: `request_logging_format` | string | Template for request log lines when `logging_format` is `text` | see [Logging Configuration](#logging-configuration) | +| flag: `--request-logging`
toml: `request_logging` | bool | Log HTTP requests | true | +| flag: `--standard-logging-format`
toml: `standard_logging_format` | string | Template for standard log lines when `logging_format` is `text` | see [Logging Configuration](#logging-configuration) | +| flag: `--standard-logging`
toml: `standard_logging` | bool | Log standard runtime information | true | +| flag: `--errors-to-info-log`
toml: `errors_to_info_log` | bool | Redirect error-level logging to the standard log channel instead of stderr | false | +| flag: `--exclude-logging-path`
toml: `exclude_logging_paths` | string | Comma separated list of paths to exclude from logging, e.g. `"/ping,/path2"` | `""` (no paths excluded) | +| flag: `--silence-ping-logging`
toml: `silence_ping_logging` | bool | Disable logging of requests to ping & ready endpoints | false | +| flag: `--request-id-header`
toml: `request_id_header` | string | Request header to use as the request ID in logging | `"X-Request-Id"` | +| flag: `--logging-filename`
toml: `logging_filename` | string | File to log requests to, empty for `stdout` | `""` (stdout) | +| flag: `--logging-max-size`
toml: `logging_max_size` | int | Maximum size in megabytes of the log file before rotation | 100 | +| flag: `--logging-max-age`
toml: `logging_max_age` | int | Maximum number of days to retain old log files | 7 | +| flag: `--logging-max-backups`
toml: `logging_max_backups` | int | Maximum number of old log files to retain; 0 to disable | 0 | +| flag: `--logging-local-time`
toml: `logging_local_time` | bool | Use local time in log files and backup filenames instead of UTC | true (local time) | +| flag: `--logging-compress`
toml: `logging_compress` | bool | Should rotated log files be compressed using gzip | false | ### Page Template Options @@ -347,75 +351,170 @@ Please check the type for each [config option](#config-options) first. ## Logging Configuration -OAuth2 Proxy uses Go's standard `log/slog` package for structured logging. All log output is structured by default, with JSON as the default format. +OAuth2 Proxy uses Go's standard `log/slog` package for log levels and structured logging support. The default output format is `text`, preserving the existing template-based log lines. Set `--logging-format=json` to emit structured JSON logs for log aggregation systems. + +By default, OAuth2 Proxy logs standard informational output to stdout and standard warning/error output to stderr. 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`. ### Log Format Two log formats are supported via `--logging-format`: -- **`json`** (default) — Machine-readable JSON, one object per line. Ideal for log aggregation systems (ELK, Loki, Datadog, etc.). -- **`text`** — Human-readable key=value format for local development. - -Example JSON output: - -```json -{"time":"2025-01-15T10:30:00Z","level":"INFO","source":{"function":"main.main","file":"main.go","line":42},"msg":"HTTP: listening on 127.0.0.1:4180"} -``` +- **`text`** (default): Human-readable log lines using the standard, authentication, and request templates documented below. +- **`json`**: Machine-readable JSON, one object per line. The template format options are ignored in JSON mode because fields are emitted as structured attributes. Example text output: ``` -time=2025-01-15T10:30:00Z level=INFO source=main.go:42 msg="HTTP: listening on 127.0.0.1:4180" +127.0.0.1:59742 - 6cccb6ca - user@example.com [2025/01/15 10:30:00] app.example.com GET - "/oauth2/callback" HTTP/1.1 "Mozilla/5.0" 200 12 0.001 +``` + +Example JSON output: + +```json +{"time":"2025-01-15T10:30:00Z","level":"INFO","source":{"function":"main.main","file":"main.go","line":42},"msg":"request","user":"user@example.com","client":"127.0.0.1:59742","host":"app.example.com","method":"GET","uri":"/oauth2/callback","protocol":"HTTP/1.1","status_code":200,"response_size":12,"duration_s":"0.001","request_id":"6cccb6ca"} ``` ### Log Levels Four levels are supported via `--logging-level`: -| Level | Description | -| ------- | ----------------------------------------------------------------- | -| `debug` | Verbose output for troubleshooting | -| `info` | Normal operational messages (default) | -| `warn` | Warning conditions (e.g. authentication failures) | -| `error` | Error conditions written to stderr (unless `--errors-to-info-log` is set) | +| Level | Description | +| ------- | ------------------------------------------------------------------------ | +| `debug` | Verbose output for troubleshooting | +| `info` | Normal operational messages (default) | +| `warn` | Warning conditions, including explicit authentication failures | +| `error` | Error conditions written to stderr unless `--errors-to-info-log` is set | -### Structured Log Fields +### Auth Log Format -Log entries automatically include structured fields relevant to the log type. +Authentication logs are logs which are guaranteed to contain a username or email address of a user attempting to authenticate. In `text` format, these logs are output by default in the below format: -**Authentication logs** include: +``` + - - [2015/03/19 17:20:19] [] +``` -| Field | Description | -| ------------ | ----------------------------------------------------------- | -| `user` | The email or username of the auth request | -| `status` | `AuthSuccess`, `AuthFailure`, or `AuthError` | -| `client` | The client/remote IP address | -| `request_id` | The request ID from `--request-id-header` (if available) | -| `host` | The Host header value | -| `method` | The HTTP request method | -| `protocol` | The request protocol | -| `user_agent` | The client User-Agent header | +The status block will contain one of the below strings: -**Request logs** include: +- `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 -| Field | Description | -| ------------- | ----------------------------------------------------------- | -| `user` | The email or username | -| `upstream` | The upstream backend that handled the request | -| `client` | The client/remote IP address | -| `request_id` | The request ID from `--request-id-header` (if available) | -| `host` | The Host header value | -| `method` | The HTTP request method | -| `uri` | The request URI path | -| `protocol` | The request protocol | -| `user_agent` | The client User-Agent header | -| `status_code` | The HTTP response status code | -| `size` | The response size in bytes | -| `duration_s` | The request duration in seconds | +If you require a different text format, you can configure it with the `--auth-logging-format` flag. The default format is configured as follows: + +``` +{{.Client}} - {{.RequestID}} - {{.Username}} [{{.Timestamp}}] [{{.Status}}] {{.Message}} +``` + +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 & reverse-proxy is set to true. | +| Host | domain.com | The value of the Host header. | +| Message | Authenticated via OAuth2 | The details of the auth attempt. | +| Protocol | HTTP/1.0 | The request protocol. | +| RequestID | 00010203-0405-4607-8809-0a0b0c0d0e0f | The request ID pulled from the `--request-id-header`. Random UUID if empty | +| RequestMethod | GET | The request method. | +| Timestamp | 2015/03/19 17:20:19 | 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. | + +### Request Log Format + +HTTP request logs will output by default in the below text format: + +``` + - - [2015/03/19 17:20:19] GET "/path/" HTTP/1.1 "" +``` + +If you require a different text format, you can configure it with the `--request-logging-format` flag. The default format is configured as follows: + +``` +{{.Client}} - {{.RequestID}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}} +``` + +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 & reverse-proxy is set to true. | +| 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. | +| RequestID | 00010203-0405-4607-8809-0a0b0c0d0e0f | The request ID pulled from the `--request-id-header`. Random UUID if empty | +| 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 | 2015/03/19 17:20:19 | 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 text format is below: + +``` +[2015/03/19 17:20:19] [main.go:40] +``` + +If you require a different text format, you can configure it with the `--standard-logging-format` flag. The default format is configured as follows: + +``` +[{{.Timestamp}}] [{{.File}}] {{.Message}} +``` + +Available variables for standard logging: + +| Variable | Example | Description | +| --------- | --------------------------------- | -------------------------------------------------- | +| Timestamp | 2015/03/19 17:20:19 | 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. | + +### JSON Fields + +When `--logging-format=json` is configured, log entries automatically include structured fields relevant to the log type. + +Authentication logs include: + +| Field | Description | +| ------------ | -------------------------------------------------------- | +| `user` | The email or username of the auth request | +| `status` | `AuthSuccess`, `AuthFailure`, or `AuthError` | +| `client` | The client/remote IP address | +| `request_id` | The request ID from `--request-id-header`, if available | +| `host` | The Host header value | +| `method` | The HTTP request method | +| `protocol` | The request protocol | +| `user_agent` | The client User-Agent header | + +Request logs include: + +| Field | Description | +| --------------- | ------------------------------------------------------- | +| `user` | The email or username | +| `upstream` | The upstream backend that handled the request | +| `client` | The client/remote IP address | +| `request_id` | The request ID from `--request-id-header`, if available | +| `host` | The Host header value | +| `method` | The HTTP request method | +| `uri` | The request URI path | +| `protocol` | The request protocol | +| `user_agent` | The client User-Agent header | +| `status_code` | The HTTP response status code | +| `response_size` | The response size in bytes | +| `duration_s` | The request duration in seconds | ### Log Routing -By default, log messages at `INFO` and below are written to stdout, while `WARN` and `ERROR` messages are written to stderr. Use `--errors-to-info-log` to redirect all log output to stdout. +By default, standard log messages at `INFO` and below are written to stdout, while `WARN` and `ERROR` messages are written to stderr. Use `--errors-to-info-log` to redirect error output to stdout. When `--logging-filename` is configured, logs are written to the specified file with automatic rotation support via `--logging-max-size`, `--logging-max-age`, `--logging-max-backups`, and `--logging-compress`. diff --git a/pkg/apis/options/logging.go b/pkg/apis/options/logging.go index a6aee2f5..3d3f642d 100644 --- a/pkg/apis/options/logging.go +++ b/pkg/apis/options/logging.go @@ -1,6 +1,7 @@ package options import ( + "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/logger" "github.com/spf13/pflag" ) @@ -9,7 +10,11 @@ type Logging struct { Level string `flag:"logging-level" cfg:"logging_level"` Format string `flag:"logging-format" cfg:"logging_format"` AuthEnabled bool `flag:"auth-logging" cfg:"auth_logging"` + AuthFormat string `flag:"auth-logging-format" cfg:"auth_logging_format"` RequestEnabled bool `flag:"request-logging" cfg:"request_logging"` + RequestFormat string `flag:"request-logging-format" cfg:"request_logging_format"` + StandardEnabled bool `flag:"standard-logging" cfg:"standard_logging"` + StandardFormat string `flag:"standard-logging-format" cfg:"standard_logging_format"` ErrToInfo bool `flag:"errors-to-info-log" cfg:"errors_to_info_log"` ExcludePaths []string `flag:"exclude-logging-path" cfg:"exclude_logging_paths"` LocalTime bool `flag:"logging-local-time" cfg:"logging_local_time"` @@ -31,9 +36,13 @@ func loggingFlagSet() *pflag.FlagSet { flagSet := pflag.NewFlagSet("logging", pflag.ExitOnError) flagSet.String("logging-level", "info", "Log level: debug, info, warn, error") - flagSet.String("logging-format", "json", "Log format: json, text") + flagSet.String("logging-format", "text", "Log format: text, json") flagSet.Bool("auth-logging", true, "Log authentication attempts") + flagSet.String("auth-logging-format", logger.DefaultAuthLoggingFormat, "Template for authentication log lines when logging-format=text") + flagSet.Bool("standard-logging", true, "Log standard runtime information") + flagSet.String("standard-logging-format", logger.DefaultStandardLoggingFormat, "Template for standard log lines when logging-format=text") flagSet.Bool("request-logging", true, "Log HTTP requests") + flagSet.String("request-logging-format", logger.DefaultRequestLoggingFormat, "Template for HTTP request log lines when logging-format=text") flagSet.Bool("errors-to-info-log", false, "Log errors to the standard logging channel instead of stderr") flagSet.StringSlice("exclude-logging-path", []string{}, "Exclude logging requests to paths (eg: '/path1,/path2,/path3')") @@ -54,13 +63,17 @@ func loggingFlagSet() *pflag.FlagSet { func loggingDefaults() Logging { return Logging{ Level: "info", - Format: "json", + Format: "text", ExcludePaths: nil, LocalTime: true, SilencePing: false, RequestIDHeader: "X-Request-Id", AuthEnabled: true, + AuthFormat: logger.DefaultAuthLoggingFormat, RequestEnabled: true, + RequestFormat: logger.DefaultRequestLoggingFormat, + StandardEnabled: true, + StandardFormat: logger.DefaultStandardLoggingFormat, ErrToInfo: false, File: LogFileOptions{ Filename: "", diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index cd08f14e..8cd7cec0 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -1,6 +1,7 @@ package logger import ( + "bytes" "context" "fmt" "io" @@ -8,7 +9,9 @@ import ( "net/http" "net/url" "os" + "runtime" "sync" + "text/template" "time" middlewareapi "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/apis/middleware" @@ -18,7 +21,17 @@ import ( // AuthStatus defines the different types of auth logging that occur type AuthStatus string +// Level indicates the log level for legacy logger callers. +type Level int + const ( + // DefaultStandardLoggingFormat defines the default standard log format. + DefaultStandardLoggingFormat = "[{{.Timestamp}}] [{{.File}}] {{.Message}}" + // DefaultAuthLoggingFormat defines the default auth log format. + DefaultAuthLoggingFormat = "{{.Client}} - {{.RequestID}} - {{.Username}} [{{.Timestamp}}] [{{.Status}}] {{.Message}}" + // DefaultRequestLoggingFormat defines the default request log format. + DefaultRequestLoggingFormat = "{{.Client}} - {{.RequestID}} - {{.Username}} [{{.Timestamp}}] {{.Host}} {{.RequestMethod}} {{.Upstream}} {{.RequestURI}} {{.Protocol}} {{.UserAgent}} {{.StatusCode}} {{.ResponseSize}} {{.RequestDuration}}" + // AuthSuccess indicates that an auth attempt has succeeded explicitly AuthSuccess AuthStatus = "AuthSuccess" // AuthFailure indicates that an auth attempt has failed explicitly @@ -27,6 +40,61 @@ const ( AuthError AuthStatus = "AuthError" ) +const ( + // Llongfile logs the full file name and line number: /a/b/c/d.go:23. + Llongfile = 1 << 6 + // Lshortfile logs the final file name element and line number: d.go:23. It overrides Llongfile. + Lshortfile = 1 << 7 + // LUTC logs UTC timestamps rather than local time. + LUTC = 1 << 8 + // LstdFlags is the initial value for the logger flags. + LstdFlags = Lshortfile +) + +const ( + // DEFAULT is the default legacy log level, effectively info. + DEFAULT Level = 10 + // ERROR is the legacy error log level. + ERROR Level = 11 +) + +// 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, + RequestID, + RequestMethod, + Timestamp, + UserAgent, + Username, + Status, + Message string +} + +type reqLogMessageData struct { + Client, + Host, + Protocol, + RequestID, + RequestDuration, + RequestMethod, + RequestURI, + ResponseSize, + StatusCode, + Timestamp, + Upstream, + UserAgent, + Username string +} + // GetClientFunc returns the apparent "real client IP" as a string. type GetClientFunc = func(r *http.Request) string @@ -35,13 +103,19 @@ var exitFunc = os.Exit // Package-level state var ( - mu sync.RWMutex - logLevel = new(slog.LevelVar) - defaultLogger = slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: logLevel, AddSource: true})) - writer io.Writer = os.Stdout - errWriter io.Writer = os.Stderr - logFormat = "json" - errToInfo = false + mu sync.RWMutex + logLevel = new(slog.LevelVar) + defaultLogger = slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: logLevel, AddSource: true})) + writer io.Writer = os.Stdout + errWriter io.Writer = os.Stderr + logFormat = "text" + errToInfo = false + standardEnabled = true + localTime = true + flags = LstdFlags + 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)) getClientFunc GetClientFunc = func(r *http.Request) string { return r.RemoteAddr } excludePaths map[string]struct{} @@ -51,6 +125,7 @@ var ( func init() { logLevel.Set(slog.LevelInfo) + defaultLogger = slog.New(newLevelSplitHandler(logFormat, writer, errWriter)) slog.SetDefault(defaultLogger) } @@ -152,62 +227,187 @@ func SetReqEnabled(e bool) { reqEnabled = e } +// SetStandardEnabled enables or disables standard runtime logging. +func SetStandardEnabled(e bool) { + mu.Lock() + defer mu.Unlock() + standardEnabled = e +} + +// SetStandardTemplate sets the template for standard text logging. +func SetStandardTemplate(t string) { + mu.Lock() + defer mu.Unlock() + stdLogTemplate = template.Must(template.New("std-log").Parse(t)) +} + +// SetAuthTemplate sets the template for authentication text logging. +func SetAuthTemplate(t string) { + mu.Lock() + defer mu.Unlock() + authTemplate = template.Must(template.New("auth-log").Parse(t)) +} + +// SetReqTemplate sets the template for request text logging. +func SetReqTemplate(t string) { + mu.Lock() + defer mu.Unlock() + reqTemplate = template.Must(template.New("req-log").Parse(t)) +} + +// SetLocalTime controls whether template text logs use local time or UTC. +func SetLocalTime(e bool) { + mu.Lock() + defer mu.Unlock() + localTime = e + if e { + flags &^= LUTC + } else { + flags |= LUTC + } +} + +// FormatTimestamp returns a formatted timestamp using the current text log time zone setting. +func FormatTimestamp(ts time.Time) string { + mu.RLock() + useLocalTime := localTime + mu.RUnlock() + + if !useLocalTime { + ts = ts.UTC() + } + + return ts.Format("2006/01/02 15:04:05") +} + +// Flags returns the output flags for the standard logger. +func Flags() int { + mu.RLock() + defer mu.RUnlock() + return flags +} + +// SetFlags sets the output flags for the standard logger. +func SetFlags(flag int) { + mu.Lock() + defer mu.Unlock() + flags = flag + localTime = flag&LUTC == 0 +} + // ---------- Structured log functions ---------- // Debug logs a message at Debug level with optional structured key-value pairs. func Debug(msg string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelDebug, 3, msg, args...) + return + } + defaultLogger.Debug(msg, args...) } // Debugf logs a formatted message at Debug level. func Debugf(format string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelDebug, 3, fmt.Sprintf(format, args...)) + return + } + defaultLogger.Debug(fmt.Sprintf(format, args...)) } // Info logs a message at Info level with optional structured key-value pairs. func Info(msg string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelInfo, 3, msg, args...) + return + } + defaultLogger.Info(msg, args...) } // Infof logs a formatted message at Info level. func Infof(format string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelInfo, 3, fmt.Sprintf(format, args...)) + return + } + defaultLogger.Info(fmt.Sprintf(format, args...)) } // Warn logs a message at Warn level with optional structured key-value pairs. func Warn(msg string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelWarn, 3, msg, args...) + return + } + defaultLogger.Warn(msg, args...) } // Warnf logs a formatted message at Warn level. func Warnf(format string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelWarn, 3, fmt.Sprintf(format, args...)) + return + } + defaultLogger.Warn(fmt.Sprintf(format, args...)) } // ErrMsg logs a message at Error level with optional structured key-value pairs. func ErrMsg(msg string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelError, 3, msg, args...) + return + } + defaultLogger.Error(msg, args...) } // ErrMsgf logs a formatted message at Error level. func ErrMsgf(format string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelError, 3, fmt.Sprintf(format, args...)) + return + } + defaultLogger.Error(fmt.Sprintf(format, args...)) } // FatalMsg logs a message at Error level and then calls os.Exit(1). func FatalMsg(msg string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelError, 3, msg, args...) + exitFunc(1) + return + } + defaultLogger.Error(msg, args...) exitFunc(1) } // FatalMsgf logs a formatted message at Error level and then calls os.Exit(1). func FatalMsgf(format string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelError, 3, fmt.Sprintf(format, args...)) + exitFunc(1) + return + } + defaultLogger.Error(fmt.Sprintf(format, args...)) exitFunc(1) } // PanicMsg logs a message at Error level and then panics. func PanicMsg(msg string, args ...any) { + if isTextFormat() { + logStandardText(slog.LevelError, 3, msg, args...) + panic(msg) + } + defaultLogger.Error(msg, args...) panic(msg) } @@ -215,10 +415,160 @@ func PanicMsg(msg string, args ...any) { // PanicMsgf logs a formatted message at Error level and then panics. func PanicMsgf(format string, args ...any) { s := fmt.Sprintf(format, args...) + if isTextFormat() { + logStandardText(slog.LevelError, 3, s) + panic(s) + } + defaultLogger.Error(s) panic(s) } +func isTextFormat() bool { + mu.RLock() + defer mu.RUnlock() + return logFormat == "text" +} + +func logStandardText(level slog.Level, callerDepth int, msg string, args ...any) { + if level < logLevel.Level() { + return + } + + mu.Lock() + defer mu.Unlock() + + if !standardEnabled { + return + } + + target := writer + if level >= slog.LevelWarn && !errToInfo { + target = errWriter + } + + var logBuff bytes.Buffer + err := stdLogTemplate.Execute(&logBuff, stdLogMessageData{ + Timestamp: formatTimestamp(time.Now(), localTime), + File: sourceFileFromCaller(callerDepth, flags), + Message: messageWithAttrs(msg, args...), + }) + if err != nil { + panic(err) + } + + if _, err = logBuff.Write([]byte("\n")); err != nil { + panic(err) + } + + if _, err = target.Write(logBuff.Bytes()); err != nil { + panic(err) + } +} + +func formatTimestamp(ts time.Time, useLocalTime bool) string { + if !useLocalTime { + ts = ts.UTC() + } + + return ts.Format("2006/01/02 15:04:05") +} + +func messageWithAttrs(msg string, args ...any) string { + if len(args) == 0 { + return msg + } + + var buf bytes.Buffer + buf.WriteString(msg) + for i := 0; i < len(args); i += 2 { + buf.WriteByte(' ') + if i+1 >= len(args) { + buf.WriteString(fmt.Sprint(args[i])) + continue + } + buf.WriteString(fmt.Sprint(args[i])) + buf.WriteByte('=') + buf.WriteString(fmt.Sprint(args[i+1])) + } + return buf.String() +} + +func logAuthText(username string, req *http.Request, status AuthStatus, msg string, args ...any) { + if username == "" { + username = "-" + } + + mu.Lock() + defer mu.Unlock() + + scope := middlewareapi.GetRequestScope(req) + err := authTemplate.Execute(writer, authLogMessageData{ + Client: getClientFunc(req), + Host: requestutil.GetRequestHost(req), + Protocol: req.Proto, + RequestID: scope.RequestID, + RequestMethod: req.Method, + Timestamp: formatTimestamp(time.Now(), localTime), + UserAgent: fmt.Sprintf("%q", req.UserAgent()), + Username: username, + Status: string(status), + Message: messageWithAttrs(msg, args...), + }) + if err != nil { + panic(err) + } + + if _, err = writer.Write([]byte("\n")); err != nil { + panic(err) + } +} + +func logRequestText(username, upstream string, req *http.Request, reqURL url.URL, ts time.Time, status int, size int) { + if username == "" { + username = "-" + } + + if upstream == "" { + upstream = "-" + } + + if reqURL.User != nil && username == "-" { + if name := reqURL.User.Username(); name != "" { + username = name + } + } + + duration := float64(time.Since(ts)) / float64(time.Second) + + mu.Lock() + defer mu.Unlock() + + scope := middlewareapi.GetRequestScope(req) + err := reqTemplate.Execute(writer, reqLogMessageData{ + Client: getClientFunc(req), + Host: requestutil.GetRequestHost(req), + Protocol: req.Proto, + RequestID: scope.RequestID, + RequestDuration: fmt.Sprintf("%0.3f", duration), + RequestMethod: req.Method, + RequestURI: fmt.Sprintf("%q", reqURL.RequestURI()), + ResponseSize: fmt.Sprintf("%d", size), + StatusCode: fmt.Sprintf("%d", status), + Timestamp: formatTimestamp(ts, localTime), + Upstream: upstream, + UserAgent: fmt.Sprintf("%q", req.UserAgent()), + Username: username, + }) + if err != nil { + panic(err) + } + + if _, err = writer.Write([]byte("\n")); err != nil { + panic(err) + } +} + // ---------- Structured auth and request logging ---------- // LogAuth logs an authentication event with structured attributes. @@ -230,6 +580,7 @@ func LogAuth(username string, req *http.Request, status AuthStatus, msg string, mu.RLock() enabled := authEnabled clientFunc := getClientFunc + format := logFormat mu.RUnlock() if !enabled { @@ -268,6 +619,15 @@ func LogAuth(username string, req *http.Request, status AuthStatus, msg string, level = slog.LevelInfo } + if level < logLevel.Level() { + return + } + + if format == "text" { + logAuthText(username, req, status, msg, args...) + return + } + defaultLogger.Log(context.Background(), level, msg, attrs...) } @@ -278,16 +638,26 @@ func LogRequest(username, upstream string, req *http.Request, reqURL url.URL, ts enabled := reqEnabled excluded := excludePaths clientFunc := getClientFunc + format := logFormat mu.RUnlock() if !enabled { return } + if slog.LevelInfo < logLevel.Level() { + return + } + if _, ok := excluded[reqURL.Path]; ok { return } + if format == "text" { + logRequestText(username, upstream, req, reqURL, ts, status, size) + return + } + duration := float64(time.Since(ts)) / float64(time.Second) if username == "" { @@ -346,8 +716,8 @@ func newLevelSplitHandler(format string, w io.Writer, errW io.Writer) *levelSpli var stdH, errH slog.Handler switch format { case "text": - stdH = slog.NewTextHandler(w, opts) - errH = slog.NewTextHandler(errW, errOpts) + stdH = newTemplateTextHandler(w) + errH = newTemplateTextHandler(errW) default: // "json" stdH = slog.NewJSONHandler(w, opts) errH = slog.NewJSONHandler(errW, errOpts) @@ -383,3 +753,98 @@ func (h *levelSplitHandler) WithGroup(name string) slog.Handler { errHandler: h.errHandler.WithGroup(name), } } + +type templateTextHandler struct { + writer io.Writer + attrs []slog.Attr +} + +func newTemplateTextHandler(w io.Writer) *templateTextHandler { + return &templateTextHandler{writer: w} +} + +func (h *templateTextHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= logLevel.Level() +} + +func (h *templateTextHandler) Handle(_ context.Context, r slog.Record) error { + mu.Lock() + defer mu.Unlock() + + if !standardEnabled { + return nil + } + + var args []any + for _, attr := range h.attrs { + args = append(args, attr.Key, attr.Value.Any()) + } + r.Attrs(func(attr slog.Attr) bool { + args = append(args, attr.Key, attr.Value.Any()) + return true + }) + + var logBuff bytes.Buffer + err := stdLogTemplate.Execute(&logBuff, stdLogMessageData{ + Timestamp: formatTimestamp(r.Time, localTime), + File: sourceFile(r.PC, flags), + Message: messageWithAttrs(r.Message, args...), + }) + if err != nil { + return err + } + + if _, err = logBuff.Write([]byte("\n")); err != nil { + return err + } + + _, err = h.writer.Write(logBuff.Bytes()) + return err +} + +func (h *templateTextHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + next := &templateTextHandler{writer: h.writer} + next.attrs = append(next.attrs, h.attrs...) + next.attrs = append(next.attrs, attrs...) + return next +} + +func (h *templateTextHandler) WithGroup(_ string) slog.Handler { + return h +} + +func sourceFile(pc uintptr, flag int) string { + if pc == 0 { + return "???:0" + } + + frame, _ := runtime.CallersFrames([]uintptr{pc}).Next() + return formatFileLine(frame.File, frame.Line, flag) +} + +func sourceFileFromCaller(depth int, flag int) string { + _, file, line, ok := runtime.Caller(depth) + if !ok { + return "???:0" + } + + return formatFileLine(file, line, flag) +} + +func formatFileLine(file string, line int, flag int) string { + if flag&Lshortfile != 0 { + file = shortFile(file) + } + + return fmt.Sprintf("%s:%d", file, line) +} + +func shortFile(file string) string { + for i := len(file) - 1; i > 0; i-- { + if file[i] == '/' { + return file[i+1:] + } + } + + return file +} diff --git a/pkg/logger/logger_test.go b/pkg/logger/logger_test.go index f326414b..57df0661 100644 --- a/pkg/logger/logger_test.go +++ b/pkg/logger/logger_test.go @@ -8,6 +8,7 @@ import ( "net/http/httptest" "strings" "testing" + "text/template" "time" middlewareapi "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/apis/middleware" @@ -17,6 +18,13 @@ import ( func resetLogger(t *testing.T) { t.Helper() logLevel.Set(slog.LevelInfo) + logFormat = "text" + standardEnabled = true + localTime = true + flags = LstdFlags + 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)) authEnabled = true reqEnabled = true excludePaths = nil @@ -74,14 +82,77 @@ func TestSetup_TextFormat(t *testing.T) { Info("hello", "key", "val") out := buf.String() - if !strings.Contains(out, "level=INFO") { - t.Errorf("expected level=INFO in text output, got: %s", out) + if strings.Contains(out, "level=INFO") { + t.Errorf("did not expect slog key=value text output, got: %s", out) } - if !strings.Contains(out, "msg=hello") { - t.Errorf("expected msg=hello in text output, got: %s", out) + if !strings.Contains(out, "hello key=val") { + t.Errorf("expected message and attrs in template output, got: %s", out) } - if !strings.Contains(out, "key=val") { - t.Errorf("expected key=val in text output, got: %s", out) + if !strings.HasSuffix(out, "\n") { + t.Errorf("expected text output to end with newline, got: %s", out) + } +} + +func TestTextFormat_StandardTemplate(t *testing.T) { + resetLogger(t) + buf := &bytes.Buffer{} + errBuf := &bytes.Buffer{} + Setup(slog.LevelInfo, "text", buf, errBuf) + SetStandardTemplate("{{.Message}}") + + Info("hello", "key", "val") + + if got, want := buf.String(), "hello key=val\n"; got != want { + t.Errorf("expected custom standard template output %q, got %q", want, got) + } +} + +func TestTextFormat_StandardTemplateFileUsesCaller(t *testing.T) { + resetLogger(t) + buf := &bytes.Buffer{} + errBuf := &bytes.Buffer{} + Setup(slog.LevelInfo, "text", buf, errBuf) + SetStandardTemplate("{{.File}}|{{.Message}}") + + Info("hello") + + out := buf.String() + if !strings.Contains(out, "logger_test.go:") { + t.Errorf("expected caller file in text output, got: %s", out) + } + if strings.Contains(out, "logger.go:") { + t.Errorf("expected external caller file, got logger wrapper file: %s", out) + } +} + +func TestSetFlags_ControlsStandardTemplateFile(t *testing.T) { + resetLogger(t) + buf := &bytes.Buffer{} + errBuf := &bytes.Buffer{} + Setup(slog.LevelInfo, "text", buf, errBuf) + SetStandardTemplate("{{.File}}") + SetFlags(0) + + Info("hello") + + out := buf.String() + if !strings.Contains(out, "/pkg/logger/logger_test.go:") { + t.Errorf("expected full caller file when Lshortfile is disabled, got: %s", out) + } +} + +func TestTextFormat_StandardLoggingDisabled(t *testing.T) { + resetLogger(t) + buf := &bytes.Buffer{} + errBuf := &bytes.Buffer{} + Setup(slog.LevelInfo, "text", buf, errBuf) + SetStandardEnabled(false) + + Info("hidden") + Warn("also hidden") + + if buf.Len() > 0 || errBuf.Len() > 0 { + t.Errorf("expected standard logs to be disabled, stdout=%q stderr=%q", buf.String(), errBuf.String()) } } @@ -273,6 +344,28 @@ func TestLogAuth_Disabled(t *testing.T) { } } +func TestLogAuth_TextTemplate(t *testing.T) { + resetLogger(t) + buf := &bytes.Buffer{} + errBuf := &bytes.Buffer{} + Setup(slog.LevelDebug, "text", buf, errBuf) + SetAuthTemplate("{{.Client}}|{{.RequestID}}|{{.Username}}|{{.Status}}|{{.Message}}") + + req := httptest.NewRequest("GET", "/test", nil) + req.RemoteAddr = "192.168.1.1:1234" + scope := &middlewareapi.RequestScope{RequestID: "req-id"} + req = middlewareapi.AddRequestScope(req, scope) + + LogAuth("user@test.com", req, AuthSuccess, "authenticated", "provider", "oidc") + + if got, want := buf.String(), "192.168.1.1:1234|req-id|user@test.com|AuthSuccess|authenticated provider=oidc\n"; got != want { + t.Errorf("expected custom auth template output %q, got %q", want, got) + } + if errBuf.Len() > 0 { + t.Errorf("expected text auth log to use standard writer, got stderr %q", errBuf.String()) + } +} + func TestLogRequest(t *testing.T) { resetLogger(t) buf := &bytes.Buffer{} @@ -358,6 +451,26 @@ func TestLogRequest_Disabled(t *testing.T) { } } +func TestLogRequest_TextTemplate(t *testing.T) { + resetLogger(t) + buf := &bytes.Buffer{} + errBuf := &bytes.Buffer{} + Setup(slog.LevelDebug, "text", buf, errBuf) + SetReqTemplate("{{.Username}}|{{.Upstream}}|{{.RequestMethod}}|{{.RequestURI}}|{{.StatusCode}}|{{.ResponseSize}}|{{.RequestID}}") + + req := httptest.NewRequest("GET", "/foo/bar?x=1", nil) + req.RemoteAddr = "127.0.0.1:5678" + scope := &middlewareapi.RequestScope{RequestID: "req-123"} + req = middlewareapi.AddRequestScope(req, scope) + + reqURL := *req.URL + LogRequest("testuser", "backend", req, reqURL, time.Now(), 204, 42) + + if got, want := buf.String(), "testuser|backend|GET|\"/foo/bar?x=1\"|204|42|req-123\n"; got != want { + t.Errorf("expected custom request template output %q, got %q", want, got) + } +} + func TestFatalMsg(t *testing.T) { resetLogger(t) buf := &bytes.Buffer{} diff --git a/pkg/validation/logging.go b/pkg/validation/logging.go index 86585d35..f6cce61d 100644 --- a/pkg/validation/logging.go +++ b/pkg/validation/logging.go @@ -91,11 +91,20 @@ func configureLogger(o options.Logging, msgs []string) []string { } } + logger.SetLocalTime(o.LocalTime) + logger.SetStandardTemplate(o.StandardFormat) + logger.SetAuthTemplate(o.AuthFormat) + logger.SetReqTemplate(o.RequestFormat) + logger.SetErrToInfo(o.ErrToInfo) + logger.SetStandardEnabled(true) + // Supply a sanity warning to the logger if all logging is disabled - if !o.AuthEnabled && !o.RequestEnabled { - logger.Warn("all categorical logging disabled: auth and request logging are both off") + if !o.StandardEnabled && !o.AuthEnabled && !o.RequestEnabled { + logger.Warn("logging disabled: standard, auth, and request logging are all off") } + logger.SetStandardEnabled(o.StandardEnabled) + // Configure categorical logging logger.SetAuthEnabled(o.AuthEnabled) logger.SetReqEnabled(o.RequestEnabled)