Page MenuHomePhabricator

ErrorException from includes/HeaderCallback.php: PHP Notice: Undefined offset: 1
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error

Request ID: AWjpBewvi-uKhB2czfH2

message
PHP Notice: Undefined offset: 1
trace
#0 /srv/mediawiki/php-1.33.0-wmf.17/includes/HeaderCallback.php(25): MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 [internal function]: MediaWiki\HeaderCallback::callback()
#2 /srv/mediawiki/php-1.33.0-wmf.17/includes/libs/MultiHttpClient.php(418): fwrite(resource, string)
#3 [internal function]: MultiHttpClient->{closure}(resource, string)
#4 /srv/mediawiki/php-1.33.0-wmf.17/includes/libs/MultiHttpClient.php(233): curl_multi_exec(resource, integer)
#5 /srv/mediawiki/php-1.33.0-wmf.17/includes/libs/MultiHttpClient.php(165): MultiHttpClient->runMultiCurl(array, array)
#6 /srv/mediawiki/php-1.33.0-wmf.17/includes/libs/MultiHttpClient.php(130): MultiHttpClient->runMulti(array, array)
#7 /srv/mediawiki/php-1.33.0-wmf.17/includes/libs/filebackend/SwiftFileBackend.php(1114): MultiHttpClient->run(array)
#8 /srv/mediawiki/php-1.33.0-wmf.17/includes/libs/filebackend/FileBackendStore.php(882): SwiftFileBackend->doStreamFile(array)
#9 /srv/mediawiki/php-1.33.0-wmf.17/includes/libs/filebackend/FileBackendMultiWrite.php(653): FileBackendStore->streamFile(array)
#10 /srv/mediawiki/php-1.33.0-wmf.17/includes/filerepo/FileRepo.php(1622): FileBackendMultiWrite->streamFile(array)
#11 /srv/mediawiki/php-1.33.0-wmf.17/thumb.php(317): FileRepo->streamFileWithStatus(string, array)
#12 /srv/mediawiki/php-1.33.0-wmf.17/thumb.php(38): wfStreamThumb(array)
#13 /srv/mediawiki/w/thumb.php(3): require(string)
#14 {main}

Impact

Notes

Event Timeline

Non-frequent error that started showing up in wmf.17. Doesn't seem rollback-worthy.

Setting as High priority and adding as a blocker to next week's train with the hope that we can fix this regression before cutting wmf.18.

thcipriani raised the priority of this task from High to Unbreak Now!.Feb 19 2019, 2:36 PM

I took a look at the code indicated by the stack trace, and it indicates that a header does not match the expected format of a key-value pair. In this case, the value is missing. The stack trace also mentions the requests are coming from the thumb.php end-point, so that should help narrow down what part of the code is at fault. Based on the [[ https://secure.php.net/manual/en/function.headers-list.php | documentation for headers_list ]], only header allows setting invalid headers, so

I've compared a few branches, from wmf.13 up to master, but none appear to have added an incorrect header call.

Manually intercepting the list of headers in HeaderCallback::callback on MediaWiki-vagrant didn't help either, presumably because the configuration on the cluster differs too much. I didn't test with the wikimediaproduction role yet.

Change 491539 had a related patch set uploaded (by Thiemo Kreuz (WMDE); owner: Thiemo Kreuz (WMDE)):
[mediawiki/core@master] Fix HeaderCallback failing on headers without a colon

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

I looked at the code in the HeaderCallback class. Questions:

  1. Does the HTTP spec actually forbid headers without a colon? If this is the case, we should make violations visible.
  2. Is it the job of the HeaderCallback class to validate all headers? If it is, it should properly log bad headers so we can see them. If not, my proposal in https://gerrit.wikimedia.org/r/491539 makes the class stop failing on headers it actually does not care about.

This doesn't seem to be new in wmf.17, the earliest hit I see is on 2019-02-04 on enwiki running wmf.14 (XFfLDgpAAEMAAFssDuIAAAAR). The rates don't really start taking off until the 9th.

Also all the hits in Kibana[1] have phpversion "7.2.8-1+0~20180725124257.2+stretch~1.gbp571e56". So it seems more likely this is something to do with PHP 7 rather than any recent MediaWiki change.

[1]: Except for 5 on 2019-02-04 and 2019-02-05, all from mw1272, that don't have a phpversion field at all.

This doesn't seem to be new in wmf.17, the earliest hit I see is on 2019-02-04 on enwiki running wmf.14 (XFfLDgpAAEMAAFssDuIAAAAR). The rates don't really start taking off until the 9th.

Also all the hits in Kibana[1] have phpversion "7.2.8-1+0~20180725124257.2+stretch~1.gbp571e56". So it seems more likely this is something to do with PHP 7 rather than any recent MediaWiki change.

[1]: Except for 5 on 2019-02-04 and 2019-02-05, all from mw1272, that don't have a phpversion field at all.

Thanks for investigation! I must have been filtering incorrectly to show this as having regressed in 1.33.0-wmf.17.

thcipriani lowered the priority of this task from Unbreak Now! to Medium.Feb 19 2019, 6:24 PM

Lowering priority and removing as train blocker since it did not regress last week.

  1. Does the HTTP spec actually forbid headers without a colon? If this is the case, we should make violations visible.

RFC 7230 § 3.2 defines a header-field as always containing a colon.

Note, though, that curl's CURLOPT_HEADERFUNCTION callback is also called for the start-line and the empty line (just a CRLF) that comes in between the header-fields and the message-body in the HTTP-message (see RFC 7230 § 3).

  1. Is it the job of the HeaderCallback class to validate all headers?

Probably not. It seems to have two purposes:

  • Set do-not-cache headers when the response contains set-cookie headers.
  • Hold a trace to when headers were sent, to later warnings that headers were already sent can include that trace.

Change 491561 had a related patch set uploaded (by Anomie; owner: Anomie):
[mediawiki/core@master] MultiHttpClient: Don't relay the end-of-headers line

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

It turns out that the invalid header is the empty string, coming from MultiHttpClient's 'relayResponseHeaders' feature. It blindly relays everything that curl passes to the CURLOPT_HEADERFUNCTION callback, which includes the status line and the "\r\n" that indicates the end of the headers. The former is no problem because header() treats that specially. The latter is what's causing the problem here under PHP 7: in HHVM header() ignores the call if the passed string is empty after trimming whitespace, while Zend PHP only ignores it if the passed string is empty before trimming whitespace.

BTW, it looks like the patch on T202352: Convert MultiHttpClient to use Guzzle will fix this too, as that changes the logic in MultiHttpClient in a way that should no longer cause this issue.

Change 491561 merged by jenkins-bot:
[mediawiki/core@master] MultiHttpClient: Don't relay the end-of-headers line

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

Change 491561 merged by jenkins-bot:
[mediawiki/core@master] MultiHttpClient: Don't relay the end-of-headers line

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

That patch should fix the log warning. You'll have to backport it if you want it in wmf.18.

Confirmed that the Guzzle-based MultiHttpClient code in T202352 is unaffected by this issue. So this issue will not reappear when that code is merged.

Krinkle assigned this task to thiemowmde.
Krinkle removed a project: Patch-For-Review.

Change 491539 merged by jenkins-bot:
[mediawiki/core@master] Fix HeaderCallback failing on headers without a colon

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

mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:07 PM