mod_fcgid: read data timeout in 45 seconds / Premature end of script headers...

[Eric Pretorious]

A client is complaining of frequent HTTP 500 errors when viewing their WordPress web site.

Looking in the error_log for their domain, I discovered that there are three different types of errors that are occuring:

1. [Tue Apr 09 21:34:57 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds

   This entry has occured approximately 5250 times since it first began appearing on April 9th, 2013.
   

2. [Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php

   This entry has occured approximately 4900 times since it first began appearing on April 9th, 2013.
   

3. [Tue Apr 09 21:36:20 2013] [warn] [client 189.162.161.205] mod_fcgid: can't apply process slot for /var/www/cgi-bin/cgi_wrapper/cgi_wrapper, referer: http://example.com/wp-login.php

   This entry has occured approximately 6900 times since it first began appearing on April 9th, 2013.

Generally, the error_log looks a lot like this:

[Tue Apr 09 21:34:57 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:34:58 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:34:58 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:34:58 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:34:58 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:01 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:03 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:03 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:03 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:04 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:05 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php

What struck me as unusual about these errors is that many of the entries are duplicated and slightly out of order. e.g., The entry at [Tue Apr 09] 21:35:04 appears several times, intermixed with other entries from about the same time:

eric@eric-v5:~/Downloads$ grep '[Tue Apr 09] 21:35:04' error_log-example.com | grep wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php
[Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php

eric@eric-v5:~/Downloads$ grep '[Tue Apr 09] 21:35:04' error_log-example.com | grep wp-login.php | wc -l
10

There appears to be a strong correlation between the timing of the messages above and these messages in /var/log/httpd/error_log. e.g.,

[Sun Jun 23 [COLOR="#00FF00"]20:18:20[/COLOR] 2013] [warn] mod_fcgid: process 15928 graceful kill fail, sending SIGKILL
[Sun Jun 23 [COLOR="#00FF00"]20:18:21[/COLOR] 2013] [warn] mod_fcgid: process 15922 graceful kill fail, sending SIGKILL
[Sun Jun 23 [COLOR="#00FF00"]20:18:21[/COLOR] 2013] [warn] mod_fcgid: process 15916 graceful kill fail, sending SIGKILL
...
[Sun Jun 23 [COLOR="#FF0000"]20:30:04[/COLOR] 2013] [warn] mod_fcgid: process 16507 graceful kill fail, sending SIGKILL
[Sun Jun 23 [COLOR="#FF0000"]20:30:04[/COLOR] 2013] [warn] mod_fcgid: process 16503 graceful kill fail, sending SIGKILL
[Sun Jun 23 [COLOR="#FF0000"]20:30:08[/COLOR] 2013] [warn] mod_fcgid: process 16515 graceful kill fail, sending SIGKILL

e.g., On June 23rd, the entries in the domain's error_log file also span the time period from 20:18 to 20:30:

eric@eric-v5:~/Downloads$ grep 'Jun 23' error_log-example.com | head -3
[Sun Jun 23 [COLOR="#00FF00"]20:18:07[/COLOR] 2013] [warn] [client 190.92.53.234] mod_fcgid: read data timeout in 45 seconds, referer: example.com/wp-login.php
[Sun Jun 23 [COLOR="#00FF00"]20:18:08[/COLOR] 2013] [warn] [client 178.137.116.223] mod_fcgid: read data timeout in 45 seconds, referer: example.com/wp-login.php
[Sun Jun 23 [COLOR="#00FF00"]20:18:09[/COLOR] 2013] [warn] [client 109.228.202.4] mod_fcgid: read data timeout in 45 seconds, referer: example.com/wp-login.php

eric@eric-v5:~/Downloads$ grep 'Jun 23' error_log-example.com | tail -3
[Sun Jun 23 [COLOR="#FF0000"]20:29:59[/COLOR] 2013] [error] [client 190.42.27.247] Premature end of script headers: wp-login.php, referer: example.com/wp-login.php
[Sun Jun 23 [COLOR="#FF0000"]20:29:59[/COLOR] 2013] [warn] [client 189.75.76.133] mod_fcgid: read data timeout in 45 seconds, referer: example.com/wp-login.php
[Sun Jun 23 [COLOR="#FF0000"]20:30:00[/COLOR] 2013] [error] [client 189.75.76.133] Premature end of script headers: wp-login.php, referer: example.com/wp-login.php

The entries in /var/log/httpd/error_log seem to indicate that, for some reason, mod_fcgid is being killed and that, in turn, is causing the login.php script to terminate which, in turn, is causing index.php to time out while waiting for login.php to return.

All this begs two questions:

1. What is killing mod_fcgid?
2. Why is mod_fcgid being killed?

 

[Nikolay.]

Version of Panel and OS?

Maybe the script just works too long and is then killed by mod_fcgid process manager?

The "mod_fcgid: can't apply process slot for" error is pretty well-known. I suggest googling it. Though it might be dependent on other issues you encountered.

 

[Eric Pretorious]

Version of Panel and OS?

OS: CentOS 6.4 (Final)
Panel version: 11.0.9 Update #53, last updated at June 8, 2013 03:41 AM
Your current PHP version: 5.3.3.

 

[Eric Pretorious]

A client is complaining of frequent HTTP 500 errors when viewing their WordPress web site.

Looking in the error_log for their domain, I discovered that there are three different types of errors that are occuring:

1. [Tue Apr 09 21:34:57 2013] [warn] [client 189.162.161.205] mod_fcgid: read data timeout in 45 seconds

   This entry has occured approximately 5250 times since it first began appearing on April 9th, 2013.
   

2. [Tue Apr 09 21:35:04 2013] [error] [client 189.162.161.205] Premature end of script headers: wp-login.php

   This entry has occured approximately 4900 times since it first began appearing on April 9th, 2013.
   

3. [Tue Apr 09 21:36:20 2013] [warn] [client 189.162.161.205] mod_fcgid: can't apply process slot for /var/www/cgi-bin/cgi_wrapper/cgi_wrapper, referer: http://example.com/wp-login.php

   This entry has occured approximately 6900 times since it first began appearing on April 9th, 2013.

I overlooked one other, very common, error:

• [Wed Apr 10 20:28:08 2013] [warn] [client 92.60.114.91] (110)Connection timed out: mod_fcgid: ap_pass_brigade failed in handle_request_ipc function, referer: http://www.example.com/

  This entry has occured approximately 625 times since it first began appearing on April 10th, 2013.

What's causing all of these errors?

 

[Eric Pretorious]

The two-part solution at ExpressionEngine -- "mod_fcgid: read data timeout in 45 seconds --> Premature end of script headers: admin.php" -- seemed promising; especially since Christopher Hubbard's blog entry "mod_fcgid errors on Parallels Plesk server" offered the same solution:

<IfModule mod_fcgid.c>
IdleTimeout 3600
ProcessLifeTime 7200
MaxProcessCount 64
DefaultMaxClassProcessCount 8
IPCConnectTimeout 300
IPCCommTimeout 7200
BusyTimeout 300
</IfModule>

But then I read the entire article and found out that adding the configuration (above) to the vhost's .htaccess file caused the vhost to stop working completely:

Jackpot?!

Erm… No. .. For some reason, whenever I put that in the .htaccess file, I’d get a 500 Server Error (all of the time).

This seems like a feasible configuration. i.e., It seems valid and correct according to the module documentation. Why does it cause the vhost to completely stop working?

 

[Nikolay.]

1) # rpm -qa | grep cgi ?

2) Module documentation you pointed to is for Apache 2.4. mod_fcgid version likely differs as well.

3) Maybe this might be related?

4) Is upgrade to Plesk 11.5.30 possible? Though I'm not sure it will help.

 

[RickyOdin]

The two-part solution at ExpressionEngine -- "mod_fcgid: read data timeout in 45 seconds --> Premature end of script headers: admin.php" -- seemed promising; especially since Christopher Hubbard's blog entry "mod_fcgid errors on Parallels Plesk server" offered the same solution:

<IfModule mod_fcgid.c>
IdleTimeout 3600
ProcessLifeTime 7200
MaxProcessCount 64
DefaultMaxClassProcessCount 8
IPCConnectTimeout 300
IPCCommTimeout 7200
BusyTimeout 300
</IfModule>

But then I read the entire article and found out that adding the configuration (above) to the vhost's .htaccess file caused the vhost to stop working completely:


This seems like a feasible configuration. i.e., It seems valid and correct according to the module documentation. Why does it cause the vhost to completely stop working?

This fiexed it for me. I had to edit the global config though as mentioned in http://www.cjhubbard.com/code/mod_fcgid-errors-parallels-plesk-server/ but you're a life saver, thanks!

 

[iliasn]

Maybe this should help.

Increase fcgi IOTimeout for scripts that are quiet too long
Increase fcgi BusyTimeout for scripts that take too long to execute
Increase nginx proxy timeout

From PleskPanel -> Website & Domains -> Web Server Settings

Add to "Additional directives for HTTP" & "Additional directives for HTTPS"
FcgidBusyTimeout 300
FcgidIOTimeout 250

Add to Additional nginx directives
proxy_read_timeout 300;