"PHP Warning: filemtime(): No such file or directory" about files removed over a year ago
Closed, ResolvedPublic

Description

When enabling debug logging via X-Wikimedia-Debug I found a few instances of PHP Warning: filemtime(): No such file or directory in the logs. I tested on various urls and domains, and found they only happen on a mobile request, such as https://en.m.wikipedia.org/w/load.php?debug=false&lang=en&modules=startup&only=scripts&skin=minerva&target=mobile

Stack trace:

MWExceptionHandler::handleError
  /srv/mediawiki/php-1.29.0-wmf.11/includes/utils/FileContentsHasher.php:60
FileContentsHasher::getFileContentsHashInternal
  /srv/mediawiki/php-1.29.0-wmf.11/includes/utils/FileContentsHasher.php:102
FileContentsHasher::getFileContentsHash
  /srv/mediawiki/php-1.29.0-wmf.11/includes/resourceloader/ResourceLoaderModule.php:981
...
ResourceLoaderFileModule::getFileHashes
  /srv/mediawiki/php-1.29.0-wmf.11/includes/resourceloader/ResourceLoaderFileModule.php:580
..
ResourceLoaderModule::getVersionHash
  /srv/mediawiki/php-1.29.0-wmf.11/includes/resourceloader/ResourceLoader.php:646
..
  /srv/mediawiki/php-1.29.0-wmf.11/includes/resourceloader/ResourceLoaderStartUpModule.php
..
  /srv/mediawiki/w/load.php

These errors aren't in the usual error logs because they have "suppressed":true, and the code in question is wrapped between suppressWarnings(), however that doesn't change the fact that it seems MobileFrontend is registering a CSS, JS or Image file in a module somewhere that doesn't exist.

Unfortunately, the error doesn't specify the file path in question.

Krinkle created this task.Feb 14 2017, 7:32 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptFeb 14 2017, 7:32 PM

Added some instrumentation on mwdebug1001 and found the following:

 public function getFileContentsHashInternal(
 	$mtime = filemtime( $filePath );
 	if ( $mtime === false ) {
+		wfDebugLog( 'wfDebug', '[krinkle] ' . __METHOD__ . ': ' . $filePath );
 		return false;
[krinkle] FileContentsHasher::getFileContentsHashInternal: /srv/mediawiki/php-1.29.0-wmf.11/resources/src/jquery/images/sort_both.gif
[krinkle] FileContentsHasher::getFileContentsHashInternal: /srv/mediawiki/php-1.29.0-wmf.11/resources/src/jquery/images/sort_down.gif

The gif files have not existed since January 2016 (over a year ago; 9080b6f763a). A Wikimedia Git search didn't turn up any results or references.

I also did an ack search on mwdebug1001 in php-1.29.0-wmf.11/ and there were no matches for sort_both.gif. The only match for sort_both is in core, for the svg and png.

krinkle@mwdebug1001:/srv/mediawiki/php-1.29.0-wmf.11$ ack sort_both -Q
resources/src/jquery/jquery.tablesorter.less
6:	.background-image-svg( 'images/sort_both.svg', 'images/sort_both.png' );

Same for sort_down.

Krinkle added a comment.EditedFeb 14 2017, 7:54 PM

Added more instrumentation to log the module name as well. Turns out, it claims to come from the core jquery.tablesorter module. Which suggests something somewhere it using an over 1-year old stale interpretation of this file, despite the copy on disk being up to date.

[krinkle] FileContentsHasher module jquery.tablesorter file /srv/mediawiki/php-1.29.0-wmf.11/resources/src/jquery/images/sort_up.gif
[krinkle] FileContentsHasher module jquery.tablesorter file /srv/mediawiki/php-1.29.0-wmf.11/resources/src/jquery/images/sort_down.gif
[krinkle] FileContentsHasher module jquery.tablesorter file /srv/mediawiki/php-1.29.0-wmf.11/resources/src/jquery/images/sort_both.gif

Also got two more from other modules:

[krinkle] FileContentsHasher module ext.cx.tools.mt file /srv/mediawiki/php-1.29.0-wmf.11/extensions/ContentTranslation/modules/tools/styles/ext.cx.tools.mt.less

[krinkle] FileContentsHasher module ext.templateDataGenerator.ui file /srv/mediawiki/php-1.29.0-wmf.11/extensions/TemplateData/modules/images/parameter-ltr.svg
Krinkle changed the title from ""PHP Warning: filemtime(): No such file or directory" from a mobile RL module" to ""PHP Warning: filemtime(): No such file or directory" about files removed over a year ago".Feb 14 2017, 8:11 PM
Krinkle edited projects, added Performance-Team; removed MediaWiki-jQuery-Tablesorter.

The only source of information in ResourceLoaderFileModule::getFileHashes() that does not directly come from a file on disk (or from a compilation cache that is trusted, short-lived, and uses verifiable keys; such as the LESS cache in APC) - is the module_deps table used for caching references to images from a CSS file - which is lazily populated when the module is first requested after a cache miss triggered by the new hash in the startup module.

It's added to getFileHashes() via the call to getFileDependencies(). Looking in the module_deps table I see that most entries look fine. For example:

md_modulemd_skinmd_deps
jquery.tablesortervector∣en["resources/src/jquery/images/sort_both.png","resources/src/jquery/images/sort_both.svg","resources/src/jquery/images/sort_down.png","resources/src/jquery/images/sort_down.svg","resources/src/jquery/images/sort_up.png","resources/src/jquery/images/sort_up.svg","resources/src/jquery/jquery.tablesorter.less","resources/src/mediawiki.less/mediawiki.mixins.less"]
jquery.tablesortercologneblue∣ar["resources/src/jquery/images/sort_both.png","resources/src/jquery/images/sort_both.svg","resources/src/jquery/images/sort_down.png","resources/src/jquery/images/sort_down.svg","resources/src/jquery/images/sort_up.png","resources/src/jquery/images/sort_up.svg","resources/src/jquery/jquery.tablesorter.less","resources/src/mediawiki.less/mediawiki.mixins.less"]
jquery.tablesortercologneblue∣en["resources/src/jquery/images/sort_both.png","resources/src/jquery/images/sort_both.svg","resources/src/jquery/images/sort_down.png","resources/src/jquery/images/sort_down.svg","resources/src/jquery/images/sort_up.png","resources/src/jquery/images/sort_up.svg","resources/src/jquery/jquery.tablesorter.less","resources/src/mediawiki.less/mediawiki.mixins.less"]

But, others are outdated:

SELECT * FROM module_deps WHERE md_module='jquery.tablesorter' AND md_deps LIKE '%gif%';
..
56 rows in set

Of these 56, most are bogus skin names which were probably simply not requested since Jan 2016 and are therefore outdated by design (the cache being lazily populated and invalidated on-demand). However, a handful of these are definitely not bogus, requested all the time, and have no excuse for being stale.
Most notably, it includes minerva|en. Which explains why this particular error only shows up on mobile. Here's a few samples:

md_modulemd_skinmd_deps
jquery.tablesortercologneblue∣cr["resources/src/jquery/images/sort_both.gif","resources/src/jquery/images/sort_down.gif","resources/src/jquery/images/sort_up.gif"]
jquery.tablesortercologneblue∣zh-hans["resources/src/jquery/images/sort_both.gif","resources/src/jquery/images/sort_down.gif","resources/src/jquery/images/sort_up.gif"]
jquery.tablesorterminerva∣en["resources/src/jquery/images/sort_both.gif","resources/src/jquery/images/sort_down.gif","resources/src/jquery/images/sort_up.gif"]
jquery.tablesortermodern∣et["resources/src/jquery/images/sort_both.gif","resources/src/jquery/images/sort_down.gif","resources/src/jquery/images/sort_up.gif"]
jquery.tablesortermonobook∣bn["resources/src/jquery/images/sort_both.gif","resources/src/jquery/images/sort_down.gif","resources/src/jquery/images/sort_up.gif"]
jquery.tablesortermonobook∣cr["resources/src/jquery/images/sort_both.gif","resources/src/jquery/images/sort_down.gif","resources/src/jquery/images/sort_up.gif"]
jquery.tablesortervector∣1some_inexistent_file_wit["resources/src/jquery/images/sort_both.gif","resources/src/jquery/images/sort_down.gif","resources/src/jquery/images/sort_up.gif"]
jquery.tablesortervector∣response.write(9030127*90["resources/src/jquery/images/sort_both.gif","resources/src/jquery/images/sort_down.gif","resources/src/jquery/images/sort_up.gif"]

Change 337649 had a related patch set uploaded (by Krinkle):
resourceloader: Limit module_deps write lock to unique index

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

Krinkle claimed this task.Feb 15 2017, 8:28 PM
Gilles moved this task from Inbox to Doing on the Performance-Team board.Feb 15 2017, 8:51 PM

Change 337752 had a related patch set uploaded (by Krinkle):
resourceloader: Use upsert() instead of replace() for module_deps write

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

Krinkle triaged this task as "Low" priority.Feb 15 2017, 8:52 PM
Krinkle moved this task from Inbox to Accepted: Bugs on the MediaWiki-ResourceLoader board.
Krinkle moved this task from Accepted: Bugs to Assigned on the MediaWiki-ResourceLoader board.

Change 337752 merged by jenkins-bot:
resourceloader: Use upsert() instead of replace() for module_deps write

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

Change 337649 merged by jenkins-bot:
resourceloader: Limit module_deps write lock to unique index

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

Krinkle added a comment.EditedFeb 18 2017, 2:00 AM

Reminder: After this rolls out with the train to all wikis, run a script for each wiki to clear the module_deps tables.

It's okay for this to happen 2 days after the change is applied (for group0 and group1 wikis). It just means that any existing stale rows that cause warnings will linger for two additional days after already having lingered for almost a year.

Mentioned in SAL (#wikimedia-operations) [2017-02-21T20:47:40Z] <Krinkle> (terbium) sql --write testwiki 'DELETE FROM module_deps' (per T158105)

Mentioned in SAL (#wikimedia-operations) [2017-02-21T20:48:37Z] <Krinkle> (terbium) sql --write test2wiki 'DELETE FROM module_deps' (3687 rows affected, 0.01 sec) - per T158105.

Mentioned in SAL (#wikimedia-operations) [2017-02-24T22:46:28Z] <Krinkle> (terbium) sql --write mediawikiwiki 'DELETE FROM module_deps' (in batches of 500; 42292 rows affected) - per T158105.

Change 339791 had a related patch set uploaded (by Krinkle):
resourceloader: Add purgeModuleDeps.php maintenance script

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

Change 339792 had a related patch set uploaded (by Krinkle):
resourceloader: Add purgeModuleDeps.php maintenance script

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

Change 340860 had a related patch set uploaded (by Krinkle):
[mediawiki/core] resourceloader: Add purgeModuleDeps.php maintenance script

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

Change 339792 abandoned by Krinkle:
resourceloader: Add purgeModuleDeps.php maintenance script

Reason:
wmf.14 instead - https://gerrit.wikimedia.org/r/#/c/340860/

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

Change 339791 merged by Krinkle:
[mediawiki/core] resourceloader: Add purgeModuleDeps.php maintenance script

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

Change 340860 merged by Krinkle:
[mediawiki/core] resourceloader: Add purgeModuleDeps.php maintenance script

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

Mentioned in SAL (#wikimedia-operations) [2017-03-03T01:33:49Z] <Krinkle> terbium$ mwscript purgeModuleDeps.php --wiki test2wiki (T158105)

Mentioned in SAL (#wikimedia-operations) [2017-03-03T01:34:07Z] <Krinkle> terbium$ foreachwikiindblist group0 purgeModuleDeps.php (T158105)

Mentioned in SAL (#wikimedia-operations) [2017-03-03T01:34:37Z] <Krinkle> terbium$ foreachwiki purgeModuleDeps.php (T158105)