Page MenuHomePhabricator
Create Task
Maniphest T312544

Deferred update 'MWCallableUpdate_GrowthExperiments\NewcomerTasks\TaskSetListener->run' failed to run.
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

Error
normalized_message
Deferred update '{deferred_type}' failed to run.
exception.trace
from /srv/mediawiki/php-1.39.0-wmf.19/vendor/wikimedia/request-timeout/src/Detail/ExcimerTimerWrapper.php(97)
#0 /srv/mediawiki/php-1.39.0-wmf.19/vendor/wikimedia/request-timeout/src/Detail/ExcimerTimerWrapper.php(72): Wikimedia\RequestTimeout\Detail\ExcimerTimerWrapper->onTimeout(integer)
#1 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Handler/CurlFactory.php(563): Wikimedia\RequestTimeout\Detail\ExcimerTimerWrapper->Wikimedia\RequestTimeout\Detail\{closure}(integer)
#2 [internal function]: GuzzleHttp\Handler\CurlFactory::GuzzleHttp\Handler\{closure}(resource, string)
#3 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Handler/CurlHandler.php(44): curl_exec(resource)
#4 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Handler/Proxy.php(28): GuzzleHttp\Handler\CurlHandler->__invoke(GuzzleHttp\Psr7\Request, array)
#5 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Handler/Proxy.php(48): GuzzleHttp\Handler\Proxy::GuzzleHttp\Handler\{closure}(GuzzleHttp\Psr7\Request, array)
#6 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Middleware.php(240): GuzzleHttp\Handler\Proxy::GuzzleHttp\Handler\{closure}(GuzzleHttp\Psr7\Request, array)
#7 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/PrepareBodyMiddleware.php(35): GuzzleHttp\Middleware::GuzzleHttp\{closure}(GuzzleHttp\Psr7\Request, array)
#8 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/RedirectMiddleware.php(55): GuzzleHttp\PrepareBodyMiddleware->__invoke(GuzzleHttp\Psr7\Request, array)
#9 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Middleware.php(61): GuzzleHttp\RedirectMiddleware->__invoke(GuzzleHttp\Psr7\Request, array)
#10 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/HandlerStack.php(75): GuzzleHttp\Middleware::GuzzleHttp\{closure}(GuzzleHttp\Psr7\Request, array)
#11 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Client.php(331): GuzzleHttp\HandlerStack->__invoke(GuzzleHttp\Psr7\Request, array)
#12 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Client.php(108): GuzzleHttp\Client->transfer(GuzzleHttp\Psr7\Request, array)
#13 /srv/mediawiki/php-1.39.0-wmf.19/vendor/guzzlehttp/guzzle/src/Client.php(123): GuzzleHttp\Client->sendAsync(GuzzleHttp\Psr7\Request, array)
#14 /srv/mediawiki/php-1.39.0-wmf.19/includes/http/GuzzleHttpRequest.php(203): GuzzleHttp\Client->send(GuzzleHttp\Psr7\Request)
#15 /srv/mediawiki/php-1.39.0-wmf.19/includes/http/HttpRequestFactory.php(174): GuzzleHttpRequest->execute()
#16 /srv/mediawiki/php-1.39.0-wmf.19/includes/http/HttpRequestFactory.php(196): MediaWiki\Http\HttpRequestFactory->request(string, string, array, string)
#17 /srv/mediawiki/php-1.39.0-wmf.19/includes/filerepo/file/ForeignDBFile.php(132): MediaWiki\Http\HttpRequestFactory->get(string, array, string)
#18 /srv/mediawiki/php-1.39.0-wmf.19/includes/libs/objectcache/wancache/WANObjectCache.php(1694): ForeignDBFile::{closure}(boolean, integer, array, NULL, array)
#19 /srv/mediawiki/php-1.39.0-wmf.19/includes/libs/objectcache/wancache/WANObjectCache.php(1523): WANObjectCache->fetchOrRegenerate(string, integer, Closure, array, array)
#20 /srv/mediawiki/php-1.39.0-wmf.19/includes/filerepo/file/ForeignDBFile.php(138): WANObjectCache->getWithSetCallback(string, integer, Closure)
#21 /srv/mediawiki/php-1.39.0-wmf.19/extensions/CommonsMetadata/src/DataCollector.php(264): ForeignDBFile->getDescriptionText(LanguageEn)
#22 /srv/mediawiki/php-1.39.0-wmf.19/extensions/CommonsMetadata/src/DataCollector.php(98): CommonsMetadata\DataCollector->getDescriptionText(ForeignDBFile, LanguageEn)
#23 /srv/mediawiki/php-1.39.0-wmf.19/extensions/CommonsMetadata/src/HookHandler.php(75): CommonsMetadata\DataCollector->collect(array, ForeignDBFile)
#24 /srv/mediawiki/php-1.39.0-wmf.19/includes/HookContainer/HookContainer.php(338): CommonsMetadata\HookHandler::onGetExtendedMetadata(array, ForeignDBFile, RequestContext, boolean, integer)
#25 /srv/mediawiki/php-1.39.0-wmf.19/includes/HookContainer/HookContainer.php(137): MediaWiki\HookContainer\HookContainer->callLegacyHook(string, array, array, array)
#26 /srv/mediawiki/php-1.39.0-wmf.19/includes/HookContainer/HookRunner.php(1814): MediaWiki\HookContainer\HookContainer->run(string, array)
#27 /srv/mediawiki/php-1.39.0-wmf.19/includes/media/FormatMetadata.php(1821): MediaWiki\HookContainer\HookRunner->onGetExtendedMetadata(array, ForeignDBFile, RequestContext, boolean, integer)
#28 /srv/mediawiki/php-1.39.0-wmf.19/includes/media/FormatMetadata.php(1738): FormatMetadata->getExtendedMetadataFromHook(ForeignDBFile, array, integer)
#29 /srv/mediawiki/php-1.39.0-wmf.19/extensions/GrowthExperiments/includes/NewcomerTasks/AddImage/ImageRecommendationMetadataService.php(60): FormatMetadata->fetchExtendedMetadata(ForeignDBFile)
#30 /srv/mediawiki/php-1.39.0-wmf.19/extensions/GrowthExperiments/includes/NewcomerTasks/AddImage/ImageRecommendationMetadataProvider.php(298): GrowthExperiments\NewcomerTasks\AddImage\ImageRecommendationMetadataService->getExtendedMetadata(string)
#31 /srv/mediawiki/php-1.39.0-wmf.19/extensions/GrowthExperiments/includes/NewcomerTasks/AddImage/ServiceImageRecommendationProvider.php(176): GrowthExperiments\NewcomerTasks\AddImage\ImageRecommendationMetadataProvider->getMetadata(array)
#32 /srv/mediawiki/php-1.39.0-wmf.19/extensions/GrowthExperiments/includes/NewcomerTasks/AddImage/ServiceImageRecommendationProvider.php(110): GrowthExperiments\NewcomerTasks\AddImage\ServiceImageRecommendationProvider::processApiResponseData(Title, string, array, GrowthExperiments\NewcomerTasks\AddImage\ImageRecommendationMetadataProvider, GrowthExperiments\NewcomerTasks\AddImage\AddImageSubmissionHandler, array)
#33 /srv/mediawiki/php-1.39.0-wmf.19/extensions/GrowthExperiments/includes/NewcomerTasks/AddImage/CacheBackedImageRecommendationProvider.php(63): GrowthExperiments\NewcomerTasks\AddImage\ServiceImageRecommendationProvider->get(Title, GrowthExperiments\NewcomerTasks\TaskType\ImageRecommendationTaskType)
#34 /srv/mediawiki/php-1.39.0-wmf.19/includes/libs/objectcache/wancache/WANObjectCache.php(1694): GrowthExperiments\NewcomerTasks\AddImage\CacheBackedImageRecommendationProvider::GrowthExperiments\NewcomerTasks\AddImage\{closure}(boolean, integer, array, NULL, array)
#35 /srv/mediawiki/php-1.39.0-wmf.19/includes/libs/objectcache/wancache/WANObjectCache.php(1523): WANObjectCache->fetchOrRegenerate(string, integer, Closure, array, array)
#36 /srv/mediawiki/php-1.39.0-wmf.19/extensions/GrowthExperiments/includes/NewcomerTasks/AddImage/CacheBackedImageRecommendationProvider.php(68): WANObjectCache->getWithSetCallback(string, integer, Closure)
#37 /srv/mediawiki/php-1.39.0-wmf.19/extensions/GrowthExperiments/includes/NewcomerTasks/TaskSetListener.php(47): GrowthExperiments\NewcomerTasks\AddImage\CacheBackedImageRecommendationProvider::getWithSetCallback(WANObjectCache, GrowthExperiments\NewcomerTasks\AddImage\ServiceImageRecommendationProvider, GrowthExperiments\NewcomerTasks\TaskType\ImageRecommendationTaskType, Title)
#38 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/MWCallableUpdate.php(38): GrowthExperiments\NewcomerTasks\TaskSetListener->GrowthExperiments\NewcomerTasks\{closure}()
#39 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdates.php(474): MWCallableUpdate->doUpdate()
#40 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdates.php(399): DeferredUpdates::attemptUpdate(MWCallableUpdate, Wikimedia\Rdbms\LBFactoryMulti)
#41 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdates.php(227): DeferredUpdates::run(MWCallableUpdate, Wikimedia\Rdbms\LBFactoryMulti, Monolog\Logger, BufferingStatsdDataFactory, MediaWiki\JobQueue\JobQueueGroupFactory, string)
#42 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdatesScope.php(267): DeferredUpdates::{closure}(MWCallableUpdate, integer)
#43 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdatesScope.php(196): DeferredUpdatesScope->processStageQueue(integer, integer, Closure)
#44 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdates.php(230): DeferredUpdatesScope->processUpdates(integer, Closure)
#45 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdatesScope.php(267): DeferredUpdates::{closure}(MWCallableUpdate, integer)
#46 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdatesScope.php(196): DeferredUpdatesScope->processStageQueue(integer, integer, Closure)
#47 /srv/mediawiki/php-1.39.0-wmf.19/includes/deferred/DeferredUpdates.php(235): DeferredUpdatesScope->processUpdates(integer, Closure)
#48 /srv/mediawiki/php-1.39.0-wmf.19/includes/MediaWiki.php(1124): DeferredUpdates::doUpdates()
#49 /srv/mediawiki/php-1.39.0-wmf.19/includes/MediaWiki.php(846): MediaWiki->restInPeace()
#50 /srv/mediawiki/php-1.39.0-wmf.19/includes/MediaWiki.php(594): MediaWiki->doPostOutputShutdown()
#51 /srv/mediawiki/php-1.39.0-wmf.19/index.php(50): MediaWiki->run()
#52 /srv/mediawiki/php-1.39.0-wmf.19/index.php(46): wfIndexMain()
#53 /srv/mediawiki/w/index.php(3): require(string)
#54 {main}
Impact

conversation with @kostajh in #wikimedia-operations:

15:13 <urbanecm> kostajh: okay. i see the timeouts and `Deferred update 'MWCallableUpdate_GrowthExperiments\NewcomerTasks\TaskSetListener->run' failed to run.` again. not sure what the deferred update is for. doesn't appear to show up in the growth-team logstash dashboard. given you say it works, perhaps we should sync and check the errors after?
15:13 <kostajh> urbanecm: the deferred update failure is because we cache calls to the image suggestion API, and processing of metadata. In this case, if it can't find the recommendation, the curl request just hangs. We should try to fix that, but it's not directly related
Notes

Details

Request URL
https://fr.wikipedia.org/w/index.php?title=*&source=*&namespace=*
SubjectRepoBranchLines +/-
AddImage: Only process metadata for a single valid suggestionmediawiki/extensions/GrowthExperimentswmf/1.39.0-wmf.19+30 -4
AddImage: Only process metadata for a single valid suggestionmediawiki/extensions/GrowthExperimentsmaster+30 -4
Customize query in gerrit

Related Objects
Search...

Event Timeline

Urbanecm_WMF created this task.Jul 7 2022, 2:09 PM
Restricted Application added a project: Growth-Team. · View Herald TranscriptJul 7 2022, 2:09 PM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript
Urbanecm_WMF renamed this task from Deferred update '{deferred_type}' failed to run. to Deferred update 'MWCallableUpdate_GrowthExperiments\NewcomerTasks\TaskSetListener->run' failed to run..Jul 7 2022, 2:09 PM
Urbanecm_WMF added a parent task: T306032: Adapt GrowthExperiments to new Image Suggestions API.
Urbanecm_WMF mentioned this in T308072: 1.39.0-wmf.19 deployment blockers.Jul 7 2022, 2:34 PM
kostajh added projects: Commons, MediaWiki-File-management.Jul 7 2022, 3:42 PM

Looking at the stack trace, it seems like this issue has to do with something broken in the "File management" component. According to Developers/Maintainers, that area of MediaWiki is unmaintained :(

Adding some tags in hopes of getting some visibility and ideas about what might be the timeouts in ForeignDBFile.php.

kostajh added subscribers: hnowlan, Eevans.Jul 7 2022, 5:16 PM

image.png (1×2 px, 887 KB)

This view of the last 6 hours shows that the increased times for processApiResponse started when we switched over to the new API.

Looking at the image-suggestion dashboard, it seems like the issue is not with the image suggestion service (cc @hnowlan @Eevans), but with GrowthExperiment's processApiResponse which ends up querying file metadata on Commons.

image.png (1×2 px, 677 KB)

CBogen moved this task from To Do to Growth: Add an Image on the Image-Suggestions board.Jul 7 2022, 6:35 PM
kostajh added a comment.Jul 8 2022, 7:41 AM

The error closely tied to this one is Wikimedia\RequestTimeout\RequestTimeoutException: The maximum execution time of {limit} seconds was exceeded, see e.g. https://logstash.wikimedia.org/app/discover#/doc/logstash-*/logstash-deploy-2022.07.08?id=vvu-3IEBWJDkYQXoYhso

kostajh claimed this task.Jul 8 2022, 9:27 AM
kostajh edited projects, added Growth-Team (Sprint 0 (Growth Team)); removed Growth-Team.
kostajh triaged this task as Medium priority.Jul 8 2022, 9:30 AM
kostajh moved this task from Incoming to In Progress on the Growth-Team (Sprint 0 (Growth Team)) board.

I think I know what is causing this. The [old API](https://image-suggestion-api.wmcloud.org/?doc#/Image Suggestions) usually returned a handful of suggestions per article. The new API seems to return many more results per article. We have some code in GrowthExperiments that iterates over the suggested images for each article and caches the metadata. What's likely happening is that, instead of iterating over e.g. 3 suggestions, we are iterating over 30 suggestions, and that is taking longer than 60 seconds to process. My proposal is to limit the metadata caching to a single suggestion, since that is all we are showing to the user in the UI anyway.

gerritbot added a comment.Jul 8 2022, 9:50 AM

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

[mediawiki/extensions/GrowthExperiments@master] AddImage: Only process metadata for a single valid suggestion

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

gerritbot added a project: Patch-For-Review.Jul 8 2022, 9:50 AM
kostajh moved this task from In Progress to Code Review on the Growth-Team (Sprint 0 (Growth Team)) board.Jul 8 2022, 10:33 AM
gerritbot added a comment.Jul 8 2022, 12:26 PM

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

[mediawiki/extensions/GrowthExperiments@wmf/1.39.0-wmf.19] AddImage: Only process metadata for a single valid suggestion

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

gerritbot added a comment.Jul 8 2022, 12:32 PM

Change 812260 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@master] AddImage: Only process metadata for a single valid suggestion

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

kostajh moved this task from Code Review to QA on the Growth-Team (Sprint 0 (Growth Team)) board.Jul 8 2022, 12:33 PM
hashar subscribed.Jul 8 2022, 1:40 PM

I am deploying the hotfix https://gerrit.wikimedia.org/r/c/mediawiki/extensions/GrowthExperiments/+/812279 , @kostajh has left test instructions on the change:

I'm stepping away for a while, but in case anyone wants to backport this, here are some testing instructions:

gerritbot added a comment.Jul 8 2022, 2:01 PM

Change 812279 merged by jenkins-bot:

[mediawiki/extensions/GrowthExperiments@wmf/1.39.0-wmf.19] AddImage: Only process metadata for a single valid suggestion

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

Stashbot added a comment.Jul 8 2022, 2:11 PM

Mentioned in SAL (#wikimedia-operations) [2022-07-08T14:10:58Z] <hashar@deploy1002> Synchronized php-1.39.0-wmf.19/extensions/GrowthExperiments/includes/NewcomerTasks/AddImage/ServiceImageRecommendationProvider.php: AddImage: Only process metadata for a single valid suggestion - T312544 (duration: 03m 25s)

hashar added a comment.Jul 8 2022, 2:13 PM

I have deployed the fix on mwdebug1001 and followed the test procedure above (thanks kosta!). Nothing showed anymore I have thus deployed the patch on all wikis Looks like the issue has vanished :]

Maintenance_bot removed a project: Patch-For-Review.Jul 8 2022, 2:31 PM
hashar closed this task as Resolved.Jul 8 2022, 2:35 PM
kostajh added a comment.Jul 8 2022, 4:02 PM

Thank you @hashar!

ReleaseTaggerBot added a project: MW-1.39-notes (1.39.0-wmf.19; 2022-07-04).Jul 12 2022, 5:02 AM
Krinkle moved this task from Untriaged to Jul 2022 on the Wikimedia-production-error board.Jul 29 2022, 11:16 PM
kostajh mentioned this in T311312: Add an image: optimize ServiceImageRecommendationProvider::processApiResponseData.Aug 22 2022, 10:20 AM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits