Page MenuHomePhabricator

Mediawiki logging indexing conflict on 'status' for 'authevents'
Closed, ResolvedPublic

Description

This indexing error is popping up in logstash events, apparently due to authevents channel logging status as two different types:

"reason"=>"object mapping for [status] tried to parse field [status] as object, but found a concrete value"}

And indeed inspecting logs on mwlog for authevents channel, some logs are in the form of

2020-12-08 13:59:34 [X8@GxgpAMNMAAi4S4CIAAAEG] mw1369 enwiki 1.36.0-wmf.20 authevents INFO: Login attempt {"event":"login","successful":false,"status":"login-throttled"}

While others

2020-12-08 13:59:35 [X8@GwwpAIIEAAPBa9lcAAAAF] mw1299 loginwiki 1.36.0-wmf.20 authevents INFO: Autocreation attempt {"event":"autocreate","status":{"Status":"<OK, no errors detected, no value set>"}}

Ditto for cases like these:

2020-12-08 14:06:38 [X8@IbQpAEKAAAqgnReEAAABM] mw1399 enwiki 1.36.0-wmf.20 authevents INFO: Account creation attempt {"event":"accountcreation","successful":false,"status":"* $1
* $2"}

Event Timeline

This is still happening, meaning some events/logs from authevents channel (and possibly others) are not being indexed in logstash (cc @Reedy )

Change 658443 had a related patch set uploaded (by Cwhite; owner: Cwhite):
[mediawiki/core@master] update authevents logging status context to use string representation directly

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

Change 658698 had a related patch set uploaded (by Cwhite; owner: Cwhite):
[mediawiki/core@master] Add LogstashFormatter pre-formatter step to respect string representations

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

Change 658698 abandoned by Cwhite:
[mediawiki/core@master] Add LogstashFormatter pre-formatter step to respect string representations

Reason:
in favor of the approach applied in If92d60289fa925d19261ef912e2f2a5d31db31dc, I7a213417c6ce9741f190beb4bf626059a97a2f4f, Ia7875346cec95fbc30bc4579ec8b7fb60e911d12, and I8d442a7bc066bc0f2a1b69ceb1a5e1a863102685

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

The extent of this issue is now available to view in logstash.

lmata added a subscriber: AMooney.

Greetings @AMooney, this patch is one of the two I was hoping to bring to your attention for next clinic duty... This one is for some changes around logging and trying out the new clinic workflow regarding the "happy path" for these types of patches. Please let me know if/how to proceed. thanks!

Change 672809 had a related patch set uploaded (by Reedy; owner: Cwhite):
[mediawiki/core@REL1_35] update authevents logging status context to use string representation directly

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

Change 658443 merged by jenkins-bot:
[mediawiki/core@master] update authevents logging status context to use string representation directly

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

Change 672809 merged by jenkins-bot:
[mediawiki/core@REL1_35] update authevents logging status context to use string representation directly

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

Reedy assigned this task to colewhite.
Reedy triaged this task as Medium priority.

We didn't get them all on the first round.

Change 673544 had a related patch set uploaded (by Cwhite; owner: Cwhite):
[mediawiki/core@master] use string representation of Status object when logging

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

@lmata, This needs PET code review correct?

Change 681154 had a related patch set uploaded (by Reedy; author: Cwhite):

[mediawiki/core@REL1_36] authevents: strval() variables passed to status when logging

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

Change 681155 had a related patch set uploaded (by Reedy; author: Cwhite):

[mediawiki/core@REL1_35] authevents: strval() variables passed to status when logging

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

Change 673544 merged by jenkins-bot:

[mediawiki/core@master] authevents: strval() variables passed to status when logging

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

Change 681155 merged by jenkins-bot:

[mediawiki/core@REL1_35] authevents: strval() variables passed to status when logging

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

Change 681154 merged by jenkins-bot:

[mediawiki/core@REL1_36] authevents: strval() variables passed to status when logging

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

Change 689956 had a related patch set uploaded (by Cwhite; author: Cwhite):

[mediawiki/extensions/CentralAuth@master] CentralAuthUtilityService: strval() status object

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

This issue caused indexing failures to increase from ~10/m to ~100/m on Aug 31st. It appears the an object-typed status field was the first encountered.

Change 689956 merged by jenkins-bot:

[mediawiki/extensions/CentralAuth@master] CentralAuthUtilityService: strval() status object

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

This issue caused indexing failures to increase from ~10/m to ~100/m on Aug 31st. It appears the an object-typed status field was the first encountered.

This issue occurred again today.

Confirmed, these errors are no more! \o/

Thanks all!