pool www exited on signal 15 (SIGTERM): execution timed out

Question

I'm running Drupal 6 with Nginx 1.5.1 and PHP-FPM (PHP 5.3.26) on a 1GB single core VPS with 3GB of swap space on SSD storage. I just switched from shared hosting to this unmanaged VPS because my site was getting too heavy, so I'm still learning the ropes. I have moderately high traffic, I don't really monitor it closely but Google Adsense usually record close to 30K page views/day. I usually have 50 to 80 authenticated users logged in and a few hundred more anonymous users hitting the Boost static HTML cache at any given moment. I have a maximum of 10 PHP-FPM child processes configured. I am using the "ondemand" PHP-FPM process manager.

I'm running into an occasional error that is really hard to debug because it's seemingly random. Out of maybe 30 intentional posts by users, 1 of them gets duplicated. I configured it so the post button is disabled after the first click, so it's not the result of double clicking. In fact, it even happened to me once when I was posting. The double posts occur within a few seconds of each other. I examined the log files, and the duplicate post always seems to correspond to an nginx POST error: recv() failed (104: Connection reset by peer) while reading response header from upstream. And this event seems to relate to a PHP-FPM error of an execution timeout error of index.php and subsequent SIGTERM of the PHP-FPM worker process.

Here are the nginx access and error logs and the PHP-FPM error log:

nginx_acess.log file:

1.2.3.4 - - [02/Jul/2013:12:34:34 -0500] "POST /comment/reply/22802/420734?quote=1 HTTP/1.1" 302 5 "http://example.com/comment/reply/22802/420734?quote=1" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:34 -0500] "GET /node/22802 HTTP/1.1" 200 18775 "http://example.com/comment/reply/22802/420734?quote=1" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:35 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=21333 HTTP/1.1" 200 707 "http://example.com/node/22802" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:35 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=21121 HTTP/1.1" 200 707 "http://example.com/node/22802" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:35 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=21122 HTTP/1.1" 200 707 "http://example.com/node/22802" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:43 -0500] "GET /comment/delete/420748 HTTP/1.1" 200 5262 "http://example.com/node/22802" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:44 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=20342 HTTP/1.1" 200 707 "http://example.com/comment/delete/420748" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:44 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=21333 HTTP/1.1" 200 707 "http://example.com/comment/delete/420748" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:44 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=21121 HTTP/1.1" 200 707 "http://example.com/comment/delete/420748" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:45 -0500] "POST /comment/delete/420748 HTTP/1.1" 302 5 "http://example.com/comment/delete/420748" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:46 -0500] "GET /node/22802 HTTP/1.1" 200 18533 "http://example.com/comment/delete/420748" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:47 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=21406 HTTP/1.1" 200 707 "http://example.com/node/22802" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:47 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=21121 HTTP/1.1" 200 707 "http://example.com/node/22802" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"
1.2.3.4 - - [02/Jul/2013:12:34:47 -0500] "GET /sites/all/modules/ad/serve.php?o=image&a=20343 HTTP/1.1" 200 707 "http://example.com/node/22802" "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0"

nginx_error.log file:

2013/07/02 11:12:52 [error] 1821#0: *2140 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/node/22802"
2013/07/02 11:16:23 [error] 1821#0: *3020 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/node/22802"
2013/07/02 11:18:13 [error] 1821#0: *3375 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /node/22763 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/node/22763"
2013/07/02 11:18:43 [error] 1821#0: *3576 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /comment/edit/420694 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/node/22763"
2013/07/02 11:19:33 [error] 1821#0: *3576 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /node/22763 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/node/22763/edit"
2013/07/02 11:22:33 [error] 1821#0: *4397 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /forum HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/"
2013/07/02 11:29:23 [error] 1821#0: *5811 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /node/22470 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/"
2013/07/02 11:34:43 [error] 1821#0: *6794 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /recent-posts HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/forum"
2013/07/02 11:41:33 [error] 1821#0: *8082 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /sites/all/modules/ad/serve.php?o=image&a=20343 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/node/22802"
2013/07/02 11:50:03 [error] 1821#0: *9435 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /forum HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/"
2013/07/02 11:55:21 [error] 1821#0: *10378 open() "/var/www/drupal6/sites/all/modules/smileys/packs/Roving/no-swear.png" failed (2: No such file or directory), client: 1.2.3.4, server: example.com, request: "GET /sites/all/modules/smileys/packs/Roving/no-swear.png HTTP/1.1", host: "example.com", referrer: "http://example.com/node/22802/edit"
2013/07/02 12:02:33 [error] 1821#0: *11677 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /user/5170/track/navigation HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/user/5170"
2013/07/02 12:03:03 [error] 1821#0: *11736 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET /node/15888 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/user/5170/track/navigation"
2013/07/02 12:15:23 [error] 1821#0: *13882 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "GET / HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/admin/reports/access/44258972"
2013/07/02 12:34:33 [error] 1821#0: *17088 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 1.2.3.4, server: example.com, request: "POST /comment/reply/22802/420734?quote=1 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9532", host: "example.com", referrer: "http://example.com/comment/reply/22802/420734?quote=1"

php-fpm_error.log file:

[02-Jul-2013 12:34:13] WARNING: [pool www] child 5768, script '/var/www/drupal6/index.php' (request: "GET /index.php") execution timed out (39.990074 sec), terminating
[02-Jul-2013 12:34:13] WARNING: [pool www] child 5767, script '/var/www/drupal6/index.php' (request: "GET /index.php") execution timed out (40.002037 sec), terminating
[02-Jul-2013 12:34:13] WARNING: [pool www] child 5767 exited on signal 15 (SIGTERM) after 50.005181 seconds from start
[02-Jul-2013 12:34:13] NOTICE: [pool www] child 5796 started
[02-Jul-2013 12:34:13] WARNING: [pool www] child 5768 exited on signal 15 (SIGTERM) after 40.019244 seconds from start
[02-Jul-2013 12:34:13] NOTICE: [pool www] child 5797 started
[02-Jul-2013 12:34:33] WARNING: [pool www] child 5769, script '/var/www/drupal6/index.php' (request: "POST /index.php") execution timed out (59.990557 sec), terminating
[02-Jul-2013 12:34:33] WARNING: [pool www] child 5769 exited on signal 15 (SIGTERM) after 60.014359 seconds from start
[02-Jul-2013 12:34:33] NOTICE: [pool www] child 5801 started

They are pruned and slightly obfuscated to show a duplicate post error that just happened today at 12:34 by me with an IP address of "1.2.3.4". The node on which the dupe happened is 22802.

This issue did not occur when I was running on Apache/FastCGI on my previous shared webhost. I should also mention that I am using Redis for caching and the Zend Optimizer+ opcache. But I tried disabling both of those mechanisms to avoid the dupes error, and it made no difference.

Thanks for any help you can provide!

Solution

Well, I'm going to answer my own question. The problem apparently had something to do with the request_terminate_timeout = 30s value that I was using, possibly combined with the ondemand FPM process manager. The double post always coincided with a PHP-FPM timeout error combined with a killing of a child process immediately after. So I disabled the request_terminate_timeout, and it appears to be redundant anyway since the php.ini file already specifies a 30 second timeout. I also realized that I don't really need the ondemand process manager because I'm the only user on this box with fairly stable load, so I switched to static and set the pm.max_requests fairly low to 100. This prevents memory leaks.

One or both of these changes has effectively eliminated the duplicates posts.

Comments

[rahim123]

I'm still dependant on some Drupal 6 modules. Drupal 6/7 isn't the issue here, though.

[rahim123]

As for the Drupal 6/7 thing, I never had problems with double posting on Drupal 6 on my previous host. It's some sort of config issue with PHP-FPM I suspect.

[Dreaded semicolon]

Thanks, this is the same issue I had. It drove me crazy.

[Mate Kocsis]

Please note that PHP's timeout only includes CPU time, while FPM measure the wall-clock time. I've submitted a PHP RFC for PHP 8.1 in order to the change this: wiki.php.net/rfc/max_execution_wall_time