If you liked what you've learned so far, dive in!
Subscribe to get access to this tutorial plus
video, code and script downloads.
With a Subscription, click any sentence in the script to jump to that part of the video!
Login SubscribeHere's our goal... and the end result is going to be pretty cool: leverage our middleware - and the fact that we're adding this unique id to every message - to log the entire lifecycle of a message to a file. I want to see when a message was originally dispatched, when it was sent to the transport, when it was received from the transport and when it was handled.
Before we get into the middleware stuff, let's configure a new logger channel that logs to a new file. Open up config/packages/dev/monolog.yaml
and add a new channels
key. Wait... that's not right. A logging channel is, sort of a "category", and you can control how log messages for each category are handled. We don't want to add it here because then that new channel would only exist in the dev environment. Nope, we want the channel to exist in all environments... even if we decide to only give those messages special treatment in dev
.
To do that, directly inside config/packages
, create a new file called monolog.yaml
... though... remember - the names of these config files aren't important. What is important is to add a monolog
key, then channels
set to an array with one new one - how about messenger_audit
.
monolog: | |
channels: [messenger_audit] |
Thanks to this, we now have a new logger service in the container for this channel. Let's find it: at your terminal, run:
php bin/console debug:container messenger_audit
There it is: monolog.logger.messenger_audit
- we'll use that in a minute. But first, I want to make any logs to this channel save to a new file in the dev
environment. Back up in config/packages/dev/monolog.yaml
, copy the main
handler, paste and change the key to messenger
... though that could be anything. Update the file to be called messenger.log
and - here's the magic - instead of saying: log all messages except those in the event
channel, change this to only log messages that are in that messenger_audit
channel.
monolog: | |
handlers: | |
... lines 3 - 7 | |
messenger: | |
type: stream | |
path: "%kernel.logs_dir%/messenger.log" | |
level: debug | |
channels: ["messenger_audit"] | |
... lines 13 - 25 |
Cool! To use this service, we can't just autowire it by type-hinting the normal LoggerInterface
... because that will give us the main logger. This is one of those cases where we have multiple services in the container that all use the same class or interface.
To make it wirable, back in services.yaml
, add a new global bind: $messengerAuditLogger
that points to the service id: copy that from the terminal, then paste as @monolog.logger.messenger_audit
.
... lines 1 - 7 | |
services: | |
... line 9 | |
_defaults: | |
... lines 11 - 12 | |
bind: | |
... lines 14 - 15 | |
$messengerAuditLogger: '@monolog.logger.messenger_audit' | |
... lines 17 - 34 |
Thank to this, if we use an argument named $messengerAuditLogger
in the constructor of a service or in a controller, Symfony will pass us that service. By the way, starting in Symfony 4.2, instead of binding only to the name of the argument, you can also bind to the name and type by saying Psr\Log\LoggerInterface $messengerAuditLogger
. That just makes things more specific: Symfony would pass us this service for any arguments that have this name and the LoggerInterface
type-hint.
Anyways, we have a new logger channel, that channel will log to a special file, and the logger service for that channel is wirable. Time to get to work!
Close up the monolog config files and go to AuditMiddleware
. Add a public function __construct()
with one argument LoggerInterface $messengerAuditLogger
- the same name we used in the config. I'll call the property itself $logger
, and finish this with $this->logger = $messengerAuditLogger
.
... lines 1 - 4 | |
use Psr\Log\LoggerInterface; | |
... lines 6 - 10 | |
class AuditMiddleware implements MiddlewareInterface | |
{ | |
private $logger; | |
public function __construct(LoggerInterface $messengerAuditLogger) | |
{ | |
$this->logger = $messengerAuditLogger; | |
} | |
... lines 19 - 40 | |
} |
Down in handle()
, remove the dump()
and create a new variable called $context
. In addition to the actual log message, it's a little-known fact that you can pass extra information to the logger... which is super handy! Let's create a key called id
set to the unique id, and another called class
that's set to the class of the original message class. We can get that with get_class($envelope->getMessage())
.
... lines 1 - 10 | |
class AuditMiddleware implements MiddlewareInterface | |
{ | |
... lines 13 - 19 | |
public function handle(Envelope $envelope, StackInterface $stack): Envelope | |
{ | |
... lines 22 - 28 | |
$context = [ | |
'id' => $stamp->getUniqueId(), | |
'class' => get_class($envelope->getMessage()) | |
]; | |
... lines 33 - 39 | |
} | |
} |
Let's do the logging next! It's a bit more interesting than you might expect. How can we figure out if the current message was just dispatched or was just received asynchronously from a transport? And if it was just dispatched, how can we find out whether or not the message will be handled right now or sent to a transport for later? The answer... lies in the stamps!
Hey @davidmintz!
(1) The logger config is... complex. It is definitely NOT one of my favorite parts of Symfony. Monolog is great - but the flexibility of how it handles channels and loggers is quite difficult to "express" in YAML. And so, honestly, I get a little lost in the YAML config for monolog also. I would NOT have thought that there would be anything special about "app". If that's true, that is very strange behavior! There is no existing, core handler or channel called "app", so I can't think of why this would cause any conflict. So, big shoulder shrug on this point - but you got it working, so that's good :p
(2) The ConsoleHandler
is kind of a weird one :). Its job is simple: when you run a console command, based on the verbosity you're using to run the command (e.g. -vv
), it will output log messages to your terminal. The way it does this is a little odd. On a monolog level, it is always active and it should receive all messages. But, unless it detects that a console command is currently executing, it just skips doing anything with the messages. So, during a web request, it receives all log messages, but then does nothing.
Anyways, that wasn't the "meat" of your question :). As I mentioned, the monolog config is tricky. To make it easier, I'll refer to this example config: https://github.com/symfony/recipes/blob/96d11c2e2ed2a33a796740ed47de0d6d25263fe8/symfony/monolog-bundle/3.7/config/packages/monolog.yaml#L40-L61
In theory, EVERY log message should be passed to EVERY handler you have. So in this case, any log message (at any level and at any channel) would be passed to each of those 4 handlers. But, there are several caveats:
A) Each handler has an optional channels
config where they can choose to only receive messages for a specific channel... or for all channels except certain channels (e.g. !event
which means "not the event channel). Internally, iirc, the result of this is that if you have a channel called foo
, then it either will or won't "have" a handler based on the handler's channels
config. What I mean is: it's NOT that a handler will receive a message and then skip it due to its channels
config. Nope, internally, the channels
config is read and then the handler is "applied" to all logger channels that meet the channels
criteria.
B) I mentioned that "EVERY log message should be passed to EVERY handler you have". That is true... except for nested handlers. What is a "nested" handler? It is any handler that is referred to by another handler. For example, because the main
(type: fingers_crossed
) handler refers to the nested
handler (via handler: nested
), Monolog now knows that the purpose of the nested
handler is just to receive messages from this handler. And so, the nested
handler will suddenly NOT receive ALL messages: it will only receive messages forwarded to it by the main
handler. So, a better statement would be:
EVERY log message will be passed to EVERY handler that is NOT referred to by another handler.
So, to your question:
Anyway, the question is: how do you configure a logger to write to a particular destination exclusively?
You should be able to do this by:
1) Creating a new logger channel (e.g. stuff
)
2) Making a new handler with channels: [stuff]
3) Add channels: [!stuff]
to any other top-level handlers that should ignore this channel.
So probably step (3) is what you're missing. However, we DO log things like you are describing and we typically skip step 3. Why? Well, on production, by default, only logs from requests with errors are logged. So, suppose I have some info
level logs going to some stuff.log
file all the time - even for non-error requests. Cool. Now, one page DOES have an error. Do I really care that the stuff
channel logs are included in the error logs for that one request? Typically, when you have an error, the more logs the better to help you figure out what was happening on that request.
Let me know if this helps!
Cheers!
Hey @weaverryan! Thank you for the characteristically prompt, detailed and lucid reply. Yes it definitely helps, and after I read it five or six more times slowly it will help even more :-)
Maybe the use of "app" as a name wasn't the source of my woes. I know the golden rule about this: only change one thing at a time, so that when it works you'll know what worked. I didn't think I changed >1 thing, but maybe....
OMG I'm reminded of another question, sorry! That is: suppose you want to name a log file dynamically, e.g.,
$logfile = sprintf('app.%s.log',date('Y-m-d'));
Hey @davidmintz!
$logfile = sprintf('app.%s.log',date('Y-m-d'));
Because the log files are in YAML (and, more technically, because their values are compiled into Symfony's container), the best choice for making something dynamic is to use environment variables... along with a custom "env var processor". But, before we run down that road, if all you really want is "log rotation", check out the rotating_file
handler - it's described on this blog post - https://eidson.info/post/rotating-logs-symfony
I haven't used that personally before, but I believe this is its exact use-case.
Cheers!
Small question :By default messenger logs are under var/log/dev.log does there any way to redirect them to a specific channel without creating a new middleware? The idea is so have the same messenger:consume logs but under a sperate file var/log/messenger.log
Hey ahmedbhs!
Hmm. Maybe... it depends on exactly what you're looking for. Messenger itself already sends all of its logs to a channel called "messenger". So that would be all the messages that say that a message is being received, handled, etc. You can easily send all messages from this channel to a special log file doing the same thing we do in this chapter, which is the same thing you can see here: https://symfony.com/doc/current/logging/channels_handlers.html
But technically, when you process a message, a LOT of things in the system might log, and those might log to all kinds of channels. If you wanted to capture all of that, the easiest way may be to actually pass the output of the messenger:consume command itself to some log file - something like php bin/console messenger:consume -vv | tee messenger.log
(tee is just a unix utility that will write to a file, but still output to the screen).
Let me know if this helps!
Cheers!
I think, there is an error on how we define new logger service on service.yaml. Instead of '@monolog.logger.messenger_audit', we should use '@monolog.logger.messenger'. Otherwise, I get error on Symfony 5.0.7. The error says: Monolog configuration error: The logging channel "messenger_audit" assigned to the "messenger" handler does not exist.
Thanks for the cool tutorial! PS: I am not able to watch the video. As far as I understand through the script.
Hey aliemre!
Hmm. I'm not aware of anything that changed, but I could always be wrong ;). I'm curious: after you create the messenger_audit
channel in config/packages/monolog.yaml
, what do you see when you run this command:
php bin/console debug:autowiring log
You should see one logger mentioned for each channel. You WILL see a logger for the messenger
channel (service id monolog.logger.messenger
) because that's actually defined by Symfony itself. But you should also see one for our custom logger. Double-check that spot and let me know if you'd like :O.
Thanks for the cool tutorial! PS: I am not able to watch the video. As far as I understand through the script
I'm really happy that the scripts + code have been useful :).
Cheers!
// composer.json
{
"require": {
"php": "^7.1.3",
"ext-ctype": "*",
"ext-iconv": "*",
"composer/package-versions-deprecated": "^1.11", // 1.11.99
"doctrine/annotations": "^1.0", // v1.8.0
"doctrine/doctrine-bundle": "^1.6.10", // 1.11.2
"doctrine/doctrine-migrations-bundle": "^1.3|^2.0", // v2.0.0
"doctrine/orm": "^2.5.11", // v2.6.3
"intervention/image": "^2.4", // 2.4.2
"league/flysystem-bundle": "^1.0", // 1.1.0
"phpdocumentor/reflection-docblock": "^3.0|^4.0", // 4.3.1
"sensio/framework-extra-bundle": "^5.3", // v5.3.1
"symfony/console": "4.3.*", // v4.3.2
"symfony/dotenv": "4.3.*", // v4.3.2
"symfony/flex": "^1.9", // v1.18.7
"symfony/framework-bundle": "4.3.*", // v4.3.2
"symfony/messenger": "4.3.*", // v4.3.4
"symfony/property-access": "4.3.*", // v4.3.2
"symfony/property-info": "4.3.*", // v4.3.2
"symfony/serializer": "4.3.*", // v4.3.2
"symfony/validator": "4.3.*", // v4.3.2
"symfony/webpack-encore-bundle": "^1.5", // v1.6.2
"symfony/yaml": "4.3.*" // v4.3.2
},
"require-dev": {
"easycorp/easy-log-handler": "^1.0.7", // v1.0.7
"symfony/debug-bundle": "4.3.*", // v4.3.2
"symfony/maker-bundle": "^1.0", // v1.12.0
"symfony/monolog-bundle": "^3.0", // v3.4.0
"symfony/stopwatch": "4.3.*", // v4.3.2
"symfony/twig-bundle": "4.3.*", // v4.3.2
"symfony/var-dumper": "4.3.*", // v4.3.2
"symfony/web-profiler-bundle": "4.3.*" // v4.3.2
}
}
I'm working on a project with Symfony 6 and I have two questions:
(1) I spent more time than I even want to admit struggling to configure a logger (or do I mean channel? or handler? or all the above?) that would write to its own file and only there, with a view to recording certain application events for posterity -- not errors or debugging stuff. Might eventually want to store these messages in a database. But I digress. I called the handler "app" and the channel "app", and it simply would not work no matter how hard I tried -- even banging my head on the table didn't work. When I ran
container:debug monolog
, the servicemonolog.handler.app
would appear, but notmonolog.logger.app
. I managed to bind this thing to a variable so that__construct(LoggerInterface $appLogger)
looked like it might work -- but $appLogger turned out to be an instance of the handler, not the logger. (In retrospect this doesn't seem so surprising.) So Symfony got upset and exploded. I then changed the name "app" to something else wherever it occured, and lo and behold, everything works! So, the question: is there something sacred about the word "app"?(2) And now that I have it working pretty well, I wonder if I can make my logger write exclusively to my file, or other destination that I decide on later -- because I see that my nice new logger has three handlers: two Streamhandlers and one ConsoleHandler. One Streamhandler logs to my custom path, one writes to dev.log, and the console handler? Is that for use with a
Symfony\Component\Console\Command\Command
? Anyway, the question is: how do you configure a logger to write to a particular destination exclusively?