Page MenuHomePhabricator

Address MediaWiki\Auth\AuthManager::autoCreateUser Logstash PHP error
Closed, ResolvedPublic

Description

There's a recurring debug message sent to Logstash logs, starting in 1.41.0-wmf.26:

channel=authentication
level=INFO

MediaWiki\Auth\AuthManager::autoCreateUser: creating new user ({username}) - from: {from}

This message is seen ~4000 times.

From the following wikis:

Wiki#
zhwiki907
srwiki604
shwiki472
kkwiki385
banwiki371
uzwiki367
wuuwiki239
kuwiki204
tgwiki153
crhwiki146
ganwiki94
enwiki29
iuwiki25
shiwiki17
amwiki5
dewiki4
jawiki4
ruwiki3
arwiki2
eswiki2

Steps to Reproduce:

  • Go to Readers Web Dashboard and filter in the MediaWiki\Auth\AuthManager::autoCreateUser custom label. It's currently filtered out.

Expected Behavior:
User creation/authentication processes should function without issues.

Actual Behavior:
The message is frequently appearing in the logs.

Event Timeline

Restricted Application added subscribers: Stang, Aklapper. · View Herald Transcript

The error should not occur, and user creation/authentication processes should function without issues.

These events are logged into the INFO channel. They are not errors.

That being said, the events contain quite a bit of information - from a privacy perspective it'd be nice to reduce what we log here. cc @Tgr since I think this is related to T326281.

That being said, the events contain quite a bit of information

Not really? They just contain the username.

cc @Tgr since I think this is related to T326281.

I don't think so. It might have made autocreations marginally more frequent since it makes autologin less broken and autologin results in autocreation when the local user didn't exist, but other than that I see no relationship. These events have always been around and their frequency didn't change much:
https://logstash.wikimedia.org/goto/7ccb4bb683b7d6ae5cd41a47df1616dd

Screenshot Capture - 2023-09-25 - 07-05-40.png (420×1 px, 49 KB)

They are not new on the Reading Web dashboard either:
https://logstash.wikimedia.org/goto/f3b9a4cd4201e1e62ff20961649e5cfd
Screenshot Capture - 2023-09-25 - 07-12-42.png (190×2 px, 40 KB)

they start at wmf.23 but that's just and artifact of filtering to Web Team components (which matches pageimages in some api.php query string, so presumably that's when someone started to make cross-wiki pageimages API queries which sometimes autocreate the user).

The better question IMO is what is the point of including such messages in the Web Team dashboard at all? I think you'd want to filter it by some or all of

  • channel:exception OR channel:error OR channel:jsonTruncated (which is more or less the logstash definition of a MediaWiki error)
  • level being at least ERROR
  • using normalized_message instead of message for the (message:MinervaNeue OR message:Monobook OR message:MobileFrontend OR message:Popups OR message:Vector OR message:TextExtracts OR message:PageImages OR message:RelatedArticles OR message:QuickSurveys OR message:WikidataPageBanner) filter (as the message can include all kinds of random things, the URL in this case).
Krinkle subscribed.
channel=authentication
level=INFO

MediaWiki\Auth\AuthManager::autoCreateUser: creating new user ({username}) - from: {from}

In this case, this is a message in the "authentication" diagnostic channel. It is neither an "error"-level message, nor a message in the "error" channel.

@KSarabia-WMF I suspect something is broken on your team's Logstash dashboard. If not addressed, this will yield many more non-issues and tasks being reported, hence taking a moment to point it out.

I generally recommend that teams create their Logsash dashboard such that it dispays exceptions (typically reduced to keywords of interest based on the stack trace), and perhaps also include specific diagnostic channels owned by extensions your team maintains. When triaging, these would also typically be limited to WARNING and above, unless you're browsing the unfiltered "Logtash: mediawiki" dashboard to trace a specific request ID.

When an uncaught error or runtime PHP Warning ocurrs, these are automatically formatted as exceptions and sent to the "error" channel. Only these are considered production errors. When developers format custom messages into their own local diagnostic channels for debugging or monitoring, these are used when debugging other issues, they are not production errors. These are useful to review periodically from your own code to ensure it is working as expected, but usually not of interest to other teams.

For more information, review https://wikitech.wikimedia.org/wiki/OpenSearch_Dashboards and https://www.mediawiki.org/wiki/Manual:Structured_logging


The "creating new user" debug message is expected and normal during the account creation process.

It does not appear to have started or increased in the last 90 days:

Screenshot 2023-09-25 at 06.36.55.png (966×2 px, 261 KB)

We adjusted the dashboard to filter out more irrelevant warnings like INFO and NOTICE