Remove utopia-php/logger and report errors through spans - #12
anurag6569201 wants to merge 1 commit into
Conversation
Source PR: appwrite#13457 Source head: fd3a1d1
⛔ Shipwright · BlockedRecommendation: do not merge PR #12 · Tier
Findings (8)
Fireworks usage: 50,722 input · 1,087 output · 51,809 total tokens · $0.0119 · 20s · 0 fix iteration(s) Open the Shipwright check for full evidence and the audit bundle. Use |
![shipwright-agent[bot]](https://avatars.githubusercontent.com/u/140162738?s=60&v=4){kind=small}
| Console::error('Error pushing log: ' . $th->getMessage()); | ||
| } | ||
| } | ||
| // Tasks run outside a request span; open one so the failure reaches the exporters. |
There was a problem hiding this comment.
Shipwright · CRITICAL
The CLI logError closure now calls $span->finish(error: $error) on the current span.
Impact: The CLI logError closure now calls $span->finish(error: $error) on the current span. If a task already has an active span (Span::current() is non-null), this finishes the caller's span prematurely. Any subsequent Span::add() or span operations in the task will target a finished span, and the exporter may emit a partial/incorrect trace. The comment says 'Tasks run outside a request span' but the code explicitly ha…
Suggested fix: Review the cited evidence, fix the risk if confirmed, and rerun Shipwright.
| $log->setAction($action); | ||
| $log->addTag('service', $action); | ||
| Span::add('http.hostname', $request->getHostname()); | ||
| Span::add('http.locale', (string)$request->getParam('locale', $request->getHeaderLine('x-appwrite-locale', ''))); |
There was a problem hiding this comment.
Shipwright · CRITICAL
The error handler now calls Span::add('user.id', ...) after retrieving $user from context.
Impact: The error handler now calls Span::add('user.id', ...) after retrieving $user from context. If $user is null (context key exists but value is null), $user->isEmpty() will throw a fatal Error, which is not caught by the surrounding try/catch because the catch only wraps the context get, not the isEmpty() call. The previous code guarded with isset($user) && !$user->isEmpty(). The new code removed the isset guard.
Suggested fix: Review the cited evidence, fix the risk if confirmed, and rerun Shipwright.
| Span::add('http.hostname', $request->getHostname()); | ||
| Span::add('http.locale', (string)$request->getParam('locale', $request->getHeaderLine('x-appwrite-locale', ''))); | ||
| if (Span::current()?->get('project.id') === null) { | ||
| Span::add('project.id', $project->getId()); |
There was a problem hiding this comment.
Shipwright · CRITICAL
The error handler now unconditionally attaches the request IP hash as user.id for guests: Span::add('user.id', $user->isEmpty() ?
Impact: The error handler now unconditionally attaches the request IP hash as user.id for guests: Span::add('user.id', $user->isEmpty() ? 'guest-' . hash('sha256', $request->getIP()) : $user->getId()). This is a stable pseudonymous identifier derived from the client IP and is exported to Sentry on every error. If Sentry is configured, this creates a persistent cross-request tracking identifier for unauthenticated u…
Suggested fix: Review the cited evidence, fix the risk if confirmed, and rerun Shipwright.
| $isProduction = System::getEnv('_APP_ENV', 'development') === 'production'; | ||
| $log->setEnvironment($isProduction ? Log::ENVIRONMENT_PRODUCTION : Log::ENVIRONMENT_STAGING); | ||
| try { | ||
| /** @var Utopia\Database\Document $user */ |
There was a problem hiding this comment.
Shipwright · HIGH
The new code adds Span::add('database.host', $dsn->getHost()) but the DSN construction has a fallback that can throw a different exception type.
Impact: The new code adds Span::add('database.host', $dsn->getHost()) but the DSN construction has a fallback that can throw a different exception type. The try/catch only catches InvalidArgumentException; if $project->getAttribute('database', 'console') returns a malformed value that causes a different exception (e.g., TypeError), the error handler itself will throw, masking the original error.
Suggested fix: Review the cited evidence, fix the risk if confirmed, and rerun Shipwright.
| Console::error('Error pushing log: ' . $th->getMessage()); | ||
| } | ||
| } | ||
| // Tasks run outside a request span; open one so the failure reaches the exporters. |
There was a problem hiding this comment.
Shipwright · HIGH
The CLI logError closure no longer catches exceptions from the logging/export path.
Impact: The CLI logError closure no longer catches exceptions from the logging/export path. The old code wrapped $logger->addLog($log) in try/catch and logged a warning. The new code calls $span->finish(error: $error) without any try/catch. If the span exporter throws (e.g., Sentry network failure, malformed span data), the error handler itself will throw, potentially crashing the CLI task instead of just reporting th…
Suggested fix: Review the cited evidence, fix the risk if confirmed, and rerun Shipwright.
1 participant
Why
Every error handler built a
Utopia\Logger\Logby hand and pushed it to a provider throughutopia-php/fetch. That path leaks the curl handle, its socket and an eventfd until PHP's cycle collector runs (utopia-php/logger#52, reproduced on a live worker: 135 fds and 67CLOSE_WAITsockets after an hour), andutopia-php/fetchis archived so it cannot be fixed at the source. Meanwhile every request, job, task and realtime event already runs inside aUtopia\Spanthat carries the same throwable, so the logger was a second, hand-maintained copy of what the span knows.What changed
utopia-php/loggeris removed fromcomposer.jsonandcomposer.lock.app/init/span.phpadds theutopia-php/spanSentry exporter when_APP_LOGGING_CONFIGis asentry://PROJECT_ID:KEY@HOST/DSN, with environment, release and server name filled from the existing env vars. The exporter only ships spans that carry an error, and handlers now seterror.publish=falseon expected client errors so the old publish rules (AppwriteException::isPublishable(), code 0 or >= 500) still decide what reaches Sentry.$log->addTag()/addExtra()is nowSpan::add(), with dotted keys (project.id,function.id,deployment.id,database.id,dns.domain,email.skipped,webhook.signed,lock.target, ...). TheLogparameter is gone from workers, proxy rule actions,Proxy\Action::verifyRule(), the embeddings endpoint andAppwrite\Locking\Lock.Log. CLI tasks and realtime server callbacks, which run outside a request span, open one so the failure still reaches the exporters.logErrorcontainer resource (used byMigrationsandPlatform\Action) keeps its signature and writes to the span.loggerandrealtimeLoggerregistry entries, thelogandloggercontainer resources,_APP_LOGGING_PROVIDER,_APP_LOGGING_CONFIG_REALTIME,_APP_EXPERIMENT_LOGGING_PROVIDERand_APP_EXPERIMENT_LOGGING_CONFIG._APP_LOGGING_CONFIGand_APP_LOGGING_FORMATstay.Behaviour changes to be aware of
_APP_LOGGING_CONFIGlike everything else._APP_EXPERIMENT_LOGGING_CONFIG) is dropped.lock.error,embedding.error) rather than standalone events, because they do not fail the request.Doctorreports the logging adapter as enabled only for asentry://DSN.Verification
pint --test, PHPStan (level fromphpstan.neon) andphp -lclean on all 36 changed files.tests/unit/Locking/LockTest.php(18),tests/unit/Platform/Workers/DatabasesTest.php,MailsTest.php(3),NotificationsTest.php(25) pass.LockTestandNotificationsTestnow assert on span attributes throughSpan\Storage\Memoryinstead of onLogtags.Downstream
appwrite-labs/cloud extends these actions and still injects
login 18 files (Workers/Mails.php,Certificates.php,Deletes.php,Builds.php,Databases.php,Patches.php,DedicatedDatabases.php, the proxy rule actions, and its ownapp/*.phphandlers). Those must be migrated toSpan::add()in the same release that bumpsappwrite/server-ce, or the workers fail at boot on the missinglogresource.🤖 Generated with Claude Code
https://claude.ai/code/session_01D9ybk4YF5Q5L2xQzqhqdCT
Takeover validation (2026-09-04)
Refreshed with current main and reran CI. In an isolated PHP 8.5.9/Swoole container with garbage collection disabled, 2,000 error exports through the old logger grew file descriptors from 8 to 2,008 and RSS by about 156 MiB. The replacement span exporter delivered all 2,000 valid events while descriptors stayed at 8. Local p95 export latency was 3.96 ms versus 3.81 ms for the old path; this is a transport microbenchmark, not application throughput.
A second drill ran 20 concurrent coroutines through success, HTTP 500, connection refusal, and recovery (2,000 exports per phase). Descriptors stayed at 8 in every phase. The local sink received 6,000 valid, distinct error events, and the exporter reported all 4,000 expected transport failures. Delivery recovered after the failures.
Staging deployment and soak validation remain pending. Both regions have pre-rollout process/socket/memory, health-latency, API, worker, and queue metric baselines. No claim of a completed staging validation is made from these local drills.
Source merge-base:
962c43a74e37a895001695032c07ed16e0b465ceSource head:
fd3a1d17daa5053a16e0886f16719cedbdee1194