Page MenuHomePhabricator

logstash_formatter_key_conflict in mediawiki logs
Closed, ResolvedPublic

Description

Looks like mediawiki's logstash formatter sometimes emits logstash_formatter_key_conflict field, specifically popular entries are for ip fields (i.e. goodpass/badpass channels) or type for LoginNotify channel. See also https://logstash.wikimedia.org/goto/52ffc2e6294ec93b6f7e73ecabab5117

Event Timeline

Change 572287 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Don't pass 'ip' through to logging

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

Change 572289 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/extensions/LoginNotify@master] Don't use 'type' as a log parameter as it is a reserved word

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

Change 572290 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Don't pass 'ip' through to logging

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

Change 572291 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Don't use 'host' as a log parameter

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

Change 572289 merged by jenkins-bot:
[mediawiki/extensions/LoginNotify@master] Don't use 'type' as a log parameter as it is a reserved word

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

Change 572300 had a related patch set uploaded (by Reedy; owner: Reedy):
[operations/mediawiki-config@master] Don't use 'ip' as a logging parameter

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

Change 572287 merged by jenkins-bot:
[mediawiki/core@master] Don't pass 'ip' through to logging

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

Change 572291 merged by jenkins-bot:
[mediawiki/core@master] Don't use 'host' as a log parameter

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

Change 572290 merged by jenkins-bot:
[mediawiki/core@master] Don't pass 'ip' through to logging

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

Change 572300 merged by jenkins-bot:
[operations/mediawiki-config@master] Don't use 'ip' as a logging parameter

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

Mentioned in SAL (#wikimedia-operations) [2020-02-14T20:21:56Z] <reedy@deploy1001> Synchronized wmf-config/CommonSettings.php: Prevent some logspam T245280 (duration: 01m 05s)

Mentioned in SAL (#wikimedia-operations) [2020-02-14T20:21:56Z] <reedy@deploy1001> Synchronized wmf-config/CommonSettings.php: Prevent some logspam T245280 (duration: 01m 05s)

Screenshot 2020-02-14 at 13.25.32.png (388×1 px, 57 KB)

Wheee

Change 572324 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Don't use 'message' as a logging key

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

Reedy triaged this task as Medium priority.Feb 14 2020, 8:53 PM

This should be in a much better place now (the mediawiki-config patch fixed most).. I've fixed (or created a subtask) most of the ones showing in the logs, and a few others pre-emptively too

I don't see any point backporting MW core patches, so .20 should clear up most of the other ones

Also filed T245289 to pre-emptively prevent some of these in the future

Change 572324 merged by jenkins-bot:
[mediawiki/core@master] Don't use 'message' as a logging key

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

@Reedy Can you confirm that this is only for making Logstash and code use the same key and not to resolve a problem with the key conflict as the task originally described? I ask because ensuring such conflicts don't ocurr should imho be core's responsibility first, and was fixed there (allegedly) in the LogststashFormatter class which rewrites these automatically to avoid that conflict indeed.

It's still nice to rename them in the code as well for consistency between them, but if a problem came up again, that would be good to know so we can also figure out why the rewrite stopped working.

EDIT: I thought this was an old task, but it's from yesterday. I guess that rules that out...

It does rewrite them, but it leaves the errors behind too, to highlight the need to cleanup

This should be in a much better place now (the mediawiki-config patch fixed most).. I've fixed (or created a subtask) most of the ones showing in the logs, and a few others pre-emptively too

I don't see any point backporting MW core patches, so .20 should clear up most of the other ones

Also filed T245289 to pre-emptively prevent some of these in the future

Thanks @Reedy ! Indeed way less conflicts now (~50 per 5min)

Change 575257 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/extensions/ConfirmEdit@master] Don't use logging reserved word 'ip' as parameter

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

Change 575258 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/extensions/ConfirmEdit@wmf/1.35.0-wmf.21] Don't use logging reserved word 'ip' as parameter

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

Change 575259 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/extensions/ConfirmEdit@wmf/1.35.0-wmf.20] Don't use logging reserved word 'ip' as parameter

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

^ Heh, and {T210817} caused a regression here ;)

Change 575258 merged by jenkins-bot:
[mediawiki/extensions/ConfirmEdit@wmf/1.35.0-wmf.21] Don't use logging reserved word 'ip' as parameter

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

Change 575259 merged by jenkins-bot:
[mediawiki/extensions/ConfirmEdit@wmf/1.35.0-wmf.20] Don't use logging reserved word 'ip' as parameter

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

Mentioned in SAL (#wikimedia-operations) [2020-02-27T15:31:18Z] <reedy@deploy1001> Synchronized php-1.35.0-wmf.21/extensions/ConfirmEdit/includes/auth/CaptchaPreAuthenticationProvider.php: T245280 (duration: 01m 05s)

Mentioned in SAL (#wikimedia-operations) [2020-02-27T15:32:49Z] <reedy@deploy1001> Synchronized php-1.35.0-wmf.20/extensions/ConfirmEdit/includes/auth/CaptchaPreAuthenticationProvider.php: T245280 (duration: 01m 04s)

Change 575278 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/core@master] Stop using reserved word 'host' as logging parameter

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

Change 575278 merged by jenkins-bot:
[mediawiki/core@master] rdbms: Avoid using reserved word "host" in Monolog context keys

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

Change 575257 merged by jenkins-bot:
[mediawiki/extensions/ConfirmEdit@master] Don't use logging reserved word 'ip' as parameter

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

Screenshot 2020-03-05 at 18.47.40.png (414×1 px, 49 KB)

We seem to be down to zero since the .22 deploy (14:05 UTC today). Leaving the task open for a couple of days, but can be closed early next week if the log is still zero

Change 577357 had a related patch set uploaded (by Reedy; owner: Reedy):
[mediawiki/extensions/PageViewInfo@master] Don't use reserved word url in logging

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

ip is a bit annoying. In the other cases there are two genuinely different things logged. For IP, the processor and the context typically intend to provide the same data, except we don't do any XFF lookup in the processor for performance reasons, so that IP ends up being utterly useless. Maybe it would make more sense to just remove it?

Change 577357 merged by jenkins-bot:
[mediawiki/extensions/PageViewInfo@master] Don't use reserved word url in logging

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

(Thanks for cleaning these up by the way!)

ip is a bit annoying. In the other cases there are two genuinely different things logged. For IP, the processor and the context typically intend to provide the same data, except we don't do any XFF lookup in the processor for performance reasons, so that IP ends up being utterly useless. Maybe it would make more sense to just remove it?

I suspect same with any logging, if it (itself, or any parameters) doesn't add any value, we should remove it or alter it (removing parameters if they serve no value)

Krinkle assigned this task to Reedy.
Krinkle moved this task from Mar 2021 to Feb2020/1.35-wmf.18 on the Wikimedia-production-error board.