Merge pull request #12298 from appwrite/chore/normalize-span-keys

chore: normalize Span keys and centralize span lifecycle
This commit is contained in:
Luke B. Silver
2026-05-13 12:01:46 +01:00
committed by GitHub
12 changed files with 132 additions and 157 deletions
+8
View File
@@ -115,6 +115,14 @@ Common injections: `$response`, `$request`, `$dbForProject`, `$dbForPlatform`, `
- Never hardcode credentials -- use environment variables.
- Code changes may require container restart. No central log location -- check relevant containers.
## Tracing with Utopia Span
In handlers, only call `Span::add($key, $value)`. **Never** call `Span::init`, `Span::error`, or `Span::finish` -- lifecycle is owned by the entry-point harness (`app/http.php`, `app/worker.php`, `app/realtime.php`, `Bus::dispatch`). For selective export, filter in the sampler in `app/init/span.php`.
Keys are `snake_case` with dots only for child relationships: `project.id` (id of project), `storage.bucket.id`. No dot otherwise: `inbound_bytes`, not `inbound.bytes`. No camelCase, no bare top-level keys (`function.id`, not `functionId`).
Cross-cutting identifiers (`project.id`, `function.id`, `user.id`) live at the top level, not under a subsystem (no `realtime.project.id`). The trace sampler and downstream filters look them up by the canonical key.
## Patch release process
For bumping patch versions (e.g., `1.9.0` -> `1.9.1`), follow the checklist in `.claude/skills/patch-release-checklist/SKILL.md`. It covers the 4 files that must be updated, console image bumps, CHANGES.md updates, and common pitfalls to avoid.
+20 -1
View File
@@ -3,11 +3,30 @@
use Utopia\Span\Exporter;
use Utopia\Span\Span;
use Utopia\Span\Storage;
use Utopia\System\System;
Span::setStorage(new Storage\Coroutine());
Span::addExporter(new Exporter\Pretty(), function (Span $span): bool {
// Resolve trace filters once at boot to avoid repeated env lookups per span.
$traceProjectId = System::getEnv('_APP_TRACE_PROJECT_ID', '');
$traceFunctionId = System::getEnv('_APP_TRACE_FUNCTION_ID', '');
$traceEnabled = $traceProjectId !== '' || $traceFunctionId !== '';
Span::addExporter(new Exporter\Pretty(), function (Span $span) use ($traceEnabled, $traceProjectId, $traceFunctionId): bool {
if (\str_starts_with($span->getAction(), 'listener.')) {
return $span->getError() !== null;
}
// Selective tracing: when _APP_TRACE_PROJECT_ID / _APP_TRACE_FUNCTION_ID are set,
// only export spans tagged with matching project.id / function.id.
if ($traceEnabled) {
if ($traceProjectId !== '' && $span->get('project.id') !== $traceProjectId) {
return false;
}
if ($traceFunctionId !== '' && $span->get('function.id') !== $traceFunctionId) {
return false;
}
}
return true;
});
+25 -25
View File
@@ -728,8 +728,8 @@ $server->onOpen(function (int $connection, SwooleRequest $request) use ($server,
$success = false;
Span::init('realtime.open');
Span::add('realtime.connectionId', $connection);
Span::add('realtime.inboundBytes', $rawSize);
Span::add('realtime.connection.id', $connection);
Span::add('realtime.inbound_bytes', $rawSize);
if (!empty($request->getOrigin())) {
Span::add('realtime.origin', $request->getOrigin());
}
@@ -936,16 +936,16 @@ $server->onOpen(function (int $connection, SwooleRequest $request) use ($server,
Span::error($th);
} finally {
Span::add('realtime.success', $success);
Span::add('realtime.responseCode', $responseCode);
Span::add('realtime.subscriptionMode', $subscriptionMode);
Span::add('realtime.channelCount', $channelCount);
Span::add('realtime.subscriptionCount', $subscriptionCount);
Span::add('realtime.outboundBytes', $outboundBytes);
Span::add('realtime.response_code', $responseCode);
Span::add('realtime.subscription_mode', $subscriptionMode);
Span::add('realtime.channel_count', $channelCount);
Span::add('realtime.subscription_count', $subscriptionCount);
Span::add('realtime.outbound_bytes', $outboundBytes);
if (!empty($project?->getId())) {
Span::add('realtime.projectId', $project->getId());
Span::add('project.id', $project->getId());
}
if (!empty($logUser?->getId())) {
Span::add('realtime.userId', $logUser->getId());
Span::add('user.id', $logUser->getId());
}
Span::current()?->finish();
}
@@ -965,9 +965,9 @@ $server->onMessage(function (int $connection, string $message) use ($server, $re
$success = false;
Span::init('realtime.message');
Span::add('realtime.connectionId', $connection);
Span::add('realtime.inboundBytes', $rawSize);
Span::add('realtime.containerId', $containerId);
Span::add('realtime.connection.id', $connection);
Span::add('realtime.inbound_bytes', $rawSize);
Span::add('realtime.container.id', $containerId);
try {
$response = new Response(new SwooleResponse());
@@ -1352,15 +1352,15 @@ $server->onMessage(function (int $connection, string $message) use ($server, $re
Span::error($th);
} finally {
Span::add('realtime.success', $success);
Span::add('realtime.responseCode', $responseCode);
Span::add('realtime.subscriptionDelta', $subscriptionDelta);
Span::add('realtime.subscriptionsRequested', $subscriptionsRequested);
Span::add('realtime.subscriptionsRemoved', $subscriptionsRemoved);
Span::add('realtime.subscribe.subscriptionsCount', $subscriptionsRequested);
Span::add('realtime.outboundBytes', $outboundBytes);
Span::add('realtime.projectId', $project?->getId() ?? $projectId);
Span::add('realtime.userId', $realtime->connections[$connection]['userId'] ?? null);
Span::add('realtime.messageType', $messageType);
Span::add('realtime.response_code', $responseCode);
Span::add('realtime.subscription_delta', $subscriptionDelta);
Span::add('realtime.subscriptions_requested', $subscriptionsRequested);
Span::add('realtime.subscriptions_removed', $subscriptionsRemoved);
Span::add('realtime.subscribe.subscriptions_count', $subscriptionsRequested);
Span::add('realtime.outbound_bytes', $outboundBytes);
Span::add('project.id', $project?->getId() ?? $projectId);
Span::add('user.id', $realtime->connections[$connection]['userId'] ?? null);
Span::add('realtime.message_type', $messageType);
Span::current()?->finish();
}
});
@@ -1372,7 +1372,7 @@ $server->onClose(function (int $connection) use ($realtime, $stats, $register) {
$success = false;
Span::init('realtime.close');
Span::add('realtime.connectionId', $connection);
Span::add('realtime.connection.id', $connection);
if (array_key_exists($connection, $realtime->connections)) {
$projectId = $realtime->connections[$connection]['projectId'] ?? null;
@@ -1411,12 +1411,12 @@ $server->onClose(function (int $connection) use ($realtime, $stats, $register) {
Span::add('realtime.success', $success);
if (!empty($projectId)) {
Span::add('realtime.projectId', $projectId);
Span::add('project.id', $projectId);
}
if (!empty($userId)) {
Span::add('realtime.userId', $userId);
Span::add('user.id', $userId);
}
Span::add('realtime.subscriptionsBeforeClose', $subscriptionsBeforeClose);
Span::add('realtime.subscriptions_before_close', $subscriptionsBeforeClose);
Span::current()?->finish();
}
+9 -1
View File
@@ -16,6 +16,7 @@ use Utopia\Pools\Group;
use Utopia\Queue\Adapter\Swoole;
use Utopia\Queue\Broker\Pool as BrokerPool;
use Utopia\Queue\Server;
use Utopia\Span\Span;
use Utopia\System\System;
Runtime::enableCoroutine();
@@ -91,8 +92,13 @@ $adapter = new Swoole(
$worker = new Server($adapter, $container);
try {
$worker->init()->action(function () use ($worker, $registerWorkerMessageResources) {
$worker->init()->action(function () use ($worker, $registerWorkerMessageResources, $queueName) {
$registerWorkerMessageResources($worker->getContainer());
Span::init("worker.{$queueName}");
});
$worker->shutdown()->action(function () {
Span::current()?->finish();
});
$container->set('bus', function ($register) use ($worker) {
@@ -120,6 +126,8 @@ $worker
->action(function (Throwable $error, ?Logger $logger, Log $log, Document $project, Authorization $authorization) use ($queueName) {
$version = System::getEnv('_APP_VERSION', 'UNKNOWN');
Span::error($error);
if ($logger) {
$log->setNamespace('appwrite-worker');
$log->setServer(System::getEnv('_APP_LOGGING_SERVICE_IDENTIFIER', \gethostname()));
+6 -14
View File
@@ -8,7 +8,6 @@ use Appwrite\Event\Publisher\Execution as ExecutionPublisher;
use Utopia\Bus\Listener;
use Utopia\Database\Document;
use Utopia\Span\Span;
use Utopia\System\System;
class Log extends Listener
{
@@ -34,20 +33,13 @@ class Log extends Listener
{
$project = new Document($event->project);
$execution = new Document($event->execution);
if ($execution->getAttribute('resourceType', '') === 'functions') {
$traceProjectId = System::getEnv('_APP_TRACE_PROJECT_ID', '');
$traceFunctionId = System::getEnv('_APP_TRACE_FUNCTION_ID', '');
$resourceId = $execution->getAttribute('resourceId', '');
if ($traceProjectId !== '' && $traceFunctionId !== '' && $project->getId() === $traceProjectId && $resourceId === $traceFunctionId) {
Span::init('execution.trace.v1_executions_enqueue');
Span::add('datetime', gmdate('c'));
Span::add('projectId', $project->getId());
Span::add('functionId', $resourceId);
Span::add('executionId', $execution->getId());
Span::add('deploymentId', $execution->getAttribute('deploymentId', ''));
Span::add('status', $execution->getAttribute('status', ''));
Span::current()?->finish();
}
Span::add('project.id', $project->getId());
Span::add('function.id', $execution->getAttribute('resourceId', ''));
Span::add('execution.id', $execution->getId());
Span::add('deployment.id', $execution->getAttribute('deploymentId', ''));
Span::add('execution.status', $execution->getAttribute('status', ''));
}
$publisherForExecutions->enqueue(new ExecutionMessage(
@@ -186,11 +186,11 @@ class Builds extends Action
array $platform,
int $timeout
): void {
Span::add('projectId', $project->getId());
Span::add('resourceId', $resource->getId());
Span::add('resourceType', $resource->getCollection());
Span::add('deploymentId', $deployment->getId());
Span::add('timeout', $timeout);
Span::add('project.id', $project->getId());
Span::add('resource.id', $resource->getId());
Span::add('resource.type', $resource->getCollection());
Span::add('deployment.id', $deployment->getId());
Span::add('build.timeout', $timeout);
Console::info('Deployment action started');
@@ -232,12 +232,12 @@ class Builds extends Action
$version = $this->getVersion($resource);
$runtime = $this->getRuntime($resource, $version);
Span::add('runtime', $resource->getAttribute($resource->getCollection() === 'sites' ? 'buildRuntime' : 'runtime', ''));
Span::add('version', $version);
Span::add('build.runtime', $resource->getAttribute($resource->getCollection() === 'sites' ? 'buildRuntime' : 'runtime', ''));
Span::add('build.version', $version);
$spec = Config::getParam('specifications')[$resource->getAttribute('buildSpecification', APP_COMPUTE_SPECIFICATION_DEFAULT)];
Span::add('cpus', (float) ($spec['cpus'] ?? APP_COMPUTE_CPUS_DEFAULT));
Span::add('memory', (int) ($spec['memory'] ?? APP_COMPUTE_MEMORY_DEFAULT));
Span::add('build.cpus', (float) ($spec['cpus'] ?? APP_COMPUTE_CPUS_DEFAULT));
Span::add('build.memory', (int) ($spec['memory'] ?? APP_COMPUTE_MEMORY_DEFAULT));
// Realtime preparation
$event = "{$resource->getCollection()}.[{$resourceKey}].deployments.[deploymentId].update";
@@ -59,9 +59,9 @@ trait Deployment
$resourceType = $repository->getAttribute('resourceType');
$logBase = "vcs.github.event.repo.{$repositoryId}";
Span::add("{$logBase}.projectId", $projectId);
Span::add("{$logBase}.resourceId", $resourceId);
Span::add("{$logBase}.resourceType", $resourceType);
Span::add('project.id', $projectId);
Span::add("{$logBase}.resource.id", $resourceId);
Span::add("{$logBase}.resource.type", $resourceType);
if ($resourceType !== "function" && $resourceType !== "site") {
continue;
+5 -5
View File
@@ -101,11 +101,11 @@ class Interval extends Action
]);
$scanned = \count($rules);
Span::add("interval.domainVerification.scanned", $scanned);
Span::add("interval.domain_verification.scanned", $scanned);
if ($scanned === 0) {
Span::add("interval.domainVerification.processed", 0);
Span::add("interval.domainVerification.failed", 0);
Span::add("interval.domain_verification.processed", 0);
Span::add("interval.domain_verification.failed", 0);
return; // No rules to verify
}
@@ -131,7 +131,7 @@ class Interval extends Action
}
}
Span::add("interval.domainVerification.processed", $processed);
Span::add("interval.domainVerification.failed", $failed);
Span::add("interval.domain_verification.processed", $processed);
Span::add("interval.domain_verification.failed", $failed);
}
}
@@ -8,7 +8,6 @@ use Utopia\Console;
use Utopia\Database\Database;
use Utopia\Database\DateTime;
use Utopia\Span\Span;
use Utopia\System\System;
/**
* ScheduleFunctions
@@ -107,22 +106,18 @@ class ScheduleFunctions extends ScheduleBase
->setPath('/')
->setProject($schedule['project']);
$projectDoc = $schedule['project'];
$functionDoc = $schedule['resource'];
$traceProjectId = System::getEnv('_APP_TRACE_PROJECT_ID', '');
$traceFunctionId = System::getEnv('_APP_TRACE_FUNCTION_ID', '');
if ($traceProjectId !== '' && $traceFunctionId !== '' && $projectDoc->getId() === $traceProjectId && $functionDoc->getId() === $traceFunctionId) {
Span::init('execution.trace.v1_functions_enqueue');
Span::add('datetime', gmdate('c'));
Span::add('projectId', $projectDoc->getId());
Span::add('functionId', $functionDoc->getId());
Span::add('scheduleId', $schedule['$id'] ?? '');
Span::init('schedule.functions.enqueue');
try {
Span::add('project.id', $schedule['project']->getId());
Span::add('function.id', $schedule['resource']->getId());
Span::add('schedule.id', $schedule['$id'] ?? '');
$queueForFunctions->trigger();
$this->recordEnqueueDelay($delayConfig['nextDate']);
} finally {
Span::current()?->finish();
}
$queueForFunctions->trigger();
$this->recordEnqueueDelay($delayConfig['nextDate']);
}
});
}
+5 -14
View File
@@ -8,7 +8,6 @@ use Utopia\Database\Database;
use Utopia\Platform\Action;
use Utopia\Queue\Message;
use Utopia\Span\Span;
use Utopia\System\System;
class Executions extends Action
{
@@ -41,19 +40,11 @@ class Executions extends Action
throw new Exception('Missing execution');
}
$traceProjectId = System::getEnv('_APP_TRACE_PROJECT_ID', '');
$traceFunctionId = System::getEnv('_APP_TRACE_FUNCTION_ID', '');
$resourceId = $execution->getAttribute('resourceId', '');
if ($traceProjectId !== '' && $traceFunctionId !== '' && $executionMessage->project->getId() === $traceProjectId && $resourceId === $traceFunctionId) {
Span::init('execution.trace.executions_worker_upsert');
Span::add('datetime', gmdate('c'));
Span::add('projectId', $executionMessage->project->getId());
Span::add('functionId', $resourceId);
Span::add('executionId', $execution->getId());
Span::add('deploymentId', $execution->getAttribute('deploymentId', ''));
Span::add('resourceType', $execution->getAttribute('resourceType', ''));
Span::current()?->finish();
}
Span::add('project.id', $executionMessage->project->getId());
Span::add('function.id', $execution->getAttribute('resourceId', ''));
Span::add('execution.id', $execution->getId());
Span::add('deployment.id', $execution->getAttribute('deploymentId', ''));
Span::add('resource.type', $execution->getAttribute('resourceType', ''));
$dbForProject->upsertDocument('executions', $execution);
}
+20 -51
View File
@@ -80,6 +80,12 @@ class Functions extends Action
$type = $payload['type'] ?? '';
Span::add('project.id', $project->getId());
Span::add('payload.type', $type);
Span::add('queue.pid', $message->getPid());
Span::add('queue.name', $message->getQueue());
Span::add('message.timestamp', (string) $message->getTimestamp());
$events = $payload['events'] ?? [];
$data = $payload['body'] ?? '';
$eventData = $payload['payload'] ?? '';
@@ -118,19 +124,7 @@ class Functions extends Action
$log->addTag('type', $type);
if (empty($events) && !$function->isEmpty()) {
$traceProjectId = System::getEnv('_APP_TRACE_PROJECT_ID', '');
$traceFunctionId = System::getEnv('_APP_TRACE_FUNCTION_ID', '');
if ($traceProjectId !== '' && $traceFunctionId !== '' && $project->getId() === $traceProjectId && $function->getId() === $traceFunctionId) {
Span::init('execution.trace.functions_worker_dequeue');
Span::add('datetime', gmdate('c'));
Span::add('projectId', $project->getId());
Span::add('functionId', $function->getId());
Span::add('payloadType', $type);
Span::add('queuePid', $message->getPid());
Span::add('queueName', $message->getQueue());
Span::add('messageTimestamp', (string) $message->getTimestamp());
Span::current()?->finish();
}
Span::add('function.id', $function->getId());
}
if (!empty($events)) {
@@ -322,19 +316,11 @@ class Functions extends Action
'duration' => 0.0,
]);
$traceProjectId = System::getEnv('_APP_TRACE_PROJECT_ID', '');
$traceFunctionId = System::getEnv('_APP_TRACE_FUNCTION_ID', '');
if ($traceProjectId !== '' && $traceFunctionId !== '' && $project->getId() === $traceProjectId && $function->getId() === $traceFunctionId) {
Span::init('execution.trace.functions_worker_before_execution_completed_bus_fail');
Span::add('datetime', gmdate('c'));
Span::add('projectId', $project->getId());
Span::add('functionId', $function->getId());
Span::add('executionId', $execution->getId());
Span::add('deploymentId', $execution->getAttribute('deploymentId', ''));
Span::add('trigger', $trigger);
Span::add('status', $execution->getAttribute('status', ''));
Span::current()?->finish();
}
Span::add('function.id', $function->getId());
Span::add('execution.id', $execution->getId());
Span::add('deployment.id', $execution->getAttribute('deploymentId', ''));
Span::add('execution.trigger', $trigger);
Span::add('execution.status', $execution->getAttribute('status', ''));
$bus->dispatch(new ExecutionCompleted(
execution: $execution->getArrayCopy(),
@@ -391,6 +377,10 @@ class Functions extends Action
$deploymentId = $function->getAttribute('deploymentId', '');
$spec = Config::getParam('specifications')[$function->getAttribute('runtimeSpecification', APP_COMPUTE_SPECIFICATION_DEFAULT)];
Span::add('function.id', $functionId);
Span::add('deployment.id', $deploymentId);
Span::add('execution.trigger', $trigger);
$log->addTag('deploymentId', $deploymentId);
/** Check if deployment exists */
@@ -450,6 +440,8 @@ class Functions extends Action
}
$headers['x-appwrite-execution-id'] = $executionId;
Span::add('execution.id', $executionId);
$headersFiltered = [];
foreach ($headers as $key => $value) {
if (\in_array(\strtolower($key), FUNCTION_ALLOWLIST_HEADERS_REQUEST)) {
@@ -554,18 +546,6 @@ class Functions extends Action
$source = $deployment->getAttribute('buildPath', '');
$extension = str_ends_with($source, '.tar') ? 'tar' : 'tar.gz';
$command = $version === 'v2' ? '' : "cp /tmp/code.$extension /mnt/code/code.$extension && nohup helpers/start.sh \"$command\"";
$traceProjectId = System::getEnv('_APP_TRACE_PROJECT_ID', '');
$traceFunctionId = System::getEnv('_APP_TRACE_FUNCTION_ID', '');
if ($traceProjectId !== '' && $traceFunctionId !== '' && $project->getId() === $traceProjectId && $functionId === $traceFunctionId) {
Span::init('execution.trace.functions_worker_before_executor');
Span::add('datetime', gmdate('c'));
Span::add('projectId', $project->getId());
Span::add('functionId', $functionId);
Span::add('executionId', $executionId);
Span::add('deploymentId', $deployment->getId());
Span::add('trigger', $trigger);
Span::current()?->finish();
}
try {
$executionResponse = $executor->createExecution(
projectId: $project->getId(),
@@ -642,19 +622,8 @@ class Functions extends Action
$errorCode = $th->getCode();
} finally {
/** Persist final execution status and record usage */
$traceProjectId = System::getEnv('_APP_TRACE_PROJECT_ID', '');
$traceFunctionId = System::getEnv('_APP_TRACE_FUNCTION_ID', '');
if ($traceProjectId !== '' && $traceFunctionId !== '' && $project->getId() === $traceProjectId && $functionId === $traceFunctionId) {
Span::init('execution.trace.functions_worker_before_execution_completed_bus');
Span::add('datetime', gmdate('c'));
Span::add('projectId', $project->getId());
Span::add('functionId', $functionId);
Span::add('executionId', $execution->getId());
Span::add('deploymentId', $execution->getAttribute('deploymentId', ''));
Span::add('status', $execution->getAttribute('status', ''));
Span::add('trigger', $trigger);
Span::current()?->finish();
}
Span::add('execution.status', $execution->getAttribute('status', ''));
$bus->dispatch(new ExecutionCompleted(
execution: $execution->getArrayCopy(),
project: $project->getArrayCopy(),
+12 -19
View File
@@ -106,27 +106,20 @@ class Messaging extends Action
Span::add('message.type', $type);
try {
switch ($type) {
case MESSAGE_SEND_TYPE_INTERNAL:
$message = new Document($payload['message'] ?? []);
$recipients = $payload['recipients'] ?? [];
switch ($type) {
case MESSAGE_SEND_TYPE_INTERNAL:
$message = new Document($payload['message'] ?? []);
$recipients = $payload['recipients'] ?? [];
$this->sendInternalSMSMessage($message, $project, $recipients, $log);
break;
case MESSAGE_SEND_TYPE_EXTERNAL:
$message = $dbForProject->getDocument('messages', $payload['messageId']);
$this->sendInternalSMSMessage($message, $project, $recipients, $log);
break;
case MESSAGE_SEND_TYPE_EXTERNAL:
$message = $dbForProject->getDocument('messages', $payload['messageId']);
$this->sendExternalMessage($dbForProject, $message, $deviceForFiles, $project, $publisherForUsage);
break;
default:
throw new \Exception('Unknown message type: ' . $type);
}
} catch (\Throwable $e) {
Span::error($e);
throw $e;
} finally {
Span::current()?->finish();
$this->sendExternalMessage($dbForProject, $message, $deviceForFiles, $project, $publisherForUsage);
break;
default:
throw new \Exception('Unknown message type: ' . $type);
}
}