Page MenuHomePhabricator

Registration timestamp not found for user ID {userId}
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error
normalized_message
GrowthExperiments\MentorDashboard\MenteeOverview\UncachedMenteeOverviewDataProvider::getFormattedDataForMentor: Registration timestamp not found for user ID {userId}
Impact
  • 86 errors every 3 hours on various wikis, starting wmf.8
Notes
  • This log statement was added in T355344 and got deployed with the wmf.8 train
Acceptance Criteria:
  • the problem is fixed (TODO: investigate, specify)
  • the filter for this task is removed from the Growth Logstash dasboard:

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald Transcript
Etonkovidova renamed this task from GrowthExperiments\MentorDashboard\MenteeOverview\UncachedMenteeOverviewDataProvider::getFormattedDataForMentor: Registration timestamp not found for user ID {userId} to Registration timestamp not found for user ID {userId}.Wed, Jun 5, 11:10 PM

Great! That's what we're looking for as the result of the changes made in T355344: GrowthExperiments: PHP Notice: Undefined index: XXXXXX.

Change #1047108 had a related patch set uploaded (by Michael Große; author: Michael Große):

[mediawiki/extensions/GrowthExperiments@master] Only log error if both registration and last_edit keys are not set

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

Urbanecm_WMF triaged this task as Medium priority.

Change #1047108 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@master] Only log error if both registration and last_edit keys are not set

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

Testing note: check when group 2 is deployed - https://logstash.wikimedia.org/goto/aed67635717e182a88afc0330e118d36

Yes, we expect there to be many fewer events and them to have a slightly different message: "Registration and last_edit timestamps not found for user ID {userId}"

There are no errors for wmf.11 deployment - https://logstash.wikimedia.org/goto/82d669789943d91b1169bc18ccd91f37. The errors stopped completely:

Screen Shot 2024-06-27 at 5.10.51 PM.png (654×2 px, 124 KB)

That is very strange. I would have expected about 4 errors every 3 hours or something like that. I'll reopen it for now because I want to look into it for a moment longer and maybe adjust logging a bit more.

Note that in rOMWC7de06e315685: CommunityConfiguration: Log info and higher, I decreased the log level for CommunityConfiguration from "everything" to "info and higher". In this particular case, we're logging an error, so it is likely not related to the confusion @Michael mentioned, but noting that regardless, just in case.

Note that in rOMWC7de06e315685: CommunityConfiguration: Log info and higher, I decreased the log level for CommunityConfiguration from "everything" to "info and higher". In this particular case, we're logging an error, so it is likely not related to the confusion @Michael mentioned, but noting that regardless, just in case.

My understanding was that the logstash Growth team dashboard filter (GE:T366761) excludes the following regardless of the severity level (logstash Growth team dashboard):

{
  "query": {
    "match_phrase": {
      "normalized_message.keyword": "GrowthExperiments\\MentorDashboard\\MenteeOverview\\UncachedMenteeOverviewDataProvider::getFormattedDataForMentor: Registration timestamp not found for user ID {userId}"
    }
  }
}

Yeah, the filter GE:T366761 can now be removed. Also, this is/was GrowthExperiments code, so this was already using the minimum log-level of info. But it is good to know that we should not get confused by there not being any debug events in logstash anymore from CommunityConfiguration, even if we remove the "NOT info/debug filter".

image.png (39×232 px, 5 KB)

That being said, when looking into T368405, I learned that using the WikimediaDebug browser extension with "Verbose log", it does log all the log message, even the debug ones. That being said, that would obviously not help much in this case, as this code is executed by a maintenance script.

However, glancing at it more, my best guess is that the original error about registration index not being set was caused by the mess-up with user names that was also fixed in T355344. So, probably, there was never anything here in the first places besides noise.