Please whitelist cPanel in your adblocker so that you’re able to see our version release promotions, thanks!

The Community Forums

Interact with an entire community of cPanel & WHM users!

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:
    191
    Likes Received:
    8
    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:
    43,672
    Likes Received:
    1,788
    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.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  3. Reado

    Reado Well-Known Member

    Joined:
    Sep 8, 2009
    Messages:
    191
    Likes Received:
    8
    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:
    43,672
    Likes Received:
    1,788
    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.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  5. Reado

    Reado Well-Known Member

    Joined:
    Sep 8, 2009
    Messages:
    191
    Likes Received:
    8
    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:
    43,672
    Likes Received:
    1,788
    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.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
  7. Reado

    Reado Well-Known Member

    Joined:
    Sep 8, 2009
    Messages:
    191
    Likes Received:
    8
    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:
    191
    Likes Received:
    8
    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:
    43,672
    Likes Received:
    1,788
    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 rotated. I'll monitor this case and update this thread with more information as it becomes available.

    Thank you.

    Update: This looks to no longer be an issue in recent versions of cPanel, as PHP-FPM logs appear to rotate as expected.
     
    Stop hovering to collapse... Click to collapse... Hover to expand... Click to expand...
    #9 cPanelMichael, Jul 25, 2017
    Last edited: Dec 18, 2017
Loading...

Share This Page

  1. This site uses cookies to help personalise content, tailor your experience and to keep you logged in if you register.
    By continuing to use this site, you are consenting to our use of cookies.
    Dismiss Notice