Page MenuHomePhabricator

Add global information to debug logger context
Closed, ResolvedPublic

Description

Certain kinds of information would be useful to have alongside each log message (e.g. in Logstash), but are not possible or inconvenient to add manually to a message. For information that is available from a log processor, we currently use a Monolog Processor plug-in to automatically it (e.g. URL, PHP version, server/host, etc.). But, this is not always possible.

For example, adding the canonical name of the current special page or the job name would be handy, but that's controller-level information and the log processing code has no access to the "current" controller (and if it is logging an uncaught exception, the controller might be in some unexpected state).

Proposal

Create a globally available static location, where application code may write into at runtime to stash "current" information for a log processor to pick up. (log4j calls this a diagnostic context.)

20:28 < bd808> One feature that monolog is missing that I loved from log4j is a global diagnostic context. That's basically a thread local dict that any code can grab and stick key=value data into that then ends up in all log events
...
20:31 < bd808> at $DAYJOB-1 we tagged logs with lots of things as we found out about them in the app stack. customer id, databases used, services called, etc
...
20:37 < bd808> and we could expose it via LoggerFactory
20:39 < bd808> log4j (and some academic papers I can't find right now) call this thing a "diagnostic context" -- https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/MDC.html
20:41 < bd808> http://c2.com/cgi/wiki?PatternsForLoggingDiagnosticMessages

Event Timeline

bd808 triaged this task as Medium priority.Aug 8 2016, 3:19 PM

Implementation ideas can be cribbed from a logging project I wrote quite a while ago but never used much: https://github.com/bd808/moar-log/blob/master/src/Moar/Log/MDC.php

Basically we'd want to have:

  • An easy way to add a context variable
  • An easy way to get all current context variables
  • A Monolog handler to merge the global context into a log event
  • Docs on all of that

The entry points could be either static methods on LoggerFactory or another service object that is easy to get from MediaWiki code. Classes using the context would be tied to the MediaWiki implementation because there isn't anything like this in the PSR3 logging standard. That shouldn't be a horrible thing because the interesting data to decorate the logs is typically found in routing context code (which SpecialPage is being invoked, etc).

This proposal is selected for the Developer-Wishlist voting round and will be added to a MediaWiki page very soon. To the subscribers, or proposer of this task: please help modify the task description: add a brief summary (10-12 lines) of the problem that this proposal raises, topics discussed in the comments, and a proposed solution (if there is any yet). Remember to add a header with a title "Description," to your content. Please do so before February 5th, 12:00 pm UTC.

Krinkle renamed this task from Add global logging context to Add global information to debug logger context.Mar 19 2024, 6:10 PM
Krinkle updated the task description. (Show Details)

This is already possible and we're kinda already doing it by injecting custom Monolog Processors - for example we add WikiProcessor (https://gerrit.wikimedia.org/g/operations/mediawiki-config/+/e976dcf9860096df1c81a891947d886fe49f7eec/wmf-config/logging.php#117)

The WikiProcessor injects things like host, wiki, mwversion or reqId and cli_argv.

I wouldn't touch the WikiProcessor, probably better to keep it small and simple.

But we could provide some DiagnosticContextProcessor, that would work as a registry. Other processes could do DiagnosticContextProcessor::register( $key, $value ).
Then, based on configs - this processor could be injected in our config. Most likely it would be best to inject it on beta, debug and groups 0 and 1.

I found a monolog implementation of this idea - https://packagist.org/packages/stevenrombauts/monolog-mdc - but most likely it would be better to have something built into our ServiceWiring.

I wouldn't touch the WikiProcessor, probably better to keep it small and simple.

Agreed, each processor would have a single purpose ideally.

Then, based on configs - this processor could be injected in our config. Most likely it would be best to inject it on beta, debug and groups 0 and 1.

Probably the way to go is to add the class to core then apply it in $wmgMonologProcessors in mediawiki-config - core isn't responsible currently for configuring Monolog (T155552 - not ideal but that's how it is). I don't think there's a reason not to use it on group 2, the impact should be negligible both in terms of risk and performance.

I found a monolog implementation of this idea - https://packagist.org/packages/stevenrombauts/monolog-mdc - but most likely it would be better to have something built into our ServiceWiring.

Nice to see this is a standard pattern, but yeah it's about twenty lines of code, at that size it's much simpler to roll our own.

I'm tagging observability as they could be interested in this topic. I would like to look into it, and I'll push some POC soon.

We should get this done, it would make e.g. OAuth issues much less annoying to debug.

Change #1135060 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):

[mediawiki/core@master] [WIP] debug: Allow adding context to all logs via LoggerFactory

https://gerrit.wikimedia.org/r/1135060

Change #1136116 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):

[mediawiki/vagrant@master] psr3: Add ContextProcessor

https://gerrit.wikimedia.org/r/1136116

Change #1136132 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):

[operations/mediawiki-config@master] logging: Add context processor

https://gerrit.wikimedia.org/r/1136132

Change #1135060 merged by jenkins-bot:

[mediawiki/core@master] debug: Allow adding extra context to all logs via LoggerFactory

https://gerrit.wikimedia.org/r/1135060

Change #1136116 merged by jenkins-bot:

[mediawiki/vagrant@master] psr3: Add ContextProcessor

https://gerrit.wikimedia.org/r/1136116

Change #1136132 merged by jenkins-bot:

[operations/mediawiki-config@master] logging: Add context processor

https://gerrit.wikimedia.org/r/1136132

Mentioned in SAL (#wikimedia-operations) [2025-05-06T13:59:42Z] <tgr@deploy1003> Started scap sync-world: Backport for [[gerrit:1136132|logging: Add context processor (T142313)]]

Mentioned in SAL (#wikimedia-operations) [2025-05-06T14:06:17Z] <tgr@deploy1003> tgr: Backport for [[gerrit:1136132|logging: Add context processor (T142313)]] synced to the testservers (https://wikitech.wikimedia.org/wiki/Mwdebug)

Mentioned in SAL (#wikimedia-operations) [2025-05-06T14:20:20Z] <tgr@deploy1003> Finished scap sync-world: Backport for [[gerrit:1136132|logging: Add context processor (T142313)]] (duration: 20m 37s)

With @Tgr's patch, you can now add global information to debug logger context using:

LoggerFactory::getContext()->add(<array>)

or (within the lifetime of a scope variable):

$scope = LoggerFactory::getContext()->addScoped(<array>)