di.xml argument type="array" and Monolog Handlers

[mttjohnson]

I ran into an issue with a 3rd party package (Monolog) that is expecting a numerical array (list) of handlers, but the way they are specified in the di.xml for injecting into the constructor, ObjectManager ends up passing in an array with named keys.

app/etc/di.xml

    <type name="Magento\Framework\Logger\Monolog">
        <arguments>
            <argument name="name" xsi:type="string">main</argument>
            <argument name="handlers"  xsi:type="array">
                <item name="system" xsi:type="object">Magento\Framework\Logger\Handler\System</item>
                <item name="debug" xsi:type="object">Magento\Framework\Logger\Handler\Debug</item>
            </argument>
        </arguments>
    </type>

\Monolog\Logger::addRecord()

        while (isset($this->handlers[$handlerKey]) &&
            false === $this->handlers[$handlerKey]->handle($record)) {
            $handlerKey++;
        }

Basically the way this is currently behaving is that the array of handlers being passed into Monolog from Magento ends up processing the first handler that it found that isHandling() was true for, and fails to process any other handlers after that handler. It takes the key (system) from the handler in $this->handlers and tries to increment ($handlerKey++) the key (systen) to get the next handler in the list, but that fails.

A potential workaround without modifying the Monolog code would be to use a sequential list of numbers on the item names in the di.xml file.

    <type name="Magento\Framework\Logger\Monolog">
        <arguments>
            <argument name="name" xsi:type="string">main</argument>
            <argument name="handlers"  xsi:type="array">
                <item name="0" xsi:type="object">Magento\Framework\Logger\Handler\System</item>
                <item name="1" xsi:type="object">Magento\Framework\Logger\Handler\Debug</item>
            </argument>
        </arguments>
    </type>

Granted this example seems pointless, but if I'm adding my own custom logger, and multiple handlers it seems to be difficult to specify it the same way as Magento has implemented in the core using di.xml to inject the parameters.

This doesn't seem like a real great solution and doesn't provide a way for additional handlers to be cleanly added to the array. If one extension tried adding a handler item with a name of "2" and some other extension also tried adding their own handler item with a name of "2" that wouldn't work too well.

I'm not seeing any current way that I can specify the list of items for an argument that will just add an item to the array without a named element. If that was an option, it would provide a better workaround for this issue.

Ultimately I would have to blame the poor behavior and limitation on Monolog in how the handlers array is iterated over, and not allowing for the fact that PHP does not distinguish between indexed and associative arrays.

[mttjohnson]

Correcting this in Monolog will end up causing a lot of duplicate logging to go to debug.log. There are multiple handlers for every log event, and each handler allows bubbling, the first handler (typically system.log as it is first in the array) and then it will move to the next handler and both will end up writing the same message to their log files.

The system handler will write entries for info log level messages and higher, and the debug handler will write for any messages with the debug log level and higher.

I haven't tested this but from reading the code I would expect any exceptions to also be duplicated in the debug log because although the system handler checks for exceptions in the contexts array and forwards the records to a different handler in the write() method, the debug handler does not check for this or forward the records anywhere else.

[victorgugo]

This looks fixed in https://github.com/Seldaek/monolog/pull/692 Closed

[mttjohnson]

Correcting this in Monolog will end up causing a lot of duplicate logging to go to debug.log. There are multiple handlers for every log event, and each handler allows bubbling, the first handler (typically system.log as it is first in the array) and then it will move to the next handler and both will end up writing the same message to their log files.

The system handler will write entries for info log level messages and higher, and the debug handler will write for any messages with the debug log level and higher.

Yes it's fixed in Monolog in the dev branch (1.17.2 is the latest release on packagist at the moment and doesn't include the fix).

Furthermore nothing has been discussed about how to account for this getting patched in Monolog because it will affect how Magento does logging once the patched version is included with Magento.

[erikhansen]

@victorgugo Monolog 1.19.0 now includes the Seldaek/monolog#692 fix you mentioned above. Can you re-open this task and create an internal MAGE task to upgrade monolog/monolog to 1.19.0?

This is important so that third-party extensions like the ClassyLlama_AvaTax extension can use named handlers. To workaround this issue in Magento/Monolog, we built the ClassyLlama_AvaTax extension to use "0" and "1" as the handler names. This recently caused an issue and someone submitted a pull request to the ClassyLlama_Avatax repository to change this, however this pull request can't be merged until Magento is updated to use the latest version of Monolog: https://github.com/classyllama/ClassyLlama_AvaTax/pull/12/files

[mttjohnson]

It looks like the specific bug I ran into with the Monolog library was corrected in 1.18.0 release.

This issue should be reopened and actually discussed and addressed. The current develop branch of Magento 2 is targeting Monolog 1.16.0.

[shiftedreality]

Hi @mttjohnson

We've created internal ticket MAGETWO-53419 for this issue. Thank you for your attention on it.

[buskamuza]

Currently, Magento uses Monolog 1.22.0 (see https://github.com/magento/magento2/blob/develop/composer.lock#L683). @mttjohnson , does it solve your issue?

[mttjohnson]

@buskamuza, As I pointed out in my comment on Nov 26, 2015 and again on Jan 13, 2016, just including the patched version of Monolog isn't the full solution here, as the correction to monolog will present behavioral changes in how Magento logs data.

The commit for adjusting the Monolog version is one step and corresponding changes to Magento's use of Monolog also need to be made.

The last time I evaluated the Magento\Framework\Logger code in how Magento is setup to utilize monolog, my expectations were that introducing the correction for Monolog would cause duplicate logging of log records cluttering log files with additional noise and space. It doesn't look like the code in that namespace has changed any since.

To retain the previous behavior and control which record levels get logged by their respective handlers it may just require an additional isHandling() method on the handlers Magento has implemented (Magento\Framework\Logger\Handler\System, and Magento\Framework\Logger\Handler\Debug) that check to see if that handler is handling that record (returning true of false in the evaluation), and use this as a filtering mechanism to control which handler is writing records for the respective log levels.

I have an example of this type of filtering in a handler (ClassyLlama\AvaTax\Model\Logger\FileHandler) I wrote that extends the system handler (Magento\Framework\Logger\Handler\System). In this example I added additional checks beyond just evaluating the log level, I also added the ability to turn off logging entirely. This may be something worth evaluating as a configuration option controlled in the admin for the core Magento logs. Having the ability to configure the application to turn off logging to disk would allow for the ability of an extension to include an additional Monolog handler in the handlers array for the arguments passed to Magento\Framework\Logger\Monolog that could respond to logs in a different fashion like shipping them to a log aggregator and have the ability to eliminate the application log files on individual web servers.

[mttjohnson]

Referencing recent commits related to the inclusion of newer versions of Monolog: 9ca160f56c4f3cde51267251f57f30a1c4da03aa 5582d1dfbfae3ad321d94af178d65306cf9cd041

It may also be useful to reference other related changes that should get additional attention now that a newer version of Monolog is included: bcfef6d1b3d60d3120725b873a20d0cbd231d29d ca6282da981108e58e6d155685c55b7a88f440ae These commits are in the develop branch but not the latest stable tagged release. It looks like the new constructor added there as a workaround should be eliminated now that a newer version of Monolog is included. Those commits referenced Issue #2234.

[buskamuza]

Thanks, @mttjohnson . Indeed, logging behavior leads to records duplicate in some cases. What do you think about single log file? Each record has its log level, so the file can be filtered if only specific levels are necessary.

[mttjohnson]

There is currently a lot of data that gets logged in debug.log, exception.log, and system.log (support_report.log also on EE builds).

If everything was in a single file, although it makes more sense from a logging standpoint for consuming everything from a single source, it may have the inadvertent affect of becoming less usable as filtering through all the noise in a single log file would become much more critical in order to get some useful piece of information out of the log. I think the implications of how duplicate log messages is resolved deserves a thorough exploration of how the system handles logging as a whole.

The log files have this tendency to grow excessively due to all the data that ends up getting captured in them, and it doesn't seem to be a common practice to manage and rotate logs on a lot of servers further amplifying some of the issues with the usefulness of the logs. I am glad to at least see the mention of logrotate in devdocs though: http://devdocs.magento.com/guides/v2.0/install-gde/install/post-install-config.html#log-rotation

As a side note, though related, I found it odd that system.log was not showing up on several newer production sites that I just checked... and it turns out on EE builds they introduced a new handler for support_report.log (vendor/magento/module-support/etc/di.xml) and because of the bug in Monolog 1.16 that has been discussed above, the addition of the report handler caused no records to ever bubble to the next handler (system), causing support_report.log to capture all logging on EE builds that you'd normally see in system.log on CE builds. This would mean that the correction to monolog and duplicate logging would be even more of an issue with the additional handler on EE the way it is currently altered by the magento/module-support module, and that module should also consider adjustments in light of an updated monolog version.

[buskamuza]

Thanks, @mttjohnson . Yes, I agree that we should revisit the way how the messages are logged. We'll work on a strategy for that. And yes... support_report.log should be revisited as well. With the new version on monolog it just duplicates system.log, as I can see.

[magento-engcom-team]

@mttjohnson, thank you for your report. The issue is already fixed in 2.2.0

[erfanimani]

Indexing the items in the array as 0, and 1 is a nice workaround in developer mode (in Magento 2.1.), it fails on production though: https://github.com/magento/magento2/issues/8803