Correlating Logs and Requests

Give every request an id, attach it to each log line, return it in a header, and pass it to the services you call.

Syntax$record->extra['request_id'] = $id; return $record;

In production your log is one stream with thousands of requests interleaved. A line saying payment declined is useless on its own: you cannot tell which of the forty lines around it belong to the same request. A request id fixes that. One value, generated at the start of the request, attached to every log line it produces, returned to the client in a header, and sent on to the services you call. Then one search gives you the whole story of one request.

The three pieces

A listener on kernel.request accepts the id from the edge or generates one, and stores it in the request's attributes bag. A Monolog processor - a callable run against every log record before it is written - copies that value into the record's extra array. A listener on kernel.response puts it in a response header, so a user can quote the id from a browser's network tab and you can find their request.

Registering the processor has two equivalent forms. The attribute #[AsMonologProcessor] on the class is the shorthand; the longhand is the monolog.processor service tag in config/services.yaml. Both end up as the same tagged service.

What trips people up

An inbound X-Request-Id header is whatever the client sent. Accept it only when the request came through an edge you trust, and check its shape first, or you have let a stranger write arbitrary text into every log line of that request.

Example

Example · php
// src/Observability/RequestIdListener.php
declare(strict_types=1);

namespace App\Observability;

use Symfony\Component\EventDispatcher\Attribute\AsEventListener;
use Symfony\Component\HttpKernel\Event\RequestEvent;
use Symfony\Component\HttpKernel\Event\ResponseEvent;
use Symfony\Component\HttpKernel\KernelEvents;
use Symfony\Component\Uid\Uuid;

final class RequestIdListener
{
    public const ATTRIBUTE = '_request_id';

    private const HEADER = 'X-Request-Id';

    // High priority: the id must exist before anything else can log.
    #[AsEventListener(event: KernelEvents::REQUEST, priority: 4096)]
    public function onRequest(RequestEvent $event): void
    {
        if (!$event->isMainRequest()) {
            return;
        }

        $incoming = (string) $event->getRequest()->headers->get(self::HEADER, '');

        // Only accept an id that looks like one. Anything else is text
        // chosen by the caller, about to be written into every log line.
        $id = 1 === preg_match('/^[A-Za-z0-9-]{8,64}$/', $incoming)
            ? $incoming
            : Uuid::v7()->toRfc4122();

        $event->getRequest()->attributes->set(self::ATTRIBUTE, $id);
    }

    #[AsEventListener(event: KernelEvents::RESPONSE)]
    public function onResponse(ResponseEvent $event): void
    {
        $id = $event->getRequest()->attributes->get(self::ATTRIBUTE);

        if (is_string($id)) {
            $event->getResponse()->headers->set(self::HEADER, $id);
        }
    }
}

When to use it

  • Pull every log line for the one failed checkout a customer reported, using the id from the response header.
  • Trace a failure across two of your own services without a tracing backend installed.
  • Give support staff an id to paste into a ticket instead of a screenshot of a timestamp.
  • Tell apart two users hitting the same endpoint in the same second.

More examples

The processor that puts the id on every line

Reach for a processor whenever a value belongs on every log line rather than on one call site. The alternative is passing the id in the context array of each logger call, which you will forget. Values added to extra are separate from the context you pass per message, which keeps your own keys from colliding with the processor's. Symfony also ships processors you can enable instead of writing: RouteProcessor adds the route and controller, TokenProcessor adds the authenticated user.

Example · php
// src/Observability/RequestIdProcessor.php
declare(strict_types=1);

namespace App\Observability;

use Monolog\Attribute\AsMonologProcessor;
use Monolog\LogRecord;
use Monolog\Processor\ProcessorInterface;
use Symfony\Component\HttpFoundation\RequestStack;

#[AsMonologProcessor]
final class RequestIdProcessor implements ProcessorInterface
{
    public function __construct(private readonly RequestStack $requestStack)
    {
    }

    // Called once per log record. Keep it cheap: no queries, no I/O.
    public function __invoke(LogRecord $record): LogRecord
    {
        // The main request, so logs written inside a sub-request
        // still carry the id of the request the user made.
        $request = $this->requestStack->getMainRequest();

        if (null === $request) {
            return $record; // console command, worker, or test
        }

        $id = $request->attributes->get(RequestIdListener::ATTRIBUTE);

        if (is_string($id)) {
            $record->extra['request_id'] = $id;
        }

        return $record;
    }
}

Making the id visible in the log output

Writing to php://stderr is the Symfony default in prod, and it is what you want in a container: the runtime collects stderr, so nothing has to rotate a file. The formatter is the part that matters here. With the default line formatter the id is buried in a string; with monolog.formatter.json each record is one JSON object and request_id becomes a searchable field. Keep both the attribute and the tag in mind, because you will meet each form in other people's projects.

Example · yaml
# config/packages/prod/monolog.yaml
monolog:
    handlers:
        main:
            type: fingers_crossed
            action_level: error
            handler: nested
            excluded_http_codes: [404, 405]
            buffer_size: 50
        nested:
            type: stream
            path: php://stderr
            level: debug
            # JSON, so extra.request_id arrives as a field the log store
            # can filter on rather than text inside a message.
            formatter: monolog.formatter.json

# config/services.yaml
# The longhand equivalent of #[AsMonologProcessor] on the class:
services:
    App\Observability\RequestIdProcessor:
        tags:
            - { name: monolog.processor }

Passing the id to the next service

Without this, a failure in the billing service is a dead end: you have the id on your side and nothing to match it against on theirs. The #[Target('billing')] attribute selects a scoped HTTP client configured elsewhere, so the base URI and credentials are not repeated here. If you also run OpenTelemetry, its HttpClient instrumentation propagates the trace id in a traceparent header for you, and the trace id can serve as the correlation key instead of a hand-rolled one.

Example · php
// src/Billing/BillingClient.php
declare(strict_types=1);

namespace App\Billing;

use Symfony\Component\DependencyInjection\Attribute\Target;
use Symfony\Component\HttpFoundation\RequestStack;
use Symfony\Contracts\HttpClient\HttpClientInterface;
use App\Observability\RequestIdListener;

final class BillingClient
{
    public function __construct(
        #[Target('billing')] private readonly HttpClientInterface $client,
        private readonly RequestStack $requestStack,
    ) {
    }

    public function charge(string $reference, int $amountInCents): int
    {
        $headers = [];
        $request = $this->requestStack->getMainRequest();
        $id = $request?->attributes->get(RequestIdListener::ATTRIBUTE);

        if (is_string($id)) {
            // The billing service logs this id too, so one search
            // covers both applications.
            $headers['X-Request-Id'] = $id;
        }

        return $this->client->request('POST', '/charges', [
            'headers' => $headers,
            'json' => ['reference' => $reference, 'amount' => $amountInCents],
        ])->getStatusCode();
    }
}

Related

symfony monologsymfony log contextsymfony tracingsymfony trusted proxiessymfony http client scoped

Discussion

  • Be the first to comment on this lesson.