EP/appsmith-bff
4
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: dedicated logging for auth and api calls

Browse Source
This commit is contained in:
Björn Fromme
2026-08-14 08:16:54 +02:00
parent cc46d8c812
commit e28b789af2
6 changed files with 306 additions and 36 deletions
Download Patch File Download Diff File Expand all files Collapse all files
README.md
+20
View File
@@ -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.<env>.log` | `auth` | 30 days | The login/logout/authorization trail |
| `api.<env>.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
config/packages/monolog.yaml
+49 -3
View File
@@ -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
src/Controller/AuthController.php
+127 -20
View File
@@ -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), '+/', '-_'), '=');
src/Controller/ProxyController.php
+58 -1
View File
@@ -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', '');
src/Security/IdTokenDecoder.php
+25 -10
View File
@@ -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<string,mixed> $decoded */
$decoded = json_decode((string) json_encode($claims), true);
src/Session/TokenRefresher.php
+27 -2
View File
@@ -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);
}
}