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:
and when clicked:
and also inside the log file (var/logs/dev.log
) itself:
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:
- It will help you understand how logging - by default - occurs in a Symfony production website, and;
- 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:
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.