From 92b5f0dcd60057ec591412ebef4c00539dfcf56b Mon Sep 17 00:00:00 2001 From: Prem Palanisamy Date: Mon, 27 Apr 2026 14:11:17 +0100 Subject: [PATCH] feat: report lock backend/release errors to logger (Sentry/Raygun/etc.) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Lock backend errors (Redis/Dragonfly unreachable) and release errors (TTL expired or backend dropped while held) were previously visible only in the lock.attempts counter and Console::warning lines. They now also push a structured Log entry through the configured logger adapter, so operators using Sentry/Raygun/AppSignal/LogOwl get first-class events for these specific failure modes. Pattern matches Embeddings/Text/Create.php exactly: - Action injects 'log' (per-request Log object) and 'logger' (?Logger, nullable when _APP_LOGGING_CONFIG unset). - Helper mutates the per-request $log instead of constructing a fresh one — preserves the per-request context Embeddings expects. - Same field set: namespace='http', server, version, type, setMessage, setAction, setEnvironment, addTag('code', ...), addExtra('file' / 'line' / 'trace'). - Defensive try/catch around addLog() so logging failures don't break fail-open. Lock-specific tags added for slicing in Sentry: - lock.target — collection name (projects, keys, users, ...). Bounded set, safe for high-cardinality stores. - lock.key_pattern — full key with the trailing document ID stripped (lock:platform:projects:* not lock:platform:projects:abc). Prevents unbounded log cardinality from per-document IDs. Rate limiting via per-pod static buckets, 60s window per (action, target) combo. During a 5-minute Dragonfly outage, a fleet of N pods produces at most N events/min, well within Sentry's dedup tolerance. Static state is per-Swoole-worker; coroutines may race on the bucket boundary but the worst case is one duplicate report. Type level set to Log::TYPE_WARNING (not ERROR): fail-open means the request still succeeds, so this is degraded operation, not a failed request. Deliberately NOT reported to Sentry: - 409 GENERAL_RESOURCE_LOCKED (normal user-facing concurrency) - skip-on-contention events (idempotent fan-out by design) - acquire retry conflicts (internal loop) - destructor cleanups (have an expected baseline rate; the lock.attempts counter aggregates them better than Sentry would) Factory signature change: distributedLock and distributedLockOrFail now accept ?Log and ?Logger as optional named args at call time (rather than capturing Logger at factory-build time). The factory closure runs once at boot but the per-request Log resource is fresh per request — capturing at boot would have given stale state. Existing call sites threaded log: $log, logger: $logger. Sites that don't (workers, CLI tasks) get null and just log to Console as before. --- app/controllers/shared/api.php | 12 ++- app/init/resources.php | 84 ++++++++++++++++--- .../Project/Http/Project/Services/Update.php | 8 +- 3 files changed, 89 insertions(+), 15 deletions(-) diff --git a/app/controllers/shared/api.php b/app/controllers/shared/api.php index b07eec1a99..142a20c4f3 100644 --- a/app/controllers/shared/api.php +++ b/app/controllers/shared/api.php @@ -39,6 +39,8 @@ use Utopia\Database\Validator\Authorization; use Utopia\Database\Validator\Authorization\Input; use Utopia\Database\Validator\Roles; use Utopia\Http\Http; +use Utopia\Logger\Log; +use Utopia\Logger\Logger; use Utopia\Span\Span; use Utopia\System\System; use Utopia\Telemetry\Adapter as Telemetry; @@ -101,7 +103,9 @@ Http::init() ->inject('apiKey') ->inject('authorization') ->inject('distributedLock') - ->action(function (Http $utopia, Request $request, Database $dbForPlatform, Database $dbForProject, AuditContext $auditContext, Document $project, User $user, ?Document $session, array $servers, string $mode, Document $team, ?Key $apiKey, Authorization $authorization, callable $distributedLock) { + ->inject('log') + ->inject('logger') + ->action(function (Http $utopia, Request $request, Database $dbForPlatform, Database $dbForProject, AuditContext $auditContext, Document $project, User $user, ?Document $session, array $servers, string $mode, Document $team, ?Key $apiKey, Authorization $authorization, callable $distributedLock, Log $log, ?Logger $logger) { $route = $utopia->getRoute(); if ($route === null) { throw new AppwriteException(AppwriteException::GENERAL_ROUTE_NOT_FOUND); @@ -263,7 +267,7 @@ Http::init() } elseif (! empty($apiKey->getTeamId())) { $dbForPlatform->getAuthorization()->skip(fn () => $dbForPlatform->purgeCachedDocument('teams', $team->getId())); } - }); + }, log: $log, logger: $logger); } $userClone = clone $user; @@ -398,7 +402,7 @@ Http::init() $authorization->skip(fn () => $dbForPlatform->updateDocument('projects', $project->getId(), new Document([ 'accessedAt' => DateTime::now() ]))); - }); + }, log: $log, logger: $logger); } } @@ -419,7 +423,7 @@ Http::init() $authorization->skip(fn () => $dbForPlatform->updateDocument('users', $user->getId(), new Document([ 'accessedAt' => $user->getAttribute('accessedAt') ]))); - }); + }, log: $log, logger: $logger); } } } diff --git a/app/init/resources.php b/app/init/resources.php index d3443ee337..d520c621b5 100644 --- a/app/init/resources.php +++ b/app/init/resources.php @@ -26,6 +26,8 @@ use Utopia\DSN\DSN; use Utopia\Lock\Adapter\Redis as LockRedisAdapter; use Utopia\Lock\Exception\LockAcquireException; use Utopia\Lock\Lock; +use Utopia\Logger\Log; +use Utopia\Logger\Logger; use Utopia\Pools\Group; use Utopia\Queue\Broker\Pool as BrokerPool; use Utopia\Queue\Publisher; @@ -225,6 +227,68 @@ $lockTargetOf = function (string $key): string { return $parts[2] ?? 'unknown'; }; +/** + * Push lock-side errors to the configured logger (Sentry/Raygun/AppSignal/etc.) + * by mutating the caller's per-request `Log` object — same pattern as + * Embeddings/Text/Create.php and the http.php request-end error handler. + * + * Rate limited per pod via a static bucket so a sustained backend outage + * doesn't flood the logger. At most one push per 60s per (action, target) + * combo. Across a fleet of N pods this caps at N events/min, well within + * Sentry's own dedup tolerance. + * + * Only "real" errors are reported here: + * - backend_error: Redis/Dragonfly unreachable + * - release_error: lock release failed (TTL expired or backend dropped) + * + * Skipped on purpose: contention 409s (normal user-facing concurrency), + * skip-on-contention events (idempotent fan-out by design), acquire retry + * conflicts (internal loop), destructor cleanups (have an expected + * baseline rate; aggregate via the `lock.attempts` counter instead). + */ +$lockErrorReporter = function (?Log $log, ?Logger $logger, string $action, string $key, string $target, Throwable $e): void { + static $lastReportAt = []; + + Console::warning("Lock {$action} for {$key}: {$e->getMessage()}"); + + if ($logger === null || $log === null) { + return; + } + + $bucket = $action . ':' . $target; + $now = time(); + if (($lastReportAt[$bucket] ?? 0) + 60 > $now) { + return; + } + $lastReportAt[$bucket] = $now; + + $log->setNamespace('http'); + $log->setServer(System::getEnv('_APP_LOGGING_SERVICE_IDENTIFIER', \gethostname())); + $log->setVersion(APP_VERSION_STABLE); + $log->setType(Log::TYPE_WARNING); + $log->setMessage('Distributed lock ' . $action . ': ' . $e->getMessage()); + $log->setAction("lock.{$action}"); + $log->setEnvironment(System::getEnv('_APP_ENV', 'development') === 'production' + ? Log::ENVIRONMENT_PRODUCTION + : Log::ENVIRONMENT_STAGING); + + $log->addTag('lock.target', $target); + // Strip the trailing document ID from the key so log aggregators don't + // see unbounded cardinality; the {target} attribute already covers slicing. + $log->addTag('lock.key_pattern', preg_replace('/:[^:]+$/', ':*', $key)); + $log->addTag('code', $e->getCode()); + + $log->addExtra('file', $e->getFile()); + $log->addExtra('line', $e->getLine()); + $log->addExtra('trace', $e->getTraceAsString()); + + try { + $logger->addLog($log); + } catch (Throwable) { + // best-effort; don't let logging failures break fail-open + } +}; + /** * Distributed-lock factory: skip-on-contention variant. * @@ -242,17 +306,17 @@ $lockTargetOf = function (string $key): string { * Metric: `lock.attempts{outcome,target}` where outcome ∈ {acquired, skipped, * backend_error, release_error}. */ -$container->set('distributedLock', function (\Redis $redis, Telemetry $telemetry) use ($lockTargetOf) { +$container->set('distributedLock', function (\Redis $redis, Telemetry $telemetry) use ($lockTargetOf, $lockErrorReporter) { $enabled = System::getEnv('_APP_LOCKING_ENABLED', 'enabled') !== 'disabled'; $attempts = $telemetry->createCounter('lock.attempts', null, 'Distributed lock acquire outcomes'); if (! $enabled) { - return function (string $key, \Closure $fn, float $ttl = 5.0): void { + return function (string $key, \Closure $fn, float $ttl = 5.0, ?Log $log = null, ?Logger $logger = null): void { $fn(); }; } - return function (string $key, \Closure $fn, float $ttl = 5.0) use ($redis, $attempts, $lockTargetOf): void { + return function (string $key, \Closure $fn, float $ttl = 5.0, ?Log $log = null, ?Logger $logger = null) use ($redis, $attempts, $lockTargetOf, $lockErrorReporter): void { $target = $lockTargetOf($key); $lock = new Lock(new LockRedisAdapter($redis), $key, $ttl); @@ -260,7 +324,7 @@ $container->set('distributedLock', function (\Redis $redis, Telemetry $telemetry $acquired = $lock->acquire(); } catch (LockAcquireException $e) { $attempts->add(1, ['outcome' => 'backend_error', 'target' => $target]); - Console::warning("Lock backend unavailable for {$key}, proceeding unlocked: {$e->getMessage()}"); + $lockErrorReporter($log, $logger, 'backend_error', $key, $target, $e); $fn(); return; } @@ -278,7 +342,7 @@ $container->set('distributedLock', function (\Redis $redis, Telemetry $telemetry $lock->release(); } catch (\Throwable $e) { $attempts->add(1, ['outcome' => 'release_error', 'target' => $target]); - Console::warning("Lock release failed for {$key}: {$e->getMessage()}"); + $lockErrorReporter($log, $logger, 'release_error', $key, $target, $e); } } }; @@ -301,17 +365,17 @@ $container->set('distributedLock', function (\Redis $redis, Telemetry $telemetry * Metric: `lock.attempts{outcome,target}` where outcome ∈ {acquired, contended, * backend_error, release_error}. */ -$container->set('distributedLockOrFail', function (\Redis $redis, Telemetry $telemetry) use ($lockTargetOf) { +$container->set('distributedLockOrFail', function (\Redis $redis, Telemetry $telemetry) use ($lockTargetOf, $lockErrorReporter) { $enabled = System::getEnv('_APP_LOCKING_ENABLED', 'enabled') !== 'disabled'; $attempts = $telemetry->createCounter('lock.attempts', null, 'Distributed lock acquire outcomes'); if (! $enabled) { - return function (string $key, \Closure $fn, float $ttl = 10.0, float $waitTimeout = 3.0): mixed { + return function (string $key, \Closure $fn, float $ttl = 10.0, float $waitTimeout = 3.0, ?Log $log = null, ?Logger $logger = null): mixed { return $fn(); }; } - return function (string $key, \Closure $fn, float $ttl = 10.0, float $waitTimeout = 3.0) use ($redis, $attempts, $lockTargetOf): mixed { + return function (string $key, \Closure $fn, float $ttl = 10.0, float $waitTimeout = 3.0, ?Log $log = null, ?Logger $logger = null) use ($redis, $attempts, $lockTargetOf, $lockErrorReporter): mixed { $target = $lockTargetOf($key); $lock = new Lock(new LockRedisAdapter($redis), $key, $ttl); @@ -319,7 +383,7 @@ $container->set('distributedLockOrFail', function (\Redis $redis, Telemetry $tel $acquired = $lock->acquire(blocking: true, waitTimeout: $waitTimeout, retryDelay: 0.1); } catch (LockAcquireException $e) { $attempts->add(1, ['outcome' => 'backend_error', 'target' => $target]); - Console::warning("Lock backend unavailable for {$key}, proceeding unlocked: {$e->getMessage()}"); + $lockErrorReporter($log, $logger, 'backend_error', $key, $target, $e); return $fn(); } @@ -341,7 +405,7 @@ $container->set('distributedLockOrFail', function (\Redis $redis, Telemetry $tel $lock->release(); } catch (\Throwable $e) { $attempts->add(1, ['outcome' => 'release_error', 'target' => $target]); - Console::warning("Lock release failed for {$key}: {$e->getMessage()}"); + $lockErrorReporter($log, $logger, 'release_error', $key, $target, $e); } } }; diff --git a/src/Appwrite/Platform/Modules/Project/Http/Project/Services/Update.php b/src/Appwrite/Platform/Modules/Project/Http/Project/Services/Update.php index 1126da8897..933d524e23 100644 --- a/src/Appwrite/Platform/Modules/Project/Http/Project/Services/Update.php +++ b/src/Appwrite/Platform/Modules/Project/Http/Project/Services/Update.php @@ -12,6 +12,8 @@ use Utopia\Config\Config; use Utopia\Database\Database; use Utopia\Database\Document; use Utopia\Database\Validator\Authorization; +use Utopia\Logger\Log; +use Utopia\Logger\Logger; use Utopia\Platform\Scope\HTTP; use Utopia\Validator\Boolean; use Utopia\Validator\WhiteList; @@ -61,6 +63,8 @@ class Update extends Action ->inject('authorization') ->inject('queueForEvents') ->inject('distributedLockOrFail') + ->inject('log') + ->inject('logger') ->callback($this->action(...)); } @@ -73,6 +77,8 @@ class Update extends Action Authorization $authorization, Event $queueForEvents, callable $distributedLockOrFail, + Log $log, + ?Logger $logger, ): void { // The services map is a JSON object on the project document. Two // concurrent service toggles read the same baseline, each set their @@ -90,7 +96,7 @@ class Update extends Action return $authorization->skip(fn () => $dbForPlatform->updateDocument('projects', $project->getId(), new Document([ 'services' => $services, ]))); - }); + }, log: $log, logger: $logger); $queueForEvents->setParam('serviceId', $serviceId);