1 Topic by iredmail.mb

  • iredmail.mb
  • Member
  • Offline
  • Registered: 2016-07-25
  • Posts: 50

Topic: issue with php-fpm

==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 1.1
- Deployed with iRedMail Easy or the downloadable installer? Downloadable
- Linux/BSD distribution name and version: FreeBSD
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? Yes
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

Hi,
a few weeks ago i upgraded to iredmail 1.1 as well as the latest iRedAdmin-Pro. In the process I also switched from using Apache to using Nginx.
Everything is working very well but I am having regular crashes of php-fpm which causes round cube to not be accessible anymore.
It looks like the crashes are happening right at midnight, so i think they might be connected with some sort of recurring event that I have not been able to identify.
I set the log to debug level, but nothing in the logs reports any crash.

To temporarily fix the issue while i figure it out, i created a simple script that runs every minute and restarts php-fpm if '/usr/local/etc/rc.d/php-fpm status' doesn't return that it is running.
As a consequence of this i'm not getting many errors like: "Mar 31 04:34:11 localhost php-fpm[77388]: [ERROR] fpm_sockets_new_listening_socket(), line 212: unable to bind listening socket for address '127.0.0.1:9999': Address already in use (48)"
These errors go on for a while (even hours) and eventually it gets restarted properly.
I would like two things:
1. a quick solution to restart it reliably if it crashes, so that all the people trying to connect to it have access to their mail.
2. figure out what's wrong at a deeper level and fix it smile

BTW: installed I have php74-7.4.2
thanks.

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,770

Re: issue with php-fpm

iredmail.mb wrote:

As a consequence of this i'm not getting many errors like: "Mar 31 04:34:11 localhost php-fpm[77388]: [ERROR] fpm_sockets_new_listening_socket(), line 212: unable to bind listening socket for address '127.0.0.1:9999': Address already in use (48)"

You should check the running php-fpm processes and kill them, then restart again.

iredmail.mb wrote:

2. figure out what's wrong at a deeper level and fix it

What's the error in php-fpm log file (or related log in any other log files under /var/log/) when it's not accessible?

3 Reply by iredmail.mb

  • iredmail.mb
  • Member
  • Offline
  • Registered: 2016-07-25
  • Posts: 50

Re: issue with php-fpm

iredmail.mb wrote:

2. figure out what's wrong at a deeper level and fix it

What's the error in php-fpm log file (or related log in any other log files under /var/log/) when it's not accessible?

This is what i see in the logs, I see nothing weird, but ...

php-fpm.log shows this at the time it stopped working

Apr  6 00:00:08 myhost newsyslog[4898]: logfile turned over
Apr  6 00:00:08 myhost php-fpm[18667]: [DEBUG] fpm_pctl_perform_idle_server_maintenance(), line 382: [pool inet] currently 0 active children, 7 spare children, 7 running children. Spawning rate 1
Apr  6 00:00:14 myhost php-fpm[5024]: [DEBUG] fpm_log_open(), line 48: open access log (/var/log/php-fpm/php-fpm.log)
Apr  6 00:00:14 myhost php-fpm[5024]: [NOTICE] fpm_conf_init_main(), line 1758: configuration file /usr/local/etc/php-fpm.conf test is successful
Apr  6 00:00:14 myhost php-fpm[5024]:
Apr  6 00:00:14 myhost php-fpm[5034]: [DEBUG] fpm_log_open(), line 48: open access log (/var/log/php-fpm/php-fpm.log)
Apr  6 00:00:14 myhost php-fpm[5034]: [NOTICE] fpm_conf_init_main(), line 1758: configuration file /usr/local/etc/php-fpm.conf test is successful
Apr  6 00:00:14 myhost php-fpm[5034]:
Apr  6 00:00:14 myhost php-fpm[5036]: [DEBUG] fpm_log_open(), line 48: open access log (/var/log/php-fpm/php-fpm.log)
Apr  6 00:00:14 myhost php-fpm[5036]: [DEBUG] fpm_unix_init_main(), line 518: The calling process is waiting for the master process to ping via fd=5
Apr  6 00:00:14 myhost php-fpm[5037]: [DEBUG] fpm_scoreboard_init_main(), line 38: got clock tick '128'
Apr  6 00:00:14 myhost php-fpm[5037]: [DEBUG] fpm_signals_init_main(), line 219: Unblocking all signals
Apr  6 00:00:14 myhost php-fpm[5037]: [ERROR] fpm_sockets_new_listening_socket(), line 212: unable to bind listening socket for address 'localhost:9999': Address already in use (48)
Apr  6 00:00:14 myhost php-fpm[5037]: [ERROR] fpm_init(), line 72: FPM initialization failed
Apr  6 00:00:14 myhost php-fpm[5037]: [DEBUG] main(), line 1839: Sending "0" (error) to parent via fd=6
Apr  6 00:00:14 myhost php-fpm[5036]: [DEBUG] fpm_unix_init_main(), line 541: The master process returned an error !


php-fpm.log shows this at the time it was successfully restarted

Apr  6 15:09:06 myhost php-fpm[10413]: [DEBUG] fpm_log_open(), line 48: open access log (/var/log/php-fpm/php-fpm.log)
Apr  6 15:09:06 myhost php-fpm[10413]: [DEBUG] fpm_unix_init_main(), line 518: The calling process is waiting for the master process to ping via fd=5
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_scoreboard_init_main(), line 38: got clock tick '128'
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_signals_init_main(), line 219: Unblocking all signals
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_socket_af_inet_socket_by_addr(), line 290: Found address for localhost, socket opened on localhost
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_event_init_main(), line 348: event module is kqueue and 1 fds have been reserved
Apr  6 15:09:06 myhost php-fpm[10414]: [NOTICE] fpm_init(), line 83: fpm is running, pid 10414
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] main(), line 1848: Sending "1" (OK) to parent via fd=6
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 407: blocking signals before child birth
Apr  6 15:09:06 myhost php-fpm[10413]: [DEBUG] fpm_unix_init_main(), line 537: I received a valid acknowledge from the master process, I can exit without error
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 431: unblocking signals, child born
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 437: [pool inet] child 10415 started
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 407: blocking signals before child birth
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 431: unblocking signals, child born
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 437: [pool inet] child 10416 started
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 407: blocking signals before child birth
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 431: unblocking signals, child born
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 437: [pool inet] child 10417 started
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 407: blocking signals before child birth
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 431: unblocking signals, child born
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 437: [pool inet] child 10418 started
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 407: blocking signals before child birth
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 431: unblocking signals, child born
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_children_make(), line 437: [pool inet] child 10419 started
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_pctl_heartbeat(), line 463: heartbeat have been set up with a timeout of 3333ms
Apr  6 15:09:06 myhost php-fpm[10414]: [DEBUG] fpm_event_loop(), line 377: 114520 bytes have been reserved in SHM
Apr  6 15:09:06 myhost php-fpm[10414]: [NOTICE] fpm_event_loop(), line 378: ready to handle connections
Apr  6 15:09:07 myhost php-fpm[10414]: [DEBUG] fpm_pctl_perform_idle_server_maintenance(), line 382: [pool inet] currently 0 active children, 5 spare children, 5 running children. Spawning rate 1
Apr  6 15:09:38 myhost syslogd: last message repeated 31 times
Apr  6 15:11:39 myhost syslogd: last message repeated 119 times
Apr  6 15:21:39 myhost syslogd: last message repeated 590 times
Apr  6 15:31:40 myhost syslogd: last message repeated 592 times
Apr  6 15:41:40 myhost syslogd: last message repeated 590 times
Apr  6 15:51:40 myhost syslogd: last message repeated 591 times
Apr  6 16:01:40 myhost syslogd: last message repeated 592 times
Apr  6 16:11:40 myhost syslogd: last message repeated 591 times
Apr  6 16:21:41 myhost syslogd: last message repeated 592 times
Apr  6 16:31:41 myhost syslogd: last message repeated 591 times


slow.log has nothing

Apr  6 00:00:08 myhost newsyslog[4898]: logfile turned over


I don't see anything useful, but maybe (hopefully) you do smile

4 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,770

Re: issue with php-fpm

iredmail.mb wrote:

Apr  6 00:00:14 myhost php-fpm[5037]: [DEBUG] fpm_scoreboard_init_main(), line 38: got clock tick '128'
Apr  6 00:00:14 myhost php-fpm[5037]: [DEBUG] fpm_signals_init_main(), line 219: Unblocking all signals
Apr  6 00:00:14 myhost php-fpm[5037]: [ERROR] fpm_sockets_new_listening_socket(), line 212: unable to bind listening socket for address 'localhost:9999': Address already in use (48)

No clue yet. but does the red text mean you're running time server/client to sync time and trigger the error? i'm not sure.

5 Reply by iredmail.mb

  • iredmail.mb
  • Member
  • Offline
  • Registered: 2016-07-25
  • Posts: 50

Re: issue with php-fpm

I have no idea what the got clock tick '128' means.
I'm not running anything special. It is coming straight from php-fpm debug functionality