Backported patch for bug #69860

[dyeldandi]

For PHP-5.6 branch

[php-pulls]

Comment on behalf of krakjoe at php.net:

Since this targets a branch in security fix only status, I'm closing this PR.

[acasademont]

why has this PR been closed? @smalyshev @nikic the patch was never merged and https://bugs.php.net/bug.php?id=69860 is still open

[staabm]

Since this targets a branch in security fix only status, I'm closing this PR.

Might make sense to provide a PR against a maintained version

[acasademont]

It was a PR against a maintained version but ignored for 1.5 years. What's the point of creating a PR targeting 7 or 7.1 if it's gonna be ignored again?

[krakjoe]

It's not going to be ignored, I'll merge it myself, target 7.0 please.

Sorry it was ignored, we are trying to do better ...

[smalyshev]

seems to be rather simple patch, unfortunately I don't know FPM code enough to validate it...

[acasademont]

Maybe @dyeldandi can provide us some clue about it :)

[dyeldandi]

Hello!

I looked into current master and it seems that 7.0 fpm code has been completely rewritten. I'm not sure this bug exists in there anymore. We don't have php7 in our projects (yet?) so I can't even test it under fair load (5.6 is doing thousands of hits per second on 6 machines).

However I'm pretty sure a lot of people will still be using 5.6 for quite some time and this issue is a real showstopper for those who have high loaded php-fpm setups, so if it is merged in 5.6 that would help a lot.

[krakjoe]

It cannot be merged into a security fix only branch.

[sunyq]

@dyeldandi
I am using php 7.0.7(with nginx 1.10.1), and this problem still exists!
The round trip time between our Nginx servers and php-fpm servers is about 55ms! But we have to disable keepalive feature because of this bug, which means each http request gets 55 more ms latency...

[dyeldandi]

@sunyq
I built php 7.0.16 on my test machine and this bug does indeed exist.
I made pull requests for 7.0.16, 7.1.2 and master -- #2375, #2376, #2377
Would you be able to try this on your servers? If you need 7.0.7 I have it in my repository https://github.com/dyeldandi/php-src/tree/PHP-7.0.7

[tpunt]

@dyeldandi In future, one PR against the lowest (supported) branch (in this case 7.0) would suffice :)

[sunyq]

@dyeldandi
Hi dyeldandi, I am very glad to try your fixed PHP-7.0.7! And I will paste my test result here.
Thank you!

[dyeldandi]

@tpunt
Got it. Sorry about that :)

[sunyq]

@dyeldandi
Hi, I just tested your fix for PHP-7.0.7.
I added this line in our php source files main/fastcgi.c:
req->hook.on_read();
then recompile it and run it.
During the test I ran 2 php-fpm servers as upstream server: one is with the patched php-fpm, and the other one is with the original php-fpm binary file.
I still got some Nginx errors like:
*539165 readv() failed (104: Connection reset by peer) while reading upstream, client: client_ip_here, server: server_ip_here, request: "GET /index.php HTTP/1.0", upstream: "fastcgi://fastcgi_server_here"
Both patched php-fpm and original php-fpm servers have this error.
And I checked the fpm_error.log, the patched php-fpm server:

[09-Feb-2017 17:39:34.004768] DEBUG: pid 22167, fpm_got_signal(), line 76: received SIGCHLD
[09-Feb-2017 17:39:34.005031] NOTICE: pid 22167, fpm_children_bury(), line 252: [pool www] child 22229 exited with code 0 after 570.078110 seconds from start
[09-Feb-2017 17:39:34.006223] NOTICE: pid 22167, fpm_children_make(), line 421: [pool www] child 24413 started
[09-Feb-2017 17:39:34.006446] DEBUG: pid 22167, fpm_event_loop(), line 419: event module triggered 1 events
[09-Feb-2017 17:39:34.951135] DEBUG: pid 22167, fpm_got_signal(), line 76: received SIGCHLD
[09-Feb-2017 17:39:34.951439] NOTICE: pid 22167, fpm_children_bury(), line 252: [pool www] child 22323 exited with code 0 after 570.966491 seconds from start
[09-Feb-2017 17:39:34.952662] NOTICE: pid 22167, fpm_children_make(), line 421: [pool www] child 24414 started
[09-Feb-2017 17:39:34.952931] DEBUG: pid 22167, fpm_event_loop(), line 419: event module triggered 1 events
[09-Feb-2017 17:39:41.316661] DEBUG: pid 22167, fpm_got_signal(), line 76: received SIGCHLD
[09-Feb-2017 17:39:41.316927] NOTICE: pid 22167, fpm_children_bury(), line 252: [pool www] child 22188 exited with code 0 after 577.416389 seconds from start
[09-Feb-2017 17:39:41.318140] NOTICE: pid 22167, fpm_children_make(), line 421: [pool www] child 24415 started
[09-Feb-2017 17:39:41.318371] DEBUG: pid 22167, fpm_event_loop(), line 419: event module triggered 1 events

but the original php-fpm server:

[09-Feb-2017 17:39:36.879334] DEBUG: pid 7078, fpm_got_signal(), line 76: received SIGCHLD
[09-Feb-2017 17:39:36.879562] NOTICE: pid 7078, fpm_children_bury(), line 252: [pool www] child 7156 exited with code 0 after 534.277482 seconds from start
[09-Feb-2017 17:39:36.881196] NOTICE: pid 7078, fpm_children_make(), line 421: [pool www] child 9092 started
[09-Feb-2017 17:39:36.881421] DEBUG: pid 7078, fpm_event_loop(), line 419: event module triggered 1 events
[09-Feb-2017 17:39:37.848866] WARNING: pid 7078, fpm_request_check_timed_out(), line 269: [pool www] child 7189, script '/index.php' (request: "GET /index.php") executing too slow (237.502454 sec), logging
[09-Feb-2017 17:39:37.849134] DEBUG: pid 7078, fpm_got_signal(), line 76: received SIGCHLD
[09-Feb-2017 17:39:37.849366] NOTICE: pid 7078, fpm_children_bury(), line 227: child 7189 stopped for tracing
[09-Feb-2017 17:39:37.849416] NOTICE: pid 7078, fpm_php_trace(), line 144: about to trace 7189
[09-Feb-2017 17:39:37.849664] NOTICE: pid 7078, fpm_php_trace(), line 172: finished trace of 7189
[09-Feb-2017 17:39:37.849799] DEBUG: pid 7078, fpm_event_loop(), line 419: event module triggered 1 events
[09-Feb-2017 17:39:40.731762] DEBUG: pid 7078, fpm_got_signal(), line 76: received SIGCHLD
[09-Feb-2017 17:39:40.732029] NOTICE: pid 7078, fpm_children_bury(), line 252: [pool www] child 7183 exited with code 0 after 538.107458 seconds from start
[09-Feb-2017 17:39:40.732999] NOTICE: pid 7078, fpm_children_make(), line 421: [pool www] child 9093 started
[09-Feb-2017 17:39:40.733210] DEBUG: pid 7078, fpm_event_loop(), line 419: event module triggered 1 events
[09-Feb-2017 17:39:42.850067] WARNING: pid 7078, fpm_request_check_timed_out(), line 269: [pool www] child 7168, script '/index.php' (request: "GET /index.php") executing too slow (245.351883 sec), logging

I think you almost solved this problem.
The reason that patched php-fpm server still results in the error "readv() failed (104: Connection reset by peer) while reading upstream" in Nginx, I think, is child processes handled the max requests configured by "pm.max_requests" in php-fpm.conf, and then they exited; but the Nginx worker processes still keep the connections with them.
As for original php-fpm server in my case, too many " executing too slow" in its log files, that's not normal child process exiting.

Could the issue of patched php-fpm be solved ?
Thanks!

[dyeldandi]

@sunyq
Can you please attach your nginx configuration, php-fpm.conf and php-fpm.d/* if you have any?

[sunyq]

@dyeldandi
here is my main nginx configuration:

user webid;
worker_processes auto;
events {
use epoll;
worker_connections 51200;
}
http {
include mime.types;
default_type application/octet-stream;
access_log off;
error_log /data/log/nginx/error.log;
sendfile on;
server_tokens off;
server_names_hash_bucket_size 128;
client_header_buffer_size 64k;
client_body_temp_path /dev/shm/client_body_temp 1 2;
large_client_header_buffers 4 128k;
tcp_nopush on;
tcp_nodelay on;
keepalive_timeout 30;

fastcgi_connect_timeout 300;
fastcgi_send_timeout 300;
fastcgi_read_timeout 300;
fastcgi_buffer_size 128k;
fastcgi_buffers 4 128k;
fastcgi_busy_buffers_size 128k;
fastcgi_temp_file_write_size 128k;
fastcgi_intercept_errors on;
fastcgi_temp_path /dev/shm/fastcgi_temp;
client_max_body_size 18m;

gzip on;
gzip_http_version 1.1;
gzip_comp_level 5;
gzip_proxied any;
gzip_min_length 1k;
#gzip_buffers 8 4k;
gzip_disable "MSIE [1-6].";
gzip_types text/* text/plain text/css text/xml text/x-js text/javascript application/javascript application/x-javascript application/xml application/xml+rss application/json;

log_format main '$time_local +$msec\t$remote_addr:$remote_port\t$host\t$remote_user\t$http_user_agent\t$http_x_forwarded_for\trequest:$request\tbbs:$body_bytes_sent\tstatus:$status\tupad:$upstream_addr\trspt:$upstream_response_time\trqtt:$request_time\trequest_body:$request_body';
include vhost/*.conf;
}

Here is my vhost file:

upstream php-keepalive {
server pacthed-php-fpm;
server original-php-fpm;
keepalive 100;
}

server {
listen 808;
server_name server_name.com;
access_log /data/log/nginx/test-php_access.log main;
root /web/;
index index.php;
error_page 500 502 503 504 /50x.html;

location = /50x.html {
root html;
}

location ~ /. {deny all;}

location / {
rewrite ^.*$ /index.php last;
}

location ~ .php$ {
include fastcgi.conf;
fastcgi_pass php-keepalive;
fastcgi_index index.php;
fastcgi_keep_conn on;
}
}

php-fpm.conf file:

[global]
pid = /var/run/php-fpm.pid
error_log = /data/log/php/fpm_error.log
log_level = debug
[www]
user = webid
group = webid
listen = 0.0.0.0:9000
listen.backlog = 4096
pm = static
pm.max_children = 200
pm.max_requests = 2000
pm.status_path = /fpm_status
slowlog = /data/log/php/fpm_slow.log
request_slowlog_timeout = 35s
request_terminate_timeout = 60s
rlimit_files = 40960

Hope those files can do some help 8)

[dyeldandi]

@sunyq
Got it! Socket needs to be shutdown() correctly before close(). I fixed this long time ago in my 5.5 branch and completely forgot about it.
I pushed the changes into my repository, branch PHP-7.0.7 (https://github.com/dyeldandi/php-src/tree/PHP-7.0.7). Can you please try that out?

[sunyq]

@dyeldandi
Great!
Just wait for some moment, please.

[sunyq]

@dyeldandi
During my test, I got several times of this error in Nginx:

upstream prematurely closed connection while reading response header from upstream

and also 2 times of status:502.
But I think that's probably because my load test is too "heavy":
ab -c 30 -n 1000000 http://server_ip_here/index.php

Here is php-fpm status:

pool: www
process manager: static
start time: 09/Feb/2017:21:24:24 +0800
start since: 165
accepted conn: 49861
listen queue: 0
max listen queue: 0
listen queue len: 4096
idle processes: 0
active processes: 545
total processes: 545
max active processes: 687
max children reached: 0
slow requests: 0

pm.max_children in my conf file is 200...

So I think you have solved this issue!
Thank you very much!

[dyeldandi]

Okey, cool! I updated pull requests. Can anyone please merge them?