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

@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

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.
$ 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.

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

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

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

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.

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
``

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.

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)

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

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().

In case other people automating MediaWiki installs arrive here... I found that this issue only occurs for the first command that is run after php maintenance/install.php and also that a web request also causes an error to be avoided, so I've added one to Ansible role I'm updating for automating MediaWiki 1.35.0 installs.

This is the error I was getting with PHP7.3 on Debian when trying to set the admin email address after running the CLI install script:

php maintenance/resetUserEmail.php Admin chris@webarchitects.co.uk
PHP Notice:  getimagesize(): Read error! in /home/wiki/sites/135/w/extensions/UploadLogo/SpecialUploadLogo.php on line 202
PHP Warning:  copy(): The first argument to copy() function cannot be a directory in /home/wiki/sites/135/w/extensions/UploadLogo/SpecialUploadLogo.php on line 284
PHP Warning:  copy(/home/wiki/sites/135/w/images/logo/candidate/20201108-94bb18940e): failed to open stream: No such file or directory in /home/wiki/sites/135/w/extensions/UploadLogo/SpecialUploadLogo.php on line 175
PHP Fatal error:  Uncaught Exception: Error Processing Request in /home/wiki/sites/135/w/extensions/UploadLogo/SpecialUploadLogo.php:176
Stack trace:
#0 /home/wiki/sites/135/w/extensions/UploadLogo/UploadLogo.hooks.php(47): SpecialUploadLogo->changeLogo('/home/wiki/site...', '/home/wiki/site...')
#1 /home/wiki/sites/135/w/includes/registration/ExtensionRegistry.php(541): UploadLogoHooks::onExtensionLoad(Array)
#2 /home/wiki/sites/135/w/includes/registration/ExtensionRegistry.php(232): ExtensionRegistry->exportExtractedData(Array)
#3 /home/wiki/sites/135/w/includes/Setup.php(161): ExtensionRegistry->loadFromQueue()
#4 /home/wiki/sites/135/w/maintenance/doMaintenance.php(91): require_once('/home/wiki/site...')
#5 /home/wiki/sites/135/w/maintenance/resetUserEmail.php(82): require_once('/home/wiki/site...')
#6 {main}
  thrown in /home/wiki/sites/135/w/extensions/UploadLogo/SpecialUploadLogo.php on line 176
PHP Fatal error:  Uncaught Error: Class 'WebRequest' not found in /home/wiki/sites/135/w/includes/HeaderCallback.php:63
Stack trace:
#0 [internal function]: MediaWiki\HeaderCallback::callback()
#1 {main}
  thrown in /home/wiki/sites/135/w/includes/HeaderCallback.php on line 63

You've still seemingly got some configuration issue relating to the UploadLogo extension... Which seems to be the pattern of an early-ish triggered warning/fatal causing Uncaught Error: Class 'WebRequest' not found... Should be fixed in 1.35.1

Presumably your web request acts in a opcache warming role?

Thanks, I have checked and you are right, I don't get the error when no extra extensions are automatically installed or when the additional extensions are all installed apart from the UploadLogo extension.

Please don't report the companion errors to "WebRequest not found" in this task; they could be pretty much anything. Use the support desk, or, if you are confident it's a bug, file a separate report.

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

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

Seen on T268141: Scap beta failing on mweval, we seem to have the same issue with RequestContext as we do with WebRequest

03:14:22 Fatal error: Uncaught Error: Class 'RequestContext' not found in /srv/mediawiki-staging/php-master/includes/WebRequest.php:333
03:14:22 Stack trace:
03:14:22 #0 /srv/mediawiki-staging/php-master/includes/HeaderCallback.php(70): WebRequest::getRequestId()
03:14:22 #1 [internal function]: MediaWiki\HeaderCallback::callback()
03:14:22 #2 {main}
03:14:22   thrown in /srv/mediawiki-staging/php-master/includes/WebRequest.php on line 333

Change 641871 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/core@master] HeaderCallback: pre-cache request ID

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

Change 641871 merged by jenkins-bot:
[mediawiki/core@master] HeaderCallback: pre-cache request ID

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

Change 649694 had a related patch set uploaded (by Reedy; owner: Gergő Tisza):
[mediawiki/core@REL1_35] HeaderCallback: pre-cache request ID

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

Change 649694 merged by jenkins-bot:
[mediawiki/core@REL1_35] HeaderCallback: pre-cache request ID

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

Happened e.g. today when trying to install extension HitCounters on MediaWiki 1.35.

Happened e.g. today when trying to install extension HitCounters on MediaWiki 1.35.

1.35.0? 1.35.1?

What's the exact error message?

@Seppl2013: Could you please answer the last comment? Thanks in advance!

I am sorry - i did not record the message. Today I tried with HitCounters-REL1_35-52da1b7.tar.gz and the problem didn't show up.