diff --git a/docs/docs/configuration/overview.md b/docs/docs/configuration/overview.md index 965953fa..013cd7b4 100644 --- a/docs/docs/configuration/overview.md +++ b/docs/docs/configuration/overview.md @@ -361,7 +361,7 @@ Logging of requests to the `/ping` endpoint (or using `--ping-user-agent`) and t ## 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: +Authentication logs describe authentication attempts. They include the user's username or email address when known, or `-` otherwise. OAuth callback diagnostics for missing or invalid CSRF cookies are authentication logs, controlled by `--auth-logging`, and include cookie names but not cookie values. These logs are output by default in the below format: ``` - - [2015/03/19 17:20:19] [] @@ -392,7 +392,7 @@ Available variables for auth logging: | 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. | +| Username | username@email.com | The email or username of the auth request, or `-` if not yet known. | | Status | AuthSuccess | The status of the auth request. See above for details. | ## Request Log Format diff --git a/oauthproxy.go b/oauthproxy.go index f8dc5471..c1f56412 100644 --- a/oauthproxy.go +++ b/oauthproxy.go @@ -918,7 +918,7 @@ func (p *OAuthProxy) OAuthCallback(rw http.ResponseWriter, req *http.Request) { // There are a lot of issues opened complaining about missing CSRF cookies. // Try to log the INs and OUTs of OAuthProxy, to be easier to analyse these issues. LoggingCSRFCookiesInOAuthCallback(req, cookieName) - logger.Println(req, logger.AuthFailure, "Invalid authentication via OAuth2: unable to obtain CSRF cookie: %s (state=%s)", err, nonce) + logger.PrintAuthf("", req, logger.AuthFailure, "Invalid authentication via OAuth2: unable to obtain CSRF cookie: %s", err) p.ErrorPage(rw, req, http.StatusForbidden, err.Error(), "Login Failed: Unable to find a valid CSRF token. Please try again.") return } @@ -1344,26 +1344,26 @@ func (p *OAuthProxy) errorJSON(rw http.ResponseWriter, code int) { rw.Write([]byte("{}")) } -// LoggingCSRFCookiesInOAuthCallback Log all CSRF cookies found in HTTP request OAuth callback, -// which were successfully parsed +// LoggingCSRFCookiesInOAuthCallback logs CSRF cookie names, never values, to +// diagnose a missing or invalid CSRF cookie in an OAuth callback. func LoggingCSRFCookiesInOAuthCallback(req *http.Request, cookieName string) { cookies := req.Cookies() if len(cookies) == 0 { - logger.Println(req, logger.AuthFailure, "No cookies were found in OAuth callback.") + logger.PrintAuthf("", req, logger.AuthFailure, "No cookies were found in OAuth callback.") return } for _, c := range cookies { if cookieName == c.Name { - logger.Println(req, logger.AuthFailure, "CSRF cookie %s was found in OAuth callback.", c.Name) + logger.PrintAuthf("", req, logger.AuthFailure, "CSRF cookie %s was found in OAuth callback.", c.Name) return } if strings.HasSuffix(c.Name, "_csrf") { - logger.Println(req, logger.AuthFailure, "CSRF cookie %s was found in OAuth callback, but it is not the expected one (%s).", c.Name, cookieName) + logger.PrintAuthf("", req, logger.AuthFailure, "CSRF cookie %s was found in OAuth callback, but it is not the expected one (%s).", c.Name, cookieName) return } } - logger.Println(req, logger.AuthFailure, "Cookies were found in OAuth callback, but none was a CSRF cookie.") + logger.PrintAuthf("", req, logger.AuthFailure, "Cookies were found in OAuth callback, but none was a CSRF cookie.") } diff --git a/oauthproxy_test.go b/oauthproxy_test.go index b3271e5b..2eb5aa23 100644 --- a/oauthproxy_test.go +++ b/oauthproxy_test.go @@ -1,6 +1,7 @@ package main import ( + "bytes" "context" "crypto" "encoding/base64" @@ -20,6 +21,7 @@ import ( "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/apis/sessions" "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/authentication/hmacauth" "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/cookies" + "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/encryption" "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/logger" internaloidc "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/providers/oidc" sessionscookie "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/sessions/cookie" @@ -27,6 +29,7 @@ import ( "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/util/ptr" "github.com/oauth2-proxy/oauth2-proxy/v7/pkg/validation" "github.com/oauth2-proxy/oauth2-proxy/v7/providers" + "github.com/onsi/ginkgo/v2" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -439,6 +442,136 @@ func (patTest *PassAccessTokenTest) getCallbackEndpoint() (httpCode int, cookie return rw.Code, cookie } +func TestOAuthCallbackCSRFCookieLogging(t *testing.T) { + opts := baseTestOptions() + require.NoError(t, validation.Validate(opts)) + proxy, err := NewOAuthProxy(opts, func(string) bool { return true }) + require.NoError(t, err) + + csrf, err := cookies.NewCSRF(proxy.CookieOptions, "synthetic-pkce-verifier") + require.NoError(t, err) + csrfCookie, err := csrf.SetCookie(httptest.NewRecorder(), httptest.NewRequest(http.MethodGet, "/", nil)) + require.NoError(t, err) + secret, err := proxy.CookieOptions.GetSecret() + require.NoError(t, err) + value, _, valid := encryption.Validate(csrfCookie, secret, proxy.CookieOptions.CSRFExpire) + require.True(t, valid) + expiredValue, err := encryption.SignedValue(secret, csrfCookie.Name, value, time.Now().Add(-proxy.CookieOptions.CSRFExpire-time.Hour)) + require.NoError(t, err) + + sessionCookie := &http.Cookie{Name: proxy.CookieOptions.Name, Value: "synthetic-session-credential"} + invalidCookie := &http.Cookie{Name: csrfCookie.Name, Value: "synthetic-invalid-csrf-credential"} + expiredCookie := &http.Cookie{Name: csrfCookie.Name, Value: expiredValue} + otherCookie := &http.Cookie{Name: "_other_csrf", Value: "synthetic-other-csrf-credential"} + testCases := []struct { + name string + cookies []*http.Cookie + diagnostic string + }{ + { + name: "no cookies", + diagnostic: "No cookies were found in OAuth callback.", + }, + { + name: "missing CSRF cookie", + cookies: []*http.Cookie{sessionCookie}, + diagnostic: "Cookies were found in OAuth callback, but none was a CSRF cookie.", + }, + { + name: "invalid expected CSRF cookie", + cookies: []*http.Cookie{sessionCookie, invalidCookie}, + diagnostic: fmt.Sprintf("CSRF cookie %s was found in OAuth callback.", csrfCookie.Name), + }, + { + name: "expired expected CSRF cookie", + cookies: []*http.Cookie{sessionCookie, expiredCookie}, + diagnostic: fmt.Sprintf("CSRF cookie %s was found in OAuth callback.", csrfCookie.Name), + }, + { + name: "other CSRF cookie", + cookies: []*http.Cookie{sessionCookie, otherCookie}, + diagnostic: fmt.Sprintf("CSRF cookie %s was found in OAuth callback, but it is not the expected one (%s).", otherCookie.Name, csrfCookie.Name), + }, + } + loggingCases := []struct { + name string + standard bool + auth bool + request bool + }{ + {name: "all enabled", standard: true, auth: true, request: true}, + {name: "auth disabled", standard: true, request: true}, + {name: "only auth enabled", auth: true}, + {name: "all disabled"}, + } + for _, tc := range testCases { + for _, logging := range loggingCases { + for _, authScheme := range []string{"Basic", "Bearer"} { + t.Run(tc.name+"/"+logging.name+"/"+authScheme, func(t *testing.T) { + var output, errors bytes.Buffer + logger.SetOutput(&output) + logger.SetErrOutput(&errors) + logger.SetStandardEnabled(logging.standard) + logger.SetAuthEnabled(logging.auth) + logger.SetReqEnabled(logging.request) + logger.SetAuthTemplate("AUTH {{.RequestID}} {{.Username}} {{.Status}} {{.Message}}") + logger.SetReqTemplate("REQUEST " + logger.DefaultRequestLoggingFormat) + t.Cleanup(func() { + logger.SetOutput(ginkgo.GinkgoWriter) + logger.SetErrOutput(ginkgo.GinkgoWriter) + logger.SetStandardEnabled(true) + logger.SetAuthEnabled(true) + logger.SetReqEnabled(true) + logger.SetAuthTemplate(logger.DefaultAuthLoggingFormat) + logger.SetReqTemplate(logger.DefaultRequestLoggingFormat) + }) + + query := url.Values{ + "code": {"synthetic-callback-code"}, + "state": {encodeState(csrf.HashOAuthState(), "/", false)}, + } + req := httptest.NewRequest(http.MethodGet, "/oauth2/callback?"+query.Encode(), nil) + req.Header.Set("X-Request-Id", "callback-log-test") + credential := "synthetic-bearer-credential" + if authScheme == "Basic" { + credential = base64.StdEncoding.EncodeToString([]byte("synthetic-user:synthetic-password")) + } + req.Header.Set("Authorization", authScheme+" "+credential) + req.Header.Set("X-Synthetic-Secret", "synthetic-header-credential") + for _, cookie := range tc.cookies { + req.AddCookie(cookie) + } + + rw := httptest.NewRecorder() + proxy.ServeHTTP(rw, req) + + assert.Equal(t, http.StatusForbidden, rw.Code) + assert.Contains(t, rw.Body.String(), "Unable to find a valid CSRF token") + assert.Empty(t, rw.Result().Cookies()) + assert.Empty(t, errors.String()) + logs := output.String() + errors.String() + assert.NotContains(t, logs, credential) + assert.NotContains(t, logs, "synthetic-header-credential") + for _, cookie := range tc.cookies { + assert.NotContains(t, logs, cookie.Value) + } + expectedAuth := "AUTH callback-log-test - AuthFailure " + tc.diagnostic + "\n" + + fmt.Sprintf("AUTH callback-log-test - AuthFailure Invalid authentication via OAuth2: unable to obtain CSRF cookie: CSRF cookie with name '%s' was not found\n", csrfCookie.Name) + if !logging.auth { + expectedAuth = "" + } + if logging.request { + assert.True(t, strings.HasPrefix(output.String(), expectedAuth+"REQUEST "), "unexpected logs: %s", output.String()) + assert.Equal(t, strings.Count(expectedAuth, "\n")+1, strings.Count(output.String(), "\n")) + } else { + assert.Equal(t, expectedAuth, output.String()) + } + }) + } + } + } +} + // getEndpointWithCookie makes a requests againt the oauthproxy with passed requestPath // and cookie and returns body and status code. func (patTest *PassAccessTokenTest) getEndpointWithCookie(cookie string, endpoint string) (httpCode int, accessToken string) {