From 1aac76af4a7f9e4a7c985bd24483b0e35e58082c Mon Sep 17 00:00:00 2001 From: Simon Franken Date: Thu, 19 Feb 2026 18:55:00 +0100 Subject: [PATCH] Add detailed logging to auth flow on backend and iOS --- backend/src/middleware/auth.ts | 12 ++++- backend/src/routes/auth.routes.ts | 18 ++++++-- .../TimeTracker/Core/Auth/AuthService.swift | 20 ++++++++- .../TimeTracker/Core/Network/APIClient.swift | 45 ++++++++++++------- 4 files changed, 75 insertions(+), 20 deletions(-) diff --git a/backend/src/middleware/auth.ts b/backend/src/middleware/auth.ts index 4a9dd8c..a8a256a 100644 --- a/backend/src/middleware/auth.ts +++ b/backend/src/middleware/auth.ts @@ -8,8 +8,11 @@ export async function requireAuth( res: Response, next: NextFunction ): Promise { + const tag = `[requireAuth] ${req.method} ${req.path}`; + // 1. Session-based auth (web frontend) if (req.session?.user) { + console.log(`${tag} -> session auth OK (user: ${req.session.user.id})`); req.user = req.session.user as AuthenticatedUser; return next(); } @@ -18,17 +21,24 @@ export async function requireAuth( const authHeader = req.headers.authorization; if (authHeader?.startsWith('Bearer ')) { const token = authHeader.slice(7); + console.log(`${tag} -> Bearer token present (first 20 chars: ${token.slice(0, 20)}…)`); try { - // Verify the backend-signed JWT locally — no IDP network call needed. req.user = verifyBackendJwt(token); + console.log(`${tag} -> JWT auth OK (user: ${req.user.id})`); return next(); } catch (err) { const message = err instanceof Error ? err.message : String(err); + console.warn(`${tag} -> JWT verification failed: ${message}`); res.status(401).json({ error: `Unauthorized: ${message}` }); return; } } + if (authHeader) { + console.warn(`${tag} -> Authorization header present but not a Bearer token: "${authHeader.slice(0, 30)}…"`); + } else { + console.warn(`${tag} -> No session and no Authorization header`); + } res.status(401).json({ error: 'Unauthorized' }); } diff --git a/backend/src/routes/auth.routes.ts b/backend/src/routes/auth.routes.ts index d502c03..65c641e 100644 --- a/backend/src/routes/auth.routes.ts +++ b/backend/src/routes/auth.routes.ts @@ -50,21 +50,24 @@ router.get("/login", async (req, res) => { await ensureOIDC(); const redirectUri = req.query.redirect_uri as string | undefined; + console.log(`[auth/login] initiated (redirect_uri: ${redirectUri ?? '(web flow)'})`); const session = createAuthSession(redirectUri); if (redirectUri) { // Native app flow: store session by state so /auth/token can retrieve it // without relying on the browser cookie jar. storeNativeSession(session); + console.log(`[auth/login] native session stored (state: ${session.state})`); } else { // Web flow: store session in the cookie-backed server session as before. req.session.oidc = session; } const authorizationUrl = getAuthorizationUrl(session, redirectUri); + console.log(`[auth/login] redirecting to IDP`); res.redirect(authorizationUrl); } catch (error) { - console.error("Login error:", error); + console.error("[auth/login] error:", error); res.status(500).json({ error: "Failed to initiate login" }); } }); @@ -129,24 +132,33 @@ router.post("/token", async (req, res) => { await ensureOIDC(); const { code, state, redirect_uri } = req.body; + console.log(`[auth/token] received (state: ${state}, redirect_uri: ${redirect_uri}, code present: ${!!code})`); if (!code || !state || !redirect_uri) { - res.status(400).json({ error: "Missing required parameters: code, state, redirect_uri" }); + const missing = ['code', 'state', 'redirect_uri'].filter(k => !req.body[k]); + console.warn(`[auth/token] missing parameters: ${missing.join(', ')}`); + res.status(400).json({ error: `Missing required parameters: ${missing.join(', ')}` }); return; } const oidcSession = popNativeSession(state); if (!oidcSession) { + console.warn(`[auth/token] no session found for state "${state}" — known states: [${[...nativeOidcSessions.keys()].join(', ')}]`); res.status(400).json({ error: "OIDC session not found or expired. Initiate login again." }); return; } + console.log(`[auth/token] session found, exchanging code with IDP`); const tokenSet = await exchangeNativeCode(code, oidcSession.codeVerifier, redirect_uri); + console.log(`[auth/token] IDP code exchange OK (access_token present: ${!!tokenSet.access_token}, id_token present: ${!!tokenSet.id_token})`); + const user = await getUserInfo(tokenSet); + console.log(`[auth/token] user resolved (id: ${user.id}, email: ${user.email})`); await syncUser(user); // Mint a backend JWT. The iOS app stores this and sends it as Bearer . const backendJwt = signBackendJwt(user); + console.log(`[auth/token] backend JWT minted for user ${user.id}`); res.json({ access_token: backendJwt, @@ -156,7 +168,7 @@ router.post("/token", async (req, res) => { }); } catch (error) { const message = error instanceof Error ? error.message : String(error); - console.error("Token exchange error:", error); + console.error("[auth/token] error:", error); res.status(500).json({ error: `Failed to exchange token: ${message}` }); } }); diff --git a/ios/TimeTracker/TimeTracker/Core/Auth/AuthService.swift b/ios/TimeTracker/TimeTracker/Core/Auth/AuthService.swift index 8b17a90..4d7a773 100644 --- a/ios/TimeTracker/TimeTracker/Core/Auth/AuthService.swift +++ b/ios/TimeTracker/TimeTracker/Core/Auth/AuthService.swift @@ -1,6 +1,9 @@ import Foundation import AuthenticationServices import CryptoKit +import OSLog + +private let logger = Logger(subsystem: "com.timetracker.app", category: "AuthService") final class AuthService: NSObject { static let shared = AuthService() @@ -29,6 +32,9 @@ final class AuthService: NSObject { throw AuthError.invalidURL } + logger.info("Starting login — auth URL: \(authURL.absoluteString)") + logger.info("Callback URL scheme: \(AppConfig.authCallbackURL)") + let callbackScheme = URL(string: AppConfig.authCallbackURL)?.scheme ?? "timetracker" // Use an ephemeral session — we only need the redirect URL back with the @@ -40,8 +46,10 @@ final class AuthService: NSObject { if let error = error { let authError: AuthError if (error as? ASWebAuthenticationSessionError)?.code == .canceledLogin { + logger.info("Login cancelled by user") authError = .cancelled } else { + logger.error("ASWebAuthenticationSession error: \(error)") authError = .failed(error.localizedDescription) } DispatchQueue.main.async { @@ -55,6 +63,7 @@ final class AuthService: NSObject { } guard let callbackURL = callbackURL else { + logger.error("ASWebAuthenticationSession returned nil callbackURL") DispatchQueue.main.async { NotificationCenter.default.post( name: .authError, @@ -91,6 +100,7 @@ final class AuthService: NSObject { let code = components.queryItems?.first(where: { $0.name == "code" })?.value, let state = components.queryItems?.first(where: { $0.name == "state" })?.value else { + logger.error("Callback URL missing code or state: \(url.absoluteString)") DispatchQueue.main.async { NotificationCenter.default.post( name: .authError, @@ -103,11 +113,13 @@ final class AuthService: NSObject { Task { do { + logger.info("Exchanging code for tokens (state: \(state), redirect_uri: \(AppConfig.authCallbackURL))") let tokenResponse = try await exchangeCodeForTokens( code: code, state: state, redirectUri: AppConfig.authCallbackURL ) + logger.info("Token exchange succeeded for user: \(tokenResponse.user.id)") await AuthManager.shared.handleTokenResponse(tokenResponse) @@ -115,6 +127,7 @@ final class AuthService: NSObject { NotificationCenter.default.post(name: .authCallbackReceived, object: nil) } } catch { + logger.error("Token exchange failed: \(error)") DispatchQueue.main.async { NotificationCenter.default.post( name: .authError, @@ -152,12 +165,17 @@ final class AuthService: NSObject { throw AuthError.failed("Invalid response") } + let bodyString = String(data: data, encoding: .utf8) ?? "(non-UTF8 body)" + logger.debug("POST /auth/token — status \(httpResponse.statusCode), body: \(bodyString)") + guard httpResponse.statusCode == 200 else { if let errorJson = try? JSONSerialization.jsonObject(with: data) as? [String: Any], let errorMessage = errorJson["error"] as? String { + logger.error("POST /auth/token — server error: \(errorMessage)") throw AuthError.failed(errorMessage) } - throw AuthError.failed("Token exchange failed with status \(httpResponse.statusCode)") + logger.error("POST /auth/token — unexpected status \(httpResponse.statusCode): \(bodyString)") + throw AuthError.failed("Token exchange failed with status \(httpResponse.statusCode): \(bodyString)") } return try JSONDecoder().decode(TokenResponse.self, from: data) diff --git a/ios/TimeTracker/TimeTracker/Core/Network/APIClient.swift b/ios/TimeTracker/TimeTracker/Core/Network/APIClient.swift index 956046f..b081cb5 100644 --- a/ios/TimeTracker/TimeTracker/Core/Network/APIClient.swift +++ b/ios/TimeTracker/TimeTracker/Core/Network/APIClient.swift @@ -1,4 +1,7 @@ import Foundation +import OSLog + +private let logger = Logger(subsystem: "com.timetracker.app", category: "APIClient") actor APIClient { private let session: URLSession @@ -43,9 +46,11 @@ actor APIClient { if authenticated { let token = await MainActor.run { AuthManager.shared.accessToken } guard let token = token else { + logger.warning("\(method.rawValue) \(endpoint) — no access token in keychain, throwing .unauthorized") throw NetworkError.unauthorized } request.setValue("Bearer \(token)", forHTTPHeaderField: "Authorization") + logger.debug("\(method.rawValue) \(endpoint) — Authorization header set (token: \(token.prefix(20))…)") } if let body = body { @@ -53,27 +58,29 @@ actor APIClient { } do { + logger.debug("\(method.rawValue) \(url.absoluteString) — sending request") let (data, response) = try await session.data(for: request) guard let httpResponse = response as? HTTPURLResponse else { throw NetworkError.invalidResponse } + logger.debug("\(method.rawValue) \(endpoint) — status \(httpResponse.statusCode)") + if httpResponse.statusCode == 401 { - let message = try? decoder.decode(ErrorResponse.self, from: data).error - await MainActor.run { - AuthManager.shared.clearAuth() - } - throw NetworkError.httpError(statusCode: 401, message: message) + let serverMessage = (try? decoder.decode(ErrorResponse.self, from: data))?.error + logger.error("\(method.rawValue) \(endpoint) — 401 Unauthorized. Server: \(serverMessage ?? "(no message)")") + await MainActor.run { AuthManager.shared.clearAuth() } + throw NetworkError.httpError(statusCode: 401, message: serverMessage) } guard (200...299).contains(httpResponse.statusCode) else { - let message = try? decoder.decode(ErrorResponse.self, from: data).error - throw NetworkError.httpError(statusCode: httpResponse.statusCode, message: message) + let serverMessage = (try? decoder.decode(ErrorResponse.self, from: data))?.error + logger.error("\(method.rawValue) \(endpoint) — HTTP \(httpResponse.statusCode). Server: \(serverMessage ?? "(no message)")") + throw NetworkError.httpError(statusCode: httpResponse.statusCode, message: serverMessage) } if data.isEmpty { - let empty: T? = nil return try decoder.decode(T.self, from: "{}".data(using: .utf8)!) } @@ -81,8 +88,10 @@ actor APIClient { } catch let error as NetworkError { throw error } catch let error as DecodingError { + logger.error("\(method.rawValue) \(endpoint) — decoding error: \(error)") throw NetworkError.decodingError(error) } catch { + logger.error("\(method.rawValue) \(endpoint) — network error: \(error)") throw NetworkError.networkError(error) } } @@ -115,9 +124,11 @@ actor APIClient { if authenticated { let token = await MainActor.run { AuthManager.shared.accessToken } guard let token = token else { + logger.warning("\(method.rawValue) \(endpoint) — no access token in keychain, throwing .unauthorized") throw NetworkError.unauthorized } request.setValue("Bearer \(token)", forHTTPHeaderField: "Authorization") + logger.debug("\(method.rawValue) \(endpoint) — Authorization header set (token: \(token.prefix(20))…)") } if let body = body { @@ -125,27 +136,31 @@ actor APIClient { } do { + logger.debug("\(method.rawValue) \(url.absoluteString) — sending request") let (data, response) = try await session.data(for: request) guard let httpResponse = response as? HTTPURLResponse else { throw NetworkError.invalidResponse } + logger.debug("\(method.rawValue) \(endpoint) — status \(httpResponse.statusCode)") + if httpResponse.statusCode == 401 { - let message = try? decoder.decode(ErrorResponse.self, from: data).error - await MainActor.run { - AuthManager.shared.clearAuth() - } - throw NetworkError.httpError(statusCode: 401, message: message) + let serverMessage = (try? decoder.decode(ErrorResponse.self, from: data))?.error + logger.error("\(method.rawValue) \(endpoint) — 401 Unauthorized. Server: \(serverMessage ?? "(no message)")") + await MainActor.run { AuthManager.shared.clearAuth() } + throw NetworkError.httpError(statusCode: 401, message: serverMessage) } guard (200...299).contains(httpResponse.statusCode) else { - let message = try? decoder.decode(ErrorResponse.self, from: data).error - throw NetworkError.httpError(statusCode: httpResponse.statusCode, message: message) + let serverMessage = (try? decoder.decode(ErrorResponse.self, from: data))?.error + logger.error("\(method.rawValue) \(endpoint) — HTTP \(httpResponse.statusCode). Server: \(serverMessage ?? "(no message)")") + throw NetworkError.httpError(statusCode: httpResponse.statusCode, message: serverMessage) } } catch let error as NetworkError { throw error } catch { + logger.error("\(method.rawValue) \(endpoint) — network error: \(error)") throw NetworkError.networkError(error) } }