| cscott | |
| Feb 28 2024, 6:48 PM |
| F88111662: image.png | |
| Fri, Jun 12, 9:15 AM |
Inconsistent revision ID
exception.trace
All log entries have reason: edit-page and they seem to all have revid2 == null; that is, the code path which leads to ParserCache::save() doesn't have a revision id set in the ParserOutput, presumably because these are newly-created revisions.
| Subject | Repo | Branch | Lines +/- | |
|---|---|---|---|---|
| RenderedRevision: Set cacheRevisionId on kept outputs after save | mediawiki/core | master | +85 -0 |
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | cscott | T350538 Move all cache property initialization into ContentRenderer | |||
| Open | PRODUCTION ERROR | HakanIST | T358708 Very large logspam of "Inconsistent revision ID" |
These warnings coincide with an Automoderator error in a job which we fire off a job in RevisionFromEditComplete. The hook handler passes the revision id as a parameter to the job. The job does a lookup for that revision id, and that lookup often comes up empty. Spot checking page history shows that these revisions do (at least eventually) exist. Is our job doing a revision lookup on a stale/bugged cache in these cases? Is the jobrunner hitting a db host endpoint that hasn't achieved write consititency? I'm wondering if these two issues have a shared underlying cause.
I see this on MediaWiki 1.42.1 in maintenance/update.php for two extensions: Flow and Semantic MediaWiki. Both create pages at this stage:
The common called function is WikiPage::doUserEditContent() and both use the flag EDIT_FORCE_BOT.
Below is the stack trace for Flow, the SMW one is similar:
#0 ParserCache->save() called at [/mediawiki-1.42.1/includes/Storage/DerivedPageDataUpdater.php:1860]
#1 MediaWiki\Storage\DerivedPageDataUpdater->doParserCacheUpdate() called at [/mediawiki-1.42.1/includes/Storage/DerivedPageDataUpdater.php:1747]
#2 MediaWiki\Storage\DerivedPageDataUpdater->MediaWiki\Storage\{closure}()
#3 call_user_func() called at [/mediawiki-1.42.1/includes/deferred/MWCallableUpdate.php:42]
#4 MediaWiki\Deferred\MWCallableUpdate->doUpdate() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdates.php:486]
#5 MediaWiki\Deferred\DeferredUpdates::attemptUpdate() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdates.php:198]
#6 MediaWiki\Deferred\DeferredUpdates::run() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdates.php:296]
#7 MediaWiki\Deferred\DeferredUpdates::MediaWiki\Deferred\{closure}() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdatesScope.php:269]
#8 MediaWiki\Deferred\DeferredUpdatesScope->processStageQueue() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdatesScope.php:198]
#9 MediaWiki\Deferred\DeferredUpdatesScope->processUpdates() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdates.php:299]
#10 MediaWiki\Deferred\DeferredUpdates::MediaWiki\Deferred\{closure}() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdatesScope.php:269]
#11 MediaWiki\Deferred\DeferredUpdatesScope->processStageQueue() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdatesScope.php:198]
#12 MediaWiki\Deferred\DeferredUpdatesScope->processUpdates() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdates.php:304]
#13 MediaWiki\Deferred\DeferredUpdates::doUpdates() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdates.php:368]
#14 MediaWiki\Deferred\DeferredUpdates::tryOpportunisticExecute() called at [/mediawiki-1.42.1/includes/deferred/DeferredUpdates.php:162]
#15 MediaWiki\Deferred\DeferredUpdates::addUpdate() called at [/mediawiki-1.42.1/includes/Storage/PageUpdater.php:1570]
#16 MediaWiki\Storage\PageUpdater->doCreate() called at [/mediawiki-1.42.1/includes/Storage/PageUpdater.php:925]
#17 MediaWiki\Storage\PageUpdater->saveRevision() called at [/mediawiki-1.42.1/includes/page/WikiPage.php:1835]
#18 WikiPage->doUserEditContent() called at [/mediawiki-1.42.1/extensions/Flow/maintenance/FlowCreateTemplates.php:122]
#19 Flow\Maintenance\FlowCreateTemplates->create() called at [/mediawiki-1.42.1/extensions/Flow/maintenance/FlowCreateTemplates.php:97]
#20 Flow\Maintenance\FlowCreateTemplates->doDBUpdates() called at [/mediawiki-1.42.1/maintenance/includes/LoggedUpdateMaintenance.php:49]
#21 LoggedUpdateMaintenance->execute() called at [/mediawiki-1.42.1/maintenance/update.php:200]
#22 UpdateMediaWiki->execute() called at [/mediawiki-1.42.1/maintenance/includes/MaintenanceRunner.php:698]
#23 MediaWiki\Maintenance\MaintenanceRunner->run() called at [/mediawiki-1.42.1/maintenance/doMaintenance.php:100]
#24 require_once(/mediawiki-1.42.1/maintenance/doMaintenance.php) called at [/mediawiki-1.42.1/maintenance/update.php:301]If I understand correctly, there is no rendered content for these edits by these extensions since only the wikitext is saved internally and consequently there is no parser cache.
⇒ Maybe it should be marked for EDIT_FORCE_BOT and/or EDIT_INTERNAL edits not to call DerivedPageDataUpdater::triggerParserCacheUpdate() – and this will prevent emitting the warning. I propose this since there is already such condition for stashed edits in PageUpdater::prepareUpdate(). However I do not have a complete overview of the workflows convered by this class.
Just chiming in to mention that this warning is emitted at an extremely high rate. We have ~633k instances for the last 24 hours, and ~8k for the last 15 minutes. The rate has remained constant over the last 3 months. I don't know what the purpose of this warning is, but at the moment it seems to mostly just be adding logspam.
Change #1285892 had a related patch set uploaded (by HakanIST; author: HakanIST):
[mediawiki/core@master] RenderedRevision: Set cacheRevisionId on kept outputs after save
Change #1285892 merged by jenkins-bot:
[mediawiki/core@master] RenderedRevision: Set cacheRevisionId on kept outputs after save
The fix is live since wmf.5. It reduced the warning rate from ~650,000/day down to ~730/day.
Remaining warnings seem to come from a different code path. These are still cosmetic since ParserCache corrects the value right after logging.
If we want to eliminate these too, I think we need a small diagnostic patch that adds a stack trace to the warning, so we can see the exact code path in Logstash and then write a targeted fix for it.