cancel
Showing results for 
Search instead for 
Did you mean: 

Customizations and usability of logging in custom modules

Customizations and usability of logging in custom modules

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?

7 Comments
apiuser
New Member

Comment from alankent, posted on GitHub Dec 14, 2015

I wrote this a while back also if interesting reading: http://alankent.me/2015/08/01/request-for-feedback-on-improving-debug-logging-in-magento-2/

We were playing with a "LogSwitchManagerInterface" internally at one stage, but it did not make the cut list relative to other work yet. The idea was in the constructor you would do something like

$this->logger = $logSwitchManager->getLogger(get_class_name($this));

It returns NULL if the switch is off, or a PSR logger if on. Then in the code when you want to log, you do something like:

if ($this->logger != NULL) {
    $message = .... // Possibly expensive computation
    $this->logger->debug($message);
}

Then you control the LogSwitchManager via environment variables, in Admin UI, or similar.

The idea of using the current class name is to namespace debug flags - using the class name is an easy convention that Java uses.

Would this sort of thing be sufficient? (Making it easier to intercept / plug in different loggers was one interesting additional requirement that came up to weave in somehow. Another idea was to allow an extension developer to supply settings to a Merchant to help with remote debugging - "set this set of variables and send me the result".)

apiuser
New Member

Comment from mttjohnson, posted on GitHub Dec 18, 2015

I found an opportunity to read through some information about log4j last night and the concept of a logger for each class seems interesting. I'm not sure I grasp why it would be useful having a logger for each class though, it seems somewhat excessive. I expect for most things you wouldn't need the configurability to the level of having separately instantiated loggers for each class. If you were able to have a logger per module, and be able to configure the logger for each module, I image that would provide an extensive amount of options for being able to configure a module specific logger.

Are you thinking that we'd be able to somehow utilize the LogSwitcherManager to pass in our own custom loggers? Like if I wrote my own class Vendor\Module\Logger\Monolog in my module to extend Monolog\Logger, would that be possible? Then I could have custom logic in Vendor\Module\Logger\Monolog to check Magento configuration or other things to determine what to do with the logging, if I wanted to have my own processors, handlers, etc..

apiuser
New Member

Comment from mttjohnson, posted on GitHub Dec 18, 2015

In reading through you concept, you could avoid the if ($this->logger != NULL) by utilizing a Psr\Log\NullLogger that way $logSwitchManager->getLogger() could always return a valid logger, rather than checking for NULL.

Then you could have simple $this->logger-debug($message) calls without having to always check to see if the $this->logger was null or not.

// Simple logging that does not have expensive computation
$this->logger->debug($message);

// Check to see if the logger is not an instance of NullLogger
if (!($this->logger instanceof Psr\Log\NullLogger)) {
    $message = .... // Possibly expensive computation
    $this->logger->debug($message);
}

// Potentially abstract the logic to the log switch manager or something for more clearly readable implemented code
if ($this->logSwitchManager->isLogging($this->logger)) {
    $message = .... // Possibly expensive computation
    $this->logger->debug($message);
}
apiuser
New Member

Comment from mttjohnson, posted on GitHub Dec 18, 2015

Anyone have any ideas on this question?

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?

apiuser
New Member

Comment from alankent, posted on GitHub Dec 19, 2015

A logger per class can be excessive, but in the Java world my experience was (1) not every class did logging, so its really "one logger per class that wants to do logging" and (2) it was an easy way to guarantee namespacing of loggers, when you had no idea what libraries were going to be included. It is mainly used by developers, so using the namespace made it easy for developers to remember the names to turn logging on/off.

You could use a NullLogger instead, however I dislike hard coding in knowledge of a particular class every time you want to check if you should do logging on not - that is, I (mildly) dislike the "instanceof Psr\Log\NullLogger". But it is an alternative for sure. Note sending a string to a null logger means you still create the string (and any computation required to form it), then call the function that throws it away. So checking for NULL looks more ugly, but ends up in faster code and is simple to understand. Both approaches work.

For your last question, PSR does not say you should inject it, but Magento is using constructor injection and so does that for the logger as well. I prefer consistency.

apiuser
New Member

Comment from adragus-inviqa, posted on GitHub Dec 19, 2015

Yeah, having to do if (!($this->logger instanceof Psr\Log\NullLogger)) { defeats the purpose of having a NullObject. But it's as bad as checking for a null.

Instead, if NullLogger would return false on $this->logSwitchManager->isLogging($this->logger), you don't have to do any of the above.

$this->logger->debug($message);

if ($this->logSwitchManager->isLogging($this->logger)) { // is false on NullLogger
    $message = .... // Possibly expensive computation
    $this->logger->debug($message);
}

This way, no information about having a null logger or null value is leaked.

apiuser
New Member

Comment from SamTay, posted on GitHub Apr 29, 2016

For what it's worth, I developed a "base module" that includes easy to extend loggers that specify filenames. Basically, it consists of two classes, one logger and one handler, and the handler accepts a filename in the construct to set its own $this->fileName property. In this way, any module that needs its own logger can easily have one by defining two new virtual types. Here is the di.xml for reference, as this was fairly painless to set up if you need something in the meantime:

<config xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="urn:magento:framework:ObjectManager/etc/config.xsd">
    <type name="BlueAcorn\Core\Model\Logger\Handler\Base">
        <arguments>
            <argument name="filesystem" xsi:type="object">Magento\Framework\Filesystem\Driver\File</argument>
            <argument name="fileName" xsi:type="string">/var/log/ba.log</argument>
        </arguments>
    </type>
    <type name="BlueAcorn\Core\Model\Logger">
        <arguments>
            <argument name="name" xsi:type="string">BlueAcorn Logger</argument>
            <argument name="handlers"  xsi:type="array">
                <item name="base" xsi:type="object">BlueAcorn\Core\Model\Logger\Handler\Base</item>
            </argument>
        </arguments>
    </type>
    <!-- ********************** Example for external modules  **********************

    To create a custom logger for the content publisher module,
    the following would be added to that module's di.xml:

    <virtualType name="BlueAcornContentPublisherLogger" type="BlueAcorn\Core\Model\Logger">
        <arguments>
            <argument name="name" xsi:type="string">BlueAcorn Content Publisher Logger</argument>
            <argument name="handlers" xsi:type="array">
                <item name="base" xsi:type="object">BlueAcornContentSchedulerLoggerHandler</item>
            </argument>
        </arguments>
    </virtualType>
    <virtualType name="BlueAcornContentSchedulerLoggerHandler" type="BlueAcorn\Core\Model\Logger\Handler\Base">
        <arguments>
            <argument name="fileName" xsi:type="string">/var/log/ba_scheduler.log</argument>
        </arguments>
    </virtualType>
    <type name="BlueAcorn\ContentPublisher\Helper\Debug">
        <arguments>
            <argument name="logger" xsi:type="object">BlueAcornContentPublisherLogger</argument>
        </arguments>
    </type>

    The two 'virtualType' elements create the object that can log to an arbitrary file name
    (the one given in the handler virtualType argument). The last 'type' element injects the logger into whichever
    class needs it. This element will need to be duplicated for any class that explicitly uses the logger object. To
    avoid this, you can copy the pattern from the ContentPublisher, which is to have a single Helper\Debug class that
    encapsulates logging for the entire module.

    **************************************************************************** -->
</config>