mod_fcgid: can't apply process slot for /var/www/php-fcgi-scripts/

Discussion in 'ISPConfig 3 Priority Support' started by sumawelt, Dec 9, 2014.

  1. sumawelt

    sumawelt New Member HowtoForge Supporter

    Hi,
    I have OnCloud installed with SSL (RapidSSL wildcard certificate) on a server running ISPconfig 3. OwnCloud runs fine without SSL but when I access it using SSL it seems to be hanging after a short while. My Error log shows many entries like
    Code:
    [Tue Dec 09 10:22:07 2014] [warn] [client 93.104.103.201] mod_fcgid: can't apply process slot for /var/www/php-fcgi-scripts/web6/.php-fcgi-starter
    [Tue Dec 09 10:22:13 2014] [warn] [client 37.120.162.222] mod_fcgid: read data timeout in 600 seconds
    [Tue Dec 09 10:22:13 2014] [error] [client 37.120.162.222] Premature end of script headers: index.php
    [Tue Dec 09 10:22:17 2014] [warn] [client 37.120.162.222] mod_fcgid: read data timeout in 600 seconds
    [Tue Dec 09 10:22:17 2014] [error] [client 37.120.162.222] Premature end of script headers: index.php
    [Tue Dec 09 10:22:17 2014] [warn] [client 37.120.162.222] mod_fcgid: read data timeout in 600 seconds
    [Tue Dec 09 10:22:17 2014] [error] [client 37.120.162.222] Premature end of script headers: index.php
    [Tue Dec 09 10:22:17 2014] [warn] [client 37.120.162.222] mod_fcgid: can't apply process slot for /var/www/php-fcgi-scripts/web6/.php-fcgi-starter
    [Tue Dec 09 10:22:17 2014] [warn] [client 37.120.162.222] mod_fcgid: can't apply process slot for /var/www/php-fcgi-scripts/web6/.php-fcgi-starter
    [Tue Dec 09 10:22:17 2014] [warn] [client 37.120.162.222] mod_fcgid: can't apply process slot for /var/www/php-fcgi-scripts/web6/.php-fcgi-starter
    [Tue Dec 09 10:22:18 2014] [warn] [client 37.120.162.222] mod_fcgid: read data timeout in 600 seconds
    [Tue Dec 09 10:22:18 2014] [error] [client 37.120.162.222] Premature end of script headers: index.php
    [Tue Dec 09 10:22:19 2014] [warn] [client 37.120.162.222] mod_fcgid: read data timeout in 600 seconds
    [Tue Dec 09 10:22:19 2014] [error] [client 37.120.162.222] Premature end of script headers: index.php
    
    Server is running Debian Wheezy and ispconfig is set up as described in http://www.howtoforge.com/perfect-server-debian-wheezy-apache2-bind-dovecot-ispconfig-3
    Any idea what is wrong here?
    Best regards
     
  2. till

    till Super Moderator Staff Member ISPConfig Developer

    Is this a virtual server or real root server?
     
  3. sumawelt

    sumawelt New Member HowtoForge Supporter

    It's a kvm vserver
     
  4. till

    till Super Moderator Staff Member ISPConfig Developer

    Please try to switch the php mode to php-fpm for the website, then wait 1-2 minutes and try again.
     
  5. sumawelt

    sumawelt New Member HowtoForge Supporter

    Unfortutnately this didn't quite seem to work. The server again seems to be hanging. I'm not sure if switching to php-fpm did actually work because the log says:
    Code:
    [Tue Dec 09 15:46:23 2014] [error] [client 81.27.127.148] FastCGI: comm with server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de" aborted: idle timeout (300 sec)
    [Tue Dec 09 15:46:23 2014] [error] [client 81.27.127.148] FastCGI: incomplete headers (0 bytes) received from server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de"
    [Tue Dec 09 15:46:25 2014] [error] [client 93.104.103.201] FastCGI: comm with server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de" aborted: idle timeout (300 sec)
    [Tue Dec 09 15:46:25 2014] [error] [client 93.104.103.201] FastCGI: incomplete headers (0 bytes) received from server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de"
    [Tue Dec 09 15:46:26 2014] [error] [client 93.104.103.201] FastCGI: comm with server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de" aborted: idle timeout (300 sec)
    [Tue Dec 09 15:46:26 2014] [error] [client 93.104.103.201] FastCGI: incomplete headers (0 bytes) received from server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de"
    [Tue Dec 09 15:46:27 2014] [error] [client 93.104.103.201] FastCGI: comm with server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de" aborted: idle timeout (300 sec)
    [Tue Dec 09 15:46:27 2014] [error] [client 93.104.103.201] FastCGI: incomplete headers (0 bytes) received from server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de"
    [Tue Dec 09 15:46:28 2014] [error] [client 93.104.103.201] FastCGI: comm with server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de" aborted: idle timeout (300 sec)
    [Tue Dec 09 15:46:28 2014] [error] [client 93.104.103.201] FastCGI: incomplete headers (0 bytes) received from server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de"
    
    I ran top in order to see the load but there's hardly any load on the machin at all but when I scrolled down a bit, I noticed MANY apache threads running on the machine. I counted 155 threads with entries like:
    Code:
         1  20727 ?        Ss     0:01 /usr/sbin/apache2 -k start
         2  20731 ?        S      0:00 /usr/sbin/apache2 -k start
         3  20735 ?        S      0:01 /usr/sbin/apache2 -k start
         4  20737 ?        S      0:01 /usr/sbin/apache2 -k start
         5  20744 ?        S      0:01 /usr/sbin/apache2 -k start
         6  20998 ?        S      0:01 /usr/sbin/apache2 -k start
         7  20999 ?        S      0:01 /usr/sbin/apache2 -k start
         8  21000 ?        S      0:02 /usr/sbin/apache2 -k start
         9  21660 ?        S      0:01 /usr/sbin/apache2 -k start
        10  24854 ?        S      0:00 /usr/sbin/apache2 -k start
        11  24857 ?        S      0:00 /usr/sbin/apache2 -k start
        12  24860 ?        S      0:00 /usr/sbin/apache2 -k start
        13  24862 ?        S      0:00 /usr/sbin/apache2 -k start
        14  24863 ?        S      0:00 /usr/sbin/apache2 -k start
    .... and so on
    
    Isn't this too much?
     
  6. till

    till Super Moderator Staff Member ISPConfig Developer

    Thats a bit too much. Seems as if apache is hanging and therefor spawns more and more processes. How much ram does the server has? And aree there any other errors in the global apache error.log or in the website error.log, especially errors that appear right after you restarted apache are of interest.
     
  7. sumawelt

    sumawelt New Member HowtoForge Supporter

    The server has 16 Gb of RAM
    this is the servers' logfile whil restarting the service:
    Code:
    [Tue Dec 09 17:05:29 2014] [notice] caught SIGTERM, shutting down
    [Tue Dec 09 17:05:30 2014] [notice] suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)
    [Tue Dec 09 17:05:30 2014] [notice] Digest: generating secret for digest authentication ...
    [Tue Dec 09 17:05:30 2014] [notice] Digest: done
    [Tue Dec 09 17:05:30 2014] [notice] FastCGI: process manager initialized (pid 29306)
    PHP Deprecated:  Comments starting with '#' are deprecated in /etc/php5/apache2/conf.d/ming.ini on line 1 in Unknown on line 0
    [Tue Dec 09 17:05:30 2014] [error] python_init: Python version mismatch, expected '2.7.2+', found '2.7.3'.
    [Tue Dec 09 17:05:30 2014] [error] python_init: Python executable found '/usr/bin/python'.
    [Tue Dec 09 17:05:30 2014] [error] python_init: Python path being used '/usr/lib/python2.7/:/usr/lib/python2.7/plat-linux2:/usr/lib/python2.7/lib-tk:/usr/lib/python2.7/lib-old:/usr/lib/python2.7/lib-dynload'.
    [Tue Dec 09 17:05:30 2014] [notice] mod_python: Creating 8 session mutexes based on 150 max processes and 0 max threads.
    [Tue Dec 09 17:05:30 2014] [notice] mod_python: using mutex_directory /tmp
    [Tue Dec 09 17:05:30 2014] [notice] Apache/2.2.22 (Debian) DAV/2 mod_fastcgi/mod_fastcgi-SNAP-0910052141 mod_fcgid/2.3.6 PHP/5.4.35-0+deb7u2 mod_python/3.3.1 Python/2.7.3 mod_ruby/1.2.6 Ruby/1.8.7(2012-02-08) mod_ssl/2.2.22 OpenSSL/1.0.1e configured -- resuming normal operations
    
    As for the vhost it self apache throws no errors during restart timeouts start during normal operations after a while:
    Code:
    [Tue Dec 09 17:10:45 2014] [error] [client 93.104.103.201] FastCGI: comm with server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-80-subdomain.domain.de" aborted: idle timeout (300 sec)
    [Tue Dec 09 17:10:45 2014] [error] [client 93.104.103.201] FastCGI: incomplete headers (0 bytes) received from server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-80-subdomain.domain.de"
    [Tue Dec 09 17:11:01 2014] [error] [client 93.104.103.201] FastCGI: comm with server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de" aborted: idle timeout (300 sec)
    [Tue Dec 09 17:11:01 2014] [error] [client 93.104.103.201] FastCGI: incomplete headers (0 bytes) received from server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de"
    [Tue Dec 09 17:11:33 2014] [error] [client 93.104.103.201] FastCGI: comm with server "/var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-443-subdomain.domain.de" aborted: idle timeout (300 sec)
    
    What also puzzles me is even though I set it to php-fpm the logfile still reports errors for php5-fcgi.
     
  8. till

    till Super Moderator Staff Member ISPConfig Developer

    Thats ok, if you compare the errors with the first errors, then you see that its a bit different. The line /var/www/clients/client1/web6/cgi-bin/php5-fcgi-xxx.xxx.xxx.xxx-80-subdomain.domain.de is from php-fpm mode.

    the problem is that php for whatever reason hangs while processing the script. But it just hans until the connection to apache times out without quitting or aborting the php file processing.

    Do you have any errors in the php fpm log file or in the suexec log file?
     
  9. sumawelt

    sumawelt New Member HowtoForge Supporter

    OK, this could be a clue. Here is the php5-fpm.log:
    Code:
    [09-Dez-2014 12:54:02] NOTICE: fpm is running, pid 20689
    [09-Dez-2014 12:54:02] NOTICE: ready to handle connections
    [09-Dez-2014 15:11:23] WARNING: [pool web6] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 6 total children
    [09-Dez-2014 15:11:24] WARNING: [pool web6] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 0 idle, and 7 total children
    [09-Dez-2014 15:11:25] WARNING: [pool web6] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 8 total children
    [09-Dez-2014 15:11:26] WARNING: [pool web6] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 9 total children
    [09-Dez-2014 15:11:27] WARNING: [pool web6] server reached pm.max_children setting (10), consider raising it
    [09-Dez-2014 16:34:04] WARNING: [pool web6] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 8 total children
    [09-Dez-2014 16:34:05] WARNING: [pool web6] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 0 idle, and 9 total children
    [09-Dez-2014 16:34:06] WARNING: [pool web6] server reached pm.max_children setting (10), consider raising it
    
    the suexec.log looks normal:
    Code:
    [2014-12-09 11:36:34]: uid: (5008/web6) gid: (5005/client1) cmd: .php-fcgi-starter
    [2014-12-09 11:44:39]: uid: (5008/web6) gid: (5005/client1) cmd: .php-fcgi-starter
    [2014-12-09 12:37:57]: uid: (5008/web6) gid: (5005/client1) cmd: .php-fcgi-starter
    [2014-12-09 12:46:01]: uid: (5008/web6) gid: (5005/client1) cmd: .php-fcgi-starter
    [2014-12-09 12:48:30]: uid: (5008/web6) gid: (5005/client1) cmd: .php-fcgi-starter
    [2014-12-09 12:53:04]: uid: (5003/ispconfig) gid: (5004/ispconfig) cmd: .php-fcgi-starter
    [2014-12-09 13:05:48]: uid: (5003/ispconfig) gid: (5004/ispconfig) cmd: .php-fcgi-starter
    [2014-12-09 16:31:02]: uid: (5003/ispconfig) gid: (5004/ispconfig) cmd: .php-fcgi-starter
    [2014-12-09 16:47:43]: uid: (5003/ispconfig) gid: (5004/ispconfig) cmd: .php-fcgi-starter
    [2014-12-09 17:18:11]: uid: (5003/ispconfig) gid: (5004/ispconfig) cmd: .php-fcgi-starter
    
    as I'm not very familiar with apache and php tuning, what settings would you suggest for php-fpm as suggested in the php-fpm log?
     
  10. till

    till Super Moderator Staff Member ISPConfig Developer

    Go to the affected website in ispconfig, ensure that php mode is set to php-fpm, then go to the options tab of the website, set the php-fpm mode to ondemand and set PHP-FPM pm.max_children to 250. Then iat 1-2 minutes to ensure that the changes are written to disk. If this dont help, please try to reboot the server afterwards, I had a similar issue some time ago where php was so locked that I had to kill all processes manuallyand a reboot will have the same result.
     

Share This Page