2017-02-20

Adding information about the logged in user to the error log in Symfony 2.8

Providing support for a Symfony application in a production environment, I am often faced with error messages in log files. And often it is unclear which user created which error message. Sometimes, users will call in and complain about a problem and it would come in handy to know which error messages were actually created by the calling user and which error messages are unrelated to the current problem. If only there was some way to store that information in the log file, next to each error message.

Fortunately, this is a task which others have tried to complete before me. I can only assume that this is the reason why the Symfony docs already contain a section on How to Add extra Data to Log Messages via a Processor. Basically, you have to create a processor class that modifies the log entry, e.g. by adding some information. Afterwards, you will need to tell Symfony that it should call your processor upon logging by adding your newly created class to the dependency injection container.

So, let's dive right in and get started with creating the processor class. We want to modify our log entry so that it always contains the user's display name and ID. Note that the display name here is a feature of my custom user class, so you might want to call a different method to get whatever value you want to display as the user's name. In Symfony, we can get the currently logged in user via the token storage. Of course, it is also possible that we are not logged in, so in that case we will get the string "anon." as a username.

<?php
namespace MyName\MyBundle;

use Symfony\Component\Security\Core\Authentication\Token\Storage\TokenStorageInterface;
use MyName\MyBundle\Entity\User;

class LoggedInUserProcessor
{
    private $tokenStorage;

    public function __construct(TokenStorageInterface $tokenStorage) {
        $this->tokenStorage = $tokenStorage;
    }

    public function processRecord(array $record) {
        if ($this->tokenStorage->getToken() && $this->tokenStorage->getToken()->getUser()) {
            $user = $this->tokenStorage->getToken()->getUser();
            if ($user instanceof User) {
                /** @var User $user */
                $record['extra']['userName'] = $user->getDisplayName();
                $record['extra']['userId'] = $user->getId();
            } else {
                $record['extra']['userName'] = $user;
            }
        return $record;
    }
}

That already concludes all the work which we need to do in our processor class. Now all we have to do is tell Symfony that it should call our processor whenever a log entry is written. We can achieve this by registering our processor class as a service and decorating it with the monolog.processor tag. Note that we also need to inject the token storage and define the method which should be called. As I am using YAML configuration files for my services, the respective entry looks like this:

    app.logged_in_user_processor:
        class: MyName\MyBundle\LoggedInUserProcessor
        arguments: ['@security.token_storage']
        tags:
            - { name: monolog.processor, method: processRecord }

And this is already it. Now, provided you haven't changed the default formatter, your added information will always be output at the end of each log entry. Here are some sample log entries from my application with the new processor enabled:

 [2017-02-17 08:09:58] event.DEBUG: Notified event "kernel.finish_request" to listener "Symfony\Component\Security\Http\Firewall::onKernelFinishRequest". []
{"userName":"Administrator","userId":1}

[2017-02-17 08:09:58] event.DEBUG: Notified event "kernel.terminate" to listener "Symfony\Bundle\SwiftmailerBundle\EventListener\EmailSenderListener::onTerminate". []
{"userName":"Administrator","userId":1}