| TheDJ | |
| May 30 2024, 11:52 AM |
| F54800382: image.png | |
| May 31 2024, 4:37 PM |
| F54734074: image.png | |
| May 30 2024, 4:44 PM |
| F54716656: Screenshot 2024-05-30 at 13.48.07.png | |
| May 30 2024, 11:52 AM |
https://logstash.wikimedia.org/goto/7f145c1f98d06e664eb8ec590c8d13a7
I noticed this spike in warnings while perusing log stash. Seems to correspond to the deploy time and as it is a warning was likely not noticed during deploy. I'm not sure if there is any impact, but it seems sloppy to have this and should probably be double checked.
Screenshot is of only commons, 3milion. but overall, its about 12 million warnings right now
It is a new logging from 9ae6fbda79effc2b6b4bfa02673959793d42c9f9, there is no impact as no value gets ignored.
The question is what code path ends with unexpected values in makeList
Change #1037525 had a related patch set uploaded (by Umherirrender; author: Umherirrender):
[mediawiki/core@master] rdbms: Pass array values to makeList on insert/upsert
While it might be innocent at execution, it is increasing the total logged messages of mediawiki with about a 3rd. And that is pre group2 release. That is not something to ignore I think.
There's impact in the logging system of such a large number of logs, of course.
The question is what code path ends with unexpected values in makeList
No exception, so no trace, but from eyeballing, on Commons, the bulk are coming in the objectcache channel from reads of pages like https://commons.wikimedia.org/wiki/Category:Lanoit_(surname), and the skipped key is keyname. There are also a smaller number in the rdbms channel with various skipped keys like rc_timestamp, tl_from_namespace, label, and others; they happen in a variety of calls, including action=submits and load.phps.
There is no impact on the user as no provided value for the database gets ignored. It is a warning, that something is used wrong. I understand that the amount of logging has a impact on the backend and the issue should not ignored.
My patch set should fix the common case for this logging and reduce the logging. It is possible that still messages gets logged after the patch set, hopefully with a low rate. But all should have different code paths and possible needs different fixes.
Is it worth doing the regular [ 'exception' => new RuntimeException() ] data addition so we can trace these warnings?
Change #1037525 merged by jenkins-bot:
[mediawiki/core@master] rdbms: Pass array values to makeList on insert/upsert
Change #1037138 had a related patch set uploaded (by Umherirrender; author: Umherirrender):
[mediawiki/core@wmf/1.43.0-wmf.7] rdbms: Pass array values to makeList on insert/upsert
Change #1037138 merged by jenkins-bot:
[mediawiki/core@wmf/1.43.0-wmf.7] rdbms: Pass array values to makeList on insert/upsert
Mentioned in SAL (#wikimedia-operations) [2024-05-30T15:22:14Z] <dancy@deploy1002> Started scap: Backport for [[gerrit:1037138|rdbms: Pass array values to makeList on insert/upsert (T366268)]]
Mentioned in SAL (#wikimedia-operations) [2024-05-30T15:24:47Z] <dancy@deploy1002> umherirrender and dancy: Backport for [[gerrit:1037138|rdbms: Pass array values to makeList on insert/upsert (T366268)]] synced to the testservers (https://wikitech.wikimedia.org/wiki/Mwdebug)
Mentioned in SAL (#wikimedia-operations) [2024-05-30T15:34:09Z] <dancy@deploy1002> Finished scap: Backport for [[gerrit:1037138|rdbms: Pass array values to makeList on insert/upsert (T366268)]] (duration: 11m 55s)
OK, this has helped a lot, thank you @Umherirrender; all the objectcache warnings are now gone:
The rdbms ones remain.
Sorry I didn't respond earlier, I wasn't checking my emails since it's a public holiday.
The warning was introduced in https://gerrit.wikimedia.org/r/c/mediawiki/core/+/1030575. The commit doesn't revert cleanly, but the added code is easy to remove. We can track down the offenders next week (at a glance, it's something in Wikibase, which doesn't really narrow it down).
Change #1037592 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):
[mediawiki/core@master] Temporarily silence noisy new warnings
I won't be able to help today, but feel free to deploy that change to unblock the train.
Change #1037593 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):
[mediawiki/extensions/Wikibase@master] Fix rdbms warnings: "array key {key} in list of values ignored"
Change #1037143 had a related patch set uploaded (by Jforrester; author: Bartosz Dziewoński):
[mediawiki/core@wmf/1.43.0-wmf.7] Temporarily silence noisy new warnings
Change #1037143 merged by jenkins-bot:
[mediawiki/core@wmf/1.43.0-wmf.7] Temporarily silence noisy new warnings
Mentioned in SAL (#wikimedia-operations) [2024-05-30T19:05:01Z] <dancy@deploy1002> Started scap: Backport for [[gerrit:1037143|Temporarily silence noisy new warnings (T366268)]]
Mentioned in SAL (#wikimedia-operations) [2024-05-30T19:11:43Z] <dancy@deploy1002> jforrester and dancy: Backport for [[gerrit:1037143|Temporarily silence noisy new warnings (T366268)]] synced to the testservers (https://wikitech.wikimedia.org/wiki/Mwdebug)
Mentioned in SAL (#wikimedia-operations) [2024-05-30T19:20:41Z] <dancy@deploy1002> Finished scap: Backport for [[gerrit:1037143|Temporarily silence noisy new warnings (T366268)]] (duration: 15m 39s)
As alternative it could use the deprecation process, that has a stack trace and it is known to show errors in phpunit tests. But that could be hard to keep extensions CI working by finding the issues before merge of the core patch.
Using production to find the warnings could flood the logs, that is also not good. It feels hard to get a good balance here, for a feature like makeList(), which is used so often.
Change #1037593 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] Fix rdbms warnings: "array key {key} in list of values ignored"
log 1 in 1000 ?
Then no one would ever see them in development.
The thing we should have done to avoid the annoyance in production was to check the beta logstash, which also shows a very high volume of these warnings:
https://beta-logs.wmcloud.org/goto/3c144b23324f01a45d5fc05e8287743b (see https://wikitech.wikimedia.org/wiki/Logstash#Beta_Cluster_Logstash for access)
It also shows that https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Wikibase/+/1037593 resolved most of them, so we probably don't need the patch to disable them on master.
(I also think we got a bit unlucky – there are probably thousands of callers for this code, and we've now found 4 of them that generate the warning, but it so happens that 2 of those are called on almost every page view.)
Change #1037592 abandoned by Bartosz Dziewoński:
[mediawiki/core@master] Temporarily silence noisy new warnings
Reason:
Shouldn't be needed per T366268#9850761
Change #1037828 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):
[mediawiki/core@master] rdbms: Add backtrace to ignored array key warning
Change #1037830 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):
[mediawiki/extensions/Flow@master] Fix rdbms warning: "array key {key} in list of values ignored"
Change #1037831 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):
[mediawiki/extensions/GrowthExperiments@master] Fix rdbms warning: "array key {key} in list of values ignored"
Change #1037828 merged by jenkins-bot:
[mediawiki/core@master] rdbms: Add backtrace to ignored array key warning
Change #1037839 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):
[mediawiki/extensions/Wikibase@master] Fix rdbms warnings: "array key {key} in list of values ignored" (2)
These patches take care of all of the remaining warnings I'm seeing in the beta cluster logstash.
Change #1037830 merged by jenkins-bot:
[mediawiki/extensions/Flow@master] Fix rdbms warning: "array key {key} in list of values ignored"
Change #1037831 merged by jenkins-bot:
[mediawiki/extensions/GrowthExperiments@master] Fix rdbms warning: "array key {key} in list of values ignored"
Change #1037839 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] Fix rdbms warnings: "array key {key} in list of values ignored" (2)
Optimistically closing. There were no more warnings on the beta cluster since those changes were merged.
If new warnings appear next week in production, they will now have the exception.trace field in logstash allowing the responsible component to be easily identified. Please file a separate task for each component, I'll help resolve them if you CC me.
I'm sorry for delaying the train with this!