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

Details

Related Gerrit Patches:
mediawiki/extensions/PageViewInfo : masterDon't use reserved word url in logging
mediawiki/extensions/ConfirmEdit : masterDon't use logging reserved word 'ip' as parameter
mediawiki/core : masterrdbms: Avoid using reserved word "host" in Monolog context keys
mediawiki/extensions/ConfirmEdit : wmf/1.35.0-wmf.20Don't use logging reserved word 'ip' as parameter
mediawiki/extensions/ConfirmEdit : wmf/1.35.0-wmf.21Don't use logging reserved word 'ip' as parameter
mediawiki/core : masterDon't use 'message' as a logging key
operations/mediawiki-config : masterDon't use 'ip' as a logging parameter
mediawiki/core : masterDon't pass 'ip' through to logging
mediawiki/core : masterDon't use 'host' as a log parameter
mediawiki/core : masterDon't pass 'ip' through to logging
mediawiki/extensions/LoginNotify : masterDon't use 'type' as a log parameter as it is a reserved word

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 14 2020, 4:25 PM

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

Restricted Application added a project: Community-Tech. · View Herald TranscriptFeb 14 2020, 5:46 PM

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)

Reedy added a subscriber: Reedy.Feb 14 2020, 8:26 PM

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

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

Krinkle added a subscriber: Krinkle.EditedFeb 15 2020, 3:47 AM

@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...

Reedy added a comment.Feb 15 2020, 5:04 AM

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

Reedy added a comment.Feb 27 2020, 3:14 PM

^ 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)

Reedy added a comment.Feb 27 2020, 3:38 PM

Back on track again

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

Reedy added a comment.Wed, Mar 4, 11:32 PM

T245303: CirrusSearch logging logs with reserved parameter message is probably fixed now. Backported to .22... So after tomorrows train, the https://logstash.wikimedia.org/goto/52ffc2e6294ec93b6f7e73ecabab5117 log should go to zero... :)

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

Tgr added a subscriber: Tgr.Fri, Mar 6, 10:02 PM

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

Tgr added a comment.Fri, Mar 6, 10:05 PM

(Thanks for cleaning these up by the way!)

Reedy added a comment.Fri, Mar 6, 10:26 PM

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 closed this task as Resolved.Tue, Mar 24, 9:02 PM
Krinkle assigned this task to Reedy.