fix: redact session identities and quote callback logs

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,15 +279,15 @@ 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,
 		)
 		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,19 +317,19 @@ 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,
 			)
 			_ = 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,

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")
+	}
+}

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

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)
+		}
+	}
+}

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.

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)
+	}
+}

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.