Trunk Timeout (?) with message "The number is not answering"

We have had a number of instances for some time of an outbound trunk call is picked up by the destinations voicemail then terminated with the recorded message “The number is not answering”.

This appears to be specific to calls to mobile numbers both in the United States and Canada where the approximate time for the destination VM to pickup is 45 seconds. The following is an instance of a failed call from the FreePBX logs, I also have two PCAP files from the Broadvox trunk carrier. (which I can provide) One of a successful call and one with the symptoms described here. Broadvox states that we are not providing and ack to their 200 ok (which is true) however we also never receive a 183 ringing on the failed call. I suspect there is a timeout in the FreePBX somewhere, but have had no luck in locating it. Of particular importance (I believe) are the logs starting at 17:41:00 the Your responses are appreciated.

[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:1] Macro(“SIP/9051-0000e69c”, “user-callerid,LIMIT,”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:1] Set(“SIP/9051-0000e69c”, “AMPUSER=9051”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:2] GotoIf(“SIP/9051-0000e69c”, “0?report”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:3] ExecIf(“SIP/9051-0000e69c”, “1?Set(REALCALLERIDNUM=9051)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:4] Set(“SIP/9051-0000e69c”, “AMPUSER=9051”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:5] Set(“SIP/9051-0000e69c”, “AMPUSERCIDNAME=Polycom Test 2”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:6] GotoIf(“SIP/9051-0000e69c”, “0?report”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:7] Set(“SIP/9051-0000e69c”, “AMPUSERCID=9051”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:8] Set(“SIP/9051-0000e69c”, “CALLERID(all)=“Polycom Test 2” <9051>”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:9] GotoIf(“SIP/9051-0000e69c”, “0?limit”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:10] ExecIf(“SIP/9051-0000e69c”, “1?Set(GROUP(concurrency_limit)=9051)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:11] ExecIf(“SIP/9051-0000e69c”, “0?Set(CHANNEL(language)=)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:12] GotoIf(“SIP/9051-0000e69c”, “1?continue”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Goto (macro-user-callerid,s,25)
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:25] Set(“SIP/9051-0000e69c”, “CALLERID(number)=9051”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:26] Set(“SIP/9051-0000e69c”, “CALLERID(name)=Polycom Test 2”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:2] Set(“SIP/9051-0000e69c”, “MOHCLASS=default”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:3] Set(“SIP/9051-0000e69c”, “_NODEST=”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:4] Macro(“SIP/9051-0000e69c”, “record-enable,9051,OUT,”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/9051-0000e69c”, “1?check”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Goto (macro-record-enable,s,4)
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:4] ExecIf(“SIP/9051-0000e69c”, “0?MacroExit()”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:5] GotoIf(“SIP/9051-0000e69c”, “0?Group:OUT”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Goto (macro-record-enable,s,14)
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:14] GotoIf(“SIP/9051-0000e69c”, “0?IN”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:15] ExecIf(“SIP/9051-0000e69c”, “1?MacroExit()”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:5] Macro(“SIP/9051-0000e69c”, “dialout-trunk,4,4035198098,”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:1] Set(“SIP/9051-0000e69c”, “DIAL_TRUNK=4”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:2] GosubIf(“SIP/9051-0000e69c”, “0?sub-pincheck,s,1”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:3] GotoIf(“SIP/9051-0000e69c”, “0?disabletrunk,1”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:4] Set(“SIP/9051-0000e69c”, “DIAL_NUMBER=4035198098”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:5] Set(“SIP/9051-0000e69c”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:6] Set(“SIP/9051-0000e69c”, “OUTBOUND_GROUP=OUT_4”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:7] GotoIf(“SIP/9051-0000e69c”, “1?nomax”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Goto (macro-dialout-trunk,s,9)
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:9] GotoIf(“SIP/9051-0000e69c”, “0?skipoutcid”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:10] Set(“SIP/9051-0000e69c”, “DIAL_TRUNK_OPTIONS=”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:11] Macro(“SIP/9051-0000e69c”, “outbound-callerid,4”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:1] ExecIf(“SIP/9051-0000e69c”, “0?Set(CALLERPRES()=)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:2] ExecIf(“SIP/9051-0000e69c”, “0?Set(REALCALLERIDNUM=9051)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:3] GotoIf(“SIP/9051-0000e69c”, “1?normcid”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Goto (macro-outbound-callerid,s,6)
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:6] Set(“SIP/9051-0000e69c”, “USEROUTCID=”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:7] Set(“SIP/9051-0000e69c”, “EMERGENCYCID=”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:8] Set(“SIP/9051-0000e69c”, “TRUNKOUTCID=9413283991”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:9] GotoIf(“SIP/9051-0000e69c”, “1?trunkcid”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Goto (macro-outbound-callerid,s,12)
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:12] ExecIf(“SIP/9051-0000e69c”, “1?Set(CALLERID(all)=9413283991)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:13] ExecIf(“SIP/9051-0000e69c”, “0?Set(CALLERID(all)=)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:14] ExecIf(“SIP/9051-0000e69c”, “0?Set(CALLERID(all)=)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:15] ExecIf(“SIP/9051-0000e69c”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:12] GosubIf(“SIP/9051-0000e69c”, “0?sub-flp-4,s,1”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:13] Set(“SIP/9051-0000e69c”, “OUTNUM=4035198098”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:14] Set(“SIP/9051-0000e69c”, “custom=SIP/broadvox-tx”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:15] ExecIf(“SIP/9051-0000e69c”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:16] ExecIf(“SIP/9051-0000e69c”, “0?Set(DIAL_TRUNK_OPTIONS=M(confirm))”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:17] Macro(“SIP/9051-0000e69c”, “dialout-trunk-predial-hook,”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:1] MacroExit(“SIP/9051-0000e69c”, “”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:18] GotoIf(“SIP/9051-0000e69c”, “0?bypass,1”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:19] GotoIf(“SIP/9051-0000e69c”, “0?customtrunk”) in new stack
[May 28 17:40:15] VERBOSE[8957] pbx.c: – Executing [[email protected]:20] Dial(“SIP/9051-0000e69c”, “SIP/broadvox-tx/4035198098,300,”) in new stack
[May 28 17:40:15] VERBOSE[8957] netsock.c: == Using SIP RTP TOS bits 184
[May 28 17:40:15] VERBOSE[8957] netsock.c: == Using SIP RTP CoS mark 5
[May 28 17:40:15] VERBOSE[8957] app_dial.c: – Called broadvox-tx/4035198098
[May 28 17:40:17] VERBOSE[8957] app_dial.c: – SIP/broadvox-tx-0000e69d is making progress passing it to SIP/9051-0000e69c
[May 28 17:40:43] VERBOSE[8961] manager.c: == Manager ‘admin’ logged on from 127.0.0.1
[May 28 17:40:43] VERBOSE[8961] manager.c: == Manager ‘admin’ logged off from 127.0.0.1
[May 28 17:40:45] VERBOSE[8963] manager.c: == Manager ‘admin’ logged on from 127.0.0.1
[May 28 17:40:45] VERBOSE[8963] manager.c: == Manager ‘admin’ logged off from 127.0.0.1
[May 28 17:41:00] VERBOSE[8957] app_dial.c: – No one is available to answer at this time (1:0/0/0)
[May 28 17:41:00] VERBOSE[8957] pbx.c: – Executing [[email protected]:21] NoOp(“SIP/9051-0000e69c”, “Dial failed for some reason with DIALSTATUS = NOANSWER and HANGUPCAUSE = 16”) in new stack
[May 28 17:41:00] VERBOSE[8957] pbx.c: – Executing [[email protected]:22] Goto(“SIP/9051-0000e69c”, “s-NOANSWER,1”) in new stack
[May 28 17:41:00] VERBOSE[8957] pbx.c: – Goto (macro-dialout-trunk,s-NOANSWER,1)
[May 28 17:41:00] VERBOSE[8957] pbx.c: – Executing [[email protected]:1] NoOp(“SIP/9051-0000e69c”, “Dial failed due to trunk reporting NOANSWER - giving up”) in new stack
[May 28 17:41:00] VERBOSE[8957] pbx.c: – Executing [[email protected]:2] Progress(“SIP/9051-0000e69c”, “”) in new stack
[May 28 17:41:00] VERBOSE[8957] pbx.c: – Executing [[email protected]:3] Playback(“SIP/9051-0000e69c”, “number-not-answering,noanswer”) in new stack
[May 28 17:41:00] VERBOSE[8957] file.c: – <SIP/9051-0000e69c> Playing ‘number-not-answering.gsm’ (language ‘en’)
[May 28 17:41:01] VERBOSE[8957] pbx.c: – Executing [[email protected]:4] Congestion(“SIP/9051-0000e69c”, “20”) in new stack
[May 28 17:41:01] WARNING[8957] channel.c: Prodding channel ‘SIP/9051-0000e69c’ failed
[May 28 17:41:01] VERBOSE[8957] app_macro.c: == Spawn extension (macro-dialout-trunk, s-NOANSWER, 4) exited non-zero on ‘SIP/9051-0000e69c’ in macro ‘dialout-trunk’
[May 28 17:41:01] VERBOSE[8957] pbx.c: == Spawn extension (from-internal, 4035198098, 5) exited non-zero on ‘SIP/9051-0000e69c’
[May 28 17:41:01] VERBOSE[8957] pbx.c: – Executing [[email protected]:1] Hangup(“SIP/9051-0000e69c”, “”) in new stack
[May 28 17:41:01] VERBOSE[8957] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/9051-0000e69c’


The dial command is being given a 300 second timeout by FreePBX. Looks like you better dig through those traces! FYI, you can do a "sip set debug peer broadvox-tx" in Asterisk to get SIP trace for a particular peer without dealing with tcpdump.

The dial command is being given a 300 second timeout by FreePBX. Looks like you better dig through those traces! FYI, you can do a “sip set debug peer broadvox-tx” in Asterisk to get SIP trace for a particular peer without dealing with tcpdump.