chore(headless-login): add request correlation logs

2026-04-01 19:42:09 +09:00
parent c3ae316570
commit 8bab8d44cc
2 changed files with 588 additions and 23 deletions
--- a/backend/internal/handler/auth_handler_login_test.go
+++ b/backend/internal/handler/auth_handler_login_test.go
@@ -18,6 +18,7 @@ import (
 	"encoding/json"
 	"errors"
 	"io"
+	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"strings"
@@ -202,6 +203,35 @@ func mustHeadlessClientAssertion(t *testing.T, privateKey *rsa.PrivateKey, clien
 	return raw
 }

+func mustHeadlessClientAssertionWithCustomClaims(
+	t *testing.T,
+	privateKey *rsa.PrivateKey,
+	clientID string,
+	claims josejwt.Claims,
+) string {
+	t.Helper()
+
+	signer, err := jose.NewSigner(jose.SigningKey{
+		Algorithm: jose.RS256,
+		Key: jose.JSONWebKey{
+			Key:       privateKey,
+			KeyID:     "test-kid",
+			Use:       "sig",
+			Algorithm: string(jose.RS256),
+		},
+	}, nil)
+	if err != nil {
+		t.Fatalf("failed to create signer: %v", err)
+	}
+
+	raw, err := josejwt.Signed(signer).Claims(claims).Serialize()
+	if err != nil {
+		t.Fatalf("failed to sign client assertion: %v", err)
+	}
+
+	return raw
+}
+
 func mustHeadlessJWKForAlgorithm(t *testing.T, alg jose.SignatureAlgorithm) (any, map[string]any) {
 	t.Helper()

@@ -379,6 +409,94 @@ func runHeadlessPasswordLoginWithAssertion(t *testing.T, jwks map[string]any, cl
 	return resp
 }

+func runHeadlessPasswordLoginWithAssertionAndLogger(
+	t *testing.T,
+	jwks map[string]any,
+	clientAssertion string,
+	logger *slog.Logger,
+) *http.Response {
+	t.Helper()
+
+	mockIdp := new(MockIdentityProvider)
+	mockIdp.On("SignIn", "employee001", "password").Return(&domain.AuthInfo{
+		SessionToken: &domain.Token{JWT: "valid-jwt"},
+		Subject:      "kratos-identity-id",
+	}, nil)
+
+	mockKratos := new(MockKratosAdminService)
+	mockKratos.On("FindIdentityIDByIdentifier", mock.Anything, "employee001").Return("kratos-identity-id", nil)
+
+	jwksBody, err := json.Marshal(jwks)
+	if err != nil {
+		t.Fatalf("failed to marshal jwks body: %v", err)
+	}
+	jwksServer := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.Header().Set("Content-Type", "application/json")
+		_, _ = w.Write(jwksBody)
+	}))
+	t.Cleanup(jwksServer.Close)
+
+	hydraHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		switch {
+		case strings.Contains(r.URL.Path, "/oauth2/auth/requests/login") && r.Method == http.MethodGet:
+			json.NewEncoder(w).Encode(domain.HydraLoginRequest{
+				Challenge: "challenge-123",
+				Client: domain.HydraClient{
+					ClientID:                "headless-login-client",
+					TokenEndpointAuthMethod: "none",
+					Metadata: map[string]interface{}{
+						"status":                              "active",
+						"headless_login_enabled":              true,
+						"headless_token_endpoint_auth_method": "private_key_jwt",
+						"headless_jwks_uri":                   jwksServer.URL + "/.well-known/jwks.json",
+					},
+				},
+			})
+			return
+		case strings.Contains(r.URL.Path, "/oauth2/auth/requests/login/accept") && r.Method == http.MethodPut:
+			json.NewEncoder(w).Encode(map[string]string{"redirect_to": "http://rp/cb"})
+			return
+		}
+		http.NotFound(w, r)
+	})
+
+	h := &AuthHandler{
+		IdpProvider: mockIdp,
+		KratosAdmin: mockKratos,
+		Hydra: &service.HydraAdminService{
+			AdminURL:   "http://hydra.test",
+			HTTPClient: &http.Client{Transport: mockHydraTransport(hydraHandler)},
+		},
+	}
+
+	app := newHeadlessPasswordLoginTestApp(h)
+
+	body, _ := json.Marshal(map[string]string{
+		"client_id":        "headless-login-client",
+		"client_assertion": clientAssertion,
+		"loginId":          "employee001",
+		"password":         "password",
+		"login_challenge":  "challenge-123",
+	})
+	req := httptest.NewRequest(http.MethodPost, "/api/v1/auth/headless/password/login", bytes.NewReader(body))
+	req.Header.Set("Content-Type", "application/json")
+	req.Header.Set("X-Request-Id", "req-headless-test-123")
+
+	if logger != nil {
+		previous := slog.Default()
+		slog.SetDefault(logger.With())
+		t.Cleanup(func() {
+			slog.SetDefault(previous)
+		})
+	}
+
+	resp, err := app.Test(req)
+	if err != nil {
+		t.Fatalf("request failed: %v", err)
+	}
+	return resp
+}
+
 // mockHydraTransport simulates Hydra API responses
 func mockHydraTransport(handler http.Handler) http.RoundTripper {
 	return roundTripFunc(func(req *http.Request) (*http.Response, error) {
@@ -900,6 +1018,222 @@ func TestHeadlessPasswordLogin_InvalidClientAssertionRejected(t *testing.T) {
 		bodyBytes, _ := io.ReadAll(resp.Body)
 		t.Fatalf("expected 401, got %d, body: %s", resp.StatusCode, string(bodyBytes))
 	}
+
+	var got map[string]any
+	if err := json.NewDecoder(resp.Body).Decode(&got); err != nil {
+		t.Fatalf("failed to decode response: %v", err)
+	}
+	if got["code"] != "invalid_client_assertion_signature" {
+		t.Fatalf("expected code=invalid_client_assertion_signature, got=%v", got["code"])
+	}
+	if got["error"] != "Client assertion signature verification failed" {
+		t.Fatalf("expected detailed signature error, got=%v", got["error"])
+	}
+}
+
+func TestHeadlessPasswordLogin_AudienceMismatchReturnsDetailedCode(t *testing.T) {
+	privateKey, jwks := mustHeadlessRSAJWK(t)
+	clientAssertion := mustHeadlessClientAssertion(
+		t,
+		privateKey,
+		"headless-login-client",
+		"https://rp.example.com/oidc/token",
+	)
+
+	resp := runHeadlessPasswordLoginWithAssertion(t, jwks, clientAssertion)
+	defer resp.Body.Close()
+
+	if resp.StatusCode != http.StatusUnauthorized {
+		bodyBytes, _ := io.ReadAll(resp.Body)
+		t.Fatalf("expected 401, got %d, body: %s", resp.StatusCode, string(bodyBytes))
+	}
+
+	var got map[string]any
+	if err := json.NewDecoder(resp.Body).Decode(&got); err != nil {
+		t.Fatalf("failed to decode response: %v", err)
+	}
+	if got["code"] != "invalid_client_assertion_audience" {
+		t.Fatalf("expected code=invalid_client_assertion_audience, got=%v", got["code"])
+	}
+	if got["error"] != "Client assertion audience mismatch" {
+		t.Fatalf("expected audience mismatch error, got=%v", got["error"])
+	}
+}
+
+func TestHeadlessPasswordLogin_IssSubMismatchReturnsDetailedCode(t *testing.T) {
+	privateKey, jwks := mustHeadlessRSAJWK(t)
+	now := time.Now()
+	clientAssertion := mustHeadlessClientAssertionWithCustomClaims(
+		t,
+		privateKey,
+		"headless-login-client",
+		josejwt.Claims{
+			Issuer:   "other-client",
+			Subject:  "headless-login-client",
+			Audience: josejwt.Audience{"http://example.com/api/v1/auth/headless/password/login"},
+			Expiry:   josejwt.NewNumericDate(now.Add(5 * time.Minute)),
+			IssuedAt: josejwt.NewNumericDate(now),
+			NotBefore: josejwt.NewNumericDate(
+				now.Add(-1 * time.Minute),
+			),
+			ID: "assertion-iss-mismatch",
+		},
+	)
+
+	resp := runHeadlessPasswordLoginWithAssertion(t, jwks, clientAssertion)
+	defer resp.Body.Close()
+
+	if resp.StatusCode != http.StatusUnauthorized {
+		bodyBytes, _ := io.ReadAll(resp.Body)
+		t.Fatalf("expected 401, got %d, body: %s", resp.StatusCode, string(bodyBytes))
+	}
+
+	var got map[string]any
+	if err := json.NewDecoder(resp.Body).Decode(&got); err != nil {
+		t.Fatalf("failed to decode response: %v", err)
+	}
+	if got["code"] != "invalid_client_assertion_iss_sub" {
+		t.Fatalf("expected code=invalid_client_assertion_iss_sub, got=%v", got["code"])
+	}
+	if got["error"] != "Client assertion issuer or subject mismatch" {
+		t.Fatalf("expected iss/sub mismatch error, got=%v", got["error"])
+	}
+}
+
+func TestHeadlessPasswordLogin_ExpiredAssertionReturnsDetailedCode(t *testing.T) {
+	privateKey, jwks := mustHeadlessRSAJWK(t)
+	now := time.Now()
+	clientAssertion := mustHeadlessClientAssertionWithCustomClaims(
+		t,
+		privateKey,
+		"headless-login-client",
+		josejwt.Claims{
+			Issuer:   "headless-login-client",
+			Subject:  "headless-login-client",
+			Audience: josejwt.Audience{"http://example.com/api/v1/auth/headless/password/login"},
+			Expiry:   josejwt.NewNumericDate(now.Add(-1 * time.Minute)),
+			IssuedAt: josejwt.NewNumericDate(now.Add(-10 * time.Minute)),
+			NotBefore: josejwt.NewNumericDate(
+				now.Add(-11 * time.Minute),
+			),
+			ID: "assertion-expired",
+		},
+	)
+
+	resp := runHeadlessPasswordLoginWithAssertion(t, jwks, clientAssertion)
+	defer resp.Body.Close()
+
+	if resp.StatusCode != http.StatusUnauthorized {
+		bodyBytes, _ := io.ReadAll(resp.Body)
+		t.Fatalf("expected 401, got %d, body: %s", resp.StatusCode, string(bodyBytes))
+	}
+
+	var got map[string]any
+	if err := json.NewDecoder(resp.Body).Decode(&got); err != nil {
+		t.Fatalf("failed to decode response: %v", err)
+	}
+	if got["code"] != "invalid_client_assertion_expired" {
+		t.Fatalf("expected code=invalid_client_assertion_expired, got=%v", got["code"])
+	}
+	if got["error"] != "Client assertion has expired" {
+		t.Fatalf("expected expired assertion error, got=%v", got["error"])
+	}
+}
+
+func TestHeadlessPasswordLogin_DebugLogIncludesDiagnostics(t *testing.T) {
+	privateKey, jwks := mustHeadlessRSAJWK(t)
+	clientAssertion := mustHeadlessClientAssertion(
+		t,
+		privateKey,
+		"headless-login-client",
+		"https://rp.example.com/oidc/token",
+	)
+
+	buf := &bytes.Buffer{}
+	logger := slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
+
+	resp := runHeadlessPasswordLoginWithAssertionAndLogger(t, jwks, clientAssertion, logger)
+	defer resp.Body.Close()
+
+	if resp.StatusCode != http.StatusUnauthorized {
+		bodyBytes, _ := io.ReadAll(resp.Body)
+		t.Fatalf("expected 401, got %d, body: %s", resp.StatusCode, string(bodyBytes))
+	}
+
+	logOutput := buf.String()
+	if !strings.Contains(logOutput, "expected_audiences") {
+		t.Fatalf("expected debug log to include expected_audiences, got=%s", logOutput)
+	}
+	if !strings.Contains(logOutput, "received_audiences") {
+		t.Fatalf("expected debug log to include received_audiences, got=%s", logOutput)
+	}
+	if !strings.Contains(logOutput, "invalid_client_assertion_audience") {
+		t.Fatalf("expected debug log to include reason code, got=%s", logOutput)
+	}
+}
+
+func TestHeadlessPasswordLogin_InfoLogOmitsDebugDiagnostics(t *testing.T) {
+	privateKey, jwks := mustHeadlessRSAJWK(t)
+	clientAssertion := mustHeadlessClientAssertion(
+		t,
+		privateKey,
+		"headless-login-client",
+		"https://rp.example.com/oidc/token",
+	)
+
+	buf := &bytes.Buffer{}
+	logger := slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelInfo}))
+
+	resp := runHeadlessPasswordLoginWithAssertionAndLogger(t, jwks, clientAssertion, logger)
+	defer resp.Body.Close()
+
+	if resp.StatusCode != http.StatusUnauthorized {
+		bodyBytes, _ := io.ReadAll(resp.Body)
+		t.Fatalf("expected 401, got %d, body: %s", resp.StatusCode, string(bodyBytes))
+	}
+
+	logOutput := buf.String()
+	if strings.Contains(logOutput, "expected_audiences") {
+		t.Fatalf("expected info log to omit expected_audiences, got=%s", logOutput)
+	}
+	if strings.Contains(logOutput, "received_audiences") {
+		t.Fatalf("expected info log to omit received_audiences, got=%s", logOutput)
+	}
+}
+
+func TestHeadlessPasswordLogin_SuccessLogIncludesCorrelationFields(t *testing.T) {
+	privateKey, jwks := mustHeadlessRSAJWK(t)
+	clientAssertion := mustHeadlessClientAssertion(
+		t,
+		privateKey,
+		"headless-login-client",
+		"http://example.com/api/v1/auth/headless/password/login",
+	)
+
+	buf := &bytes.Buffer{}
+	logger := slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelInfo}))
+
+	resp := runHeadlessPasswordLoginWithAssertionAndLogger(t, jwks, clientAssertion, logger)
+	defer resp.Body.Close()
+
+	if resp.StatusCode != http.StatusOK {
+		bodyBytes, _ := io.ReadAll(resp.Body)
+		t.Fatalf("expected 200, got %d, body: %s", resp.StatusCode, string(bodyBytes))
+	}
+
+	logOutput := buf.String()
+	for _, needle := range []string{
+		"headless password login succeeded",
+		`"req_id":"req-headless-test-123"`,
+		`"path":"/api/v1/auth/headless/password/login"`,
+		`"client_id":"headless-login-client"`,
+		`"login_challenge_prefix":"challenge-12"`,
+		`"response_status":200`,
+	} {
+		if !strings.Contains(logOutput, needle) {
+			t.Fatalf("expected success log to include %s, got=%s", needle, logOutput)
+		}
+	}
 }

 func TestHeadlessPasswordLogin_AcceptsConfiguredClientAssertionAlgorithms(t *testing.T) {