bug fix #61471 (request error handling) #2180

axot · 2016-10-30T04:41:31Z

php_handler does not process request error well.
Should we fix this?

https://bugs.php.net/bug.php?id=61471

marcosptf · 2016-11-10T00:26:35Z

@axot
i think the bugfix needs a test.
what do you think about?

axot · 2016-11-10T06:24:26Z

@marcosptf There may have an impact on performance, so I also think this needs a test. Is there any exists mod_php related test case to use as reference?

marcosptf · 2016-11-10T10:28:04Z

@axot i don't know if this case tests can help, but are some examples:
https://github.com/php/php-src/tree/master/sapi/tests
https://github.com/php/php-src/blob/c482ee6020aab78f4dfde84f79c533850e2ff93a/tests/output/sapi_windows_vt100_support_winko_err.phpt
https://github.com/php/php-src/blob/c482ee6020aab78f4dfde84f79c533850e2ff93a/tests/output/sapi_windows_vt100_support_winko_in-err.phpt

@KalleZ do you have any suggestion to us ?

axot · 2016-11-10T15:01:33Z

while (ap_get_brigade(r->input_filters, brigade, AP_MODE_READBYTES, APR_BLOCK_READ, len) == APR_SUCCESS) {
    ...
}

ap_get_brigade will return error include timeout, maybe a better way is handle error cases inside php_apache_sapi_read_post function?

KalleZ · 2016-11-10T17:43:48Z

@marcosptf I looked around a bit, and our general coverage for SAPIs is low, so I'd be alright with no test as the fix itself is relatively simple

marcosptf · 2016-11-10T17:52:06Z

@axot
like the PHP Master @KalleZ said, this bugfix is fine without .phpt
Thanks!

axot · 2016-11-11T01:06:46Z

@marcosptf @KalleZ Before merging to master I want do some local tests for performance and large post data, I'll report the test result when it is done. By the way, how to make this commit to merge into PHP-5.6 branch, do I need create a new commit for this purpose?

marcosptf · 2016-11-11T11:54:31Z

@axot you can commit in this same branch!

axot · 2016-11-11T12:23:59Z

@marcosptf Thank you!

axot · 2016-12-03T13:01:00Z

I tested this patch with PHP 5.6.27 and 7.0.11 in CentOS 7.

Before patch:

$ nc shao-test-xxx.ap-northeast-1.elb.amazonaws.com 80
POST /ajax/errors/test HTTP/1.1
HOST: shao-test-xxx.ap-northeast-1.elb.amazonaws.com
User-Agent: telnet
Accept: */*
Content-Length: 7
Content-Type: application/x-www-form-urlencoded

b=te
HTTP/1.1 200 OK
Date: Sat, 03 Dec 2016 12:55:15 GMT
Server: Apache
Charset: x-user-defined
Content-Length: 64
Connection: close
Content-Type: application/x-msgpack

With this patch:

$ nc shao-test-xxx.ap-northeast-1.elb.amazonaws.com 80
POST /ajax/errors/test HTTP/1.1
HOST: shao-test-xxx.ap-northeast-1.elb.amazonaws.com
User-Agent: telnet
Accept: */*
Content-Length: 7
Content-Type: application/x-www-form-urlencoded

b=te
HTTP/1.1 408 Request Timeout
Date: Sat, 03 Dec 2016 12:58:45 GMT
Server: Apache
Content-Length: 324
Connection: close
Content-Type: text/html; charset=iso-8859-1

<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>408 Request Timeout</title>
</head><body>
<h1>Request Timeout</h1>
<p>Server timeout waiting for the HTTP request from the client.</p>
<hr>
<address>Apache Server at shao-test-xxx.ap-northeast-1.elb.amazonaws.com Port 80</address>
</body></html>

axot · 2016-12-03T14:18:25Z

@KalleZ @laruence I updated the code, and tested it lightly, but I have not tested it in the production environment and there is no test case, so is there a problem such as memory leak? If possible, will you be able to review it in case?

laruence · 2016-12-06T11:06:23Z

hmm, I am not sure about this fix, but maybe we could fix this in the place where we calling read_post, because we already have SG(request_info).content_length.

And I think the fix could be more clean than the current one...

what do you think ? thanks

axot · 2016-12-06T11:19:46Z

Thank you @laruence , did you mean to check SG(request_info).content_length in sapi_read_post_block? But I don't know how to return an error code to apache side, which apache will call php_handler function directly and want know what error(timeout or bad request?) occurred from it.

axot · 2016-12-06T12:37:43Z

Here is a related discussion in apache community.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60313

By Yann Ylavic 2016-10-28 22:57:17 UTC

If the connection has issues (timeout, closed, reset...) before the announced body is fully received (per Content-Length), httpd tells so to the module asking for it (mod_php or whatever).
If that module (as a request handler) wants httpd to respond with the relevant HTTP error, it simply returns the corresponding ap_map_http_request_error().
But if the caller ignores the error, there is nothing httpd can do.
No builtin httpd module should ignore errors, but mod_php is not maintained by the Apache HTTP server community, and I don't know enough about its internals to tell whether the error is ignored by it or the final application.

laruence · 2016-12-08T15:21:57Z

I understand the problem, your current fix is not quite right, like at least you should not use a global flag, because this sapi could also be used in apache-worker mpm(ZTS).

anyway, the flow is php_handler() calls read_post, maybe we could compare readed length and SG(request_info).content_length, then return 400 to apache, but I am not sure about the side-affect.

need some time and more work to verify it. thanks

axot · 2016-12-08T15:43:13Z

Thanks for the tips, I did not consider the MPM case.

axot · 2016-12-12T06:03:17Z

I delete the global variable and use SG(request_info).content_length to detect the error. It is more reasonable to me now, what do you think about this fix @laruence ? Thank you.

laruence · 2016-12-17T09:26:04Z

seems much better now, if there is no concerns show up in next few days, I will merge this, thanks

nikic · 2016-12-17T11:04:53Z

sapi/apache2handler/sapi_apache2.c

@@ -656,6 +665,13 @@ zend_first_try {
 		brigade = ctx->brigade;
 	}

+	if (SG(request_info).content_length > SG(read_post_bytes)) {
+		ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, "attemp to read POST data error: %d", SG(sapi_headers).http_response_code);


Typo in error message: attemp -> attempt? Though maybe something like "Error while attempting to read POST data: %d" might be better.

laruence · 2016-12-28T07:30:37Z

hmm,

/home/huixinchen/opensource/php-7.0/sapi/apache2handler/sapi_apache2.c: In function ‘php_apache_sapi_read_post’:
/home/huixinchen/opensource/php-7.0/sapi/apache2handler/sapi_apache2.c:212:4: warning: implicit declaration of function ‘ap_map_http_request_error’ [-Wimplicit-function-declaration]
    SG(sapi_headers).http_response_code = ap_map_http_request_error(ret, HTTP_REQUEST_TIME_OUT);
    ^

ap_map_http_request_error is not defined.

according to https://fossies.org/diffs/httpd/2.2.29_vs_2.2.31/include/http_protocol.h-diff.html , seems this function is added recently ? in that case, we should take care compatibility for old versions.

axot · 2016-12-28T16:24:06Z

Thank you for mention about the compatibility issue. @laruence I pushed a new commit for fixing it. ap_map_http_request_error was added in httpd 2.2.31 and 2.4.16 above. So I tested this commit all passed in httpd 2.2.15, 2.2.31, 2.4.12, 2.4.16. For these older httpd version, I copied ap_map_http_request_error function for it, I think it is better than just return a HTTP_BAD_REQUEST error. How do you think about this commit? Thank you.

laruence · 2016-12-29T03:14:40Z

hmm, maybe a better way to do this is:

#if apache's version is newer than 2.2.31 or 2.4.16
#define php_ap_map_http_request_error  ap_map_http_request_error
#else
static int php_ap_map_http_request_error()  {
}
#endif

then later you could use php_ap_map_http_request_error without any extra checks

axot · 2016-12-29T07:13:25Z

Thank you for figure out the code problem, does this look better now? @laruence

alexpott · 2017-01-04T16:27:42Z

This change has caused some interesting behaviour differences in Drupal 8 testing against PHP 7. We're now getting 200s and "Error while attempting to read POST data" in our Apache logs files when we post invalid JSON to a server. See https://www.drupal.org/node/2840974#comment-11852288 for more. Not sure why this change is causing that.

alexpott · 2017-01-05T09:40:10Z

So it is easy to write a test for the behaviour change.

curl -H "Content-Type: application/json" -X PATCH --data "al" http://localhost/test.php

Where test.php is:

<?php

var_dump(file_get_contents("php://input"));

PHP versions before this patch:
string(2) "al"

After this patch:

<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>200 OK</title>
</head><body>
<h1>OK</h1>
<p>The server encountered an internal error or
misconfiguration and was unable to complete
your request.</p>
<p>Please contact the server administrator at
 [no address given] to inform them of the time this error occurred,
 and the actions you performed just before this error.</p>
<p>More information about this error may be available
in the server error log.</p>
</body></html>

alexpott · 2017-01-05T09:41:41Z

If the method is POST everything still works as expected but PATCH is broken.

alexpott · 2017-01-05T09:53:57Z

It does not even have to be invalid JSON - that's what the test the discovered this was testing but even:

curl -H "Content-Type: application/json" -X PATCH --data '{"username":"xyz","password":"xyz"}' http://localhost/test.php

is broken.

wimleers · 2017-01-05T09:56:12Z

@alexpott I think we perhaps need to create a new ticket for this regression, and then just point to this PR. It's quite possible the PHP maintainers are not seeing new comments here, just like we don't see new comments on "closed" issues on drupal.org.

krakjoe · 2017-01-05T09:58:38Z

I'm seeing them ... please do open a ticket, put a link here, and in any subsequent PR's that are made to resolve it.

nikic · 2017-01-05T10:00:35Z

It looks like this was merged into 7.0, so this commit will need to be reverted from the release branches as well (a8931df).

/cc @weltling

alexpott · 2017-01-05T10:05:53Z

@nikic @krakjoe If you're going to revert this do I need to file a bug on https://bugs.php.net/report.php? I'm more than happy to if that helps - but don't want to create more noise than necessary.

krakjoe · 2017-01-05T10:48:58Z

I'll be doing whatever @weltling does, one or both of us will provide update here.

weltling · 2017-01-05T13:07:47Z

I've reverted this in dev for now and reopened https://bugs.php.net/61471. @axot please lets use another PR for the improved patch.

Thanks.

axot · 2017-01-05T13:12:22Z

@weltling Thank you for reverting the commit.

smalyshev added the Bug label Oct 31, 2016

axot force-pushed the bugfix_timeout_61471 branch from ff13a85 to 4dfc957 Compare December 3, 2016 12:41

axot force-pushed the bugfix_timeout_61471 branch from f237645 to 11ddf50 Compare December 5, 2016 14:54

axot changed the base branch from master to PHP-5.6 December 5, 2016 14:55

axot force-pushed the bugfix_timeout_61471 branch from 9ae9551 to 53c4c38 Compare December 17, 2016 04:36

bug fixed #61471 in apache2handler

9b65a10

axot changed the base branch from PHP-5.6 to PHP-7.0 December 17, 2016 04:38

nikic reviewed Dec 17, 2016

View reviewed changes

Zheng SHAO added 2 commits December 17, 2016 20:26

typo fixed

fb98907

Fixed NEWS conflicts

884e2a0

axot force-pushed the bugfix_timeout_61471 branch from 6fb5e94 to 884e2a0 Compare December 20, 2016 00:50

add old versions of httpd support

d92606a

define php_ap_map_http_request_error function for older httpd only

587497e

php-pulls merged commit 587497e into php:PHP-7.0 Dec 29, 2016

axot deleted the bugfix_timeout_61471 branch January 5, 2017 15:34

axot mentioned this pull request Jan 20, 2017

Bug fixed #61471 #2323

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

bug fix #61471 (request error handling) #2180

bug fix #61471 (request error handling) #2180

axot commented Oct 30, 2016

marcosptf commented Nov 10, 2016

axot commented Nov 10, 2016

marcosptf commented Nov 10, 2016

axot commented Nov 10, 2016

KalleZ commented Nov 10, 2016

marcosptf commented Nov 10, 2016

axot commented Nov 11, 2016

marcosptf commented Nov 11, 2016 •

edited

Loading

axot commented Nov 11, 2016

axot commented Dec 3, 2016 •

edited

Loading

axot commented Dec 3, 2016

laruence commented Dec 6, 2016

axot commented Dec 6, 2016 •

edited

Loading

axot commented Dec 6, 2016 •

edited

Loading

laruence commented Dec 8, 2016

axot commented Dec 8, 2016

axot commented Dec 12, 2016

laruence commented Dec 17, 2016

nikic Dec 17, 2016

laruence commented Dec 28, 2016 •

edited

Loading

axot commented Dec 28, 2016

laruence commented Dec 29, 2016 •

edited

Loading

axot commented Dec 29, 2016

alexpott commented Jan 4, 2017

alexpott commented Jan 5, 2017

alexpott commented Jan 5, 2017

alexpott commented Jan 5, 2017

wimleers commented Jan 5, 2017

krakjoe commented Jan 5, 2017

nikic commented Jan 5, 2017

alexpott commented Jan 5, 2017

krakjoe commented Jan 5, 2017

weltling commented Jan 5, 2017

axot commented Jan 5, 2017

bug fix #61471 (request error handling) #2180

bug fix #61471 (request error handling) #2180

Conversation

axot commented Oct 30, 2016

marcosptf commented Nov 10, 2016

axot commented Nov 10, 2016

marcosptf commented Nov 10, 2016

axot commented Nov 10, 2016

KalleZ commented Nov 10, 2016

marcosptf commented Nov 10, 2016

axot commented Nov 11, 2016

marcosptf commented Nov 11, 2016 • edited Loading

axot commented Nov 11, 2016

axot commented Dec 3, 2016 • edited Loading

axot commented Dec 3, 2016

laruence commented Dec 6, 2016

axot commented Dec 6, 2016 • edited Loading

axot commented Dec 6, 2016 • edited Loading

laruence commented Dec 8, 2016

axot commented Dec 8, 2016

axot commented Dec 12, 2016

laruence commented Dec 17, 2016

nikic Dec 17, 2016

Choose a reason for hiding this comment

laruence commented Dec 28, 2016 • edited Loading

axot commented Dec 28, 2016

laruence commented Dec 29, 2016 • edited Loading

axot commented Dec 29, 2016

alexpott commented Jan 4, 2017

alexpott commented Jan 5, 2017

alexpott commented Jan 5, 2017

alexpott commented Jan 5, 2017

wimleers commented Jan 5, 2017

krakjoe commented Jan 5, 2017

nikic commented Jan 5, 2017

alexpott commented Jan 5, 2017

krakjoe commented Jan 5, 2017

weltling commented Jan 5, 2017

axot commented Jan 5, 2017

marcosptf commented Nov 11, 2016 •

edited

Loading

axot commented Dec 3, 2016 •

edited

Loading

axot commented Dec 6, 2016 •

edited

Loading

axot commented Dec 6, 2016 •

edited

Loading

laruence commented Dec 28, 2016 •

edited

Loading

laruence commented Dec 29, 2016 •

edited

Loading