FreePBX 17 - Slow Shutdown

I was wondering if anyone else is seeing a slow shutdown on their new FreePBX 17 setups? We’ve migrated over nine of our PBXes now, and all are VMs running in Hyper-V. We’ve noticed that when we ask for a shutdown or restart from System Admin, it drops the ssh session and the Hyper-V console window changes to a blinking cursor. Then it seems to wait for about two or three minutes before the shutdown or reboot occurs. I have seen that with previous versions, but with FreePBX 17 it seems to be consistent.

I will see what I can find in the logging by timing when I issue the shutdown command and then checking the logs after reboot to see what is occurring in that time window.

Does it do this when you first install Debian and before you install FreePBX? This might be a Debian on Hyper-V thing.

If you hit enter at the blinking cursor screen in the Hyper-V console does it change to a screen with more status messages for the shutdown procedure?

I installed freePBX-17/Debian 12 in Virtualbox…same phenomenon. It takes about >1min to shut down. I had this problem on older systems (16) too…occasionally…

I checked two of the VMs that I am setting up that I haven’t run the FreePBX install script on yet. One took 15 seconds from hitting Enter on the reboot command to booting up back to a command prompt, the other was 17 seconds. It’s definitely occurring after FreePBX is installed. I chose one of the new FreePBX 17 VMs. From when I hit Enter after typing “reboot” in the GUI, it was 2:45 when the uptime counter in Hyper-V zeroed out to show it was rebooting. It booted up fairly quickly after that in 10 or 15 seconds.

Hitting enter in the Hyper-V console still shows the blinking cursor.

A similar problem when rebooting and shutting down the guest OS on vmware16x Debian12 freepbx17, and the problem starts only after installing the freepbx17 script, a clean Debian12 system works instantly, both when rebooting and when shutting down the guest OS.

Use journalctl ,

journalctl -b -1|tac|less

run as root will extract the last boot session and ‘page’ it in reverse order.

That’s good information, dicko. I see a minute and a half gap in the logging at one point, so that accounts for some of it.

Aug 23 13:21:59 HOSTNAME systemd[1]: freepbx.service: Killing process 1873 (asterisk) with signal SIGKILL.
Aug 23 13:21:59 HOSTNAME systemd[1]: freepbx.service: Killing process 1697 (asterisk) with signal SIGKILL.
Aug 23 13:21:59 HOSTNAME systemd[1]: freepbx.service: State ‘stop-sigterm’ timed out. Killing.
Aug 23 13:20:28 HOSTNAME systemd[1]: freepbx.service: Control process exited, code=exited, status=1/FAILURE
Aug 23 13:20:28 HOSTNAME fwconsole[119663]: Asterisk is still running and we can’t stop it!
Aug 23 13:20:28 HOSTNAME audit: PROCTITLE proctitle=2F7573722F62696E2F656E76007069646F6600617374657269736B
Aug 23 13:20:28 HOSTNAME audit: PATH item=2 name=“/lib64/ld-linux-x86-64.so.2” inode=2490390 dev=08:02 mode=0100755 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
Aug 23 13:20:28 HOSTNAME audit: PATH item=1 name=“/usr/bin/pidof” inode=2494019 dev=08:02 mode=0120777 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
Aug 23 13:20:28 HOSTNAME audit: PATH item=0 name=“/usr/bin/pidof” inode=2494009 dev=08:02 mode=0100755 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0 cap_fi=0 cap_fe=0 cap_fver=0 cap_frootid=0
Aug 23 13:20:28 HOSTNAME audit: CWD cwd=“/”

would indicate that the fwconsole.service ExecStop= is not working, so the command will timeout after 90’s, which it did . There probably should not be two instances of asterisk running (pidof asterisk)

Aug 24 13:28:10 OFFICE-VOIP systemd-journald[267]: Journal stopped
Aug 24 13:28:10 OFFICE-VOIP VGAuthService[523]: ServiceEndMainLoop: about to stop main loop
Aug 24 13:28:10 OFFICE-VOIP VGAuthService[523]: Processing SIGTERM; service exiting
Aug 24 13:28:10 OFFICE-VOIP systemd-journald[267]: Received SIGTERM from PID 1 (systemd-shutdow).
Aug 24 13:28:10 OFFICE-VOIP systemd-shutdown[1]: Sending SIGTERM to remaining processes…
Aug 24 13:28:10 OFFICE-VOIP systemd-shutdown[1]: Syncing filesystems and block devices.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Shutting down.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Reached target reboot.target - System Reboot.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Finished systemd-reboot.service - System Reboot.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-reboot.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Reached target final.target - Late Shutdown Services.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Reached target shutdown.target - System Shutdown.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped systemd-remount-fs.service - Remount Root and Kernel File Systems.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-remount-fs.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped systemd-sysusers.service - Create System Users.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-sysusers.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Reached target umount.target - Unmount All Filesystems.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped target local-fs-pre.target - Preparation for Local File Systems.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unmounted run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev.service.mount - /run/credentials/systemd-tmpfiles-setup-dev.service.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev.service.mount: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unmounted run-credentials-systemd\x2dsysusers.service.mount - /run/credentials/systemd-sysusers.service.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: run-credentials-systemd\x2dsysusers.service.mount: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unmounted boot-efi.mount - /boot/efi.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: boot-efi.mount: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped systemd-modules-load.service - Load Kernel Modules.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-modules-load.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unmounting run-credentials-systemd\x2dtmpfiles\x2dsetup\x2ddev.service.mount - /run/credentials/systemd-tmpfiles-setup-dev.service…
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unmounting run-credentials-systemd\x2dsysusers.service.mount - /run/credentials/systemd-sysusers.service…
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unmounting boot-efi.mount - /boot/efi…
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped target local-fs.target - Local File Systems.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped netfilter-persistent.service - netfilter persistent configuration.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: netfilter-persistent.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP netfilter-persistent[122075]: Automatic flush disabled; use ‘/usr/sbin/netfilter-persistent flush’
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unmounted run-credentials-systemd\x2dsysctl.service.mount - /run/credentials/systemd-sysctl.service.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: run-credentials-systemd\x2dsysctl.service.mount: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped systemd-sysctl.service - Apply Kernel Variables.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-sysctl.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopping netfilter-persistent.service - netfilter persistent configuration…
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped target network-pre.target - Preparation for Network.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped networking.service - Raise network interfaces.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: networking.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unmounted run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount - /run/credentials/systemd-tmpfiles-setup.service.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped systemd-tmpfiles-setup.service - Create Volatile Files and Directories.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped systemd-update-utmp.service - Record System Boot/Shutdown in UTMP.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-update-utmp.service: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Deactivated swap dev-disk-by\x2duuid-9a4dd3cf\x2d5cc7\x2d48b4\x2d898c\x2df1c23b2c9fc8.swap - /dev/disk/by-uuid/9a4dd3cf-5cc7-48b4-898c-f1c23b2c9fc8.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: dev-disk-by\x2duuid-9a4dd3cf\x2d5cc7\x2d48b4\x2d898c\x2df1c23b2c9fc8.swap: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Deactivated swap dev-sda3.swap - /dev/sda3.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: dev-sda3.swap: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Deactivated swap dev-disk-by\x2dpartuuid-60de1268\x2de644\x2d42c4\x2d855d\x2d27f8f7e4bfac.swap - /dev/disk/by-partuuid/60de1268-e644-42c4-855d-27f8f7e4bfac.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: dev-disk-by\x2dpartuuid-60de1268\x2de644\x2d42c4\x2d855d\x2d27f8f7e4bfac.swap: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Deactivated swap dev-disk-by\x2dpath-pci\x2d0000:00:10.0\x2dscsi\x2d0:0:0:0\x2dpart3.swap - /dev/disk/by-path/pci-0000:00:10.0-scsi-0:0:0:0-part3.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:10.0\x2dscsi\x2d0:0:0:0\x2dpart3.swap: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: proc-sys-fs-binfmt_misc.mount: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Unset automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: proc-sys-fs-binfmt_misc.automount: Deactivated successfully.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: Stopped systemd-binfmt.service - Set Up Additional Binary Formats.
Aug 24 13:28:10 OFFICE-VOIP systemd[1]: systemd-binfmt.service: Deactivated successfully.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopping systemd-update-utmp.service - Record System Boot/Shutdown in UTMP…
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopping systemd-binfmt.service - Set Up Additional Binary Formats…
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopping networking.service - Raise network interfaces…
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Deactivating swap dev-disk-by\x2dpartuuid-60de1268\x2de644\x2d42c4\x2d855d\x2d27f8f7e4bfac.swap - /dev/disk/by-partuuid/60de1268-e644-42c4-855d-27f8f7e4bfac…
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Closed syslog.socket - Syslog Socket.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: syslog.socket: Deactivated successfully.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopped target veritysetup.target - Local Verity Protected Volumes.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopped target swap.target - Swaps.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopped target integritysetup.target - Local Integrity Protected Volumes.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopped systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: systemd-ask-password-wall.path: Deactivated successfully.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopped systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: systemd-ask-password-console.path: Deactivated successfully.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopped target cryptsetup.target - Local Encrypted Volumes.
Aug 24 13:28:09 OFFICE-VOIP systemd[1]: Stopped target sysinit.target - System Initialization.

That shows an orderly shutdown of 1 second but no startup, If that is all in journalctl -b -1 look in journalctl -b -2 which would show the penultimate 'session. ’ , ( ‘tac’ is to sort reverse the report, ‘less’ to ‘page’ it)

I see the same slow shutdown with my FreePBX17. Same thing, fresh install of Debian followed by FreePBX install script.

Is there a fix for this?

@akkl, that looks like just the end of the log right before shutdown. Do you see a part of the logs like my example that shows about a 90 second gap between entries? Does it show the “Asterisk is still running and we can’t stop it!” message as well?

@steve_pbuk, are you running FreePBX in a VM as well? Do you see the “Asterisk is still running and we can’t stop it!” and the 90 second gap in the logs?

If the FreePBX service is failing to stop Asterisk, Debian will execute all /usr/lib/systemd/system-shutdown/*.shutdown files, so to force asterisk to stop .in asterisk.shutdown put

#!/usr/bin/sh -c "/usr/sbin/rasterisk -x 'core stop now'"

Yes it is running in a VM.

I don’t specifically see “Asterisk is still running and we can’t stop it!” but I do see a delay in the logs.

Logs showing the delay are below:

Aug 29 09:59:24 srv-voip-01 systemd[1]: Stopped target network-online.target - Network is Online.
Aug 29 09:59:24 srv-voip-01 systemd[1]: freepbx.service: Consumed 4min 48.496s CPU time.
Aug 29 09:59:24 srv-voip-01 systemd[1]: Stopped freepbx.service - FreePBX VoIP Server.
Aug 29 09:59:24 srv-voip-01 systemd[1]: freepbx.service: Failed with result 'timeout'.
Aug 29 09:59:24 srv-voip-01 mariadbd[658]: 2024-08-29  9:59:24 43 [Warning] Aborted connection 43 to db: 'asteriskcdrdb' user: 'freepbxuser' host: 'localhost' (Got an error reading communication packets)
Aug 29 09:59:24 srv-voip-01 systemd[1]: freepbx.service: Killing process 15333 (asterisk) with signal SIGKILL.
Aug 29 09:59:24 srv-voip-01 systemd[1]: freepbx.service: Killing process 1540 (asterisk) with signal SIGKILL.
Aug 29 09:59:24 srv-voip-01 systemd[1]: freepbx.service: State 'final-sigterm' timed out. Killing.
Aug 29 09:57:54 srv-voip-01 systemd[1]: freepbx.service: Control process exited, code=killed, status=15/TERM
Aug 29 09:57:54 srv-voip-01 mariadbd[658]: 2024-08-29  9:57:54 520 [Warning] Aborted connection 520 to db: 'asterisk' user: 'freepbxuser' host: 'localhost' (Got an error reading communication packets)
Aug 29 09:57:54 srv-voip-01 mariadbd[658]: 2024-08-29  9:57:54 521 [Warning] Aborted connection 521 to db: 'asteriskcdrdb' user: 'freepbxuser' host: 'localhost' (Got an error reading communication packets)
Aug 29 09:57:54 srv-voip-01 systemd[1]: freepbx.service: Stopping timed out. Terminating.
Aug 29 09:56:59 srv-voip-01 fwconsole[15329]: stty: 'standard input': Inappropriate ioctl for device
Aug 29 09:56:59 srv-voip-01 fwconsole[15327]: stty: 'standard input': Inappropriate ioctl for device
Aug 29 09:56:59 srv-voip-01 fwconsole[14915]: Press N to shut down NOW
Aug 29 09:56:59 srv-voip-01 fwconsole[14915]: Press C to Cancel
Aug 29 09:56:59 srv-voip-01 fwconsole[14915]: Shutting down Asterisk Gracefully. Will forcefully kill after 30 seconds.
Aug 29 09:56:59 srv-voip-01 fwconsole[14915]: Stopped UCP Node Server

This is terrible. On v16, the shutdown was a few seconds. On v17, the shutdown is a few minutes.

It is getting stuck on this. You can clearly see it during shutdown when you turn on the shutdown log screen.
Job freepbx.service/stop running (10s / 2min 37s)

That “10s” is counting up until it gets to 2min 37s and then it continues the shutdown.

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.