Asterisk 16 won't start after reboot using latest Distro ISO

ben_itse · March 15, 2021, 4:01pm

Asterisk 16 is not starting up when rebooting the PBX. It receives a PID, but does not start. Restarting the PBX from the GUI on an unused system takes about 10 minutes; the console simply goes black and after 10 minutes it restarts. Restarting from the console is immediate. Either way, asterisk 16 does not start (fire symbol and does not appear on the pm2 list).

All latest core and module updates installed.

I can confirm with two different instances that the issue is with the ISO.

I can also confirm that doing a ‘fwconsole restart’ starts asterisk as expected. Nothing on the logs besides the obvious.

I read about adding that command to the boot up script; however this is a patch and not a fix. The normal behavior is for asterisk to simply start.

This is a major issue, as asterisk is the core of a PBX.

Used SNG7-FPBX-64bit-2011-5.iso

Created a bug tracker at https://issues.freepbx.org/browse/FREEPBX-22384

billsimon · March 15, 2021, 4:16pm

Can you share some logs and system specifications?

ben_itse · March 15, 2021, 9:21pm

Of course! Which logs would you like?

System Specs:
FPBX15-2011-5.iso install hosted on a cloud environment. 1 CPU and 2GB RAM. Nothing special; just regular installation of the distro image with the automatic-install option selected. All updates installed; both system and module.

I can confirm that asterisk does receive a PID upon boot, however, it does not start. If I run a ‘fwconsole restart’ then it starts up just fine.

dicko · March 15, 2021, 9:28pm

If Asterisk got to generating a PID, then it did indeed start but presumably then crashed leaving the PID orphaned, look in the /var/log/asterisk/full and /var/log/messages

billsimon · March 15, 2021, 9:31pm

dmesg (kernel log) might be informative too. But start with @dicko’s recommendations.

ben_itse · March 19, 2021, 7:54pm

Thanks @dicko and @billsimon. So, looking at the logs, I was able to find the following on the asterisk full log:

[2021-03-19 15:22:15] WARNING[2279] loader.c: Some non-required modules failed to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: Error loading module 'chan_local.so': /usr/lib64/asterisk/modules/chan_local.so: cannot open shared object file: No such file or directory
[2021-03-19 15:22:15] ERROR[2279] loader.c: Error loading module 'res_pjsip_phoneprov_provider.so', missing dependency: res_phoneprov
[2021-03-19 15:22:15] ERROR[2279] loader.c: res_config_sqlite declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: res_stun_monitor declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: res_xmpp declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: Declined modules which depend on res_xmpp: chan_motif
[2021-03-19 15:22:15] ERROR[2279] loader.c: chan_console declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: chan_skinny declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: chan_mobile declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: chan_ooh323 declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: res_hep declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: Declined modules which depend on res_hep: res_hep_rtcp, res_hep_pjsip
[2021-03-19 15:22:15] ERROR[2279] loader.c: app_agent_pool declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: res_calendar declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: Declined modules which depend on res_calendar: res_calendar_caldav, res_calendar_ews, res_calendar_exchange, res_calendar_icalendar
[2021-03-19 15:22:15] ERROR[2279] loader.c: cdr_csv declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: cdr_manager declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: cdr_odbc declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: app_alarmreceiver declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: app_festival declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: app_followme declined to load.  
[2021-03-19 15:22:15] ERROR[2279] loader.c: chan_phone declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: chan_unistim declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: pbx_ael declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: pbx_dundi declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: pbx_lua declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: func_odbc declined to load.
[2021-03-19 15:22:15] ERROR[2279] loader.c: res_pktccops declined to load.
[2021-03-19 15:22:15] VERBOSE[2279] asterisk.c: Asterisk Ready.

Also, on the ‘messages’ log, I saw the following, but I am not sure it is related:

Unparseable output from getservices - ["Exception: Asterisk is not connected in file \/var\/www\/html\/admin\/libraries\/php-asmanager.php on line 248","Stack trace:"," 1. Exception->() \/var\/www\/html\/admin\/libraries\/php-asmanager.php:248"," 2. AGI_AsteriskManager->send_request() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:447"," 3. FreePBX\\modules\\Firewall\\Smart->getPjsipContacts() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:437"," 4. FreePBX\\modules\\Firewall\\Smart->getRegistrations() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:69"," 5. FreePBX\\modules\\Firewall\\Smart->getAllPorts() \/var\/www\/html\/admin\/modules\/firewall\/Firewall.class.php:1928"," 6. FreePBX\\modules\\Firewall->getSmartPorts() \/var\/www\/html\/admin\/modules\/firewall\/bin\/getservices:22"] - returned 1

The result is that asterisk does not load up properly and a flame appears on the dashboard with ‘Unable to find asterisk results’; if I do an ‘fwconsole restart’ then it starts up as expected.

dicko · March 19, 2021, 8:21pm

Unless you re-started Asterisk at 15:22 , the log-lines suggests that just before :-

[2021-03-19 15:22:15] WARNING[2279] loader.c: Some non-required modules failed to load.

Asterisk had crashed and restarted. So did you restart asterisk then ? if not post some lines previous to those and look in /var/log/messges for lines immediately before that time stamp.

ben_itse · March 22, 2021, 2:23pm

@dicko - asterisk was never re-started. Here are some lines before that…

[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading pbx_ael.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'AELSub'
[2021-03-19 15:22:15] NOTICE[2279] pbx_ael.c: File /etc/asterisk/extensions.ael not found; AEL declining load
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_format_attr_h264.so.
[2021-03-19 15:22:15] VERBOSE[2279] format.c: Registered format interface for codec 'h264'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_format_attr_h264.so => (H.264 Format Attribute Module)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading pbx_dundi.so.
[2021-03-19 15:22:15] ERROR[2279] pbx_dundi.c: Unable to load config dundi.conf
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading pbx_loopback.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: pbx_loopback.so => (Loopback Switch)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading pbx_lua.so.
[2021-03-19 15:22:15] ERROR[2279] pbx_lua.c: Error loading extensions.lua: cannot open '/etc/asterisk/extensions.lua' for reading: No such file or directory
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading pbx_realtime.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: pbx_realtime.so => (Realtime Switch)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading pbx_spool.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: pbx_spool.so => (Outgoing Spool Support)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_mutestream.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'MUTEAUDIO'
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action MuteAudio
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_mutestream.so => (Mute audio stream resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_http_media_cache.so.
[2021-03-19 15:22:15] VERBOSE[2279] bucket.c: Registered bucket scheme 'http'
[2021-03-19 15:22:15] VERBOSE[2279] bucket.c: Registered bucket scheme 'https'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_http_media_cache.so => (HTTP Media Cache Backend)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_mysql.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'MYSQL'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_mysql.so => (Simple Mysql Interface)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_stasis_answer.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_stasis_answer.so => (Stasis application answer support)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_stasis_device_state.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_stasis_device_state.so => (Stasis application device state support)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_realtime.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_realtime.so => (Realtime Data Lookup/Rewrite)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_stasis_snoop.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_stasis_snoop.so => (Stasis application snoop support)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_dahdiras.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'DAHDIRAS'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_dahdiras.so => (DAHDI ISDN Remote Access Server)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_flash.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'Flash'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_flash.so => (Flash channel application)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading func_odbc.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'ODBC_FETCH'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'ODBCFinish'
[2021-03-19 15:22:15] NOTICE[2279] func_odbc.c: Unable to load config for func_odbc: func_odbc.conf
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_page.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'Page'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_page.so => (Page Multiple Phones)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_flite.so.
[2021-03-19 15:22:15] WARNING[2279] app_flite.c: Flite: Unable to read config file flite.conf. Using default settings
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'Flite'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_flite.so => (Flite TTS Interface)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_security_log.so.
[2021-03-19 15:22:15] VERBOSE[2279] res_security_log.c: Security Logging Enabled
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_security_log.so => (Security Event Logging)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading codec_dahdi.so.
[2021-03-19 15:22:15] VERBOSE[2279] codec_dahdi.c: No hardware transcoders found.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: codec_dahdi.so => (Generic DAHDI Transcoder Codec Translator)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_voicemail.so.
[2021-03-19 15:22:15] WARNING[2279] app_voicemail.c: maxsilence should be less than minsecs or you may get empty messages
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'VoiceMail'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'VoiceMailMain'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'MailboxExists'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'VMAuthenticate'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'VoiceMailPlayMsg'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'VMSayName'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'MAILBOX_EXISTS'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'VM_INFO'
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action VoicemailUsersList
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action VoicemailUserStatus
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action VoicemailRefresh
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_voicemail.so => (Comedian Mail (Voicemail System))
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_pktccops.so.
[2021-03-19 15:22:15] WARNING[2279] res_pktccops.c: Unable to load config file res_pktccops.conf
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading codec_ast16_g729.so.
[2021-03-19 15:22:15] VERBOSE[2279] translate.c: Registered translator 'g729tolin' from codec g729 to slin, table cost, 900000, computational cost 517
[2021-03-19 15:22:15] VERBOSE[2279] translate.c: Registered translator 'lintog729' from codec slin to g729, table cost, 600000, computational cost 1604
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: codec_ast16_g729.so => (g729 Coder/Decoder, based on Intel IPP)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: codec_resample.so => (SLIN Resampling Codec)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_speech_utils.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechCreate'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechLoadGrammar'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechUnloadGrammar'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechActivateGrammar'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechDeactivateGrammar'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechStart'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechBackground'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechDestroy'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'SpeechProcessingSound'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'SPEECH'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'SPEECH_SCORE'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'SPEECH_TEXT'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'SPEECH_GRAMMAR'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'SPEECH_ENGINE'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'SPEECH_RESULTS_TYPE'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_speech_utils.so => (Dialplan Speech Applications)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_stasis.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'Stasis'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_stasis.so => (Stasis dialplan application)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading func_pjsip_aor.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'PJSIP_AOR'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: func_pjsip_aor.so => (Get information about a PJSIP AOR)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading func_pjsip_contact.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'PJSIP_CONTACT'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: func_pjsip_contact.so => (Get information about a PJSIP contact)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading func_pjsip_endpoint.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'PJSIP_ENDPOINT'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: func_pjsip_endpoint.so => (Get information about a PJSIP endpoint)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_applications.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_applications.so => (RESTful API module - Stasis application resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_stasis_playback.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_stasis_playback.so => (Stasis application playback support)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_pjsip_endpoint_identifier_anonymous.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_pjsip_endpoint_identifier_anonymous.so => (PJSIP Anonymous endpoint identifier)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_pjsip_stir_shaken.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_pjsip_stir_shaken.so => (PSIP STIR/SHAKEN Module for Asterisk)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_pjsip_endpoint_identifier_dpma.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_pjsip_endpoint_identifier_dpma.so => (DPMA PJSIP Support)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_asterisk.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_asterisk.so => (RESTful API module - Asterisk resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_bridges.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_bridges.so => (RESTful API module - Bridge resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_channels.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_channels.so => (RESTful API module - Channel resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_device_states.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_device_states.so => (RESTful API module - Device state resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_endpoints.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_endpoints.so => (RESTful API module - Endpoint resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_events.so.
[2021-03-19 15:22:15] VERBOSE[2279] res_http_websocket.c: WebSocket registered sub-protocol 'ari'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_events.so => (RESTful API module - WebSocket resource)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_playbacks.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_playbacks.so => (RESTful API module - Playback control resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_recordings.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_recordings.so => (RESTful API module - Recording resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_ari_sounds.so.
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_ari_sounds.so => (RESTful API module - Sound resources)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading app_queue.so.
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'Queue'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'AddQueueMember'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'RemoveQueueMember'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'PauseQueueMember'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'UnpauseQueueMember'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'QueueLog'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_app.c: Registered application 'QueueUpdate'
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueStatus
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueSummary
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueAdd
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueRemove
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueuePause
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueLog
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueuePenalty
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueMemberRingInUse
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueRule
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueReload
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueReset
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action QueueChangePriorityCaller
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'QUEUE_VARIABLES'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'QUEUE_EXISTS'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'QUEUE_MEMBER'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'QUEUE_MEMBER_COUNT'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'QUEUE_MEMBER_LIST'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'QUEUE_GET_CHANNEL'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'QUEUE_WAITING_COUNT'
[2021-03-19 15:22:15] VERBOSE[2279] pbx_functions.c: Registered custom function 'QUEUE_MEMBER_PENALTY'
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: app_queue.so => (True Call Queueing)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_manager_presencestate.so.
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action PresenceStateList
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_manager_presencestate.so => (Manager Presence State Topic Forwarder)
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: Loading res_manager_devicestate.so.
[2021-03-19 15:22:15] VERBOSE[2279] manager.c: Manager registered action DeviceStateList
[2021-03-19 15:22:15] VERBOSE[2279] loader.c: res_manager_devicestate.so => (Manager Device State Topic Forwarder)
[2021-03-19 15:22:15] WARNING[2279] loader.c: Some non-required modules failed to load.

From the /var/log/messages log at around that time frame:

Mar 19 19:22:08 c2cpbx fwconsole: Running Asterisk pre from Vega module
Mar 19 19:22:08 c2cpbx fwconsole: Running Vega Hooks
Mar 19 19:22:08 c2cpbx systemd: Reloading.
Mar 19 19:22:08 c2cpbx fwconsole: Starting Asterisk...
Mar 19 19:22:09 c2cpbx fwconsole: [>---------------------------] < 1 sec
Mar 19 19:22:09 c2cpbx fwconsole: [->--------------------------] 1 sec
Mar 19 19:22:09 c2cpbx systemd: Reloading.
Mar 19 19:22:09 c2cpbx fwconsole: [-->-------------------------] 1 sec
Mar 19 19:22:10 c2cpbx fwconsole: [--->------------------------] 1 sec
Mar 19 19:22:10 c2cpbx systemd: Reloading.
Mar 19 19:22:10 c2cpbx fwconsole: [---->-----------------------] 2 secs
Mar 19 19:22:11 c2cpbx systemd: Reloading.
Mar 19 19:22:11 c2cpbx fwconsole: [----->----------------------] 2 secs
Mar 19 19:22:11 c2cpbx php: Unparseable output from getservices - ["Exception: Asterisk is not connected in file \/var\/www\/html\/admin\/libraries\/php-asmanager.php on line 248","Stack trace:","  1. Exception->() \/var\/www\/html\/admin\/libraries\/php-asmanager.php:248","  2. AGI_AsteriskManager->send_request() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:447","  3. FreePBX\\modules\\Firewall\\Smart->getPjsipContacts() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:437","  4. FreePBX\\modules\\Firewall\\Smart->getRegistrations() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:69","  5. FreePBX\\modules\\Firewall\\Smart->getAllPorts() \/var\/www\/html\/admin\/modules\/firewall\/Firewall.class.php:1928","  6. FreePBX\\modules\\Firewall->getSmartPorts() \/var\/www\/html\/admin\/modules\/firewall\/bin\/getservices:22"] - returned 1
Mar 19 19:22:11 c2cpbx fwconsole: [------>---------------------] 3 secs
Mar 19 19:22:11 c2cpbx fwconsole: [------->--------------------] 3 secs
Mar 19 15:22:12 c2cpbx chronyd[648]: Selected source 2600:3c02:e000:74::123:0
Mar 19 15:22:12 c2cpbx chronyd[648]: System clock wrong by -14399.527583 seconds, adjustment started
Mar 19 15:22:12 c2cpbx chronyd[648]: System clock was stepped by -14399.527583 seconds
Mar 19 15:22:12 c2cpbx systemd: Time has been changed
Mar 19 15:22:12 c2cpbx php: Unparseable output from getservices - ["Exception: Asterisk is not connected in file \/var\/www\/html\/admin\/libraries\/php-asmanager.php on line 248","Stack trace:","  1. Exception->() \/var\/www\/html\/admin\/libraries\/php-asmanager.php:248","  2. AGI_AsteriskManager->send_request() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:447","  3. FreePBX\\modules\\Firewall\\Smart->getPjsipContacts() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:437","  4. FreePBX\\modules\\Firewall\\Smart->getRegistrations() \/var\/www\/html\/admin\/modules\/firewall\/Smart.class.php:69","  5. FreePBX\\modules\\Firewall\\Smart->getAllPorts() \/var\/www\/html\/admin\/modules\/firewall\/Firewall.class.php:1928","  6. FreePBX\\modules\\Firewall->getSmartPorts() \/var\/www\/html\/admin\/modules\/firewall\/bin\/getservices:22"] - returned 1
Mar 19 15:22:12 c2cpbx php: Unable to see safemode in services.. Sleeping 5 seconds and retrying
Mar 19 15:22:12 c2cpbx fwconsole: [-------->-------------------] 3 secs
Mar 19 15:22:13 c2cpbx fwconsole: [--------->------------------]
Mar 19 15:22:13 c2cpbx fwconsole: [---------->-----------------]
Mar 19 15:22:13 c2cpbx fwconsole: [----------->----------------]
Mar 19 15:22:14 c2cpbx fwconsole: [------------>---------------]
Mar 19 15:22:14 c2cpbx fwconsole: [------------->--------------]
Mar 19 15:22:14 c2cpbx kernel: Bluetooth: Core ver 2.22
Mar 19 15:22:14 c2cpbx kernel: NET: Registered protocol family 31
Mar 19 15:22:14 c2cpbx kernel: Bluetooth: HCI device and connection manager initialized
Mar 19 15:22:14 c2cpbx kernel: Bluetooth: HCI socket layer initialized
Mar 19 15:22:14 c2cpbx kernel: Bluetooth: L2CAP socket layer initialized
Mar 19 15:22:14 c2cpbx kernel: Bluetooth: SCO socket layer initialized
Mar 19 15:22:15 c2cpbx fwconsole: [-------------->-------------]
Mar 19 15:22:15 c2cpbx fwconsole: [--------------->------------]
Mar 19 15:22:15 c2cpbx fwconsole: Asterisk Started
Mar 19 15:22:15 c2cpbx fwconsole: Running Asterisk post from Adv_recovery module
Mar 19 15:22:15 c2cpbx fwconsole: Advanced Recovery is not licensed.
Mar 19 15:22:15 c2cpbx fwconsole: Running Asterisk post from Core module
Mar 19 15:22:16 c2cpbx fwconsole: Starting Core FastAGI Server...

dicko · March 22, 2021, 2:34pm

Before even that, , before 15:22:15 ? (Or 14 . . .)

ben_itse · March 22, 2021, 3:08pm

@dicko - it’s not letting me submit so many lines or upload a text file

Any recommendation on how to upload the log to you?

Stewart1 · March 22, 2021, 3:38pm

Paste at pastebin.freepbx.org and post the link here.

ben_itse · March 22, 2021, 3:43pm

Thanks @Stewart1!

@dicko - log can be found here: https://pastebin.freepbx.org/view/44358364

ben_itse · March 22, 2021, 3:49pm

@dicko - also, as I test, we rebooted the pbx and left it running with the crashed asterisk to see if asterisk would ever start automatically. It took about 4 hours (difference between the “boot time counter” and the asterisk running time counter"), but asterisk started

dicko · March 22, 2021, 3:59pm

That just shows asterisk starting normally in 6 seconds, nothing to diagnose

lzcantrell · March 22, 2021, 4:20pm

I had a machine do this exact same thing the other day, I seen somewhere that said do a asterisk-version-switch. Which I did, to get a fresh pull of Asterisk, but I have not rebooted yet to see if the problem persists.

ben_itse · March 22, 2021, 4:47pm

thanks for confirming this issue happens to you as well @lzcantrell - you probably saw that suggestion to do an asterisk-version-switch on the bug tracker page I posted. However, that is not a fix. It should work just fine on a clean install.

lzcantrell · March 22, 2021, 6:40pm

I agree, after doing the asterisk-version-switch, did Asterisk start as intended when rebooting?

ben_itse · March 22, 2021, 8:01pm

@dicko - Per your request, those are the lines on the log before what I sent earlier, which is the modules not starting up as expected which cause asterisk to not load up correctly.

ben_itse · March 22, 2021, 8:16pm

@lzcantrell - It does not. Just tried doing asterisk-version-switch and switching to version 18. Rebooted and the same issue persists. Asterisk only comes up after you do a fwconsole restart.

ben_itse · March 23, 2021, 1:11pm

If I leave the machine running with asterisk crashed, it will come up after 4 hours according to the dashboard. (time difference between asterisk uptime and system last rebooted time).

That seems to be a setting somewhere. Can those 4 hours be adjusted to something less?