Flag of Ukraine
SymfonyCasts stands united with the people of Ukraine

Logger Channel Setup and Autowiring

Keep on Learning!

If you liked what you've learned so far, dive in!
Subscribe to get access to this tutorial plus
video, code and script downloads.

Start your All-Access Pass
Buy just this tutorial for $12.00

With a Subscription, click any sentence in the script to jump to that part of the video!

Login Subscribe

Here'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.

Adding a Log Handler

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

Autowiring the Channel Logger

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
}

Setting up the Context

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!

Leave a comment!

8
Login or Register to join the conversation
davidmintz Avatar
davidmintz Avatar davidmintz | posted 3 months ago | edited

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 service monolog.handler.app would appear, but not monolog.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?

Reply

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!

Reply
davidmintz Avatar

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'));
Reply

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!

Reply

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

Reply

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/cur...

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!

1 Reply
aliemre Avatar
aliemre Avatar aliemre | posted 2 years ago

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.

Reply

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!

Reply
Cat in space

"Houston: no signs of life"
Start the conversation!

This tutorial is built with Symfony 4.3, but will work well on Symfony 4.4 or 5.

What PHP libraries does this tutorial use?

// 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
    }
}