10 Tips For A Better Symfony Debug Log


In this video we are going to cover 10 ways in which I use Jordi Boggiano's excellent Monolog library inside Symfony to make my life as a developer that much easier. Of course Jordi Boggiano / Seldaek is also the creator of Composer, and Packagist, and is someone to who the entire PHP community will - I'm sure - join me in saying an absolutely huge thank you too.

There's a ton (well, 10) of things to cover in this video, so let's get started.

1. Logging in a Controller

The very easiest way to get started with Monolog is to do so from any Symfony controller action:

// Symfony 4
public function myAction(LoggerInterface $logger)
{
    $logger->debug('detailed debug output');
    $logger->info('e.g. a user logged in');
}

// Symfony 2
public function myAction()
{
    $this->get('logger')->debug('detailed debug output');
    $this->get('logger')->info('e.g. a user logged in');
    $this->get('logger')->notice('normal but significant events');
    $this->get('logger')->warning('undesirable things that are not necessarily wrong');

    // or if logging a bunch at once, maybe...
    $logger = $this->get('logger');

    $logger->error(' Runtime errors that do not require immediate action');
    $logger->critical('Application component unavailable, unexpected exception');
    $logger->alert('Entire website down, database unavailable, etc');
    $logger->emergency('System is unusable');

    return $this->render(...)
}

Now, in the development environment, when you browse to the route that this controller action is for you should expect to see additional information on your Symfony web debug toolbar:

Monolog on the web debug toolbar

and when clicked:

Monolog output inside the Symfony profiler

and also inside the log file (var/logs/dev.log) itself:

Monolog output from the command line / Symfony debug log

2. Logging In A Symfony Service

Almost as easy as logging from a controller action is using Monolog inside a Symfony service. I say almost as you will need to inject the logger. If this is something you aren't yet sure how to do, be sure to watch Symfony Services 101 where this is covered in more depth.

# /app/config/services.yml

# note you may not even need an explicit service definition
# if using Symfony 4, with autowiring

services:
    app.example_service:
        class: AppBundle\Service\ExampleService
        arguments:
            - "@logger"

And then in our service:

<?php

namespace AppBundle\Service;

use Psr\Log\LoggerInterface;

class ExampleService
{
    /**
     * @var LoggerInterface
     */
    private $logger;

    public function __construct(LoggerInterface $logger)
    {
        $this->logger = $logger;
    }

    public function exampleMethod($ourVar)
    {
        $this->logger->debug('detailed debug output');
        $this->logger->info('e.g. a user logged in');
        $this->logger->notice('normal but significant events');

        // and so on
    }
}

Worth noting here is injecting something that conforms to LoggerInterface rather than tying directly to Monolog. In this instance, the likelihood of switching is slim, but you technically could use any PSR-3 compatible logger.

3. tail'ing Your Logs

Logs are great, and having access to them via the Web Debug Toolbar is very nice.

As your projects grow in complexity, the Web Debug Toolbar becomes a nice-to-have, but the raw log files themselves become essential.

A very quick way to interact with your log files is to:

cd /your/project/
tail -f var/logs/dev.log

This gives you a running output of your log files without needing to have an open browser window to see your debug logs. And also even when the debug toolbar isn't available. And also in prod... the list goes on as to when this single command is useful.

I have another video available if you'd like to learn a few more tips on working with Symfony from the command line.

4. We Can Do Better Than sprintf

Simple strings are great in helping you locate your logging statements, but inevitably you will need to log information related to the current execution of your code - or in layman's terms: what them there variables contained at the time of when you dun' run your code.

It's really tempting to use sprintf, and it maybe enough to get the job done. But we can do better:

    public function exampleMethod($ourVar)
    {
        $this->logger->debug(sprintf('$ourVar was set to %s', $ourVar));

        // better
        $this->logger->debug('exampleMethod :: $ourVar at interesting time', [
            'our_var' => $ourVar
        ]);
    }

The convention I use in the second statement is of my own preference, you are completely free to write your log statements in any format you choose.

Now when you call exampleMethod('hello'), the log output looks a little different:

[2017-01-23 12:58:25] app.DEBUG: $ourVar was set to hello
[2017-01-23 12:58:25] app.DEBUG: detailed debug output {"our_var":"hello"}

Using that context array allows different handlers to work with our extra data in interesting ways. One of which we will see shortly.

5. Fingers Crossed

Sometimes naming things is hard. Sometimes, naming things is fun!

One thing you may have spotted when first prodding around (excuse the pun) in app/config/config_prod.yml is the monolog.handlers config for main:

// /app/config/config_prod.yml

monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: error
            handler:      nested
        nested:
            type:  stream
            path:  "%kernel.logs_dir%/%kernel.environment%.log"
            level: debug
        console:
            type:  console

Most of this looks very 'computersy', but fingers_crossed?

Understanding this is really useful for two big reasons:

  1. It will help you understand how logging - by default - occurs in a Symfony production website, and;
  2. It will help you understand Monolog's handler stack concept.

Starting with the second point, the handler stack.

Anything you log will go through the handler stack, from top to bottom - i.e. starting with main, then going to nested, and finally to console, unless stopped by a specific handler along the way.

Each handler has a type. This type defines which class to use, of which there are plenty of options, though not all are immediately available in Symfony (to the very best of my knowledge).

This default config_prod.yml configuration is really helpful, but initially confusing.

main won't do anything unless triggered. But all log entries still pass through it.

nested will write any log entry to the var/logs/prod.log file, as the minimum log level is set to debug.

console will write messages out to the terminal on which any console command is run.

A very common question I get asked at this point is - then why don't I see anything logged to my terminal when I browse my site in prod mode?

Good question, let's answer it very shortly.

You now know that any log entry you - or anything else (e.g. Symfony) - makes will be pass through each handler in turn, unless the handler explicitly stops propagation.

That covers #2.

Now, back to point #1.

fingers_crossed can be thought of as a filter.

Messages have to pass through it, but it will hold onto them, and silently discard them - unless your tolerated action_level (or higher) is met.

By default, Symfony sets this level to error, meaning unless at some point in any given request an entry is logged with a severity of error or higher, the logs will be silently dropped at the end of the request, and the handlers further 'down' the handler stack will be none the wiser.

Ok, so we say let's cross our fingers and hope everything goes to plan, but if not, Symfony please can you keep me the log files for the request that had the errors? Thanks.

And then a request comes in which does trigger the error log level (or higher) in some way, and every single log entry is given to the nested handler, which will itself write everything with debug level or greater (so, anything) to the on disk log file. Nice. Our prod.log file is kept clutter free, unless things go wrong, in which case we make note of everything.

But what about console?

Ahh, another special case. You don't see anything logged to your stderr (terminal) by default, because console is only concerned with Symfony's Console Commands.

For a more thorough dive into this concept, check out the Core Concepts documentation. It doesn't take very long to read, and will give you a good understanding of any potential headscratchers.

6. One Line Log Rotation

It gives me no pleasure to say that a few years ago I received a phone call around tea time (6:30pm give or take) from a rather stressed out company director, stating that his entire website was down, and could I please drop everything and fix it.

It gives me some pleasure to say that thankfully, I wasn't the source of the problem :)

What had happened was that this site had been in production for some time, and during that time, the log file had grown, and grown, and grown, until it had consumed the entire disk. It baffles me that as this was a fully managed server from a very big name in the industry that they let this happen, but there you go.

Anyway, for the love of Mike, rotate your log files.

I would urge you to use LogRotate in almost every circumstance.

But, sometimes that is not possible.

And if it isn't, a very easy solution is to use the max_files option:

#/app/config/config_prod.yml

monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: error
            handler:      nested
        nested:
            type:  stream
            path:  "%kernel.logs_dir%/%kernel.environment%.log"
            level: debug
            max_files: 7

Where max_files is the number of days worth of logs to keep on disk.

Easy.

7. Use Channels To Log Critical Paths

By default, any log entry you add from your Symfony application will be put onto the app channel:

$ tail -f var/logs/dev.log

[2017-01-23 12:21:56] security.INFO: Populated the TokenStorage with an anonymous Token. [] []
[2017-01-23 12:21:56] app.INFO: e.g. a user logged in [] []
[2017-01-23 12:21:56] app.NOTICE: normal but significant events [] []
[2017-01-23 12:21:56] app.WARNING: undesirable things that are not necessarily wrong [] []
[2017-01-23 12:21:56] app.ERROR:  Runtime errors that do not require immediate action [] []
[2017-01-23 12:21:56] app.CRITICAL: Application component unavailable, unexpected exception [] []
[2017-01-23 12:21:56] app.ALERT: Entire website down, database unavailable, etc [] []
[2017-01-23 12:21:56] app.EMERGENCY: System is unusable [] []
[2017-01-23 12:21:56] request.INFO: Matched route "_wdt". {"route":"_wdt","route_parameters":{"_controller":"web_profiler.controller.profiler:toolbarAction","token":"a0f93a","_route":"_wdt"},"request_uri":"http://127.0.0.1:8000/_wdt/a0f93a","method":"GET"} []

This is fine, as you can quickly see where your app is doing things by grep'ing for app, e.g.:

tail -f var/logs/prod.log | grep "app"

Which would 'filter' down to just logs relevant to your code:

$ tail -f var/logs/dev.log | grep "app"

[2017-01-23 12:21:56] app.INFO: e.g. a user logged in [] []
[2017-01-23 12:21:56] app.NOTICE: normal but significant events [] []
[2017-01-23 12:21:56] app.WARNING: undesirable things that are not necessarily wrong [] []
[2017-01-23 12:21:56] app.ERROR:  Runtime errors that do not require immediate action [] []
[2017-01-23 12:21:56] app.CRITICAL: Application component unavailable, unexpected exception [] []
[2017-01-23 12:21:56] app.ALERT: Entire website down, database unavailable, etc [] []
[2017-01-23 12:21:56] app.EMERGENCY: System is unusable [] []

But this becomes a little less useful on larger apps where a single request may traverse a bunch of 'parts' inside your system. Logging everything to app can lead to a bunch of 'muddy' log entries that make it trickier to single out just the particular concept of your system that is interesting / going wrong.

A way I find this particularly useful is to group anything related to a single concept into using the same channel. An example of this might be the process of user registration, or in connecting a user's account to their social media profile, or a Symfony console command that triggers off some import business process.

Using Channels is really easy. We just need to tag our services with the name of the channel we wish to log too:

#/app/config/services.yml

services:
   app.example_service:
        class: AppBundle\Service\ExampleService
        arguments:
            - "@logger"
        tags:
            - { name: monolog.logger, channel: "my_channel" }

Now, when the ExampleService creates a new log entry, the entry will switch from app to my_channel in the logs:

$ tail -f var/logs/dev.log

[2017-01-23 12:22:31] my_channel.INFO: e.g. a user logged in [] []
[2017-01-23 12:22:31] my_channel.NOTICE: normal but significant events [] []
[2017-01-23 12:22:31] my_channel.WARNING: undesirable things that are not necessarily wrong [] []
[2017-01-23 12:22:31] my_channel.ERROR:  Runtime errors that do not require immediate action [] []

8. Log Channels To Their Own File

Depending on the complexity of your application it can sometimes be easier to create separate log files for the different critical paths (channels) through your application.

This is easy to achieve by combining a stream channel type with the channels option:

#/app/config/config_dev.yml

monolog:
    handlers:
        my_channel:
            type: stream
            path: "%kernel.logs_dir%/%kernel.environment%-my_channel.log"
            level: debug
            channels: [my_channel]

Here any log file entries created by a logger that uses the channel of my_channel will also be written to a file called var/logs/dev-my_channel.log.

You can also leverage the channels option to filter any channels from the current handler:

#/app/config/config_dev.yml

monolog:
    handlers:
        my_channel:
            type: stream
            path: "%kernel.logs_dir%/%kernel.environment%-my_channel.log"
            level: debug
            channels: [my_channel]
        main:
            type: stream
            path: "%kernel.logs_dir%/%kernel.environment%.log"
            level: debug
            channels: [!event, !my_channel]

Prefixing with the channel with ! will ensure it is excluded.

9. Logging From Symfony Console Commands

Logging from a Symfony console command is no different from logging in a Controller, or in a Service.

We need a logger instance, and then we can start logging. One way of doing this would be to extends ContainerAwareCommand, which you could then grab the logger via getContainer()->get('logger').

A better way - in my opinion - of defining console commands is to define them as services in their own right. This allows 'standard' service definition-style arguments which enable constructor injection.

services:
    app.example_command:
        class: AppBundle\Command\ExampleCommand
        arguments:
            - "@logger"
        tags:
            - { name: console.command }

And in ExampleCommand:

<?php

// /src/AppBundle/Command/ExampleCommand.php

namespace AppBundle\Command;

use AppBundle\Service\ExampleService;
use Psr\Log\LoggerInterface;
use Symfony\Component\Console\Command\Command;
use Symfony\Component\Console\Input\InputInterface;
use Symfony\Component\Console\Output\OutputInterface;

class ExampleCommand extends Command
{
    /**
     * @var LoggerInterface
     */
    private $logger;
    /**
     * @var ExampleService
     */
    private $exampleService;

    public function __construct(LoggerInterface $logger)
    {
        parent::__construct();

        $this->logger = $logger;
    }

    protected function configure()
    {
        $this
            // the name of the command (the part after "bin/console")
            ->setName('app:example-logger')
        ;
    }

    protected function execute(InputInterface $input, OutputInterface $output)
    {
        $this->logger->debug('debug message from console command');

        $output->writeln('hello from console command');
    }
}

Running this would write the debug log to the var/log/dev.log as you would expect. It would also output the contents of the writeln call to your screen.

The downside now is you have to then go and cat or tail your dev.log as another set of keystrokes. Boo.

Wouldn't it be nicer if you could see your log output right there in the console? Of course it would.

monolog:
    handlers:
        # others removed for brevity
        console:
            type:   console
            channels: [!event, !doctrine]
            verbosity_levels:
                VERBOSITY_NORMAL: debug

By setting the level of VERBOSITY_NORMAL to debug we now get our logged statements output to the screen along with our writeln output. Thats nice, and the log entries are of course still logged to our dev.log file as we would expect.

In case you were wondering, VERBOSITY_NORMAL defaults to the level of warning, meaning logging an entry with a severity of warning or higher would log to the terminal without you having to do anything.

10. Log To Graylog From Monolog

A critical piece of 'going live' for my projects is to ensure I have an instance of Graylog up, running, and being logged too from my production environment. As your application(s) grow, if you end up with a cluster of servers, trying to tail a log file may be fruitless if you're tests are hitting the other cluster node!

Getting Graylog up and running is outside the scope of this video, but I would point your in the direction of the official Graylog ansible role. If you are new to Ansible, I have a full free tutorial for you to enjoy.

To start logging to Graylog from Symfony you first need to add graylog2/gelf-php to your project.

Then, we need to define a formatter service to format our log entries in a Graylog compatible manner (GELF format):

# /app/config/services.yml

services:
    app.gelf_formatter:
        class: Monolog\Formatter\GelfMessageFormatter
        arguments:
            - "my example server"

I would advise making the first argument the hostname of your server, as it will be used prominently by Graylog. As you most likely want to differentiate between your dev, prod, (and others), it makes sense to use a parameter here instead of a hardcoded value. I'm hardcoding as this is a demo.

Next, we need to tell Monolog about our new handler. I'm going to call mine gelf, but call it whatever. The type: gelf is the important bit.

The publisher section is the hostname and port of your Graylog server. I'm using a local server, and the standard port. Obviously this would need some firewall considerations in prod.

We have already covered level, but to recap this handler will capture everything with a log severity level of debug or higher (so, anything).

Lastly, we use our newly defined formatting service as the formatter:

# /app/config/config_dev.yml

monolog:
    handlers:
        gelf:
            type: gelf
            publisher:
                hostname: 192.168.0.31
                port: 12201
            level: debug
            formatter: app.gelf_formatter

Next, give your application a cache:clear, even in development.

Inside Graylog you can add in a GELF UDP input and the very next time you write a new log entry, boom, it's in Graylog:

Logging to Graylog from Symfony

I hope you've found these ideas for using Monolog to be useful, and if you have any you'd like to share then do please leave them in the comments below.

Episodes

# Title Duration
1 10 Tips For A Better Symfony Debug Log 10:13