Magento 2 has adopted the standard PSR-3 (Logging), but is it enough? This post explores some simple possible extensions to the Magento 2 logging system to increase its utility. Community feedback welcome!

Uses for Logging

Logging has traditionally not been used much in Magento. Sure, there is the PHP error log, and some extensions have done their own thing for logging, but there is nothing in the framework that compares to what is common in say Enterprise Java applications.

The reason for this difference may be driven from the fact that Magento is a single monolithic code base. Tracing through the code with a debugging is not that difficult to do in Magento. Enterprise systems often comprise a range of different applications running in server mode (no UI), making debugging by tracing through the code harder. So I can understand why Magento traditionally has not had extensive logging support, but that does not mean there are not advantages to lifting the game here.

Here are a few example cases where logging can help:

• Extension developers trying to remote debug customer reported problems want to be able to give Merchants simple instructions on how to capture the behavior of the system. Having a simple, standard way to collect information about what the system is doing can help extension developers who do not have (and do not want!) access to the live system.
• New developers can use logging, as an alternative to tracing in a debugger, to understand the flow through various parts of the code. For example, which layout files got loaded to process a result, which modules were invoked as part of page assembly, how URL resolution processed the current request, which REST service got invoked and why, and so on. The log messages can be self-explanatory, compared to having to understand the code structure to trace what is going on effectively. Using logging can also be used in production without having to connect a debugger to the process – as long as you can turn debug flags on for a short period without restarting the web server.

In both cases, it is useful to have detailed logging information available, but it is even more useful to be able to selectively turn logging messages on and off. Turning on all debug output in a large system can quickly overwhelm the developer.

A final requirement I have for a good logging system is to make sure I can add avoid incurring significant additional processing overhead it debugging output is turned off. This is particularly important for code inside loops. For example, to generate useful debug output, additional (possibly expensive) function calls may be required. If logging has been turned off for that section of code, it is wasteful to compute the output and then just discard it. It is better to not generate the output in the first place.

Magento 2 Logging Today

Currently Magento 2 uses the Symfony “Monolog” implementation by default. Because Magento depends on PSR-3, other logging packages can be dropped in instead. While PSR-3 provides multiple level of logging output (through a series of functions such as warn(), info(), and critical()), it does not contain any support for switching logging on/off for specific areas of the code.

In contrast, logging libraries such as log4j in the Java community give each logger a name. The names typically use the fully qualified class name (the package name and class name, equivalent to namespace and class name in PHP). This makes it easy to guarantee there will not be collisions between logger names when multiple independently developed libraries of code are merged into the one application. Each logger can then be separately set to a specific log level. (For example, you can turn debug logging on for selected classes, not everything at once.) (A negative is you end up creating lots of logger instances, one per class that wants to do logging, as each logger holds the class name of the class using the logger.)

This is different to the concept of “Channels” in Monolog. Channels are useful, but do not allow you to switch on and off debugging output in different areas of the code. Rather it lets you write debug messages to a separate file to errors. This is useful, but not a replacement to debugging switches.

Implementation Strategy

For me, learning from the Java community, the best approach is to have named switches, most likely with a name per class where that name matches the namespace and class name of the PHP code. Allowing regular expressions in the switch names (so can switch on debugging for all of Magento\Customer or Vendor\ExtensionName with a single option) is useful (like Magento\Customer\*).

Further, there should be a way for code to ask if the debugging output is going to be saved or discarded. If discarded, then the caller may avoid generating the output and save some processing cycles.

if (debugEnabled($this->logger)) {
    // Do expensive code to generate output to be logged
    $this->logger->debug($output);
}

If just logging strings, you typically don’t do this extra check as the code starts getting messy and the extra call to check if debugging is enabled may be greater overhead than the saving achieved.

$this->logger->debug("URL $url matches!");

Ok, time for readers to engage their brains and expressing their opinions! Here are a few strategies to consider. Which seems best to you? Do you have a better idea?

Strategy 1: PSR-3 and Dependency Injection

In this approach, there are zero changes to the current code that uses a logger. As the dependency injection framework creates most objects in Magento 2, add support for logging switches into the dependency injection framework.

That is, whenever the dependency injection framework detects that the constructor of the class it is instantiating requires a PSR-3 logger instance (Psr\Log\LoggerInterface), then it checks for debug flags using the fully qualified class name. The result determines which of two loggers is passed to the class: one logger is configured to discard debug output, the other logger instance is configured to capture debug output. The extension does not need to know this happens – it just calls whatever logger is provided.

As above, for performance reasons, I would go one step further than this. I would also add some form of debugEnabled($logger) function to allow extensions to detect if debug output will be discarded or not. This function would say check which logger instance was provided, so needs to work in conjunction with the dependency injection framework.

Strategy 2: Invent a New Logging API

Another strategy is to not have modules use PSR-3 logging directly. Instead, create a new Magento “debug logging” class/interface. This class would check for debugging flags and send output to the PSR-3 logger instance. It can also provide a debugEnabled() function. This is closer to way logging frequently works in Java.

The slight challenge here is the class or debug functions would need to somehow obtain the fully qualified class name of the current code, in order to know whether to turn the debugging on or off for that class.

Strategy 3: Plugins

Another possible approach would be to use plugins instead of having debugging code embedded directly in the code base. Turning on debugging involves turning on plugins. They can intercept function calls, but only exist if debugging was enabled.

This has the benefit of zero overhead if debugging is turned off. A negative however is that plugins can only be associated with function calls. They cannot be used inside a loop (unless the code is restructured to call a function inside the loop). They also don’t have access to local variables.

Your Voice

What do you think? This work is currently not planned, but would you use it?

My opinion? I lean towards the first approach. It means anyone can develop code immediately using the PSR-3 debug() function, and later without their code changing there will be the ability to turn off/off debugging output. I dislike the need for an additional function to check if debug output should be generated, but it is important enough to include. (That function could be a separate interface passed to the constructor, but only if the class wants to check the flag.)

What do you think? What additional requirements do you have? For example, do you want an Admin interface to turn flags on/off, with a “text area” for dropping in the debug configuration settings to use? This would allow an extension developer to supply the flags for a Merchant to copy/paste. Or would you rather have a web UI to interactively turn on/off flags? Do you want the Admin interface to be able to capture the debug output, again to make it easier to collect details to send to the extension developer.

I look forward to any ideas here. If a clear winner emerges, volunteers to knock up this code are also welcome!