diff --git a/authsession.go b/authsession.go index 281693a..8948ea6 100644 --- a/authsession.go +++ b/authsession.go @@ -35,6 +35,16 @@ func authTimerEntryExpiry(entry *authTimerState) (expiry time.Time) { return } +// debugSessionPrefix returns a short cookie prefix for log correlation. +func debugSessionPrefix(sess *jaws.Session) string { + value := sess.CookieValue() + // Keep at least eight base-32 characters out of logs. + if len(value) >= 12 { + return value[:4] + } + return "" +} + func tokenDebugAttrs(token *oauth2.Token) []any { attrs := []any{"token_nil", token == nil} if token != nil { @@ -144,12 +154,9 @@ func (srv *Server) setSessionAuthFromToken(ctx context.Context, sess *jaws.Sessi } func (srv *Server) refreshSessionAuth(ctx context.Context, sess *jaws.Session, minExpiry time.Time, entry *authTimerState) (err error) { - var sessionID uint64 - if sess != nil { - sessionID = sess.ID() - } + sessionPrefix := debugSessionPrefix(sess) srv.debugLog("jawsauth: refresh session auth started", - "session_id", sessionID, + "session_prefix", sessionPrefix, "min_expiry", minExpiry, "timer_entry", entry != nil, "entry_expiry", authTimerEntryExpiry(entry), @@ -161,41 +168,41 @@ func (srv *Server) refreshSessionAuth(ctx context.Context, sess *jaws.Session, m if tokenSource != nil { authctx := srv.oauth2Context(ctx) var token *oauth2.Token - srv.debugLog("jawsauth: requesting token from stored token source", "session_id", sessionID) + srv.debugLog("jawsauth: requesting token from stored token source", "session_prefix", sessionPrefix) if token, err = tokenSource.Token(); err == nil { - srv.debugLog("jawsauth: stored token source returned token", append([]any{"session_id", sessionID}, tokenDebugAttrs(token)...)...) + srv.debugLog("jawsauth: stored token source returned token", append([]any{"session_prefix", sessionPrefix}, tokenDebugAttrs(token)...)...) err = srv.setSessionAuthFromToken(authctx, sess, tokenSource, token, minExpiry, entry) if err == nil { - srv.debugLog("jawsauth: stored token refreshed session auth", "session_id", sessionID) + srv.debugLog("jawsauth: stored token refreshed session auth", "session_prefix", sessionPrefix) } else { - srv.debugErrorLog("jawsauth: stored token did not refresh session auth", err, "session_id", sessionID) + srv.debugErrorLog("jawsauth: stored token did not refresh session auth", err, "session_prefix", sessionPrefix) } if err != nil && token != nil && token.RefreshToken != "" && !errors.Is(err, errAuthTimerStale) { - srv.debugErrorLog("jawsauth: forcing refresh with refresh token", err, "session_id", sessionID) + srv.debugErrorLog("jawsauth: forcing refresh with refresh token", err, "session_prefix", sessionPrefix) tokenSource = srv.oauth2cfg.TokenSource(authctx, &oauth2.Token{ RefreshToken: token.RefreshToken, }) if token, err = tokenSource.Token(); err == nil { - srv.debugLog("jawsauth: forced refresh returned token", append([]any{"session_id", sessionID}, tokenDebugAttrs(token)...)...) + srv.debugLog("jawsauth: forced refresh returned token", append([]any{"session_prefix", sessionPrefix}, tokenDebugAttrs(token)...)...) err = srv.setSessionAuthFromToken(authctx, sess, tokenSource, token, minExpiry, entry) if err == nil { - srv.debugLog("jawsauth: forced refresh updated session auth", "session_id", sessionID) + srv.debugLog("jawsauth: forced refresh updated session auth", "session_prefix", sessionPrefix) } else { - srv.debugErrorLog("jawsauth: forced refresh did not update session auth", err, "session_id", sessionID) + srv.debugErrorLog("jawsauth: forced refresh did not update session auth", err, "session_prefix", sessionPrefix) } } else { - srv.debugErrorLog("jawsauth: forced refresh token source failed", err, "session_id", sessionID) + srv.debugErrorLog("jawsauth: forced refresh token source failed", err, "session_prefix", sessionPrefix) } } } else { - srv.debugErrorLog("jawsauth: stored token source failed", err, "session_id", sessionID) + srv.debugErrorLog("jawsauth: stored token source failed", err, "session_prefix", sessionPrefix) } } else { - srv.debugLog("jawsauth: refresh session auth missing token source", "session_id", sessionID) + srv.debugLog("jawsauth: refresh session auth missing token source", "session_prefix", sessionPrefix) } } else { srv.debugLog("jawsauth: refresh session auth not configured", - "session_id", sessionID, + "session_prefix", sessionPrefix, "server_nil", srv == nil, "session_nil", sess == nil, "oauth2_configured", srv != nil && srv.oauth2cfg != nil, @@ -227,7 +234,7 @@ func (srv *Server) scheduleSessionAuthTimer(sess *jaws.Session, expiry time.Time }) srv.mu.Unlock() srv.debugLog("jawsauth: scheduled auth refresh timer", - "session_id", sess.ID(), + "session_prefix", debugSessionPrefix(sess), "expiry", expiry, "delay", delay, "refresh_skew", authRefreshSkew, @@ -272,7 +279,7 @@ func (srv *Server) handleSessionAuthTimer(sess *jaws.Session, entry *authTimerSt if srv.sessionAuthTimerCurrent(sess, entry) { current, present := srv.sessionAuthStatus(sess, time.Now) srv.debugLog("jawsauth: auth refresh timer fired", - "session_id", sess.ID(), + "session_prefix", debugSessionPrefix(sess), "entry_expiry", authTimerEntryExpiry(entry), "session_current", current, "session_present", present, @@ -280,7 +287,7 @@ func (srv *Server) handleSessionAuthTimer(sess *jaws.Session, entry *authTimerSt err := srv.refreshSessionAuth(context.Background(), sess, entry.expiry, entry) if err != nil { if errors.Is(err, errAuthTimerStale) { - srv.debugErrorLog("jawsauth: auth refresh timer became stale", err, "session_id", sess.ID()) + srv.debugErrorLog("jawsauth: auth refresh timer became stale", err, "session_prefix", debugSessionPrefix(sess)) return } current, present = srv.sessionAuthStatus(sess, time.Now) @@ -300,7 +307,7 @@ func (srv *Server) handleSessionAuthTimer(sess *jaws.Session, entry *authTimerSt srv.mu.Unlock() if retryScheduled { srv.debugErrorLog("jawsauth: auth refresh timer failed; keeping current auth", err, - "session_id", sess.ID(), + "session_prefix", debugSessionPrefix(sess), "entry_expiry", authTimerEntryExpiry(entry), "session_current", current, "session_present", present, @@ -310,7 +317,7 @@ func (srv *Server) handleSessionAuthTimer(sess *jaws.Session, entry *authTimerSt } } srv.debugErrorLog("jawsauth: auth refresh timer failed; clearing auth", err, - "session_id", sess.ID(), + "session_prefix", debugSessionPrefix(sess), "entry_expiry", authTimerEntryExpiry(entry), "session_current", current, "session_present", present, @@ -318,11 +325,11 @@ func (srv *Server) handleSessionAuthTimer(sess *jaws.Session, entry *authTimerSt _ = srv.Jaws.Log(err) srv.clearSessionAuth(sess, nil, true, true, entry) } else { - srv.debugLog("jawsauth: auth refresh timer completed", "session_id", sess.ID()) + srv.debugLog("jawsauth: auth refresh timer completed", "session_prefix", debugSessionPrefix(sess)) } } else if sess != nil { srv.debugLog("jawsauth: stale auth refresh timer ignored", - "session_id", sess.ID(), + "session_prefix", debugSessionPrefix(sess), "entry_expiry", authTimerEntryExpiry(entry), ) } @@ -365,7 +372,7 @@ func (srv *Server) clearSessionAuth(sess *jaws.Session, hr *http.Request, callLo } cleared = true srv.debugLog("jawsauth: cleared session auth", - "session_id", sess.ID(), + "session_prefix", debugSessionPrefix(sess), "request_present", hr != nil, "call_logout", callLogout, "reload", reload, diff --git a/authsession_test.go b/authsession_test.go index 81b0314..b4cacf2 100644 --- a/authsession_test.go +++ b/authsession_test.go @@ -2,8 +2,10 @@ package jawsauth import ( "errors" + "log/slog" "net/http" "net/http/httptest" + "strconv" "strings" "sync" "testing" @@ -1110,3 +1112,39 @@ func TestServerLogout(t *testing.T) { t.Fatal("nil session should report nothing cleared") } } + +func TestAuthDebugSessionPrefix(t *testing.T) { + jw, err := jaws.New() + if err != nil { + t.Fatal(err) + } + defer jw.Close() + var output strings.Builder + jw.Debug = true + jw.Logger = slog.New(slog.NewTextHandler(&output, nil)) + factory := &testAuthTimerFactory{} + srv := newTimerTestServer(t, jw, "https://issuer.example", factory) + req := httptest.NewRequest(http.MethodGet, "/", nil) + sess := jw.NewSession(httptest.NewRecorder(), req) + expiry := time.Now().Add(time.Hour) + if err = srv.storeSessionAuthClaims(t.Context(), sess, map[string]any{"email": "user@example.com"}, tokenSourceFunc(func() (*oauth2.Token, error) { + return nil, errAuthSessionTestToken + }), expiry, nil); err != nil { + t.Fatal(err) + } + factory.timer(0).fire() + srv.Logout(sess, req) + logs := output.String() + for _, forbidden := range []string{"session_id=", strconv.FormatUint(sess.ID(), 10), sess.CookieValue()} { + if strings.Contains(logs, forbidden) { + t.Fatal("session identifier appeared in debug output") + } + } + want := "" + if encoded := strconv.FormatUint(sess.ID(), 32); len(encoded) >= 12 { + want = encoded[:4] + } + if debugSessionPrefix(sess) != want || !strings.Contains(logs, "session_prefix="+want) || debugSessionPrefix(nil) != "" { + t.Fatal("missing session cookie prefix") + } +} diff --git a/cmd/demo/demo.go b/cmd/demo/demo.go index 15203bd..0ad5d5c 100644 --- a/cmd/demo/demo.go +++ b/cmd/demo/demo.go @@ -339,9 +339,9 @@ func demoLoginFailed(hw http.ResponseWriter, hr *http.Request, httpCode int, err } if email != "" { - demoLoginFailedLogger.Printf("demo login failed: status=%d email=%q err=%v", httpCode, email, err) + demoLoginFailedLogger.Printf("demo login failed: status=%d email=%q err=%q", httpCode, email, err) } else { - demoLoginFailedLogger.Printf("demo login failed: status=%d err=%v", httpCode, err) + demoLoginFailedLogger.Printf("demo login failed: status=%d err=%q", httpCode, err) } https := hr != nil && hr.TLS != nil diff --git a/cmd/demo/loginfailed_test.go b/cmd/demo/loginfailed_test.go index 84e8885..7087926 100644 --- a/cmd/demo/loginfailed_test.go +++ b/cmd/demo/loginfailed_test.go @@ -7,6 +7,7 @@ import ( "log" "net/http" "net/http/httptest" + "strconv" "strings" "testing" ) @@ -63,3 +64,18 @@ func TestDemoLoginFailed(t *testing.T) { t.Fatalf("log output missing underlying error: %q", logText) } } + +func TestDemoLoginFailedQuotesError(t *testing.T) { + var output strings.Builder + original := demoLoginFailedLogger + demoLoginFailedLogger = log.New(&output, "", 0) + t.Cleanup(func() { demoLoginFailedLogger = original }) + for _, email := range []string{"", "user@example.com"} { + output.Reset() + err := errors.New("provider error\r\nTrace ID: 123\x1b") + demoLoginFailed(httptest.NewRecorder(), nil, http.StatusBadRequest, err, email) + if got := output.String(); strings.Count(got, "\n") != 1 || strings.ContainsAny(got, "\r\x1b") || !strings.Contains(got, strconv.Quote(err.Error())) { + t.Fatalf("unquoted log: %q", got) + } + } +} diff --git a/erroauth2callback.go b/erroauth2callback.go index af323db..85086d5 100644 --- a/erroauth2callback.go +++ b/erroauth2callback.go @@ -6,7 +6,10 @@ import ( "strings" ) -// ErrOAuth2Callback matches OAuth2 callback errors returned by the identity provider. +// ErrOAuth2Callback matches OAuth2 callback errors. +// +// Callback fields are untrusted browser input, even when they appear to come +// from the identity provider. var ErrOAuth2Callback = errors.New("oauth2 callback error") // OAuth2CallbackError describes an OAuth2 callback error response. diff --git a/erroauth2callback_test.go b/erroauth2callback_test.go index 6fe7564..f9b4baa 100644 --- a/erroauth2callback_test.go +++ b/erroauth2callback_test.go @@ -5,6 +5,7 @@ import ( "io" "net/http" "net/http/httptest" + "net/url" "strings" "testing" @@ -223,3 +224,23 @@ func Test_handleAuthResponseOAuthErrorCallbackReceivesSessionEmail(t *testing.T) t.Fatal(email) } } + +func TestCallbackParametersPreserveProviderText(t *testing.T) { + values := url.Values{ + "error": {"server_error"}, + "error_description": {" Åtkomst nekad\r\nTrace ID: 123\t "}, + "error_uri": {"https://provider.example/help\x1b"}, + } + req := httptest.NewRequest(http.MethodGet, "/callback?"+values.Encode(), nil) + _, err := oauth2CallbackError(http.StatusBadRequest, req) + var callbackErr *OAuth2CallbackError + if !errors.As(err, &callbackErr) { + t.Fatal(err) + } + if callbackErr.Description != "Åtkomst nekad\r\nTrace ID: 123" || callbackErr.URI != "https://provider.example/help\x1b" { + t.Fatal(callbackErr) + } + if !strings.Contains(err.Error(), "\r\nTrace ID: 123") { + t.Fatal(err) + } +} diff --git a/server.go b/server.go index 3d56af9..e08a465 100644 --- a/server.go +++ b/server.go @@ -58,7 +58,8 @@ type EventFunc func(sess *jaws.Session, hr *http.Request) // FailedFunc is called when a login attempt fails. // // It returns true if it wrote the HTTP response itself, in which case jawsauth writes -// nothing further. +// nothing further. Errors can contain untrusted browser-supplied text. Quote errors +// when logging them and escape them for the output format when rendering them. type FailedFunc func(hw http.ResponseWriter, hr *http.Request, httpCode int, err error, email string) (wroteresponse bool) // Server provides OIDC-verified authentication for JaWS sessions.