Page MenuHomePhabricator

PHP fatal error handler not working on mwdebug servers
Closed, ResolvedPublic

Description

When using https://en.wikipedia.org/w/fatal-error.php to generate a fatal error (e.g. action=nomethod), it shows an error page generated by HHVM (and soon PHP 7).

This page shows the PHP error at the bottom of the page, and also (in PHP) sends an increment to Graphite.

This code is puppetised as /etc/hhvm/fatal-error.php (and previously under wmf-config:/errorpages).

When enabling X-Wikimedia-Debug, though, it error page isn't being served by PHP. Instead, Varnish is hijacking the response and giving its own response instead.

This is making it harder to test this subsystem, and seems like a bug.

Reproduce:

  1. check https://en.wikipedia.org/w/fatal-error.php with X-Wikimedia-Debug off
  • We get the PHP error
  1. Check again, with X-Wikimedia-Debug on
  • we get
Request from a.b.c.d via cp1087 cp1087, Varnish XID 824167321
Error: 500, Internal Server Error at Fri, 10 May 2019 06:12:52 GMT
  1. Test again with both Enable PHP7.x and X-Wikimedia-Debug on
  • We get the PHP error

Details

Related Gerrit Patches:
operations/puppet : productiondebug_proxy: force http/1.1 when proxying
operations/puppet : productiondebug_proxy: force http/1.1 when proxying

Event Timeline

Krinkle created this task.Mar 7 2019, 4:15 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 7 2019, 4:15 PM
jijiki triaged this task as Medium priority.Mar 19 2019, 6:20 PM
jijiki added a subscriber: jijiki.May 9 2019, 7:21 PM

What is a bit more weird is that this works as expected with PHP7.

jijiki updated the task description. (Show Details)May 10 2019, 9:49 AM
jijiki updated the task description. (Show Details)May 10 2019, 9:52 AM
jijiki added a comment.EditedMay 10 2019, 10:33 AM

After some debugging on hassium, I found some interesting things:

Test 1:
Enabled: Beta feature, X-Wikimedia-Debug, PHP7.x
https://phabricator.wikimedia.org/P8507

Test 2:
Enabled: Beta feature, X-Wikimedia-Debug (no PHP7.x)
https://phabricator.wikimedia.org/P8508

So far it looks that we get different results depending on which engine we are using. The difference is that hhvm's error is never shown to the user

Moreover on Test 1 we have Content-Length: 429., but in Test 2 we have Content-Length: 0.

Lastly, on Test 2, hassium nginx says:

[error] 29589#29589: *5063 upstream prematurely closed connection while sending to client, client: ::ffff:10.64.0.132, server: _, request: "GET /w/fatal-error.php

and hhvm on mwdebug1002 says:

May  9 20:11:47 mwdebug1002 hhvm: #012Fatal error: Call to undefined function thisFunctionIntentionallyDoesNotExist() in /srv/mediawiki/w/fatal-error.php on line 121
May  9 20:11:47 mwdebug1002 hhvm[15582]: [Thu May  9 20:11:47 2019] [hphp] [15582:7f933bbff700:5066:000001] [] \nFatal error: Call to undefined function thisFunctionIntentionallyDoesNotExist() in /srv/mediawiki/w/fatal-error.php on line 121

Change 509848 had a related patch set uploaded (by Effie Mouzeli; owner: Effie Mouzeli):
[operations/puppet@production] debug_proxy: force http/1.1 when proxying

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

jijiki added a comment.EditedMay 13 2019, 1:53 PM

@Krinkle After a little more digging, looks like nginx in hassium is using HTTP/1.0 when forwarding requests to mwdebug*. My theory is that when HHVM returns a 500 and proto version is HTTP/1.0, it adds the Content-length: 0 header. Varnish in turn sees Content-length: 0, so it returns its own generic error since it believes there are no data to serve.

When throwing a 500 error with HTTP/1.1 to mwdebug, HHVM does not add a Content-length header.

Krinkle added a comment.EditedMay 14 2019, 10:34 PM

Not sure if the change went out or if something else happened related, but related as of today: T223336: [Regression] fatal-errors.php action=segfault results in a 503 error under php7-fpm.

Change 510305 had a related patch set uploaded (by Effie Mouzeli; owner: Effie Mouzeli):
[operations/puppet@production] debug_proxy: force http/1.1 when proxying

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

Change 509848 abandoned by Effie Mouzeli:
debug_proxy: force http/1.1 when proxying

Reason:
Rebase conflicts, re-uploaded as 510305

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

Change 510305 merged by Effie Mouzeli:
[operations/puppet@production] debug_proxy: force http/1.1 when proxying

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

jijiki closed this task as Resolved.May 15 2019, 6:36 AM
jijiki claimed this task.

@Krinkle sorry for the delay in merging this. LGTM now, please reopen if there are issues.