Page MenuHomePhabricator

Validate and normalize file contents for UTF-8 in FFS
Closed, ResolvedPublic

Description

Seems to happen regularly, just a few seconds into each job queue run on intense.wmflabs.org.

root@ttmserver-mediawiki01:/srv/mediawiki/workdir# php /srv/mediawiki/targets/production/maintenance/runJobs.php --procs=2 --memory-limit=max --maxtime=250 
2015-01-24 08:27:27 MessageGroupStatesUpdaterJob Z:englobe-dpkg--473995-requested_operation_requires_s/nn (id=166701) STARTING
2015-01-24 08:27:27 MessageGroupStatesUpdaterJob Z:englobe-dselect--91bde8-Removed_packages_(configuratio/nn (id=166741) STARTING
2015-01-24 08:27:28 MessageGroupStatesUpdaterJob Z:englobe-dpkg--473995-requested_operation_requires_s/nn (id=166701) t=892 good
2015-01-24 08:27:28 MessageUpdateJob Z:englobe-dselect--9837d9-Press_?_for_help_menu,_._for_n/ko content=도움말 메뉴는 ?, 다음 주제는 ., 도움말에서 나가시려면 <space>를 누르십시오. fuzzy= (id=147442) STARTING
2015-01-24 08:27:28 MessageGroupStatesUpdaterJob Z:englobe-dselect--91bde8-Removed_packages_(configuratio/nn (id=166741) t=983 good
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-apt-all--699808-Can't_mmap_an_empty_file/fi (id=166737) STARTING
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-apt-all--699808-Can't_mmap_an_empty_file/fi (id=166737) t=84 good
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-dselect--b32ef3-Explanation/el (id=166745) STARTING
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-dselect--b32ef3-Explanation/el (id=166745) t=45 good
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-apt-all--0f941a-The_diversion_file_is_corrupte/vi (id=166729) STARTING
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-apt-all--0f941a-The_diversion_file_is_corrupte/vi (id=166729) t=61 good
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-dselect--1c9814-Installed_packages/el (id=166719) STARTING
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-dselect--1c9814-Installed_packages/el (id=166719) t=27 good
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-apt-all--ea654b-Build_command_'=25s'_failed.=0A\/th (id=166680) STARTING
2015-01-24 08:27:29 MessageGroupStatesUpdaterJob Z:englobe-apt-all--ea654b-Build_command_'=25s'_failed.=0A\/th (id=166680) t=6 good
2015-01-24 08:27:29 MessageUpdateJob Z:englobe-dpkg-man--f3ac16-B=3C--altdir=3EI=3C_directory=3E/en content=B<--altdir>I< directory> fuzzy= (id=153567) STARTING
2015-01-24 08:27:32 MessageUpdateJob Z:englobe-dselect--9837d9-Press_?_for_help_menu,_._for_n/ko content=도움말 메뉴는 ?, 다음 주제는 ., 도움말에서 나가시려면 <space>를 누르십시오. fuzzy= (id=147442) t=3435 good
2015-01-24 08:27:32 MessageUpdateJob Z:englobe-dpkg-man--f3ac16-B=3C--altdir=3EI=3C_directory=3E/en content=B<--altdir>I< directory> fuzzy= (id=153567) t=2765 good
2015-01-24 08:27:32 MessageGroupStatesUpdaterJob Z:englobe-dpkg--37b912-name_=25s_is_both_primary_and_sl/ru (id=166743) STARTING
2015-01-24 08:27:32 MessageGroupStatesUpdaterJob Z:englobe-dpkg--da8da7-Updating_=25s_(=25s)_to_point_to_=25/ko (id=166695) STARTING
2015-01-24 08:27:32 MessageGroupStatesUpdaterJob Z:englobe-dpkg--37b912-name_=25s_is_both_primary_and_sl/ru (id=166743) t=176 good
2015-01-24 08:27:32 MessageGroupStatesUpdaterJob Z:englobe-apt-all--783f02-Logging_in/tl (id=166643) STARTING
2015-01-24 08:27:32 MessageGroupStatesUpdaterJob Z:englobe-apt-all--783f02-Logging_in/tl (id=166643) t=18 good
2015-01-24 08:27:32 MessageGroupStatesUpdaterJob Z:englobe-dpkg--da8da7-Updating_=25s_(=25s)_to_point_to_=25/ko (id=166695) t=268 good
2015-01-24 08:27:32 MessageUpdateJob Z:englobe-dpkg-man--fa3cd9-I=3Cpackage=3E_I=3Cpriority=3E_I=3Csecti/de content=I<Paket> I<Priorit�t> I<Bereich> [I<Betreuerinformation>] fuzzy= (id=153724) STARTING
2015-01-24 08:27:32 MessageUpdateJob Z:englobe-dpkg--346652-old_=25s_script/hu content=régi %s szkript fuzzy= (id=125170) STARTING
2015-01-24 08:27:33 MessageUpdateJob Z:englobe-dpkg--346652-old_=25s_script/hu content=régi %s szkript fuzzy= (id=125170) t=310 good
2015-01-24 08:27:33 MessageGroupStatesUpdaterJob Z:englobe-dpkg-man--37555d-B=3CCOLUMNS=3E/ru (id=166747) STARTING
ElasticSearchTTMServer::update: update failed (Elastica\Exception\ResponseException: MapperParsingException[failed to parse, document is empty]); retrying.
2015-01-24 08:27:33 MessageGroupStatesUpdaterJob Z:englobe-dpkg-man--37555d-B=3CCOLUMNS=3E/ru (id=166747) t=129 good
2015-01-24 08:27:33 MessageUpdateJob Z:englobe-dpkg-man--6e9313-The_name_of_the_source_package/fr content=Le nom du paquet source d'o� provient le paquet binaire, s'il y a une diff�rence entre les deux noms. fuzzy= (id=156231) STARTING
ElasticSearchTTMServer::update: update failed (Elastica\Exception\ResponseException: MapperParsingException[failed to parse, document is empty]); retrying.
ElasticSearchTTMServer::update: update failed (Elastica\Exception\ResponseException: MapperParsingException[failed to parse, document is empty]); retrying.
ElasticSearchTTMServer::update: update failed (Elastica\Exception\ResponseException: MapperParsingException[failed to parse, document is empty]); retrying.
ElasticSearchTTMServer::update: update failed (Elastica\Exception\ResponseException: MapperParsingException[failed to parse, document is empty]); retrying.
ElasticSearchTTMServer::update: update failed (Elastica\Exception\ResponseException: MapperParsingException[failed to parse, document is empty]); retrying.
ElasticSearchTTMServer::update: update failed (Elastica\Exception\ResponseException: MapperParsingException[failed to parse, document is empty]); retrying.
ElasticSearchTTMServer::update: update failed (Elastica\Exception\ResponseException: MapperParsingException[failed to parse, document is empty]); retrying.

Fatal error: Uncaught exception 'Elastica\Exception\ResponseException' with message 'MapperParsingException[failed to parse, document is empty]' in /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Transport/Http.php:146
Stack trace:
#0 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Request.php(168): Elastica\Transport\Http->exec()
#1 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Client.php(592): Elastica\Request->send()
#2 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Index.php(444): Elastica\Client->request()
#3 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Type.php(511): Elastica\Index->request()
#4 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Type.php(90): Elastica\Type->request()
#5 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/ttmserver/ElasticSearchTTMServer.php(238): Elastica\Type->addDocument()
#6 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/ttmserver/TTMServer.php(140): ElasticSearchTTMServer->update()
#7 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/TranslateEditAddons.php(186): TTMServer::onChange()
#8 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/Hooks.php(209): TranslateEditAddons::onSave()
#9 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/page/WikiPage.php(2014): Hooks::run()
#10 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/utils/MessageUpdateJob.php(44): WikiPage->doEditContent()
#11 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/jobqueue/JobRunner.php(136): MessageUpdateJob->run()
#12 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/runJobs.php(80): JobRunner->run()
#13 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/doMaintenance.php(101): RunJobs->execute()
#14 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/runJobs.php(95): include()
#15 {main}
Unexpected non-MediaWiki exception encountered, of type "Elastica\Exception\ResponseException"
[2d00db39] [no req]   Elastica\Exception\ResponseException from line 146 of /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Transport/Http.php: MapperParsingException[failed to parse, document is empty]
Backtrace:
#0 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Request.php(168): Elastica\Transport\Http->exec(Elastica\Request, array)
#1 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Client.php(592): Elastica\Request->send()
#2 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Index.php(444): Elastica\Client->request(string, string, array, array)
#3 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Type.php(511): Elastica\Index->request(string, string, array, array)
#4 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Type.php(90): Elastica\Type->request(string, string, array, array)
#5 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/ttmserver/ElasticSearchTTMServer.php(238): Elastica\Type->addDocument(Elastica\Document)
#6 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/ttmserver/TTMServer.php(140): ElasticSearchTTMServer->update(MessageHandle, string)
#7 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/TranslateEditAddons.php(186): TTMServer::onChange(MessageHandle, string, boolean)
#8 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/Hooks.php(209): TranslateEditAddons::onSave(WikiPage, User, TextContent, string, integer, NULL, NULL, integer, Revision)
#9 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/page/WikiPage.php(2014): Hooks::run(string, array)
#10 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/utils/MessageUpdateJob.php(44): WikiPage->doEditContent(TextContent, string, integer, boolean, User)
#11 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/jobqueue/JobRunner.php(136): MessageUpdateJob->run()
#12 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/runJobs.php(80): JobRunner->run(array)
#13 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/doMaintenance.php(101): RunJobs->execute()
#14 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/runJobs.php(95): include(string)
#15 {main}

Fatal error: Uncaught exception 'Elastica\Exception\ResponseException' with message 'MapperParsingException[failed to parse, document is empty]' in /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Transport/Http.php:146
Stack trace:
#0 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Request.php(168): Elastica\Transport\Http->exec()
#1 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Client.php(592): Elastica\Request->send()
#2 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Index.php(444): Elastica\Client->request()
#3 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Type.php(511): Elastica\Index->request()
#4 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Type.php(90): Elastica\Type->request()
#5 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/ttmserver/ElasticSearchTTMServer.php(238): Elastica\Type->addDocument()
#6 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/ttmserver/TTMServer.php(140): ElasticSearchTTMServer->update()
#7 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/TranslateEditAddons.php(186): TTMServer::onChange()
#8 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/Hooks.php(209): TranslateEditAddons::onSave()
#9 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/page/WikiPage.php(2014): Hooks::run()
#10 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/utils/MessageUpdateJob.php(44): WikiPage->doEditContent()
#11 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/jobqueue/JobRunner.php(136): MessageUpdateJob->run()
#12 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/runJobs.php(80): JobRunner->run()
#13 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/doMaintenance.php(101): RunJobs->execute()
#14 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/runJobs.php(95): include()
#15 {main}
Unexpected non-MediaWiki exception encountered, of type "Elastica\Exception\ResponseException"
[0eca412a] [no req]   Elastica\Exception\ResponseException from line 146 of /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Transport/Http.php: MapperParsingException[failed to parse, document is empty]
Backtrace:
#0 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Request.php(168): Elastica\Transport\Http->exec(Elastica\Request, array)
#1 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Client.php(592): Elastica\Request->send()
#2 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Index.php(444): Elastica\Client->request(string, string, array, array)
#3 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Type.php(511): Elastica\Index->request(string, string, array, array)
#4 /srv/mediawiki/tags/2015-01-18_22:08:56/vendor/ruflin/elastica/lib/Elastica/Type.php(90): Elastica\Type->request(string, string, array, array)
#5 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/ttmserver/ElasticSearchTTMServer.php(238): Elastica\Type->addDocument(Elastica\Document)
#6 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/ttmserver/TTMServer.php(140): ElasticSearchTTMServer->update(MessageHandle, string)
#7 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/TranslateEditAddons.php(186): TTMServer::onChange(MessageHandle, string, boolean)
#8 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/Hooks.php(209): TranslateEditAddons::onSave(WikiPage, User, TextContent, string, integer, NULL, NULL, integer, Revision)
#9 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/page/WikiPage.php(2014): Hooks::run(string, array)
#10 /srv/mediawiki/tags/2015-01-18_22:08:56/extensions/Translate/utils/MessageUpdateJob.php(44): WikiPage->doEditContent(TextContent, string, integer, boolean, User)
#11 /srv/mediawiki/tags/2015-01-18_22:08:56/includes/jobqueue/JobRunner.php(136): MessageUpdateJob->run()
#12 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/runJobs.php(80): JobRunner->run(array)
#13 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/doMaintenance.php(101): RunJobs->execute()
#14 /srv/mediawiki/tags/2015-01-18_22:08:56/maintenance/runJobs.php(95): include(string)
#15 {main}

Event Timeline

Nemo_bis raised the priority of this task from to Medium.
Nemo_bis updated the task description. (Show Details)
Nemo_bis added subscribers: Nemo_bis, Nikerabbit.

intense.log on the ES instance has things like

[2015-01-24 10:15:12,263][DEBUG][action.index             ] [Living Mummy] [ttmserver][1], node[icYyHm-hQJmIgVEEOtevJQ], [P], s[STARTED]: Faile
d to execute [index {[ttmserver][message][intense-Z:englobe-dpkg-man--a4d68f-The source package version.-0/sv], source[_na_]}]
org.elasticsearch.index.mapper.MapperParsingException: failed to parse, document is empty

That title is indeed empty, while without -0 it exists (though with encoding issues, apparently). Where is the error?

The message key is constructed of dbprefix-title-revid. We just had similar bug in translatewiki.net where invalid utf-8 in message resulted in empty export file. I think the best option here is to refuse to touch files which are not valid utf-8, because everything will blow up in unexpected ways if that stuff ends up in the database.

I agree, but it would be nice to catch the exception.

Catch it and do what? Silently ignore the error?

Silently ignore, or log, anything but die.

I'm finding more examples with the following (to report upstream):

$ grep -B 1 "update failed" /var/log/jobqueue.log | grep STARTING
\ fuzzy= (id=145716) STARTING
2015-01-24 12:12:41 MessageUpdateJob Z:englobe-dselect--2092cb-doupdate_failed/en content=doupdate failed fuzzy= (id=139481) STARTING
2015-01-29 13:15:16 MessageUpdateJob Z:gnu-www-ja-copyright-and-globalization--788a8f-Now_for_the_first_few_centurie/ro content=Acum, în primele secole ale tiparului, cărțile tipărite nu au înlocuit complet copierea manuală. Încă se mai făceau cărți copiate de mână, uneori de către oameni bogați, iar alteori de către oameni săraci. Oamenii bogați făceau aceasta pentru a obține o copie deosebit de frumoasă care să arate cât de bogați sunt, iar oamenii săraci o făceau pentru că poate nu aveau destui bani să cumpere o copie tipărită, dar aveau timp să copieze o carte de mână. Vorba cântecului, „Timpul nu este bani când timpul este tot ce ai”. fuzzy= (id=164791) STARTING
\ fuzzy= (id=241307) STARTING
2015-01-29 13:20:16 MessageUpdateJob Z:gnu-gawk--bdf9e6-sleep:_missing_required_numeri/ca content=sleep: no hi ha un argument num�ric requerit fuzzy= (id=227255) STARTING
2015-01-29 13:25:17 MessageUpdateJob Z:gnu-gcl-binutils--d248e9-fontdir_device_name/fr content=nom du p�riph�rique fontdir fuzzy= (id=181686) STARTING
2015-01-29 13:30:10 MessageUpdateJob Z:gnu-www-ja-bokma-gnu--a22175-Please_see_the_=3Ca_href=3D"/serve/en content=Please see the <a href="/server/standards/README.translations.html">Translations README</a> for information on coordinating and submitting translations of this article. fuzzy= (id=58092) STARTING
2015-01-29 13:30:21 MessageUpdateJob Z:gnu-gawk--513f10-xor:_argument_=25d_negative_valu/it content=xor: argomento %d, valore negativo %g dar� risultati strani fuzzy= (id=232389) STARTING

Sigh, 882 po files which are not UTF-8: P238, according to nemobis@ttmserver-mediawiki01:/data/scratch/ttmserver-repolibrary$ find -type f -name '*.po' -print0 | xargs -0 file | grep -v UTF-8.

I reported gnu-gawk and disabled some languages but this is too much to handle on a case by case basis.

MariaDB [intense]> select count(*) from job where job_attempts > 0 limit 10;
+----------+
| count(*) |
+----------+
|    14376 |
+----------+
1 row in set (0.01 sec)

I kept a list of job_title in ~nemobis

Nikerabbit renamed this task from Fatal error: Uncaught exception 'Elastica\Exception\ResponseException' with message 'MapperParsingException[failed to parse, document is empty]' to Validate and normalize file contents for UTF-8 in FFS.Feb 7 2015, 12:10 PM
Nikerabbit set Security to None.
gerritbot added a subscriber: gerritbot.

Change 189191 had a related patch set uploaded (by Nikerabbit):
Validate and normalize file contents in FFS

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

Patch-For-Review

Change 189191 merged by jenkins-bot:
Validate and normalize file contents in FFS

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

Thanks! Now, how to test this? Resync the problematic groups and see what happens?