PHP 7.2/7.3 Upgrade Crashing Servers CPU 100%

Discussion in 'Installation/Configuration' started by Thane, Jun 18, 2019.

  1. Thane

    Thane New Member HowtoForge Supporter

    Hi all,
    Just wanted to get some feelers out for anyone else that may have had a similar issue when adding php versions 7.2/7.3 to their servers. I added these versions following the 'easy way':
    https://www.howtoforge.com/tutorial...fig-3-from-debian-packages-on-debian-8-and-9/

    Servers are all debian 9.9, running Apache.

    To get everything running smoothly for the mostly-wordpress hosted sites, I added these modules:
    php7.2-bcmath php7.3-bcmath php7.2-curl php7.3-curl php7.2-xml php7.3-xml php7.2-mysql php7.3-mysql php7.2-mbstring php7.3-mbstring libapache2-mod-php php-curl php7.3-soap php7.2-soap php7.2-gd php7.3-gd

    The sites all run nice and smooth on both 7.2 and 7.3, the problem is shortly after adding the new php versions (including updating server packages and reboot) CPU begins spiking and maxing out. Most servers were able to continue functioning with the high load, but of course it's not an ideal situation, so try rebooting to see if that helps - it does. Server monitor shows the sites consuming the huge CPU appear to be sites that were left on php 7.0/default. So next step was to switch all sites on servers to 7.2/7.3, which seemed like it might work but still getting random servers locking up. Sometimes the process maxing out CPU and getting "stuck" at high CPU is either php-cgi, or apache2, sometimes not able to figure out which process is locked/stuck because the server monitors get locked before they can log anything.

    Looking at error logs for latest server freeze, nothing important in Apache logs, ispconfig log empty, mysql log just shows usual info after reboot, site error logs are usual.

    I saw Till tell someone in a semi-related thread about their high cpu usage that "their php.ini wasn't allowing ispconfig to run", I checked the ini's for 7.2/7.3 and ran comparison against the ini's in 7.0, no major differences.
     
  2. Thane

    Thane New Member HowtoForge Supporter

    This is an example server that was locked up last night, the php process at the top of the list was stuck at 100% (load was super high at ~8.0 when normal load is <1.0), couldn't restart apache, couldn't reboot from command line - had to give it a hard reboot:
    [​IMG]
     
  3. Jesse Norell

    Jesse Norell Well-Known Member

    That php process was running as root from the command line (or cronjob or similar) .. you'll need to look more to see what it was doing / how it started / etc. Eg. look at ps output (eg. ps auxww | grep php), pstree, see what lsof shows (lsof -p {pid}) and the like.
     
  4. Thane

    Thane New Member HowtoForge Supporter

    Thanks @Jesse Norell
    I attempted 'ps auxww | grep php' and after a few lines the server locked up, had to hard reboot. This server was experiencing the high load and site stuck on high CPU (on default php 7.0):
    [​IMG]

    I noticed in ISPC>System>Server Config>PHP Settings, it still has old paths to php5, so just copied over settings from another server that has 7.0 for default - maybe there's something going on with that @[email protected]
     
  5. Jesse Norell

    Jesse Norell Well-Known Member

    So in that last screenshot, investigate process id 11098 (first column). It has so much cpu time used (51:51), I'd wonder if it's a website being exploited. It might be something legitimate too, just things have gone awry (eg. I used to see the combo of large wordpress site backup files with (old) wordfence scanning for malware regularly hammer server load - a combo of configuration to ignore those and further improvements to wordfence have resolved it for several years now).

    'ls -l /var/www/ | grep web31/ | awk '{print $9}' will tell you the website name; 'lsof -p 11098' will show what filehandles the process has open, which might be an indication of what script(s) it's running. Check syslog or php_error.log for php related errors/messages (you might have to enable the error_log setting in your php.ini). Your apache logs should log requests made, if you can correlate that with when a problem php fires off.

    Also make sure you have all software up to date, starting with the OS packages, but also the software running on any affected websites (web31 in this case). You might run some malware scanners on your website files.
     
  6. Thane

    Thane New Member HowtoForge Supporter

    Thanks for more tips, much appreciated (I just wish someone else had this problem to confirm its not just me XD).

    Indeed that site was garbage, it's ancient theme, tons of plugins and no security setup - I added Wordfence to get some basic security added and ran a scan, came up clean enough.

    Ran through the error logs again and now there is a lot of info, though not sure if it's helpful...

    First there's a bunch of these:
    [Tue Jun 18 15:59:32.761437 2019] [proxy_fcgi:error] [pid 7033] [client 91.134.231.96:5952] AH01071: Got error 'Primary script unknown'
    No LSB modules are available.
    No LSB modules are available.

    Followed by about 500 of these:
    [Tue Jun 18 18:51:44.358709 2019] [fcgid:warn] [pid 24051] mod_fcgid: process 11098 graceful kill fail, sending SIGKILL

    Then this chunk was logged happening about 5 times:
    [ 2019-06-18 20:11:04.1243 4081/7f12eb062700 age/Ust/UstRouterMain.cpp:422 ]: Signal received. Gracefully shutting down... (send signal 2 more time(s) to force shutdown)
    [ 2019-06-18 20:11:04.1246 4081/7f12f16b0600 age/Ust/UstRouterMain.cpp:492 ]: Received command to shutdown gracefully. Waiting until all clients have disconnected...
    [ 2019-06-18 20:11:04.1276 4081/7f12ea861700 Ser/Server.h:817 ]: [UstRouterApiServer] Freed 0 spare client objects
    [ 2019-06-18 20:11:04.1276 4081/7f12ea861700 Ser/Server.h:464 ]: [UstRouterApiServer] Shutdown finished
    [ 2019-06-18 20:11:04.1277 4081/7f12eb062700 Ser/Server.h:464 ]: [UstRouter] Shutdown finished

    [ 2019-06-18 20:11:04.1279 4074/7f93866a0700 age/Cor/CoreMain.cpp:532 ]: Signal received. Gracefully shutting down... (send signal 2 more time(s) to force shutdown)
    [ 2019-06-18 20:11:04.1280 4074/7f938cf5d600 age/Cor/CoreMain.cpp:901 ]: Received command to shutdown gracefully. Waiting until all clients have disconnected...
    [ 2019-06-18 20:11:04.1283 4074/7f93577fe700 Ser/Server.h:817 ]: [ServerThr.6] Freed 128 spare client objects
    [ 2019-06-18 20:11:04.1283 4074/7f93577fe700 Ser/Server.h:464 ]: [ServerThr.6] Shutdown finished
    [ 2019-06-18 20:11:04.1283 4074/7f9384d1a700 Ser/Server.h:817 ]: [ServerThr.4] Freed 128 spare client objects
    [ 2019-06-18 20:11:04.1284 4074/7f9384d1a700 Ser/Server.h:464 ]: [ServerThr.4] Shutdown finished
    [ 2019-06-18 20:11:04.1285 4074/7f9356ffd700 Ser/Server.h:817 ]: [ApiServer] Freed 0 spare client objects
    [ 2019-06-18 20:11:04.1285 4074/7f9356ffd700 Ser/Server.h:464 ]: [ApiServer] Shutdown finished
    [ 2019-06-18 20:11:04.1313 4081/7f12f16b0600 age/Ust/UstRouterMain.cpp:523 ]: Passenger UstRouter shutdown finished
    [ 2019-06-18 20:11:04.1314 4074/7f93866a0700 Ser/Server.h:817 ]: [ServerThr.1] Freed 128 spare client objects
    [ 2019-06-18 20:11:04.1314 4074/7f93866a0700 Ser/Server.h:464 ]: [ServerThr.1] Shutdown finished
    [ 2019-06-18 20:11:04.1314 4074/7f9385e1e700 Ser/Server.h:817 ]: [ServerThr.2] Freed 128 spare client objects
    [ 2019-06-18 20:11:04.1314 4074/7f9385e1e700 Ser/Server.h:464 ]: [ServerThr.2] Shutdown finished
    [ 2019-06-18 20:11:04.1315 4074/7f938559c700 Ser/Server.h:817 ]: [ServerThr.3] Freed 128 spare client objects
    [ 2019-06-18 20:11:04.1315 4074/7f938559c700 Ser/Server.h:464 ]: [ServerThr.3] Shutdown finished
    [ 2019-06-18 20:11:04.1316 4074/7f9357fff700 Ser/Server.h:817 ]: [ServerThr.5] Freed 128 spare client objects
    [ 2019-06-18 20:11:04.1316 4074/7f9357fff700 Ser/Server.h:464 ]: [ServerThr.5] Shutdown finished
    [ 2019-06-18 20:11:04.2351 4074/7f938cf5d600 age/Cor/CoreMain.cpp:967 ]: Passenger core shutdown finished
    [Tue Jun 18 20:11:04.238080 2019] [core:notice] [pid 4060] AH00052: child pid 9900 exit signal Segmentation fault (11)
    [Tue Jun 18 20:11:07.513744 2019] [core:warn] [pid 4060] AH00045: child process 9896 still did not exit, sending a SIGTERM
    [Tue Jun 18 20:11:07.513818 2019] [core:warn] [pid 4060] AH00045: child process 9899 still did not exit, sending a SIGTERM
    [Tue Jun 18 20:11:09.515994 2019] [core:warn] [pid 4060] AH00045: child process 9896 still did not exit, sending a SIGTERM
    [Tue Jun 18 20:11:09.516062 2019] [core:warn] [pid 4060] AH00045: child process 9899 still did not exit, sending a SIGTERM
    [Tue Jun 18 20:11:11.518234 2019] [core:warn] [pid 4060] AH00045: child process 9896 still did not exit, sending a SIGTERM
    [Tue Jun 18 20:11:11.518317 2019] [core:warn] [pid 4060] AH00045: child process 9899 still did not exit, sending a SIGTERM
    [Tue Jun 18 20:11:13.520501 2019] [core:error] [pid 4060] AH00046: child process 9896 still did not exit, sending a SIGKILL
    [Tue Jun 18 20:11:13.522766 2019] [core:error] [pid 4060] AH00046: child process 9899 still did not exit, sending a SIGKILL
    [Tue Jun 18 20:11:14.523981 2019] [mpm_prefork:notice] [pid 4060] AH00169: caught SIGTERM, shutting down
    [ 2019-06-18 20:11:14.6872 9929/7feddaad9600 age/Wat/WatchdogMain.cpp:1291 ]: Starting Passenger watchdog...
    [ 2019-06-18 20:11:14.6988 9932/7f7fb9b25600 age/Cor/CoreMain.cpp:982 ]: Starting Passenger core...
    [ 2019-06-18 20:11:14.6989 9932/7f7fb9b25600 age/Cor/CoreMain.cpp:235 ]: Passenger core running in multi-application mode.
    [ 2019-06-18 20:11:14.7014 9932/7f7fb9b25600 age/Cor/CoreMain.cpp:732 ]: Passenger core online, PID 9932
    [ 2019-06-18 20:11:14.7136 9939/7f2b1b9b7600 age/Ust/UstRouterMain.cpp:529 ]: Starting Passenger UstRouter...
    [ 2019-06-18 20:11:14.7143 9939/7f2b1b9b7600 age/Ust/UstRouterMain.cpp:342 ]: Passenger UstRouter online, PID 9939
    [Tue Jun 18 20:11:14.729677 2019] [suexec:notice] [pid 9927] AH01232: suEXEC mechanism enabled (wrapper: /usr/lib/apache2/suexec)


    [ 2019-06-18 20:11:14.7322 9932/7f7fb3268700 age/Cor/CoreMain.cpp:532 ]: Signal received. Gracefully shutting down... (send signal 2 more time(s) to force shutdown)
    [ 2019-06-18 20:11:14.7323 9939/7f2b15369700 age/Ust/UstRouterMain.cpp:422 ]: Signal received. Gracefully shutting down... (send signal 2 more time(s) to force shutdown)
    [ 2019-06-18 20:11:14.7323 9939/7f2b1b9b7600 age/Ust/UstRouterMain.cpp:492 ]: Received command to shutdown gracefully. Waiting until all clients have disconnected...
    [ 2019-06-18 20:11:14.7324 9939/7f2b15369700 Ser/Server.h:464 ]: [UstRouter] Shutdown finished
    [ 2019-06-18 20:11:14.7324 9939/7f2b14b68700 Ser/Server.h:817 ]: [UstRouterApiServer] Freed 0 spare client objects
    [ 2019-06-18 20:11:14.7324 9939/7f2b14b68700 Ser/Server.h:464 ]: [UstRouterApiServer] Shutdown finished
    [ 2019-06-18 20:11:14.7327 9932/7f7fb9b25600 age/Cor/CoreMain.cpp:901 ]: Received command to shutdown gracefully. Waiting until all clients have disconnected...
    [ 2019-06-18 20:11:14.7329 9939/7f2b1b9b7600 age/Ust/UstRouterMain.cpp:523 ]: Passenger UstRouter shutdown finished
    [ 2019-06-18 20:11:14.7332 9932/7f7fb29e6700 Ser/Server.h:817 ]: [ServerThr.2] Freed 128 spare client objects
    [ 2019-06-18 20:11:14.7332 9932/7f7fb29e6700 Ser/Server.h:464 ]: [ServerThr.2] Shutdown finished
    [ 2019-06-18 20:11:14.7333 9932/7f7fb18e2700 Ser/Server.h:817 ]: [ServerThr.4] Freed 128 spare client objects
    [ 2019-06-18 20:11:14.7333 9932/7f7fb1060700 Ser/Server.h:817 ]: [ServerThr.5] Freed 128 spare client objects
    [ 2019-06-18 20:11:14.7333 9932/7f7fb18e2700 Ser/Server.h:464 ]: [ServerThr.4] Shutdown finished
    [ 2019-06-18 20:11:14.7333 9932/7f7fb1060700 Ser/Server.h:464 ]: [ServerThr.5] Shutdown finished
    [ 2019-06-18 20:11:14.7334 9932/7f7fb2164700 Ser/Server.h:817 ]: [ServerThr.3] Freed 128 spare client objects
    [ 2019-06-18 20:11:14.7334 9932/7f7fb2164700 Ser/Server.h:464 ]: [ServerThr.3] Shutdown finished
    [ 2019-06-18 20:11:14.7335 9932/7f7f7bfff700 Ser/Server.h:817 ]: [ServerThr.6] Freed 128 spare client objects
    [ 2019-06-18 20:11:14.7335 9932/7f7f7bfff700 Ser/Server.h:464 ]: [ServerThr.6] Shutdown finished
    [ 2019-06-18 20:11:14.7335 9932/7f7fb3268700 Ser/Server.h:817 ]: [ServerThr.1] Freed 128 spare client objects
    [ 2019-06-18 20:11:14.7335 9932/7f7fb3268700 Ser/Server.h:464 ]: [ServerThr.1] Shutdown finished
    [ 2019-06-18 20:11:14.7335 9932/7f7f7b7fe700 Ser/Server.h:817 ]: [ApiServer] Freed 0 spare client objects
    [ 2019-06-18 20:11:14.7335 9932/7f7f7b7fe700 Ser/Server.h:464 ]: [ApiServer] Shutdown finished
    [ 2019-06-18 20:11:14.8165 9932/7f7fb9b25600 age/Cor/CoreMain.cpp:967 ]: Passenger core shutdown finished
    [Tue Jun 18 20:11:14.826759 2019] [:notice] [pid 9969] FastCGI: process manager initialized (pid 9969)
    [ 2019-06-18 20:11:14.8400 9971/7fe5190b3600 age/Wat/WatchdogMain.cpp:1291 ]: Starting Passenger watchdog...
    [ 2019-06-18 20:11:14.8538 9978/7f470b17e600 age/Cor/CoreMain.cpp:982 ]: Starting Passenger core...
    [ 2019-06-18 20:11:14.8539 9978/7f470b17e600 age/Cor/CoreMain.cpp:235 ]: Passenger core running in multi-application mode.
    [ 2019-06-18 20:11:14.8564 9978/7f470b17e600 age/Cor/CoreMain.cpp:732 ]: Passenger core online, PID 9978
    [ 2019-06-18 20:11:14.8689 9985/7fe498ce3600 age/Ust/UstRouterMain.cpp:529 ]: Starting Passenger UstRouter...
    [ 2019-06-18 20:11:14.8696 9985/7fe498ce3600 age/Ust/UstRouterMain.cpp:342 ]: Passenger UstRouter online, PID 9985
    [Tue Jun 18 20:11:14.913661 2019] [:error] [pid 9964] python_init: Python version mismatch, expected '2.7.5+', found '2.7.13'.
    [Tue Jun 18 20:11:14.913776 2019] [:error] [pid 9964] python_init: Python executable found '/usr/bin/python'.
    [Tue Jun 18 20:11:14.913783 2019] [:error] [pid 9964] python_init: Python path being used '/usr/lib/python2.7:/usr/lib/python2.7/plat-x86_64-linux-gnu:/usr/lib/python2.7/lib-tk:/usr/lib/python2.7/lib-old:/usr/lib/python2.7/lib-dynload'.
    [Tue Jun 18 20:11:14.913811 2019] [:notice] [pid 9964] mod_python: Creating 8 session mutexes based on 500 max processes and 0 max threads.
    [Tue Jun 18 20:11:14.913816 2019] [:notice] [pid 9964] mod_python: using mutex_directory /tmp
    [Tue Jun 18 20:11:14.947976 2019] [mpm_prefork:notice] [pid 9964] AH00163: Apache/2.4.25 (Debian) mod_fastcgi/mod_fastcgi-SNAP-0910052141 mod_fcgid/2.3.9 Phusion_Passenger/5.0.30 mod_python/3.3.1 Python/2.7.13 OpenSSL/1.0.2r configured -- resuming normal operations
    [Tue Jun 18 20:11:14.948027 2019] [core:notice] [pid 9964] AH00094: Command line: '/usr/sbin/apache2'
     
  7. Thane

    Thane New Member HowtoForge Supporter

    I would also note the peculiarity of the issue, some of these affected servers have been running perfect for years - they get hammered by 10-20 million pageviews/month and never crash, just since adding php 7.2/7.3 have had this issue. I noticed after installing the new php versions that new updates were available (despite running updates before/during the new php version install), and the servers seem more stable after applying those updates + rebooting. Yesterday was the first full day with the new php's added and every server crashed, some servers crashed more than others, changing the php version of the "locked / frozen / high cpu" sites to 7.2/7.3 seemed to fix the problem, at least until a different site on the server acted up. Today we switched about 99% of sites on all the servers to 7.2/7.3 since that seemed more stable, so far only had 2 servers get locked up - improvement at least. Also haven't had a server lock up in the last couple hours since updating the default php file path info in ispc>system>server config>web>php (and in the separate fastcgi tab too) - would be great if that was the root cause of the problem, but I don't see how it could @[email protected]
     
  8. ahrasis

    ahrasis Well-Known Member

    Really strange. I can't believe simply adding php7.2 and 7.3 would cause all of that. At least I never had that problem with my nginx / ubuntu server.
     
  9. till

    till Super Moderator Staff Member ISPConfig Developer

    That part is ok, ISPConfig will not alter the paths on its own after the initial install, so you must change them manually as you did already.

    Regarding your main problem, never had such a problem with PHP 7.2 / 7.3 yet.
     
  10. till

    till Super Moderator Staff Member ISPConfig Developer

    If I remember correctly, the guy in that thread had just set a memory limit which was too low, but this should not be the case if you are using a php.ini from 7.0 for a newer version.
     
  11. Thane

    Thane New Member HowtoForge Supporter

    Thanks for reading @till .
    Yes I'm still quite stumped on the problem, but may have incidentally stumbled into the solution. So as servers would lock up and require a hard reboot, I noticed new packages available for update, so I ran the updates and rebooted from command line, did that on a handful of servers before I noticed those servers started running normally. I ran through all servers, ran the update for the few packages available, reboot, no more problem the last couple days... So maybe my adding of the new php versions coincided with system updates that required multiple reboots or something.

    Not sure exactly which packages required updating after upgrading, but should be 3-4 of these that came up:
    icu-devtools libicu-dev linux-image-4.9.0-9-amd64 linux-libc-dev php php-bz2
    php-gd php-intl php-mbstring php-mysql php-pspell php-soap php-xml php-zip

    Anyhoo, still running strong for 4 days now, hopefully some of my ramblings here will help someone if they run into similar issue.

    BTW thanks for building an awesome server control panel and how-to docs, ispc is a great contribution to the internet :)

    Final Solution: Run updates again and reboot, lol.
     
    till likes this.
  12. Taleman

    Taleman Well-Known Member HowtoForge Supporter

    You can check which packages got updated on which days from /var/log/dpkg.log.
     

Share This Page