A 'message' key in the extra log data overwrites the actual message
Closed, ResolvedPublic

Description

When a log event is recorded via Monolog and the structured data contains a message key, Logstash will show the value of that key instead of the actual message. (A number of other fields are also affected, e.g. type, channel.)

Example (compare message and normalized_message).

This is not exactly unexpected behavior (Logstash just merges the structured data array with the rest of the metadata) but still seems weird and might result in information loss (IIRC the normalized message is cut off at some limit while the original message can be longer). Maybe we should use _message instead?

Tgr created this task.Sep 8 2016, 8:51 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 8 2016, 8:51 PM
bd808 added a subscriber: bd808.

I don't think this a Logstash or Monolog problem. It looks to me more like an application level metadata problem. The trivial fix would be for AuthManager::autoCreateUser to use msg instead of message as the PSR3 replacement parameter.

Tgr added a comment.Sep 26 2016, 11:37 PM

The trivial fix would be for AuthManager::autoCreateUser to use msg instead of message as the PSR3 replacement parameter.

Given how easy that is to do, you are certainly right. I don't see how it is an application-level problem though. The application interface is LoggerInterface::error( $message, array $context ). There is no reason to suspect that $context['message'] will magically override $message.

There is no reason to suspect that $context['message'] will magically override $message.

This collision happens because of how we have configured Monolog's Logstash formatter. Specifically it's due to the use of '' as the prefix for context data. message is always a magic key in the JSON structure Logstash uses to record log events in Elasticsearch.

Change 313638 had a related patch set uploaded (by Gergő Tisza):
Avoid 'message' in log context in AuthManager

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

Anomie added a subscriber: Anomie.Oct 3 2016, 3:33 PM

Can we have Monolog throw an exception in this situation?

bd808 added a comment.Oct 3 2016, 3:50 PM

Can we have Monolog throw an exception in this situation?

I think an exception would be a bit harsh, but we could fire a PHP warning I suppose. The downside of that would be that we would have to add processing of the context keys for all PSR-3 log messages somehow. Since the PSR-3 provider is pluggable, we couldn't do that consistently for all providers. We could do it for the LegacyLogger implementation in MediaWiki core and provide a Monolog filter that could be optional added via configuration to make the same check.

Change 313932 had a related patch set uploaded (by Gergő Tisza):
Warn when a log context accidentally overrides 'message'

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

Change 313638 merged by jenkins-bot:
Avoid 'message' in log context in AuthManager

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

Change 313932 merged by jenkins-bot:
Warn when a log context accidentally overrides a log processor

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

Tgr closed this task as Resolved.Nov 22 2016, 4:01 AM
Tgr removed a project: Patch-For-Review.
Tgr claimed this task.
Tgr reopened this task as Open.Nov 23 2016, 1:00 AM

Gives a bajillion warnings because apparently we overwrite these keys all the time.

Change 323099 had a related patch set uploaded (by Gergő Tisza):
Revert "Warn when a log context accidentally overrides a log processor"

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

Change 323492 had a related patch set uploaded (by Gergő Tisza):
Use custom LogstashFormatter

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

Tgr updated the task description. (Show Details)Nov 26 2016, 12:55 AM

Change 323638 had a related patch set uploaded (by Gergő Tisza):
Rename 'type' field of authevents channel to 'eventType'

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

Change 323639 had a related patch set uploaded (by Gergő Tisza):
Rename 'type' field of authevents channel to 'eventType'

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

Change 323640 had a related patch set uploaded (by Gergő Tisza):
Rename 'type' field of authevents channel to 'eventType'

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

Change 323638 merged by jenkins-bot:
Rename 'type' field of authevents channel to 'eventType'

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

Change 323640 merged by jenkins-bot:
Rename 'type' field of authevents channel to 'eventType'

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

Change 323639 merged by jenkins-bot:
Rename 'type' field of authevents channel to 'eventType'

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

Change 324339 had a related patch set uploaded (by Chad):
Rewrite logstash key conflict warning from I6677dbf6

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

Change 323099 merged by jenkins-bot:
Rewrite logstash key conflict warning from I6677dbf6

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

Change 324339 merged by jenkins-bot:
Rewrite logstash key conflict warning from I6677dbf6

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

demon closed this task as Resolved.Nov 29 2016, 11:00 PM

Change 323492 merged by jenkins-bot:
[operations/mediawiki-config] Use custom LogstashFormatter

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

Mentioned in SAL (#wikimedia-operations) [2017-03-15T18:19:17Z] <legoktm@tin> Synchronized wmf-config/logging.php: Use custom LogstashFormatter - T145133, T151290 (duration: 00m 42s)