Page MenuHomePhabricator

UnexpectedValueException: Tried to submit link suggestion reviews for revision "31193961" which has already been reviewed
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error
normalized_message
[{reqId}] {exception_url}   UnexpectedValueException: Tried to submit link suggestion reviews for revision "31193961" which has already been reviewed.
exception.trace
from /srv/mediawiki/php-1.37.0-wmf.23/extensions/GrowthExperiments/includes/NewcomerTasks/AddLink/AddLinkSubmissionHandler.php(103)
#0 /srv/mediawiki/php-1.37.0-wmf.23/extensions/GrowthExperiments/includes/VisualEditorHooks.php(127): GrowthExperiments\NewcomerTasks\AddLink\AddLinkSubmissionHandler->run(Title, User, integer, integer, array)
#1 /srv/mediawiki/php-1.37.0-wmf.23/includes/HookContainer/HookContainer.php(160): GrowthExperiments\VisualEditorHooks->onVisualEditorApiVisualEditorEditPostSave(MediaWiki\Page\PageIdentityValue, User, string, array, array, array, array)
#2 /srv/mediawiki/php-1.37.0-wmf.23/extensions/VisualEditor/includes/VisualEditorHookRunner.php(72): MediaWiki\HookContainer\HookContainer->run(string, array, array)
#3 /srv/mediawiki/php-1.37.0-wmf.23/extensions/VisualEditor/includes/ApiVisualEditorEdit.php(512): MediaWiki\Extension\VisualEditor\VisualEditorHookRunner->onVisualEditorApiVisualEditorEditPostSave(MediaWiki\Page\PageIdentityValue, User, string, array, array, array, array)
#4 /srv/mediawiki/php-1.37.0-wmf.23/includes/api/ApiMain.php(1878): ApiVisualEditorEdit->execute()
#5 /srv/mediawiki/php-1.37.0-wmf.23/includes/api/ApiMain.php(857): ApiMain->executeAction()
#6 /srv/mediawiki/php-1.37.0-wmf.23/includes/api/ApiMain.php(828): ApiMain->executeActionWithErrorHandling()
#7 /srv/mediawiki/php-1.37.0-wmf.23/api.php(90): ApiMain->execute()
#8 /srv/mediawiki/php-1.37.0-wmf.23/api.php(45): wfApiMain()
#9 /srv/mediawiki/w/api.php(3): require(string)
#10 {main}
Impact
Notes

Looks like a rare corner case which is got missed in the code :)

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald Transcript
Tgr moved this task from Incoming to Ready for Development on the Growth-Team (Current Sprint) board.
Tgr added a subscriber: Tgr.

I suppose it should go to the Growth channel, not the exception channel as this is probably a race condition and not a real error.

Also should probably be parametrized.

Actually I think this was fixed in rEGRE16d1a84b6d35: Add Image: Handle submission.

Testing notes:
To be re-checked: the fix is for wmf.1 - currently there are 8 errors for wmf23 (no errors on testwiki wmf.1) - link to the normalized_message error message.

On second thought this is not really done. The linked patch sends errors to the client (instead of Logstash), but the client will still send them to logstash via mw.errorLogger. That's less disruptive (doesn't show up on the mediawiki-errors dashboard that deployers use) but still not ideal.

I think the way to go here is to have the logging system differentiate between fatal and warning statuses (via the relevant StatusValue mechanism) and only log warnings to the browser console / to the Growth channel.

I'm not sure it's a race condition, exactly. I suspected that as well, especially because I've seen similar issues caused by replication lag on the the wikis affected (arwiki, fawiki, frwiki).

But looking at e.g. this error, the error was logged on August 28, but looking at the Special:Log on frwiki, we can see that link recommendations were added on August 19.

It gets weird, though, because looking at the history for that article https://fr.wikipedia.org/w/index.php?title=Th%C3%A9or%C3%A8me_d%27Erd%C5%91s-Kac&action=history&uselang=en, I don't see a "Suggested: Add links" edit on August 19 (or any other date). Nor does it show up for the user's contributions.

Looking at the database, I see:

SELECT * FROM growthexperiments_link_submissions WHERE gels_page = 694830 \G;
*************************** 1. row ***************************
     gels_revision: 183606218
gels_anchor_offset: 1482
       gels_target: 2212
         gels_page: 694830
gels_edit_revision: NULL
         gels_user: 4069852
gels_anchor_length: 14
     gels_feedback: r
*************************** 2. row ***************************
     gels_revision: 183606218
gels_anchor_offset: 1553
       gels_target: 9388
         gels_page: 694830
gels_edit_revision: NULL
         gels_user: 4069852
gels_anchor_length: 13
     gels_feedback: r
2 rows in set (0.001 sec)

183606218 is indeed the most recent revision, and the user ID corresponds to the user we see in the Special:Log entry from August 19.

There's a Logstash entry on August 19 for this article, that says Transaction spent 0.00235915184021 second(s) in writes, less than the limit of 3, which seems to indicate a successful save.

For the frwiki error mentioned above, I can see that there was an error updating ElasticSearch (T291634):

Search backend error during updating 1 documents after 49: bulk: Error in one or more bulk request actions:

update: /frwiki_content_1627811641/page/694830 caused [page][694830]: version conflict, current version [2] is different than the one provided [1] [index: frwiki_content_1627811641]
  - update: /frwiki_content_1627811641/page/694830 caused [page][694830]: version conflict, current version [2] is different than the one provided [1] [index: frwiki_content_1627811641]: version_conflict_engine_exception: [page][694830]: version conflict, current version [2] is different than the one provided [1]

Ah. So, what happens is that:

  1. user makes a null edit (skipped and/or rejected all links)
  2. a submission is recorded
  3. refreshLinkRecommendations.php does not check the log to see if there was a link recommendation review for the revision, a recommendation object is stored in the DB
  4. a user tries to work on the article
  5. now we get an error that the submission for that revision already exists

We should fix this in refreshLinkRecommendations#evaluateRecommendation

Change 723222 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):

[mediawiki/extensions/GrowthExperiments@master] refreshLinkRecommendations: Check if submission already exists

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

kostajh renamed this task from UnexpectedValueException: Tried to submit link suggestion reviews for revision "31193961" which has already been reviewed. to UnexpectedValueException: Tried to submit link suggestion reviews for revision "31193961" which has already been reviewed.Sep 23 2021, 3:37 PM
kostajh moved this task from In Progress to Code Review on the Growth-Team (Current Sprint) board.

Change 723222 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@master] refreshLinkRecommendations: Check if submission already exists

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

Hm, I guess this is a mistake in the DB schema - there is nothing wrong with multiple rejectsions for the same revision. It is really gels_edit_revision that should be unique, not gels_revision (but that's nullable so it can't be used as a PK). Oh well, not really worth the effort fixing. Thanks for tracking down the error!

Change 723415 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):

[mediawiki/extensions/GrowthExperiments@master] Unify error handling for structured tasks

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

Change 723415 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@master] Unify error handling for structured tasks

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

The last timestamp for the error - Sep 20, 2021 @ 09:24:54.004 - marking as Resolved.

Change 739400 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):

[mediawiki/extensions/GrowthExperiments@master] Add Link: Make the updater's force flag more aggressive

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

Change 739400 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@master] Add Link: Make the updater's force flag more aggressive

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