The Community Forums

Interact with an entire community of cPanel & WHM users!
  1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.

php-fpm error.log using up 100% disk space

Discussion in 'EasyApache' started by Reado, Jul 12, 2017.

Tags:
  1. Reado

    Reado Well-Known Member

    Joined:
    Sep 8, 2009
    Messages:
    184
    Likes Received:
    7
    Trophy Points:
    68
    Location:
    United Kingdom
    cPanel Access Level:
    DataCenter Provider
    I am running Apache 2.4.25 + HTTP/2 in an MPM Prefork + PHP DSO configuration.

    According to the change log for Apache 2.4.27, HTTP/2 won't work anymore with Prefork:

    Code:
      *) COMPATIBILITY: mod_http2: Disable and give warning when using Prefork.
         The server will continue to run, but HTTP/2 will no longer be negotiated.
         [Stefan Eissing]
    Therefore I have changed the MPM to Event, but this causes EA4 to instruct me to use PHP-FPM.

    The overall website performance since switching to PHP-FPM has been much better.

    However, this morning (48+ hours after switching to PHP-FPM), the server had appeared to be out of disk space. Further investigation indicated the error.log file located within /opt/cpanel/ea-php56/root/usr/var/log was consuming more than 13GB! A quick tail of the file showed line-after-line of notices saying worker started, worker closed. These lines repeated what looked like hundreds of times a second! Unfortunately I had to delete the file to resolve the disk space issue.

    Since rebooting the server, the file now looks like this:

    # tail -f error.log -n 128
    [12-Jul-2017 09:22:43] NOTICE: fpm is running, pid 1275
    [12-Jul-2017 09:22:43] NOTICE: ready to handle connections
    [12-Jul-2017 09:22:43] NOTICE: systemd monitor interval set to 10000ms
    [12-Jul-2017 09:24:05] WARNING: [pool dev3_reades_local] server reached max_children setting (5), consider raising it
    [12-Jul-2017 09:40:15] NOTICE: Terminating ...
    [12-Jul-2017 09:40:15] NOTICE: exiting, bye-bye!
    [12-Jul-2017 09:40:17] NOTICE: fpm is running, pid 4764
    [12-Jul-2017 09:40:17] NOTICE: ready to handle connections
    [12-Jul-2017 09:40:17] NOTICE: systemd monitor interval set to 10000ms
    [12-Jul-2017 09:40:46] NOTICE: Terminating ...
    [12-Jul-2017 09:40:46] NOTICE: exiting, bye-bye!
    [12-Jul-2017 09:40:46] NOTICE: fpm is running, pid 5124
    [12-Jul-2017 09:40:46] NOTICE: ready to handle connections
    [12-Jul-2017 09:40:46] NOTICE: systemd monitor interval set to 10000ms

    This is the entire log. Since 09:40, I have accessed the website numerous times but no additional entries have been written.

    Why would the log file use the entire disk to start with? Is there anything I can do to prevent this happening in future?

    Also according to this, it says "pm" defaults to "ondemand" and the PHP configuration here says max_children is used when pm is set to "static". Since that is not the case, why does the log suggest I need to change the max_children value?
     
  2. cPanelMichael

    cPanelMichael Forums Analyst
    Staff Member

    Joined:
    Apr 11, 2011
    Messages:
    37,064
    Likes Received:
    1,288
    Trophy Points:
    363
    cPanel Access Level:
    Root Administrator
    Hello,

    Could you run the commands below and let us know the output?

    Code:
    grep rotatelogs_size_threshhold /var/cpanel/cpanel.config
    cat /usr/local/cpanel/version
    Thank you.
     
  3. Reado

    Reado Well-Known Member

    Joined:
    Sep 8, 2009
    Messages:
    184
    Likes Received:
    7
    Trophy Points:
    68
    Location:
    United Kingdom
    cPanel Access Level:
    DataCenter Provider
    # grep rotatelogs_size_threshhold /var/cpanel/cpanel.config
    rotatelogs_size_threshhold_in_megabytes=300
    # cat /usr/local/cpanel/version
    11.64.0.32
     
  4. cPanelMichael

    cPanelMichael Forums Analyst
    Staff Member

    Joined:
    Apr 11, 2011
    Messages:
    37,064
    Likes Received:
    1,288
    Trophy Points:
    363
    cPanel Access Level:
    Root Administrator
    Hello @Reado,

    Could you open a support ticket using the link in my signature so we can take a closer look?

    Thank you.
     
  5. Reado

    Reado Well-Known Member

    Joined:
    Sep 8, 2009
    Messages:
    184
    Likes Received:
    7
    Trophy Points:
    68
    Location:
    United Kingdom
    cPanel Access Level:
    DataCenter Provider
    The issue hasn't occurred since, with that server. However I have just deployed PHP-FPM to another server and noticed the PHP-FPM process in "top" is using 60% CPU constantly. In the same folder, there's an error.log file increasing at a rate of 1MB a minute with this:

    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27617 exited with code 0 after 0.008659 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27624 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27619 exited with code 0 after 0.008629 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27625 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27620 exited with code 0 after 0.008704 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27626 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27621 exited with code 0 after 0.007758 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27627 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27622 exited with code 0 after 0.008097 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27628 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27625 exited with code 0 after 0.006393 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27630 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27624 exited with code 0 after 0.009182 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27631 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27626 exited with code 0 after 0.007949 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27632 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27627 exited with code 0 after 0.007170 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27633 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27628 exited with code 0 after 0.008140 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27634 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27631 exited with code 0 after 0.006551 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27636 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27630 exited with code 0 after 0.009470 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27638 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27632 exited with code 0 after 0.009755 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27639 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27633 exited with code 0 after 0.008710 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27640 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27634 exited with code 0 after 0.006793 seconds from start
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27641 started
    [17-Jul-2017 16:08:55] NOTICE: [pool reades_co_uk] child 27636 exited with code 0 after 0.007413 seconds from start
     
  6. cPanelMichael

    cPanelMichael Forums Analyst
    Staff Member

    Joined:
    Apr 11, 2011
    Messages:
    37,064
    Likes Received:
    1,288
    Trophy Points:
    363
    cPanel Access Level:
    Root Administrator
    Could you open a support ticket so we can take a closer look to see why that's happening, and to determine why the log is not rotated?

    Thank you.
     
  7. Reado

    Reado Well-Known Member

    Joined:
    Sep 8, 2009
    Messages:
    184
    Likes Received:
    7
    Trophy Points:
    68
    Location:
    United Kingdom
    cPanel Access Level:
    DataCenter Provider
    I have opened a support ticket.

    A server reboot seems to resolve the issue. However that was done 3 days ago and today the issue resurfaced:

    1515 root 20 0 502096 17984 11792 R 100.0 0.5 785:29.86 php-fpm: master process (/opt/cpanel/ea-php56/root/etc/php-fpm.conf)

    root@web0 [/opt/cpanel/ea-php56/root/usr/var/log/php-fpm]# v -h
    total 7.0G
    drwxrwx---. 2 nobody root 4.0K Jul 21 09:30 ./
    drwxr-xr-x. 3 root root 4.0K Jul 17 15:19 ../
    -rw-------. 1 root root 7.0G Jul 21 09:44 error.log
    root@web0 [/opt/cpanel/ea-php56/root/usr/var/log/php-fpm]#

    I don't think it's as simple as the log being rotated. The main PHP-FPM process is using more than 50% CPU consistently while the error.log file is being written to. Will await to hear from support.
     
  8. Reado

    Reado Well-Known Member

    Joined:
    Sep 8, 2009
    Messages:
    184
    Likes Received:
    7
    Trophy Points:
    68
    Location:
    United Kingdom
    cPanel Access Level:
    DataCenter Provider
    I have discovered what's causing the error. I'm running a PHP script via my browser that minifies our site's CSS files using shell_exec(). The script runs fine and the shell_exec() command completes, but each time it does, the PHP-FPM starts using 100% CPU and the error.log file starts expanding.

    However it seems that only certain commands executed via shell_exec() are triggering the issue. In my case, I'm using postcss and autoprefixer which results in this output:

    "✔ Finished css_from.css (64ms)"

    As soon as the script finishes, the errors begin:

    [21-Jul-2017 10:12:07] WARNING: [pool dev3_reades_local] child 15509 said into stderr: "✔ Finished css_from.css (64ms)"
    [21-Jul-2017 10:12:07] NOTICE: [pool dev3_reades_local] child 15509 exited with code 0 after 1.037395 seconds from start
    [21-Jul-2017 10:12:07] NOTICE: [pool dev3_reades_local] child 15520 started
    [21-Jul-2017 10:12:07] NOTICE: [pool dev3_reades_local] child 15520 exited with code 0 after 0.007442 seconds from start
    [21-Jul-2017 10:12:07] NOTICE: [pool dev3_reades_local] child 15521 started
    [21-Jul-2017 10:12:07] NOTICE: [pool dev3_reades_local] child 15521 exited with code 0 after 0.007127 seconds from start
    [21-Jul-2017 10:12:07] NOTICE: [pool dev3_reades_local] child 15522 started

    If I append the command so there's no output, the issue still occurs. However if I execute something like shell_exec("uptime"), the issue does not occur.

    Now I know the cause, I was curious, so I Googled and found this:

    PHP :: Bug #70185 :: php-fpm restarts master process in a loop when exec() and using ssh multiplexing

    This bug dates back to PHP 5.4 and does not appear to have ever been fixed. I have posted a comment on that page.

    Luckily we have a workaround - don't execute any PHP scripts from the browser that contain exec() or shell_exec() - execute them from the command line instead. This workaround works for me.
     
  9. cPanelMichael

    cPanelMichael Forums Analyst
    Staff Member

    Joined:
    Apr 11, 2011
    Messages:
    37,064
    Likes Received:
    1,288
    Trophy Points:
    363
    cPanel Access Level:
    Root Administrator
    Hello,

    I'd also like to note that internal case CPANEL-14681 is open to address an issue where /opt/cpanel/ea-php$$/root/usr/var/log/php-fpm/error.log isn't not rotated. I'll monitor this case and update this thread with more information as it becomes available.

    Thank you.
     
Loading...

Share This Page