Increased varnish log and increased Apache logs and found:
[Thu Oct 28 10:54:02 2021] [notice] caught SIGTERM, shutting down
[Thu Oct 28 10:54:02 2021] [notice] suEXEC mechanism enabled (wrapper: /usr/sbin/suexec)
[Thu Oct 28 10:54:02 2021] [notice] Digest: generating secret for digest authentication ...
[Thu Oct 28 10:54:02 2021] [notice] Digest: done
[Thu Oct 28 10:54:02 2021] [debug] util_ldap.c(2089): LDAP merging Shared Cache conf: shm=0x556e25522e88 rmm=0x556e25522ee0 for VHOST: staging03.cherry.com
[Thu Oct 28 10:54:02 2021] [debug] util_ldap.c(2089): LDAP merging Shared Cache conf: shm=0x556e25522e88 rmm=0x556e25522ee0 for VHOST: preprod.staging03.cherry.com
[Thu Oct 28 10:54:02 2021] [info] APR LDAP: Built with OpenLDAP LDAP SDK
[Thu Oct 28 10:54:02 2021] [info] LDAP: SSL support available
[Thu Oct 28 10:54:02 2021] [notice] FastCGI: process manager initialized (pid 2450)
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1909): proxy: grabbed scoreboard slot 0 in child 2451 for worker proxy:reverse
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(2025): proxy: initialized single connection worker 0 in child 2451 for (*)
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1909): proxy: grabbed scoreboard slot 0 in child 2452 for worker proxy:reverse
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1929): proxy: worker proxy:reverse already initialized
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(2025): proxy: initialized single connection worker 0 in child 2452 for (*)
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1909): proxy: grabbed scoreboard slot 0 in child 2453 for worker proxy:reverse
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1929): proxy: worker proxy:reverse already initialized
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(2025): proxy: initialized single connection worker 0 in child 2453 for (*)
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1909): proxy: grabbed scoreboard slot 0 in child 2454 for worker proxy:reverse
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1929): proxy: worker proxy:reverse already initialized
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(2025): proxy: initialized single connection worker 0 in child 2454 for (*)
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1909): proxy: grabbed scoreboard slot 0 in child 2456 for worker proxy:reverse
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1929): proxy: worker proxy:reverse already initialized
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(2025): proxy: initialized single connection worker 0 in child 2456 for (*)
[Thu Oct 28 10:54:02 2021] [notice] Apache/2.2.15 (Unix) DAV/2 mod_fastcgi/2.4.6 configured -- resuming normal operations
[Thu Oct 28 10:54:02 2021] [info] Server built: Jun 19 2018 15:45:13
[Thu Oct 28 10:54:02 2021] [debug] prefork.c(1033): AcceptMutex: sysvsem (default: sysvsem)
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1909): proxy: grabbed scoreboard slot 0 in child 2457 for worker proxy:reverse
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1929): proxy: worker proxy:reverse already initialized
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(2025): proxy: initialized single connection worker 0 in child 2457 for (*)
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1909): proxy: grabbed scoreboard slot 0 in child 2455 for worker proxy:reverse
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1929): proxy: worker proxy:reverse already initialized
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(2025): proxy: initialized single connection worker 0 in child 2455 for (*)
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1909): proxy: grabbed scoreboard slot 0 in child 2458 for worker proxy:reverse
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(1929): proxy: worker proxy:reverse already initialized
[Thu Oct 28 10:54:02 2021] [debug] proxy_util.c(2025): proxy: initialized single connection worker 0 in child 2458 for (*)
Doing curl gives me nothing
curl -H 'Authorization: Basic somethingsomething==' 127.0.0.1:80
This, however, gives me:
curl -H 'Authorization: Basic somethingsomething==' 172.31.22.60
<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html>
<head>
<title>503 Service Unavailable</title>
</head>
<body>
<h1>Error 503 Service Unavailable</h1>
<p>Service Unavailable</p>
<h3>Guru Meditation:</h3>
<p>XID: 1108131285</p>
</body>
</html>
It keeps switching from 500 error to 503 suggesting that something breaks the Apache server, but I am not getting anything in the logs. The SIGTERM makes me wonder if the Apache server is never restarting after shutting down.
[centos@staging03 ~]$ sudo service httpd status
httpd (pid 2448) is running...
However, when I do that, it tells me otherwise.
Doing sudo service httpd restart and sudo service varnish restart turns the 503 error into a 500 error.
Checking the php-fpm logs after enabling logging I got:
[28-Oct-2021 10:53:35.374356] DEBUG: pid 2228, fpm_unix_init_main(), line 520: The calling process is waiting for the master process to ping via fd=5
[28-Oct-2021 10:53:35.375469] DEBUG: pid 2229, fpm_scoreboard_init_main(), line 40: got clock tick '100'
[28-Oct-2021 10:53:35.376924] DEBUG: pid 2229, fpm_socket_af_inet_listening_socket(), line 298: Found address for 127.0.0.1, socket opened on 127.0.0.1
[28-Oct-2021 10:53:35.376961] DEBUG: pid 2229, fpm_event_init_main(), line 337: event module is epoll and 27 fds have been reserved
[28-Oct-2021 10:53:35.377002] NOTICE: pid 2229, fpm_init(), line 85: fpm is running, pid 2229
[28-Oct-2021 10:53:35.377012] DEBUG: pid 2229, main(), line 1875: Sending "1" (OK) to parent via fd=6
[28-Oct-2021 10:53:35.377067] DEBUG: pid 2228, fpm_unix_init_main(), line 539: I received a valid acknoledge from the master process, I can exit without error
[28-Oct-2021 10:53:35.377452] DEBUG: pid 2229, fpm_children_make(), line 421: [pool php5-fcgi-staging03] child 2230 started
[28-Oct-2021 10:53:35.377852] DEBUG: pid 2229, fpm_children_make(), line 421: [pool php5-fcgi-staging03] child 2231 started
[28-Oct-2021 10:53:35.378242] DEBUG: pid 2229, fpm_children_make(), line 421: [pool php5-fcgi-staging03] child 2232 started
[28-Oct-2021 10:53:35.378619] DEBUG: pid 2229, fpm_children_make(), line 421: [pool php5-fcgi-staging03] child 2233 started
[28-Oct-2021 10:53:35.378966] DEBUG: pid 2229, fpm_children_make(), line 421: [pool www] child 2234 started
[28-Oct-2021 10:53:35.379324] DEBUG: pid 2229, fpm_children_make(), line 421: [pool www] child 2235 started
[28-Oct-2021 10:53:35.379682] DEBUG: pid 2229, fpm_children_make(), line 421: [pool www] child 2236 started
[28-Oct-2021 10:53:35.380037] DEBUG: pid 2229, fpm_children_make(), line 421: [pool www] child 2237 started
[28-Oct-2021 10:53:35.380387] DEBUG: pid 2229, fpm_children_make(), line 421: [pool www] child 2238 started
[28-Oct-2021 10:53:35.380402] DEBUG: pid 2229, fpm_pctl_heartbeat(), line 460: heartbeat have been set up with a timeout of 2666ms
[28-Oct-2021 10:53:35.380412] DEBUG: pid 2229, fpm_event_loop(), line 366: 74328 bytes have been reserved in SHM
[28-Oct-2021 10:53:35.380416] NOTICE: pid 2229, fpm_event_loop(), line 367: ready to handle connections
[28-Oct-2021 10:53:36.381545] DEBUG: pid 2229, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:36.381587] DEBUG: pid 2229, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
[28-Oct-2021 10:53:37.382730] DEBUG: pid 2229, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:37.382774] DEBUG: pid 2229, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
[28-Oct-2021 10:53:37.831707] DEBUG: pid 2229, fpm_got_signal(), line 85: received SIGTERM
[28-Oct-2021 10:53:37.831732] NOTICE: pid 2229, fpm_got_signal(), line 86: Terminating ...
[28-Oct-2021 10:53:37.831739] DEBUG: pid 2229, fpm_pctl(), line 231: switching to 'terminating' state
[28-Oct-2021 10:53:37.831760] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool php5-fcgi-staging03] sending signal 15 SIGTERM to child 2233
[28-Oct-2021 10:53:37.831768] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool php5-fcgi-staging03] sending signal 15 SIGTERM to child 2232
[28-Oct-2021 10:53:37.831775] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool php5-fcgi-staging03] sending signal 15 SIGTERM to child 2231
[28-Oct-2021 10:53:37.831782] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool php5-fcgi-staging03] sending signal 15 SIGTERM to child 2230
[28-Oct-2021 10:53:37.831789] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 2238
[28-Oct-2021 10:53:37.831796] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 2237
[28-Oct-2021 10:53:37.831803] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 2236
[28-Oct-2021 10:53:37.831810] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 2235
[28-Oct-2021 10:53:37.831817] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 15 SIGTERM to child 2234
[28-Oct-2021 10:53:37.831821] DEBUG: pid 2229, fpm_pctl_kill_all(), line 168: 9 child(ren) still alive
[28-Oct-2021 10:53:37.831828] DEBUG: pid 2229, fpm_event_loop(), line 419: event module triggered 1 events
[28-Oct-2021 10:53:37.831835] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool php5-fcgi-staging03] sending signal 9 SIGKILL to child 2233
[28-Oct-2021 10:53:37.831840] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool php5-fcgi-staging03] sending signal 9 SIGKILL to child 2232
[28-Oct-2021 10:53:37.831844] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool php5-fcgi-staging03] sending signal 9 SIGKILL to child 2231
[28-Oct-2021 10:53:37.831849] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool php5-fcgi-staging03] sending signal 9 SIGKILL to child 2230
[28-Oct-2021 10:53:37.831854] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 9 SIGKILL to child 2238
[28-Oct-2021 10:53:37.831859] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 9 SIGKILL to child 2237
[28-Oct-2021 10:53:37.831864] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 9 SIGKILL to child 2236
[28-Oct-2021 10:53:37.831869] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 9 SIGKILL to child 2235
[28-Oct-2021 10:53:37.831874] DEBUG: pid 2229, fpm_pctl_kill_all(), line 159: [pool www] sending signal 9 SIGKILL to child 2234
[28-Oct-2021 10:53:37.831878] DEBUG: pid 2229, fpm_pctl_kill_all(), line 168: 9 child(ren) still alive
[28-Oct-2021 10:53:37.833521] DEBUG: pid 2229, fpm_event_loop(), line 419: event module triggered 8 events
[28-Oct-2021 10:53:37.833538] DEBUG: pid 2229, fpm_got_signal(), line 76: received SIGCHLD
[28-Oct-2021 10:53:37.833577] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool php5-fcgi-staging03] child 2230 exited on signal 15 (SIGTERM) after 2.456158 seconds from start
[28-Oct-2021 10:53:37.833589] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool php5-fcgi-staging03] child 2231 exited on signal 15 (SIGTERM) after 2.455757 seconds from start
[28-Oct-2021 10:53:37.833597] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool php5-fcgi-staging03] child 2232 exited on signal 15 (SIGTERM) after 2.455380 seconds from start
[28-Oct-2021 10:53:37.833613] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool php5-fcgi-staging03] child 2233 exited on signal 15 (SIGTERM) after 2.455013 seconds from start
[28-Oct-2021 10:53:37.833621] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool www] child 2234 exited on signal 15 (SIGTERM) after 2.454666 seconds from start
[28-Oct-2021 10:53:37.833640] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool www] child 2235 exited on signal 15 (SIGTERM) after 2.454333 seconds from start
[28-Oct-2021 10:53:37.833649] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool www] child 2236 exited on signal 15 (SIGTERM) after 2.453977 seconds from start
[28-Oct-2021 10:53:37.833657] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool www] child 2237 exited on signal 15 (SIGTERM) after 2.453634 seconds from start
[28-Oct-2021 10:53:37.833664] DEBUG: pid 2229, fpm_children_bury(), line 252: [pool www] child 2238 exited on signal 15 (SIGTERM) after 2.453292 seconds from start
[28-Oct-2021 10:53:37.833668] NOTICE: pid 2229, fpm_pctl_exit(), line 70: exiting, bye-bye!
[28-Oct-2021 10:53:37.991265] DEBUG: pid 2263, fpm_unix_init_main(), line 520: The calling process is waiting for the master process to ping via fd=5
[28-Oct-2021 10:53:37.992395] DEBUG: pid 2264, fpm_scoreboard_init_main(), line 40: got clock tick '100'
[28-Oct-2021 10:53:37.993247] DEBUG: pid 2264, fpm_socket_af_inet_listening_socket(), line 298: Found address for 127.0.0.1, socket opened on 127.0.0.1
[28-Oct-2021 10:53:37.993287] DEBUG: pid 2264, fpm_event_init_main(), line 337: event module is epoll and 27 fds have been reserved
[28-Oct-2021 10:53:37.993325] NOTICE: pid 2264, fpm_init(), line 85: fpm is running, pid 2264
[28-Oct-2021 10:53:37.993335] DEBUG: pid 2264, main(), line 1875: Sending "1" (OK) to parent via fd=6
[28-Oct-2021 10:53:37.993367] DEBUG: pid 2263, fpm_unix_init_main(), line 539: I received a valid acknoledge from the master process, I can exit without error
[28-Oct-2021 10:53:37.993785] DEBUG: pid 2264, fpm_children_make(), line 421: [pool php5-fcgi-staging03] child 2265 started
[28-Oct-2021 10:53:37.994191] DEBUG: pid 2264, fpm_children_make(), line 421: [pool php5-fcgi-staging03] child 2266 started
[28-Oct-2021 10:53:37.994609] DEBUG: pid 2264, fpm_children_make(), line 421: [pool php5-fcgi-staging03] child 2267 started
[28-Oct-2021 10:53:37.995005] DEBUG: pid 2264, fpm_children_make(), line 421: [pool php5-fcgi-staging03] child 2268 started
[28-Oct-2021 10:53:37.995382] DEBUG: pid 2264, fpm_children_make(), line 421: [pool www] child 2269 started
[28-Oct-2021 10:53:37.995777] DEBUG: pid 2264, fpm_children_make(), line 421: [pool www] child 2270 started
[28-Oct-2021 10:53:37.996145] DEBUG: pid 2264, fpm_children_make(), line 421: [pool www] child 2271 started
[28-Oct-2021 10:53:37.996527] DEBUG: pid 2264, fpm_children_make(), line 421: [pool www] child 2272 started
[28-Oct-2021 10:53:37.996938] DEBUG: pid 2264, fpm_children_make(), line 421: [pool www] child 2273 started
[28-Oct-2021 10:53:37.996955] DEBUG: pid 2264, fpm_pctl_heartbeat(), line 460: heartbeat have been set up with a timeout of 2666ms
[28-Oct-2021 10:53:37.996964] DEBUG: pid 2264, fpm_event_loop(), line 366: 74328 bytes have been reserved in SHM
[28-Oct-2021 10:53:37.996968] NOTICE: pid 2264, fpm_event_loop(), line 367: ready to handle connections
[28-Oct-2021 10:53:38.998110] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:38.998153] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
[28-Oct-2021 10:53:39.999278] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:39.999320] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
[28-Oct-2021 10:53:41.000578] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:41.000639] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
[28-Oct-2021 10:53:42.001767] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:42.001814] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
[28-Oct-2021 10:53:43.002931] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:43.002982] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
[28-Oct-2021 10:53:44.004234] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:44.004282] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
[28-Oct-2021 10:53:45.005408] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool php5-fcgi-staging03] currently 0 active children, 4 spare children, 4 running children. Spawning rate 1
[28-Oct-2021 10:53:45.005454] DEBUG: pid 2264, fpm_pctl_perform_idle_server_maintenance(), line 379: [pool www] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
The error log for php is supposed to be in error_log = /var/log/website/php_errors.log, but it's empty.
Also, when I shut down varnish and do the following I get:
[centos@staging03 ~]$ sudo service varnish stop
Stopping Varnish Cache: [ OK ]
[centos@staging03 ~]$ curl -H 'Authorization: Basic somethingsomething' 172.31.22.60
<html>
<head><title>502 Bad Gateway</title></head>
<body>
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx</center>
</body>
</html>
[centos@staging03 ~]$ curl -H 'Authorization: Basic somethingsomething' 127.0.0.1:80
[centos@staging03 ~]$ curl -H 'Authorization: Basic somethingsomething' 127.0.0.1:80
Doing netstat afterward gives:
[centos@staging03 ~]$ sudo netstat -plnt
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
tcp 0 0 127.0.0.1:80 0.0.0.0:* LISTEN 2620/httpd
tcp 0 0 172.31.22.60:80 0.0.0.0:* LISTEN 1530/nginx
tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN 1249/sshd
tcp 0 0 127.0.0.1:25 0.0.0.0:* LISTEN 1499/master
tcp 0 0 127.0.0.1:443 0.0.0.0:* LISTEN 2620/httpd
tcp 0 0 127.0.0.1:9000 0.0.0.0:* LISTEN 2264/php-fpm
tcp 0 0 127.0.0.1:11211 0.0.0.0:* LISTEN 1227/memcached
tcp 0 0 127.0.0.1:6379 0.0.0.0:* LISTEN 1059/redis-server 1
tcp 0 0 :::22 :::* LISTEN 1249/sshd
tcp 0 0 :::3306 :::* LISTEN 1381/mysqld
[centos@staging03 ~]$
