diff --git a/README.md b/README.md index aa3abf1..a0bb9cf 100644 --- a/README.md +++ b/README.md @@ -99,6 +99,26 @@ Production: point your webserver at `public/` as document root, `APP_ENV=prod`, Sessions are stored via Symfony's filesystem cache by default (`config/packages/cache.yaml`) — fine for one instance. For multiple instances behind a load balancer, switch the `bff.session_cache` pool to `cache.adapter.redis` and add `REDIS_DSN`. +## Logging + +Two dedicated Monolog channels write to their own rotating files in `var/log`, in every environment: + +| File | Channel | Kept | Records | +| --- | --- | --- | --- | +| `auth..log` | `auth` | 30 days | The login/logout/authorization trail | +| `api..log` | `api` | 14 days | One record per `/api/*` call | + +**`auth`** — `auth.login.start` and `auth.login.unknown_app` (login redirect), `auth.callback.state_mismatch` and `auth.callback.failed` (a failed code exchange or token decode, previously an anonymous 500), `auth.login.denied` (missing access role), `auth.login.success`, `auth.logout`, and the per-call rejections from `/auth/verify` and `/auth/me`: `auth.session.unauthenticated`, `auth.session.unknown_app`, `auth.session.expired`, `auth.session.access_denied`. Server-side token refreshes add `auth.session.refreshed`, `auth.session.missing`, `auth.session.refresh_failed` and `auth.token.decode_failed`. Successful `verify`/`me` calls are deliberately *not* logged — they run on every page load and would bury the rest. + +**`api`** — `api.request` for every completed proxy call (`info` below status 400, `warning` from 400 up) with method, path, backend, upstream status and `duration_ms`, plus `api.request.unauthenticated`, `api.request.session_expired`, `api.request.unknown_backend` and `api.request.upstream_unreachable`. + +Both channels are excluded from the `main` handler, so records are never duplicated and — importantly in prod, where `main` is `fingers_crossed` — never buffered away just because the request succeeded. + +Two things to know about the content: + +- **It contains PII.** Records carry `user_id` (Keycloak `sub`), `email`, `preferred_username` and the user's role list. Treat `var/log` accordingly: it is a personal-data store, not just diagnostics. +- **It never contains credentials.** Sessions appear only as `sid_hash`, a 12-character SHA-256 prefix of the `sid` — enough to follow one session across both files, useless as a bearer token. Access, refresh and ID tokens, request/response bodies, query strings and forwarded headers are never logged. + ## Appsmith app integration ### Queries to set up diff --git a/config/packages/monolog.yaml b/config/packages/monolog.yaml index 2d7f6df..817166f 100644 --- a/config/packages/monolog.yaml +++ b/config/packages/monolog.yaml @@ -1,6 +1,13 @@ monolog: channels: - deprecation # Deprecations are logged in the dedicated "deprecation" channel when it exists + # Audit channels, each with its own file in every env (see below). + # "auth" is the login/logout/authorization trail, "api" one record per + # proxied backend call. Both are excluded from "main" everywhere, so + # they never get duplicated — and, in prod, never get swallowed by the + # fingers_crossed buffer that only flushes on an error. + - auth + - api when@dev: monolog: @@ -9,11 +16,23 @@ when@dev: type: stream path: "%kernel.logs_dir%/%kernel.environment%.log" level: debug - channels: ["!event"] + channels: ["!event", "!auth", "!api"] console: type: console process_psr_3_messages: false channels: ["!event", "!doctrine", "!console"] + auth: + type: rotating_file + channels: [auth] + path: "%kernel.logs_dir%/auth.%kernel.environment%.log" + max_files: 30 + level: info + api: + type: rotating_file + channels: [api] + path: "%kernel.logs_dir%/api.%kernel.environment%.log" + max_files: 14 + level: info when@test: monolog: @@ -23,11 +42,23 @@ when@test: action_level: error handler: nested excluded_http_codes: [404, 405] - channels: ["!event"] + channels: ["!event", "!auth", "!api"] nested: type: stream path: "%kernel.logs_dir%/%kernel.environment%.log" level: debug + auth: + type: rotating_file + channels: [auth] + path: "%kernel.logs_dir%/auth.%kernel.environment%.log" + max_files: 30 + level: info + api: + type: rotating_file + channels: [api] + path: "%kernel.logs_dir%/api.%kernel.environment%.log" + max_files: 14 + level: info when@prod: monolog: @@ -37,7 +68,7 @@ when@prod: action_level: error handler: nested excluded_http_codes: [404, 405] - channels: ["!deprecation"] + channels: ["!deprecation", "!auth", "!api"] buffer_size: 50 # How many messages should be saved? Prevent memory leaks nested: # Plain rsync/Deployer shared hosting (see deploy.php), not a @@ -56,3 +87,18 @@ when@prod: channels: [deprecation] path: "%kernel.logs_dir%/%kernel.environment%.deprecation.log" max_files: 14 + auth: + # The audit trail: kept longer than everything else, and never + # routed through fingers_crossed — these info records must land + # even on a request where nothing went wrong. + type: rotating_file + channels: [auth] + path: "%kernel.logs_dir%/auth.%kernel.environment%.log" + max_files: 30 + level: info + api: + type: rotating_file + channels: [api] + path: "%kernel.logs_dir%/api.%kernel.environment%.log" + max_files: 14 + level: info diff --git a/src/Controller/AuthController.php b/src/Controller/AuthController.php index 43c51e5..d73274e 100644 --- a/src/Controller/AuthController.php +++ b/src/Controller/AuthController.php @@ -7,6 +7,8 @@ use App\Security\AppRegistry; use App\Security\IdTokenDecoder; use App\Session\BffSessionStore; use App\Session\TokenRefresher; +use Monolog\Attribute\WithMonologChannel; +use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\JsonResponse; use Symfony\Component\HttpFoundation\RedirectResponse; @@ -15,6 +17,7 @@ use Symfony\Component\HttpFoundation\Response; use Symfony\Component\Routing\Attribute\Route; use Symfony\Contracts\HttpClient\HttpClientInterface; +#[WithMonologChannel('auth')] class AuthController extends AbstractController { public function __construct( @@ -24,6 +27,7 @@ class AuthController extends AbstractController private readonly IdTokenDecoder $idTokenDecoder, private readonly AppRegistry $apps, private readonly AccessTokenRoles $tokenRoles, + private readonly LoggerInterface $logger, private readonly string $kcBaseUrl, private readonly string $kcRealm, private readonly string $kcClientId, @@ -43,6 +47,11 @@ class AuthController extends AbstractController { $appKey = (string) $request->query->get('app', ''); if (!$this->apps->isValidApp($appKey)) { + $this->logger->warning('auth.login.unknown_app', [ + 'app' => $appKey, + 'ip' => $request->getClientIp(), + ]); + throw $this->createNotFoundException('Unknown or missing app key'); } @@ -67,6 +76,11 @@ class AuthController extends AbstractController 'code_challenge_method' => 'S256', ]); + $this->logger->info('auth.login.start', [ + 'app' => $appKey, + 'ip' => $request->getClientIp(), + ]); + return new RedirectResponse( "{$this->kcBaseUrl}/realms/{$this->kcRealm}/protocol/openid-connect/auth?{$params}" ); @@ -80,32 +94,54 @@ class AuthController extends AbstractController $expectedState = (string) $session->get('oauth_state', ''); $givenState = (string) $request->query->get('state', ''); if ($expectedState === '' || !hash_equals($expectedState, $givenState)) { + $this->logger->warning('auth.callback.state_mismatch', [ + 'ip' => $request->getClientIp(), + 'had_expected_state' => $expectedState !== '', + ]); + return new Response('Invalid or missing state', 401); } $appKey = (string) $session->get('oauth_app'); $returnUrl = $this->apps->resolveReturnUrl($appKey); - $response = $this->client->request( - 'POST', - "{$this->kcBaseUrl}/realms/{$this->kcRealm}/protocol/openid-connect/token", - [ - 'body' => [ - 'grant_type' => 'authorization_code', - 'client_id' => $this->kcClientId, - 'client_secret' => $this->kcClientSecret, - 'code' => $request->query->get('code'), - 'redirect_uri' => $this->kcRedirectUri, - 'code_verifier' => $session->get('pkce_verifier'), - ], - ] - ); - $tokens = $response->toArray(); + // Everything from here to the role check either succeeds or throws + // (Keycloak unreachable, code rejected, bad signature, expired token, + // no sid claim) and ends as an anonymous 500. Log the cause, then let + // it through untouched — the response behaviour is deliberately + // unchanged. + try { + $response = $this->client->request( + 'POST', + "{$this->kcBaseUrl}/realms/{$this->kcRealm}/protocol/openid-connect/token", + [ + 'body' => [ + 'grant_type' => 'authorization_code', + 'client_id' => $this->kcClientId, + 'client_secret' => $this->kcClientSecret, + 'code' => $request->query->get('code'), + 'redirect_uri' => $this->kcRedirectUri, + 'code_verifier' => $session->get('pkce_verifier'), + ], + ] + ); + $tokens = $response->toArray(); - $idClaims = $this->idTokenDecoder->decode($tokens['id_token']); - $kcSid = $idClaims['sid'] ?? null; - if (!$kcSid) { - throw new \RuntimeException('Keycloak did not issue a "sid" claim on the ID token'); + $idClaims = $this->idTokenDecoder->decode($tokens['id_token']); + $kcSid = $idClaims['sid'] ?? null; + if (!$kcSid) { + throw new \RuntimeException('Keycloak did not issue a "sid" claim on the ID token'); + } + + $accessClaims = $this->idTokenDecoder->decode($tokens['access_token']); + } catch (\Throwable $e) { + $this->logger->error('auth.callback.failed', [ + 'app' => $appKey, + 'ip' => $request->getClientIp(), + 'exception' => $e, + ]); + + throw $e; } // Authorization gate: does this user hold the role required for @@ -119,9 +155,16 @@ class AuthController extends AbstractController // the app's finer-grained permissions. Those are display data for // the app's UI only; they are never re-checked per request here — // the backend authorizes off the forwarded access token. - $accessClaims = $this->idTokenDecoder->decode($tokens['access_token']); $roles = $this->tokenRoles->extract($accessClaims); if (!in_array($this->apps->accessRole($appKey), $roles, true)) { + $this->logger->warning('auth.login.denied', [ + 'app' => $appKey, + 'required_role' => $this->apps->accessRole($appKey), + 'roles' => $roles, + 'user_id' => $idClaims['sub'] ?? null, + 'email' => $idClaims['email'] ?? null, + ]); + $session->remove('pkce_verifier'); $session->remove('oauth_state'); $session->remove('oauth_app'); @@ -154,6 +197,16 @@ class AuthController extends AbstractController ], ]); + $this->logger->info('auth.login.success', [ + 'app' => $appKey, + 'user_id' => $idClaims['sub'], + 'email' => $idClaims['email'] ?? null, + 'preferred_username' => $idClaims['preferred_username'] ?? null, + 'roles' => $roles, + 'sid_hash' => $this->sidHash($kcSid), + 'expires_at' => time() + (int) $tokens['expires_in'], + ]); + $separator = str_contains($returnUrl, '?') ? '&' : '?'; return new RedirectResponse($returnUrl . $separator . http_build_query(['sid' => $kcSid])); @@ -229,6 +282,8 @@ class AuthController extends AbstractController { $kcSid = $this->extractBearer($request); if (!$kcSid) { + $this->logger->info('auth.logout.no_session'); + return new JsonResponse(['error' => 'missing session'], 401); } @@ -238,6 +293,15 @@ class AuthController extends AbstractController // One delete kills the session for every app that shared it. $this->store->revoke($kcSid); + $this->logger->info('auth.logout', [ + 'sid_hash' => $this->sidHash($kcSid), + 'user_id' => $data['user_id'] ?? null, + 'email' => $data['profile']['email'] ?? null, + // false when the sid was already dead (expired, or a second + // logout from another tab) — the response is the same either way. + 'was_live' => $data !== null, + ]); + $params = http_build_query(array_filter([ 'id_token_hint' => $idToken, 'post_logout_redirect_uri' => $this->postLogoutRedirect, @@ -264,19 +328,42 @@ class AuthController extends AbstractController { $kcSid = $this->extractBearer($request); if (!$kcSid) { + // Routine on first page load, before an app has a sid to send. + $this->logger->info('auth.session.unauthenticated', [ + 'app' => $appKey, + 'endpoint' => $request->getPathInfo(), + ]); + return new JsonResponse(['error' => 'unauthenticated'], 401); } if (!$this->apps->isValidApp($appKey)) { + $this->logger->warning('auth.session.unknown_app', [ + 'app' => $appKey, + 'endpoint' => $request->getPathInfo(), + ]); + return new JsonResponse(['error' => 'unknown or missing app key'], 400); } if ($this->refresher->ensureFresh($kcSid) === null) { + $this->logger->info('auth.session.expired', [ + 'app' => $appKey, + 'endpoint' => $request->getPathInfo(), + 'sid_hash' => $this->sidHash($kcSid), + ]); + return new JsonResponse(['error' => 'session expired'], 401); } $session = $this->store->get($kcSid); if ($session === null) { + $this->logger->info('auth.session.expired', [ + 'app' => $appKey, + 'endpoint' => $request->getPathInfo(), + 'sid_hash' => $this->sidHash($kcSid), + ]); + return new JsonResponse(['error' => 'session expired'], 401); } @@ -284,6 +371,16 @@ class AuthController extends AbstractController // every app the user opens, so a sid on its own says nothing about // which app its holder may enter. if (!in_array($this->apps->accessRole($appKey), $session['roles'] ?? [], true)) { + $this->logger->warning('auth.session.access_denied', [ + 'app' => $appKey, + 'endpoint' => $request->getPathInfo(), + 'required_role' => $this->apps->accessRole($appKey), + 'roles' => $session['roles'] ?? [], + 'user_id' => $session['user_id'] ?? null, + 'email' => $session['profile']['email'] ?? null, + 'sid_hash' => $this->sidHash($kcSid), + ]); + return new JsonResponse(['error' => 'access_denied'], 403); } @@ -297,6 +394,16 @@ class AuthController extends AbstractController return str_starts_with($header, 'Bearer ') ? substr($header, 7) : null; } + /** + * A sid is a live bearer credential, so it never goes into a log file. + * This short digest is enough to correlate records of one session + * without being replayable if the logs leak. + */ + private function sidHash(string $kcSid): string + { + return substr(hash('sha256', $kcSid), 0, 12); + } + private function base64UrlEncode(string $bytes): string { return rtrim(strtr(base64_encode($bytes), '+/', '-_'), '='); diff --git a/src/Controller/ProxyController.php b/src/Controller/ProxyController.php index 79b4e4a..097295a 100644 --- a/src/Controller/ProxyController.php +++ b/src/Controller/ProxyController.php @@ -3,7 +3,9 @@ namespace App\Controller; use App\Security\BackendRegistry; +use App\Session\BffSessionStore; use App\Session\TokenRefresher; +use Monolog\Attribute\WithMonologChannel; use Psr\Log\LoggerInterface; use Symfony\Bundle\FrameworkBundle\Controller\AbstractController; use Symfony\Component\HttpFoundation\Request; @@ -11,6 +13,7 @@ use Symfony\Component\HttpFoundation\Response; use Symfony\Component\Routing\Attribute\Route; use Symfony\Contracts\HttpClient\HttpClientInterface; +#[WithMonologChannel('api')] class ProxyController extends AbstractController { private const string DEFAULT_BACKEND_KEY = 'default'; @@ -25,6 +28,7 @@ class ProxyController extends AbstractController private readonly HttpClientInterface $client, private readonly TokenRefresher $refresher, private readonly BackendRegistry $backends, + private readonly BffSessionStore $store, private readonly LoggerInterface $logger, ) { } @@ -37,22 +41,51 @@ class ProxyController extends AbstractController #[Route('/api/{path}', requirements: ['path' => '.+'], methods: ['GET', 'POST', 'PUT', 'PATCH', 'DELETE'])] public function proxy(Request $request, string $path): Response { + $start = microtime(true); + $kcSid = $this->extractBearer($request); if (!$kcSid) { + $this->logger->info('api.request.unauthenticated', [ + 'method' => $request->getMethod(), + 'path' => $path, + ]); + return $this->jsonError('unauthenticated', 401); } $accessToken = $this->refresher->ensureFresh($kcSid); if (!$accessToken) { + $this->logger->info('api.request.session_expired', [ + 'method' => $request->getMethod(), + 'path' => $path, + 'sid_hash' => $this->sidHash($kcSid), + ]); + return $this->jsonError('session expired', 401); } $backendKey = $request->headers->get('X-Backend', self::DEFAULT_BACKEND_KEY); if (!$this->backends->isValidBackend($backendKey)) { + $this->logger->warning('api.request.unknown_backend', [ + 'backend' => $backendKey, + 'method' => $request->getMethod(), + 'path' => $path, + 'sid_hash' => $this->sidHash($kcSid), + ]); + return $this->jsonError('unknown backend', 400); } $backendBaseUrl = $this->backends->resolveBaseUrl($backendKey); + // ensureFresh() has just read (and possibly rewritten) this entry, so + // this is a cache hit — it costs nothing and gives the log an identity. + $session = $this->store->get($kcSid); + $caller = [ + 'user_id' => $session['user_id'] ?? null, + 'email' => $session['profile']['email'] ?? null, + 'sid_hash' => $this->sidHash($kcSid), + ]; + $forwardHeaders = []; foreach ($request->headers->all() as $name => $values) { $lower = strtolower($name); @@ -72,18 +105,42 @@ class ProxyController extends AbstractController $body = $upstream->getContent(false); $contentType = $upstream->getHeaders(false)['content-type'][0] ?? 'application/json'; } catch (\Throwable $e) { - $this->logger->error('Proxy request to backend failed', [ + $this->logger->error('api.request.upstream_unreachable', $caller + [ 'backend' => $backendKey, + 'method' => $request->getMethod(), 'path' => $path, + 'duration_ms' => $this->elapsedMs($start), 'exception' => $e, ]); return $this->jsonError('upstream unreachable', 502); } + // Never log bodies, query strings or headers: the forwarded headers + // carry the real Keycloak access token, and both bodies and query + // strings can carry anything the backend deals in. + $this->logger->log($status >= 400 ? 'warning' : 'info', 'api.request', $caller + [ + 'backend' => $backendKey, + 'method' => $request->getMethod(), + 'path' => $path, + 'status' => $status, + 'duration_ms' => $this->elapsedMs($start), + ]); + return new Response($body, $status, ['Content-Type' => $contentType]); } + private function elapsedMs(float $start): float + { + return round((microtime(true) - $start) * 1000, 1); + } + + /** Never log a raw sid — see AuthController::sidHash(). */ + private function sidHash(string $kcSid): string + { + return substr(hash('sha256', $kcSid), 0, 12); + } + private function extractBearer(Request $request): ?string { $header = $request->headers->get('Authorization', ''); diff --git a/src/Security/IdTokenDecoder.php b/src/Security/IdTokenDecoder.php index 33165d0..c508009 100644 --- a/src/Security/IdTokenDecoder.php +++ b/src/Security/IdTokenDecoder.php @@ -4,7 +4,9 @@ namespace App\Security; use Firebase\JWT\JWK; use Firebase\JWT\JWT; +use Monolog\Attribute\WithMonologChannel; use Psr\Cache\InvalidArgumentException; +use Psr\Log\LoggerInterface; use Symfony\Contracts\Cache\CacheInterface; use Symfony\Contracts\Cache\ItemInterface; use Symfony\Contracts\HttpClient\HttpClientInterface; @@ -14,11 +16,13 @@ use Symfony\Contracts\HttpClient\HttpClientInterface; * trusting any claims from it (in particular the "sid" and "sub" claims we * key sessions on). Requires firebase/php-jwt. */ +#[WithMonologChannel('auth')] class IdTokenDecoder { public function __construct( private readonly HttpClientInterface $client, private readonly CacheInterface $cache, + private readonly LoggerInterface $logger, private readonly string $kcBaseUrl, private readonly string $kcRealm, ) { @@ -29,18 +33,29 @@ class IdTokenDecoder */ public function decode(string $idToken): array { - $jwks = $this->cache->get('keycloak_jwks_' . $this->kcRealm, function (ItemInterface $item) { - $item->expiresAfter(3600); - $response = $this->client->request( - 'GET', - "{$this->kcBaseUrl}/realms/{$this->kcRealm}/protocol/openid-connect/certs" - ); + // A bad signature, an expired token or an unreachable JWKS endpoint all + // surface to the caller as a 500. Record why, then rethrow unchanged. + try { + $jwks = $this->cache->get('keycloak_jwks_' . $this->kcRealm, function (ItemInterface $item) { + $item->expiresAfter(3600); + $response = $this->client->request( + 'GET', + "{$this->kcBaseUrl}/realms/{$this->kcRealm}/protocol/openid-connect/certs" + ); - return $response->toArray(); - }); + return $response->toArray(); + }); - $keys = JWK::parseKeySet($jwks); - $claims = JWT::decode($idToken, $keys); + $keys = JWK::parseKeySet($jwks); + $claims = JWT::decode($idToken, $keys); + } catch (\Throwable $e) { + $this->logger->error('auth.token.decode_failed', [ + 'realm' => $this->kcRealm, + 'exception' => $e, + ]); + + throw $e; + } /** @var array $decoded */ $decoded = json_decode((string) json_encode($claims), true); diff --git a/src/Session/TokenRefresher.php b/src/Session/TokenRefresher.php index 54dfa8d..480c612 100644 --- a/src/Session/TokenRefresher.php +++ b/src/Session/TokenRefresher.php @@ -4,9 +4,11 @@ namespace App\Session; use App\Security\AccessTokenRoles; use App\Security\IdTokenDecoder; +use Monolog\Attribute\WithMonologChannel; use Psr\Log\LoggerInterface; use Symfony\Contracts\HttpClient\HttpClientInterface; +#[WithMonologChannel('auth')] class TokenRefresher { private const int EXPIRY_LEEWAY_SECONDS = 30; @@ -34,6 +36,12 @@ class TokenRefresher { $session = $this->store->get($kcSid); if ($session === null) { + // Expired out of the cache, revoked by a logout, or simply never + // existed (a forged sid) — indistinguishable from here. + $this->logger->info('auth.session.missing', [ + 'sid_hash' => $this->sidHash($kcSid), + ]); + return null; } @@ -57,7 +65,9 @@ class TokenRefresher $tokens = $response->toArray(); } catch (\Throwable $e) { // Refresh token expired/revoked (e.g. Keycloak-side admin logout) — kill the session. - $this->logger->warning('Keycloak token refresh failed, revoking session', [ + $this->logger->warning('auth.session.refresh_failed', [ + 'sid_hash' => $this->sidHash($kcSid), + 'user_id' => $session['user_id'] ?? null, 'exception' => $e, ]); $this->store->revoke($kcSid); @@ -78,13 +88,28 @@ class TokenRefresher ); } catch (\Throwable $e) { // Keep the previous list — a decode hiccup must not drop the session. - $this->logger->warning('Could not re-read roles from refreshed access token', [ + $this->logger->warning('auth.session.role_reread_failed', [ + 'sid_hash' => $this->sidHash($kcSid), + 'user_id' => $session['user_id'] ?? null, 'exception' => $e, ]); } $this->store->put($kcSid, $session); + $this->logger->info('auth.session.refreshed', [ + 'sid_hash' => $this->sidHash($kcSid), + 'user_id' => $session['user_id'] ?? null, + 'roles' => $session['roles'] ?? [], + 'expires_at' => $session['expires_at'], + ]); + return $session['access_token']; } + + /** Never log a raw sid — see AuthController::sidHash(). */ + private function sidHash(string $kcSid): string + { + return substr(hash('sha256', $kcSid), 0, 12); + } }