Skip to main content

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

Reado
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:
*) 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

Comments

8 comments

Date Votes
  • cPanelMichael
    Hello, Could you run the commands below and let us know the output?
    grep rotatelogs_size_threshhold /var/cpanel/cpanel.config cat /usr/local/cpanel/version
    Thank you.
    0
  • Reado
    Hello, Could you run the commands below and let us know the output?
    grep rotatelogs_size_threshhold /var/cpanel/cpanel.config cat /usr/local/cpanel/version
    Thank you.

    # grep rotatelogs_size_threshhold /var/cpanel/cpanel.config rotatelogs_size_threshhold_in_megabytes=300 # cat /usr/local/cpanel/version 11.64.0.32
    0
  • cPanelMichael
    Hello @Reado, Could you open a support ticket using the link in my signature so we can take a closer look? Thank you.
    0
  • Reado
    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
    0
  • cPanelMichael
    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.
    0
  • Reado
    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.
    0
  • Reado
    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.
    0
  • cPanelMichael
    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.
    0

Please sign in to leave a comment.

Didn't find what you were looking for?

New post