Feature request from mttjohnson, posted on GitHub Dec 14, 2015
I've been digging into how logging works in Magento in order to accommodate adding logging into a module I'm working on.
It looks like there is a little bit of discussion on #2641 regarding how to improve the usability of logging in Magento.
I logged an issue #2529 that identifies a problem with Magento's use of Monolog with multiple handlers specified in di.xml. I provided a workaround to utilize multiple handlers with Monolog 1.16.0 to make it possible to specify multiple handlers in the di.xml so that Monolog recognizes them correctly. I also noted that the fix to Monolog that allows it to handle associative arrays properly would cause some duplicate logging the way that Magento has implemented the use of logging.
A few other people like #2058 have run into some of the difficulty in figuring out how to utilize logging in Magento or work around it.
I had the need for some logging in a module I'm working on, and I implemented a custom Logger that extends Monolog\Logger and then I inject an instance my logger using DI into any class that I want to utilize the custom logger, in a similar way to how Magento injects Psr\Log\LoggerInterface for any class that needs access to log information. The custom logger extends Monolog\Logger but doesn't add anything to the implementation, I basically utilize the class so I can specify it's type in di.xml with an array of handlers and processors to instantiate the object with similar to how Magento is using Monolog.
I wanted to have some control to turn off logging, or specify in the Magento Admin Configuration what level of detail to log. I added some code to the handler constructor to conditionally add a custom processor to my handler that includes the store_id in the log record if I have configuration settings set to log a lot of additional details to the log records. I implemented a custom handler that extends the Magento\Framework\Logger\Handler\System hander and I overwrote the isHandling() method to check config settings and determine if it should be logging information or not. I also overwrote the write() method to check config settings and conditionally alter the amount of additional context details to include in the log record that is written.
I also had certain log messages that I was wanting to log to both a database table and to a log file. I wrote a separate custom handler for writing log records to a database table using a simple custom Model in my module. This way I can have structured information logged to a table when an event occurs and have other pieces of code interact with that event information rather than the information getting burried into a log file.
The way I implemented the use of my custom logger, I pass additional details across via the context array and my handlers will either include or exclude certain context keys into the log records depending on the level of detail the configuration settings specify.
$this->myCustomLogger->info(
'response from external web api call',
[ /* context */
'request' => var_export($request, true),
'response' => var_export($response, true),
'processing_time' = var_export($processingTime, true),
]
);
$this->myCustomLogger->info(
'decision was programmatically determined',
[ /* context */
'input' => var_export($input, true),
'event_circumstances' => var_export($whatHappened, true),
'action_taken' = var_export($howItWasResolved, true),
'manual_adjustment_needed' = var_export($detailsOfManualAdjustmentToBeMadeLater, true),
]
);I figure that during development and testing of my module, the logging details will be useful, but during production we would want to keep logging to a minimum of necessary details. The additional context data gives me relevant information to try and diagnose a situation when the module is deployed somewhere, and there is the ability to control if it is logging, where, and how much detail it logs based on configuration settings in the admin. In the event that some issue is occurring with the module in production, additional details could be logged temporarily to collect more details to better diagnose and analyze an issue to isolate it.
Having two custom handlers for my custom logger allows me to have one log entry anywhere my code needs to log something, and I can control how I want the handlers to process the log records via configuration settings in the admin. If for some reason I wanted to add a third handler for something like Loggly to aggregate log details somewhere else it would be pretty simple to add to my custom logger.
Being able to use Monolog and implement additional logic in the handlers allows me to control the logging more specifically and seems to work well, but I'm basically doing almost all of this outside of anything built into Magento for logging.
I don't see anything in Magento that allows me to control logging much, if it writes logs, where it writes, or how much it logs. It looks like out of the box it is set to always log everything to files whenever the logger is called to write a record.
It seems like there should be some kind of allowance for managing different loggers in Magento, and each logger have it's own set of handlers and processors. I wouldn't want my custom handlers trying to process or filter out logging events throughout the rest of Magento, or even some other custom 3rd party module. Monolog has the ability to identify different loggers by the logger's name which is also referred to as a channel. Symfony appears to use channels to organize multiple loggers and provide a relationship to the part of the application being logged. The separate loggers can share the same handler that writes to a file, but each logger has the option to specify their own file path. Some loggers may write to the same file, but other could write to a separate file. Organizing and managing multiple loggers would allow a lot more flexibility in Magento so that as a module developer I could add my own logger to some manager and specify a few things in my custom logger to have it control if, when, and what it should be logging, and where.
Instead of having separate handlers for writing System, Debug, Exception logs, you could have separate loggers each with their own channel/name for System, Debug, and Exception logs. Each logger could manage what handlers it uses to write the log files, and pass into each handler details like where it is supposed to write. If you wanted to aggregate logs centrally, you can just add an additional handler to each logger that will write/forward log records to the aggregator. Treating a handler more like a generic type of how things are getting written would probably be more flexible than having separate handlers for each file getting logged. Monolog is expecting to iterate through all handlers in the logger's list until a handler specifies that it shouldn't bubble the record onto the next handler in the list.
I'm still struggling with wrapping my head around how to deal with adhering to the simplicity and common implementation of PSR-3 and having a bit more control organizing logs together in related groups (channel) so that each group can have additional control or processing based on the group. If Magento was managing multiple loggers for us, how would we specify which logger gets instantiated and passed into a class as an implementation of Psr\Log\LoggerInterface or should something else be passed in that gives us the ability to specify which logger/channel we want, and that object delivers us the Psr\Log\LoggerInterface implementation that we log against? Is it important that we inject Psr\Log\LoggerInterface into our class for PSR-3, or is it merely important that any log activity be against an implementation of Psr\Log\LoggerInterface allowing for the use of multiple implementations of Psr\Log\LoggerInterface to manage the organization and grouping of various log activity?