feat: report lock backend/release errors to logger (Sentry/Raygun/etc.)

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.
This commit is contained in:
Prem Palanisamy
2026-04-27 17:25:31 +01:00
parent 77982f4b90
commit 92b5f0dcd6
3 changed files with 89 additions and 15 deletions
+8 -4
View File
@@ -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);
}
}
}
+74 -10
View File
@@ -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);
}
}
};
@@ -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);