Page MenuHomePhabricator

Strange secondary error "Class 'WebRequest' not found" in logs after errors like "extension.json is not a valid JSON file"
Open, Needs TriagePublic

Description

To reproduce, make a typo in extension.json. The following will appear in logs:

[Wed Aug 26 04:03:15.514476 2020] [php7:notice] [pid 1016] [client 127.0.0.1:40328] PHP Fatal error: Uncaught Exception: /var/www/html/trunkwiki/extensions/Something/extension.json is not a valid JSON file. in [...]
[Wed Aug 26 04:03:15.520782 2020] [php7:notice] [pid 1016] [client 127.0.0.1:40328] PHP Fatal error: Uncaught Error: Class 'WebRequest' not found in /var/www/html/trunkwiki/includes/HeaderCallback.php:63\nStack trace:\n#0 [internal function]: MediaWiki\\HeaderCallback::callback()\n#1 {main}\n thrown in /var/www/html/trunkwiki/includes/HeaderCallback.php on line 63

This is possibly harmless (because invalid extension.json is fatal error anyway), but the cause of this message is unclear, + message is strange/confusing and shouldn't be in the logs.
This didn't happen in 1.34, but happens in 1.35.

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptAug 26 2020, 1:13 AM

@edwardspec Could you include the stack trace for the first fatal error? (Relating to extension.json.) This would help confirm the hypthesis that this ocurrs before the autoloader is ready and thus WebRequest is not yet loadable.

[Wed Aug 26 04:03:15.514476 2020] [php7:notice] [pid 1016] [client 127.0.0.1:40328] PHP Fatal error:  Uncaught Exception: /var/www/html/trunkwiki/extensions/Something/extension.json is not a valid JSON file. in /var/www/html/trunkwiki/includes/registration/ExtensionRegistry.php:347\nStack trace:\n#0 /var/www/html/trunkwiki/includes/registration/ExtensionRegistry.php(229): ExtensionRegistry->readFromQueue(Array)\n#1 /var/www/html/trunkwiki/includes/Setup.php(161): ExtensionRegistry->loadFromQueue()\n#2 /var/www/html/trunkwiki/includes/WebStart.php(89): require_once('/var/www/html/t...')\n#3 /var/www/html/trunkwiki/index.php(44): require('/var/www/html/t...')\n#4 {main}\n  thrown in /var/www/html/trunkwiki/includes/registration/ExtensionRegistry.php on line 347

The autoloader has to be registered already for the ExtensionRegistry class to be loaded in the first place...I was able to reproduce this locally though (only on a fresh wiki, not my dev wiki for some reason...). Sticking a class_exists('WebRequest') at the top of HeaderCallback::callback() yields false, which doesn't make sense to be why the autoloader is being skipped.

It's also noted that while the code in question here is new in rMWfaca43e3f72f: Set X-Request-Id on all web responses, code that uses WebRequest (and other classes that would be autoloaded) have been there for years rMWf193271cffbc: Log a backtrace from the culprit location if headers were already sent... Whether commonly exercised, is a different question

Reedy added a comment.Sat, Sep 26, 2:28 AM

Another report of this on IRC

[03:24:16] <foreclosurepedia> MW 1.34.2 upgrade to 1.35: Hosting provider tried to update and got following error: 2020-09-26 02:17:55.314738 [NOTICE] [225519] [31.41.218.11:53218] [STDERR] PHP Fatal error:  Uncaught Error: Class 'WebRequest' not found in /home/iafstghq/digitalmatrixgroup.com/includes/HeaderCallback.php:63  thrown in
[03:24:16] <foreclosurepedia> /home/iafstghq/digitalmatrixgroup.com/includes/HeaderCallback.php on line 63
[03:24:51] <foreclosurepedia> *Upgrade.
Tgr added a comment.Sat, Sep 26, 3:46 AM
$ cat test.php 
<?php

spl_autoload_register( function () {
        class Autoloaded {}
} );

header_register_callback( function () {
	new Autoloaded();
} );

throw new Exception();

$ php test.php
PHP Fatal error:  Uncaught Exception in test.php:16
Stack trace:
#0 {main}
  thrown in test.php on line 16
PHP Fatal error:  Uncaught Error: Class 'Autoloaded' not found in test.php:13
Stack trace:
#0 [internal function]: {closure}()
#1 {main}
  thrown in test.php on line 13

I guess this is a PHP bug? With register_shutdown_function for example autoloading after a fatal works fine.

Tgr added a comment.Sat, Sep 26, 3:49 AM

I can't reproduce on 3v4l but maybe it just aborts on fatals more aggressively.

Reedy added a comment.Sat, Sep 26, 6:50 PM

Another report of this on IRC

[03:24:16] <foreclosurepedia> MW 1.34.2 upgrade to 1.35: Hosting provider tried to update and got following error: 2020-09-26 02:17:55.314738 [NOTICE] [225519] [31.41.218.11:53218] [STDERR] PHP Fatal error:  Uncaught Error: Class 'WebRequest' not found in /home/iafstghq/digitalmatrixgroup.com/includes/HeaderCallback.php:63  thrown in
[03:24:16] <foreclosurepedia> /home/iafstghq/digitalmatrixgroup.com/includes/HeaderCallback.php on line 63
[03:24:51] <foreclosurepedia> *Upgrade.

And again, it was related to an extension.json issue it seems

Fatal error: Uncaught UnexpectedValueException: callback 'MapsRegistration::onRegistration' is not callable in /home/iafstghq/digitalmatrixgroup.com/includes/registration/ExtensionRegistry.php:539 Stack trace: #0 /home/iafstghq/digitalmatrixgroup.com/includes/registration/ExtensionRegistry.php(232): ExtensionRegistry->exportExtractedData(Array) #1 /home/iafstghq/digitalmatrixgroup.com/includes/Setup.php(161): ExtensionRegistry->loadFromQueue() #2 /home/iafstghq/digitalmatrixgroup.com/includes/WebStart.php(89): require_once('/home/iafstghq/...') #3 /home/iafstghq/digitalmatrixgroup.com/index.php(44): require('/home/iafstghq/...') #4 {main} thrown in /home/iafstghq/digitalmatrixgroup.com/includes/registration/ExtensionRegistry.php on line 539

Change 630354 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/core@master] Preload class used in HeaderCallback

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

Tgr added a comment.Tue, Sep 29, 3:39 AM

FWIW this was fixed at some point in PHP (could not reproduce it with PHP 8 beta).

Reedy added a comment.Tue, Sep 29, 7:32 PM

FWIW this was fixed at some point in PHP (could not reproduce it with PHP 8 beta).

Is it worth upstreaming it to see if they can narrow it down and backport to 7.4, and maybe even 7.3 (even if that's EOL soon)

The same secondary message might appear in other contexts. In my case it is:

[Thu Oct 01 05:09:55.814806 2020] [php7:warn] [pid 3581] [client 2.0.0.15:59543] PHP Warning:  require_once(/extensions/Push/Push.php): failed to open stream: No such file or directory in /hd/xatu/srv/www/mediawiki/sites/wiki.bitplan.com/BITPlanSettings.php on line 9, referer: http://merkur.bitplan.com/
[Thu Oct 01 05:09:55.814906 2020] [php7:error] [pid 3581] [client 2.0.0.15:59543] PHP Fatal error:  require_once(): Failed opening required '/extensions/Push/Push.php' (include_path='/hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/vendor/pear/console_getopt:/hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/vendor/pear/mail:/hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/vendor/pear/mail_mime:/hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/vendor/pear/net_smtp:/hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/vendor/pear/net_socket:/hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/vendor/pear/pear-core-minimal/src:/hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/vendor/pear/pear_exception:.:/usr/share/php') in /hd/xatu/srv/www/mediawiki/sites/wiki.bitplan.com/BITPlanSettings.php on line 9, referer: http://merkur.bitplan.com/
[Thu Oct 01 05:09:55.815393 2020] [php7:error] [pid 3581] [client 2.0.0.15:59543] PHP Fatal error:  Uncaught Error: Class 'WebRequest' not found in /hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/includes/HeaderCallback.php:63\nStack trace:\n#0 [internal function]: MediaWiki\\HeaderCallback::callback()\n#1 {main}\n  thrown in /hd/xatu/srv/www/mediawiki/mediawiki-1.35.0/includes/HeaderCallback.php on line 63, referer: http://merkur.bitplan.com/

The errore message doesn't make much sense like this infact it's only the variable $IP that is not set which makes require_once look in a wrong directory.

Reedy added a comment.Thu, Oct 1, 8:39 PM

Amusingly, Beta is failing with this too atm

21:36:38 20:36:38 Checking for new runtime errors locally
21:36:42 20:36:42 Scap failed!: Call to mwscript eval.php returned: 255
21:36:42 20:36:42 stderr: Fatal error: Uncaught ConfigException: Failed to load configuration from etcd: (curl error: 7) Couldn't connect to server in /srv/mediawiki-staging/php-master/includes/config/EtcdConfig.php:202
21:36:42 Stack trace:
21:36:42 #0 /srv/mediawiki-staging/php-master/includes/config/EtcdConfig.php(124): EtcdConfig->load()
21:36:42 #1 /srv/mediawiki-staging/wmf-config/CommonSettings.php(132): EtcdConfig->getModifiedIndex()
21:36:42 #2 /srv/mediawiki-staging/php-master/LocalSettings.php(5): require('/srv/mediawiki-...')
21:36:42 #3 /srv/mediawiki-staging/php-master/includes/Setup.php(143): require_once('/srv/mediawiki-...')
21:36:42 #4 /srv/mediawiki-staging/php-master/maintenance/doMaintenance.php(90): require_once('/srv/mediawiki-...')
21:36:42 #5 /srv/mediawiki-staging/php-master/maintenance/CommandLineInc.php(74): require('/srv/mediawiki-...')
21:36:42 #6 /srv/mediawiki-staging/php-master/maintenance/eval.php(39): require_once('/srv/mediawiki-...')
21:36:42 #7 /srv/mediawiki-staging/multiversion/MWScript.php(101): require_once('/srv/mediawiki-...')
21:36:42 #8 {main}
21:36:42   thrown in /srv/mediawiki-staging/php-master/includes/config/EtcdConfig.php on line 202
21:36:42 Fatal error: Uncaught Error: Class 'WebRequest' not found in /srv/mediawiki-staging/php-master/includes/HeaderCallback.php:63
21:36:42 Stack trace:
21:36:42 #0 [internal function]: MediaWiki\HeaderCallback::callback()
21:36:42 #1 {main}
21:36:42   thrown in /srv/mediawiki-staging/php-master/includes/HeaderCallback.php on line 63
``
CDanis added a subscriber: CDanis.Sat, Oct 3, 2:08 AM
ema added a subscriber: ema.Mon, Oct 5, 7:22 AM

Amusingly, Beta is failing with this too atm

21:36:38 20:36:38 Checking for new runtime errors locally
21:36:42 20:36:42 Scap failed!: Call to mwscript eval.php returned: 255
21:36:42 20:36:42 stderr: Fatal error: Uncaught ConfigException: Failed to load configuration from etcd: (curl error: 7) Couldn't connect to server in /srv/mediawiki-staging/php-master/includes/config/EtcdConfig.php:202
21:36:42 Stack trace:
21:36:42 #0 /srv/mediawiki-staging/php-master/includes/config/EtcdConfig.php(124): EtcdConfig->load()
21:36:42 #1 /srv/mediawiki-staging/wmf-config/CommonSettings.php(132): EtcdConfig->getModifiedIndex()
21:36:42 #2 /srv/mediawiki-staging/php-master/LocalSettings.php(5): require('/srv/mediawiki-...')
21:36:42 #3 /srv/mediawiki-staging/php-master/includes/Setup.php(143): require_once('/srv/mediawiki-...')
21:36:42 #4 /srv/mediawiki-staging/php-master/maintenance/doMaintenance.php(90): require_once('/srv/mediawiki-...')
21:36:42 #5 /srv/mediawiki-staging/php-master/maintenance/CommandLineInc.php(74): require('/srv/mediawiki-...')
21:36:42 #6 /srv/mediawiki-staging/php-master/maintenance/eval.php(39): require_once('/srv/mediawiki-...')
21:36:42 #7 /srv/mediawiki-staging/multiversion/MWScript.php(101): require_once('/srv/mediawiki-...')
21:36:42 #8 {main}
21:36:42   thrown in /srv/mediawiki-staging/php-master/includes/config/EtcdConfig.php on line 202
21:36:42 Fatal error: Uncaught Error: Class 'WebRequest' not found in /srv/mediawiki-staging/php-master/includes/HeaderCallback.php:63
21:36:42 Stack trace:
21:36:42 #0 [internal function]: MediaWiki\HeaderCallback::callback()
21:36:42 #1 {main}
21:36:42   thrown in /srv/mediawiki-staging/php-master/includes/HeaderCallback.php on line 63
``

That's because extensions disappeared from beta, fixed in T264563. Scap is running (https://integration.wikimedia.org/ci/job/beta-scap-eqiad/319599/console), and it should complete w/o errors.

Reedy added a comment.EditedMon, Oct 5, 11:38 AM

No its not. It’s a different error ;)

The etcd host had been turned off for maintenance, and was fixed when it was turned on again. Hence Couldn't connect to server in /srv/mediawiki-staging/php-master/includes/config/EtcdConfig.php:202

I only posted it on here as it was another example of this error, but one that didn't involve any extensions

Change 630354 merged by jenkins-bot:
[mediawiki/core@master] Preload class used in HeaderCallback

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

Change 632562 had a related patch set uploaded (by Reedy; owner: Gergő Tisza):
[mediawiki/core@REL1_35] Preload class used in HeaderCallback

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

Change 632679 had a related patch set uploaded (by Jforrester; owner: Gergő Tisza):
[mediawiki/core@wmf/1.36.0-wmf.12] Preload class used in HeaderCallback

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

Change 632680 had a related patch set uploaded (by Hashar; owner: Gergő Tisza):
[mediawiki/core@wmf/1.36.0-wmf.10] Preload class used in HeaderCallback

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

Change 632681 had a related patch set uploaded (by Jforrester; owner: Gergő Tisza):
[mediawiki/core@wmf/1.36.0-wmf.11] Preload class used in HeaderCallback

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

Change 632680 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.10] Preload class used in HeaderCallback

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

Mentioned in SAL (#wikimedia-operations) [2020-10-07T18:12:06Z] <hashar@deploy1001> Synchronized php-1.36.0-wmf.10/includes/HeaderCallback.php: Preload class used in HeaderCallback - T261260 (duration: 01m 01s)

Tgr added a comment.Wed, Oct 7, 6:29 PM

Is it worth upstreaming it to see if they can narrow it down and backport to 7.4, and maybe even 7.3 (even if that's EOL soon)

We probably should, yeah.

Change 632681 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.11] Preload class used in HeaderCallback

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

Change 632679 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.12] Preload class used in HeaderCallback

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

Tgr added a comment.Fri, Oct 9, 11:58 PM

Is it worth upstreaming it to see if they can narrow it down and backport to 7.4, and maybe even 7.3 (even if that's EOL soon)

We probably should, yeah.

Looks like this might be #79718. According to which, what actually matters is not the fatal but the lack of output and the same can happen for e.g. 301 or 204 responses. Which checks out - the test case in T261260#6495675 works just as well without the exception throwing.

To quote from that bug: the callback is running when output is being flushed after script execution and when autoloading is no longer available ... Which leads to an easy solution: have your script flush at the end. So the more robust fix would be to call flush() somewhere, probably right before MediaWiki::doPostOutputShutdown().