Topic: php70-php-fpm, php71-php-fpm, php72-php-fpm failed to start

[holck]

This morning, I couldn't log in to horde (webmail). I found out that the services for php70-php-fpm, php71-php-fpm, and php72-php-fpm had failed to start, and after restarting these ($systemctl restart php70-php-fpm etc.), everything works fine. But I don't know what caused the services to fail. Where can I find some information?

[TerryF]

Logs are here, /var/log/php/

eg
# cd /var/log/php/php70
# ll
total 28
-rw------- 1 root root  959 Aug  8 03:13 php70-fpm.log
-rw------- 1 root root 2412 Jul 13 07:33 php70-fpm.log-20210718
-rw------- 1 root root 1469 Jul 22 20:24 php70-fpm.log-20210725
-rw------- 1 root root 8310 Jul 30 13:05 php70-fpm.log-20210801
-rw------- 1 root root  959 Aug  1 03:29 php70-fpm.log-20210808

[holck]

Thanks Terry.

Here's today's php70-fpm.log:

Code: [Select]

Aug  8 03:32:43 sme10 php70-fpm[1042]: [NOTICE] Reloading in progress ...
Aug  8 03:32:43 sme10 php70-fpm[1042]: [NOTICE] reloading: execvp("/opt/remi/php70/root/usr/sbin/php-fpm", {"/opt/remi/php70/root/usr/sbin/php-fpm", "--nodaemonize"})
Aug  8 09:47:08 sme10 php70-fpm[32446]: [NOTICE] fpm is running, pid 32446
Aug  8 09:47:08 sme10 php70-fpm[32446]: [NOTICE] ready to handle connections
Aug  8 09:47:08 sme10 php70-fpm[32446]: [NOTICE] systemd monitor interval set to 10000ms09:47 was when I restarted the service. Last week's php70-fpm.log shows a lot more happening when starting:

Code: [Select]

Aug  1 03:28:16 sme10 php70-fpm[12060]: [NOTICE] Reloading in progress ...
Aug  1 03:28:16 sme10 php70-fpm[12060]: [NOTICE] reloading: execvp("/opt/remi/php70/root/usr/sbin/php-fpm", {"/opt/remi/php70/root/usr/sbin/php-fpm", "--nodaemonize"})
Aug  1 03:28:16 sme10 php70-fpm[12060]: [NOTICE] using inherited socket fd=6, "/var/run/php-fpm/php70.sock"
Aug  1 03:28:16 sme10 php70-fpm[12060]: [NOTICE] fpm is running, pid 12060
Aug  1 03:28:16 sme10 php70-fpm[12060]: [NOTICE] ready to handle connections
Aug  1 03:28:16 sme10 php70-fpm[12060]: [NOTICE] systemd monitor interval set to 10000ms
Aug  1 03:28:17 sme10 php70-fpm[12060]: [NOTICE] Reloading in progress ...
Aug  1 03:28:17 sme10 php70-fpm[12060]: [NOTICE] reloading: execvp("/opt/remi/php70/root/usr/sbin/php-fpm", {"/opt/remi/php70/root/usr/sbin/php-fpm", "--nodaemonize"})
Aug  1 03:28:17 sme10 php70-fpm[12060]: [NOTICE] using inherited socket fd=6, "/var/run/php-fpm/php70.sock"
Aug  1 03:28:17 sme10 php70-fpm[12060]: [NOTICE] fpm is running, pid 12060
Aug  1 03:28:17 sme10 php70-fpm[12060]: [NOTICE] ready to handle connections
Aug  1 03:28:17 sme10 php70-fpm[12060]: [NOTICE] systemd monitor interval set to 10000ms
Aug  1 15:30:42 sme10 php70-fpm[1042]: [NOTICE] fpm is running, pid 1042
Aug  1 15:30:42 sme10 php70-fpm[1042]: [NOTICE] ready to handle connections
Aug  1 15:30:42 sme10 php70-fpm[1042]: [NOTICE] systemd monitor interval set to 10000ms
To me it looks like the service didn't properly start this morning. But no errors or warnings to be seen.

[ReetP]

This should restart all:

Code: [Select]

signal-event smeserver-php-update
Need to try and see what stopped them.

Might be something in /var/log/messages

Or:

Code: [Select]

journalctl -xe
Or a specific unit:

Code: [Select]

journalctl -u php70-php-fpm

Or check unit status:

Code: [Select]

systemctl status php70-php-fpm etc

[holck]

/var/log/messages shows:

Code: [Select]

Aug  8 03:32:45 sme10 rsyslogd:  [origin software="rsyslogd" swVersion="8.24.0-57.el7_9.1" x-pid="26365" x-info="http://www.rsyslog.com"] rsyslogd was HUPedAnd journalctl shows

Code: [Select]

# journalctl -u php70-php-fpm
-- Logs begin at Sun 2021-08-01 15:30:15 CEST, end at Sun 2021-08-08 13:15:04 CEST. --
Aug 01 15:30:33 sme10.ibsgaarden.dk systemd[1]: Starting The PHP FastCGI Process Manager...
Aug 01 15:30:42 sme10.ibsgaarden.dk systemd[1]: Started The PHP FastCGI Process Manager.
Aug 08 03:32:43 sme10.ibsgaarden.dk systemd[1]: Reloading The PHP FastCGI Process Manager.
Aug 08 03:32:43 sme10.ibsgaarden.dk systemd[1]: Reloaded The PHP FastCGI Process Manager.
Aug 08 03:32:43 sme10.ibsgaarden.dk systemd[1]: Reloading The PHP FastCGI Process Manager.
Aug 08 03:32:43 sme10.ibsgaarden.dk systemd[1]: php70-php-fpm.service: main process exited, code=killed, status=12/USR2
Aug 08 03:32:43 sme10.ibsgaarden.dk systemd[1]: Reload failed for The PHP FastCGI Process Manager.
Aug 08 03:32:43 sme10.ibsgaarden.dk systemd[1]: Unit php70-php-fpm.service entered failed state.
Aug 08 03:32:43 sme10.ibsgaarden.dk systemd[1]: php70-php-fpm.service failed.
Aug 08 09:47:07 sme10.ibsgaarden.dk systemd[1]: Starting The PHP FastCGI Process Manager...
Aug 08 09:47:08 sme10.ibsgaarden.dk systemd[1]: Started The PHP FastCGI Process Manager.
This is identical for php71-php-fpm and php72-php-fpm. But php73-php-fpm, php74-php-fpm and php80-php-fpm start with no problems.

[TerryF]

/var/log/messages shows:

Code: [Select]

Aug  8 03:32:45 sme10 rsyslogd:  [origin software="rsyslogd" swVersion="8.24.0-57.el7_9.1" x-pid="26365" x-info="http://www.rsyslog.com"] rsyslogd was HUPed

Looks to be caused by logrotate the time also looks right

My mesage.log

Aug  8 01:12:06 fagehome esmith::event[12102]: S98fail2ban-resume-logs=action|Event|logrotate|Action|S98fail2ban-resume-logs|Start|1628349124 44171|End|1628349126 32512|Elapsed|1.988341
Aug  8 03:13:10 fagehome rsyslogd:  [origin software="rsyslogd" swVersion="8.24.0-57.el7_9.1" x-pid="12124" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Aug  8 03:13:11 fagehome rsyslogd:  [origin software="rsyslogd" swVersion="8.24.0-57.el7_9.1" x-pid="12124" x-info="http://www.rsyslog.com"] rsyslogd was HUPed

[Jean-Philippe Pialasse]

seems indeed related to logrotate. 
probably better to do a restart than a reload.

[holck]

/var/log/audit/audit.log shows something that might be relevant:

Code: [Select]

type=ANOM_ABEND msg=audit(1628408812.116:56122): auid=0 uid=0 gid=0 ses=5174 pid=32430 comm="systemd-tty-ask" reason="memory violation" sig=11
type=SERVICE_START msg=audit(1628408828.099:56123): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=php70-php-fpm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
type=SERVICE_START msg=audit(1628408842.815:56124): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=php71-php-fpm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
type=SERVICE_START msg=audit(1628408848.485:56125): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=php72-php-fpm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

/var/log/cron doesn't show anything alarming:

Code: [Select]

Aug  8 03:32:01 sme10 anacron[27436]: Job `cron.daily' started
Aug  8 03:32:01 sme10 run-parts(/etc/cron.daily)[27699]: starting 0logwatch
Aug  8 03:32:19 sme10 run-parts(/etc/cron.daily)[28042]: finished 0logwatch
Aug  8 03:32:19 sme10 run-parts(/etc/cron.daily)[27699]: starting 0yum-daily.cron
Aug  8 03:32:19 sme10 run-parts(/etc/cron.daily)[28048]: finished 0yum-daily.cron
Aug  8 03:32:19 sme10 run-parts(/etc/cron.daily)[27699]: starting cleanup_fail2ban
Aug  8 03:32:19 sme10 run-parts(/etc/cron.daily)[28054]: finished cleanup_fail2ban
Aug  8 03:32:19 sme10 run-parts(/etc/cron.daily)[27699]: starting conf-mod_ssl
Aug  8 03:32:20 sme10 run-parts(/etc/cron.daily)[28105]: finished conf-mod_ssl
Aug  8 03:32:20 sme10 run-parts(/etc/cron.daily)[27699]: starting logrotate
Aug  8 03:32:48 sme10 run-parts(/etc/cron.daily)[28421]: finished logrotate
Aug  8 03:32:48 sme10 run-parts(/etc/cron.daily)[27699]: starting man-db.cron
Aug  8 03:33:06 sme10 run-parts(/etc/cron.daily)[28433]: finished man-db.cron
Aug  8 03:33:06 sme10 run-parts(/etc/cron.daily)[27699]: starting mlocate
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[28444]: finished mlocate
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[27699]: starting prelink
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[28451]: finished prelink
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[27699]: starting smeserver-yum
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[28470]: finished smeserver-yum
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[27699]: starting sogo-tmpwatch
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[28478]: finished sogo-tmpwatch
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[27699]: starting tmpwatch-formmagick
Aug  8 03:33:07 sme10 run-parts(/etc/cron.daily)[28485]: finished tmpwatch-formmagick
Aug  8 03:33:07 sme10 run-part

[holck]

seems indeed related to logrotate. 
probably better to do a restart than a reload.

So change "reload" to "restart" in /etc/e-smith/templates/etc/logrotate.d/php-fpm/php-fpm ?

[Jean-Philippe Pialasse]

yes.  then see if this occurs again in the next weeks.  then open a bug against smeserver-php for 10.0 with target milestone 10.1.