So typically the small handful of times we lose connectivity to our SIP trunking provider, I see events like this logged.
[2019-10-12 21:22:26] NOTICE[28800] chan_sip.c: Peer '5264232744GW2' is now UNREACHABLE! Last qualify: 39
[2019-10-12 21:22:30] NOTICE[28800] chan_sip.c: Peer '5294877463GW2' is now UNREACHABLE! Last qualify: 40
[2019-10-12 21:22:32] NOTICE[28800] chan_sip.c: Peer '5294877463GW1' is now UNREACHABLE! Last qualify: 26
[2019-10-12 21:22:36] NOTICE[28800] chan_sip.c: Peer '5264232744GW2' is now Reachable. (154ms / 2000ms)
[2019-10-12 21:22:40] NOTICE[28800] chan_sip.c: Peer '5294877463GW2' is now Reachable. (39ms / 2000ms)
[2019-10-12 21:22:52] NOTICE[28800] chan_sip.c: Peer '5264232744GW1' is now UNREACHABLE! Last qualify: 26
Today we had a hiccup. My SIP trunking provider sends me an automated SMS message informing me that SIP trunking registration has been lost. When I immediately hopped into their web portal, it likewise shows unregistered. Then after a couple of seconds we registered again.
When I looked at the Asterisk logs, I didn’t see any of the typical lost registration events like above. All I saw around the time of the blip was the following:
[2020-03-05 13:06:56] VERBOSE[3605][C-00003612] pbx.c: Executing [16143364545@from-trunk:19] Set("SIP/5264232744GW1-00006b69", "FAXOPT(faxdetect)=yes") in new stack
[2020-03-05 13:06:56] VERBOSE[3605][C-00003612] pbx.c: Executing [16143364545@from-trunk:20] Answer("SIP/5264232744GW1-00006b69", "") in new stack
[2020-03-05 13:06:57] VERBOSE[3605][C-00003612] pbx.c: Executing [16143364545@from-trunk:21] Wait("SIP/5264232744GW1-00006b69", "4") in new stack
[2020-03-05 13:07:01] WARNING[3605][C-00003612] channel.c: Exceptionally long queue length queuing to SIP/5264232744GW1-00006b69
[2020-03-05 13:07:01] WARNING[3605][C-00003612] channel.c: Exceptionally long queue length queuing to SIP/5264232744GW1-00006b69
[2020-03-05 13:07:01] WARNING[3605][C-00003612] channel.c: Exceptionally long queue length queuing to SIP/5264232744GW1-00006b69
[2020-03-05 13:07:01] WARNING[3605][C-00003612] channel.c: Exceptionally long queue length queuing to SIP/5264232744GW1-00006b69
That one warning repeated dozens of times (same timestamp) until the next line in the workflow finally kicked in. Specifically, hitting the daynite call flow control.
[2020-03-05 13:07:01] VERBOSE[3605][C-00003612] pbx.c: Executing [16143364545@from-trunk:22] Goto("SIP/5264232744GW1-00006b69", "app-daynight,0,1") in new stack
[2020-03-05 13:07:01] VERBOSE[3605][C-00003612] pbx_builtins.c: Goto (app-daynight,0,1)
[2020-03-05 13:07:01] VERBOSE[3605][C-00003612] pbx.c: Executing [0@app-daynight:1] GotoIf("SIP/5264232744GW1-00006b69", "0?timeconditions,2,1:timeconditions,1,1") in new stack
[2020-03-05 13:07:01] VERBOSE[3605][C-00003612] pbx_builtins.c: Goto (timeconditions,1,1)
Looking at the utilization around this time, it’s not like FreePBX was being slammed with concurrent calls, heavy CPU load, etc. First time I recall seeing this. Any suggestions?