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 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?

 

[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.

 

[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

 

[cPanelMichael]

Hello @Reado,

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

Thank you.

 

[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

 

[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.

 

[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)

[email protected] [/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
[email protected] [/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.

 

[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.

 

[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.