7

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!

3
  • Why aren't you on Drupal 7 already? Jul 2, 2013 at 18:10
  • I'm still dependant on some Drupal 6 modules. Drupal 6/7 isn't the issue here, though.
    – rahim123
    Jul 2, 2013 at 18:18
  • 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.
    – rahim123
    Jul 2, 2013 at 18:24

1 Answer 1

11

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.

2
  • Thanks, this is the same issue I had. It drove me crazy. Oct 20, 2016 at 14:29
  • 2
    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 Dec 18, 2020 at 10:43

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .