Dialing a busy number, hear "your call cannot be completed"

Basildane · August 9, 2010, 12:02pm

Whenever we dial a number that is busy, instead of getting a busy signal, our users get the error message “your call cannot be completed as dialed. Please check the number and dial again…”

I am running FreePBX 2.8.
Asterisk 1.6.2.10.
Trunk and stations are SIP.

Here is a log snippet.


[Aug  8 14:28:22] VERBOSE[22324] app_dial.c:     -- Called VoicePulse/9999999999
[Aug  8 14:28:25] VERBOSE[16533] chan_sip.c:     -- Got SIP response 486 "Busy Here" back from 64.61.93.190
[Aug  8 14:28:25] VERBOSE[22324] app_dial.c:     -- SIP/VoicePulse-000000a5 is busy
[Aug  8 14:28:25] VERBOSE[22324] app_dial.c:   == Everyone is busy/congested at this time (1:1/0/0)
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:20] NoOp("Local/[email protected];2", "Dial failed for some reason with DIALSTATUS = BUSY and HANGUPCAUSE = 17") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:21] Goto("Local/[email protected];2", "s-BUSY,1") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Goto (macro-dialout-trunk,s-BUSY,1)
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] NoOp("Local/[email protected];2", "Dial failed due to trunk reporting BUSY - giving up") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] PlayTones("Local/[email protected];2", "busy") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:3] Busy("Local/[email protected];2", "20") in new stack
[Aug  8 14:28:25] VERBOSE[22323] app_dial.c:     -- Local/[email protected];1 is busy
[Aug  8 14:28:25] VERBOSE[22323] app_dial.c:   == Everyone is busy/congested at this time (1:1/0/0)
[Aug  8 14:28:25] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:6] Playback("SIP/202-000000a4", "silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer") in new stack

mickecarlsson · August 10, 2010, 3:03pm

Please provide more details. You are using the Local channel, how is the call made?

Provide the complete log from where the call started to the end.

Basildane · August 10, 2010, 5:49pm

OK, here is the full call flow, I think.
I discovered something just now.

I did a test call with a direct dialed number and it worked. It returned busy.
The call that failed, that is attached, was a speed dial call.
Prefix = 3, speedial = 25.

It seems to hit a macro called sub-flp, and after that, it returns the busy signal to the wrong channel. It plays the busy signal to the destination number. That’s how it looks to me.

If I left anything out, just let me know.

[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:1] Macro("SIP/202-000000a4", "user-callerid,") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:1] Set("SIP/202-000000a4", "AMPUSER=202") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:2] GotoIf("SIP/202-000000a4", "0?report") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:3] ExecIf("SIP/202-000000a4", "0?Set(REALCALLERIDNUM=202)") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:4] Set("SIP/202-000000a4", "AMPUSER=202") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:5] Set("SIP/202-000000a4", "AMPUSERCIDNAME=Phil") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:6] GotoIf("SIP/202-000000a4", "0?report") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:7] Set("SIP/202-000000a4", "AMPUSERCID=202") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:8] Set("SIP/202-000000a4", "CALLERID(all)="Phil" <202>") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:9] ExecIf("SIP/202-000000a4", "0?Set(CHANNEL(language)=)") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:10] GotoIf("SIP/202-000000a4", "0?continue") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:11] Set("SIP/202-000000a4", "__TTL=63") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:12] GotoIf("SIP/202-000000a4", "1?continue") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Goto (macro-user-callerid,s,19)
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:19] NoOp("SIP/202-000000a4", "Using CallerID "Phil" <202>") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:2] Set("SIP/202-000000a4", "SPEEDDIALLOCATION=25") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:3] Macro("SIP/202-000000a4", "speeddial-lookup,25,202") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:1] GotoIf("SIP/202-000000a4", "0]?lookupsys") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:2] Set("SIP/202-000000a4", "SPEEDDIALNUMBER=") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:3] Set("SIP/202-000000a4", "SPEEDDIALNUMBER=") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:4] GotoIf("SIP/202-000000a4", "1?lookupsys") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Goto (macro-speeddial-lookup,s,104)
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:104] Set("SIP/202-000000a4", "SPEEDDIALNUMBER=4109999999") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:105] GotoIf("SIP/202-000000a4", "0?failed") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:106] NoOp("SIP/202-000000a4", "Found system speeddial 25: 4109999999") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:107] Goto("SIP/202-000000a4", "end") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Goto (macro-speeddial-lookup,s,206)
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:206] NoOp("SIP/202-000000a4", "End of Speeddial-lookup") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:4] GotoIf("SIP/202-000000a4", "0?failed") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:5] Dial("SIP/202-000000a4", "Local/[email protected]/n,") in new stack
[Aug  8 14:28:21] VERBOSE[22323] app_dial.c:     -- Called [email protected]/n
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] Macro("Local/[email protected];2", "user-callerid,SKIPTTL,") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] Set("Local/[email protected];2", "AMPUSER=202") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "1?report") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Goto (macro-user-callerid,s,10)
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:10] GotoIf("Local/[email protected];2", "1?continue") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Goto (macro-user-callerid,s,19)
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:19] NoOp("Local/[email protected];2", "Using CallerID "Phil" <202>") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] NoOp("Local/[email protected];2", "Calling Out Route: 10_Digits") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:3] Set("Local/[email protected];2", "MOHCLASS=default") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:4] Set("Local/[email protected];2", "_NODEST=") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:5] Macro("Local/[email protected];2", "record-enable,202,OUT,") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "1?check") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Goto (macro-record-enable,s,4)
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:4] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:5] GotoIf("Local/[email protected];2", "0?Group:OUT") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Goto (macro-record-enable,s,15)
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:15] GotoIf("Local/[email protected];2", "0?IN") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:16] ExecIf("Local/[email protected];2", "1?MacroExit()") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:6] Macro("Local/[email protected];2", "dialout-trunk,2,4109999999,") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] Set("Local/[email protected];2", "DIAL_TRUNK=2") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] GosubIf("Local/[email protected];2", "0?sub-pincheck,s,1") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "0?disabletrunk,1") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:4] Set("Local/[email protected];2", "DIAL_NUMBER=4109999999") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:5] Set("Local/[email protected];2", "DIAL_TRUNK_OPTIONS=tTrwWkK") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:6] Set("Local/[email protected];2", "OUTBOUND_GROUP=OUT_2") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:7] GotoIf("Local/[email protected];2", "0?nomax") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:8] GotoIf("Local/[email protected];2", "0?chanfull") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?skipoutcid") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:10] Set("Local/[email protected];2", "DIAL_TRUNK_OPTIONS=tTwWkK") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:11] Macro("Local/[email protected];2", "outbound-callerid,2") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] ExecIf("Local/[email protected];2", "0?Set(CALLERPRES()=)") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] ExecIf("Local/[email protected];2", "1?Set(REALCALLERIDNUM=202)") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "1?normcid") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:6] Set("Local/[email protected];2", "USEROUTCID=") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:7] Set("Local/[email protected];2", "EMERGENCYCID=") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:8] Set("Local/[email protected];2", "TRUNKOUTCID=4105551234") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "1?trunkcid") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Goto (macro-outbound-callerid,s,12)
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:12] ExecIf("Local/[email protected];2", "1?Set(CALLERID(all)=4105551234)") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:13] ExecIf("Local/[email protected];2", "0?Set(CALLERID(all)=)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:14] ExecIf("Local/[email protected];2", "0?Set(CALLERID(all)=)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:15] ExecIf("Local/[email protected];2", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:12] GosubIf("Local/[email protected];2", "1?sub-flp-2,s,1") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] ExecIf("Local/[email protected];2", "0?Set(TARGET_FLP42=9999999)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "0?match") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:3] ExecIf("Local/[email protected];2", "0?Return()") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:4] ExecIf("Local/[email protected];2", "1?Set(TARGET_FLP42=14109999999)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:5] GotoIf("Local/[email protected];2", "1?match") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Goto (sub-flp-2,s,9)
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:9] Set("Local/[email protected];2", "DIAL_NUMBER=14109999999") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:10] Return("Local/[email protected];2", "") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:13] Set("Local/[email protected];2", "OUTNUM=14109999999") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:14] Set("Local/[email protected];2", "custom=SIP/VoicePulse") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:15] ExecIf("Local/[email protected];2", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)tTwWkK)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:16] Macro("Local/[email protected];2", "dialout-trunk-predial-hook,") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] NoOp("Local/[email protected];2", "security check") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "0?Record911") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "0?alarm") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:4] MacroExit("Local/[email protected];2", "") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:17] GotoIf("Local/[email protected];2", "0?bypass,1") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]unk:18] GotoIf("Local/[email protected];2", "0?customtrunk") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:19] Dial("Local/[email protected];2", "SIP/VoicePulse/14109999999,300,tTwWkK") in new stack
[Aug  8 14:28:22] VERBOSE[22324] netsock.c:   == Using SIP RTP TOS bits 184
[Aug  8 14:28:22] VERBOSE[22324] netsock.c:   == Using SIP RTP CoS mark 5
[Aug  8 14:28:22] VERBOSE[22324] netsock.c:   == Using SIP VRTP TOS bits 136
[Aug  8 14:28:22] VERBOSE[22324] netsock.c:   == Using SIP VRTP CoS mark 6
[Aug  8 14:28:22] VERBOSE[22324] netsock.c:   == Using UDPTL TOS bits 184
[Aug  8 14:28:22] VERBOSE[22324] netsock.c:   == Using UDPTL CoS mark 5
[Aug  8 14:28:22] VERBOSE[22324] app_dial.c:     -- Called VoicePulse/14109999999
[Aug  8 14:28:25] VERBOSE[16533] chan_sip.c:     -- Got SIP response 486 "Busy Here" back from 64.61.93.190
[Aug  8 14:28:25] VERBOSE[22324] app_dial.c:     -- SIP/VoicePulse-000000a5 is busy
[Aug  8 14:28:25] VERBOSE[22324] app_dial.c:   == Everyone is busy/congested at this time (1:1/0/0)
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:20] NoOp("Local/[email protected];2", "Dial failed for some reason with DIALSTATUS = BUSY and HANGUPCAUSE = 17") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:21] Goto("Local/[email protected];2", "s-BUSY,1") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Goto (macro-dialout-trunk,s-BUSY,1)
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] NoOp("Local/[email protected];2", "Dial failed due to trunk reporting BUSY - giving up") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] PlayTones("Local/[email protected];2", "busy") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:3] Busy("Local/[email protected];2", "20") in new stack
[Aug  8 14:28:25] VERBOSE[22323] app_dial.c:     -- Local/[email protected];1 is busy
[Aug  8 14:28:25] VERBOSE[22323] app_dial.c:   == Everyone is busy/congested at this time (1:1/0/0)
[Aug  8 14:28:25] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:6] Playback("SIP/202-000000a4", "silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer") in new stack
[Aug  8 14:28:25] VERBOSE[22324] app_macro.c:   == Spawn extension (macro-dialout-trunk, s-BUSY, 3) exited non-zero on 'Local/[email protected];2' in macro 'dialout-trunk'
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:   == Spawn extension (from-internal, 4109999999, 6) exited non-zero on 'Local/[email protected];2'
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] Macro("Local/[email protected];2", "hangupcall") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "1?skiprg") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:4] GotoIf("Local/[email protected];2", "1?skipblkvm") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:7] GotoIf("Local/[email protected];2", "1?theend") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:9] Hangup("Local/[email protected];2", "") in new stack
[Aug  8 14:28:25] VERBOSE[22324] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'Local/[email protected];2' in macro 'hangupcall'
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/[email protected];2'
[Aug  8 14:28:25] VERBOSE[22323] file.c:     -- <SIP/202-000000a4> Playing 'silence/1.gsm' (language 'en')
[Aug  8 14:28:26] VERBOSE[22323] file.c:     -- <SIP/202-000000a4> Playing 'cannot-complete-as-dialed.ulaw' (language 'en')
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:   == Spawn extension (from-internal, 325, 6) exited non-zero on 'SIP/202-000000a4'
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:1] Macro("SIP/202-000000a4", "hangupcall") in new stack
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:1] GotoIf("SIP/202-000000a4", "1?skiprg") in new stack
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:4] GotoIf("SIP/202-000000a4", "1?skipblkvm") in new stack
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:7] GotoIf("SIP/202-000000a4", "1?theend") in new stack
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:9] Hangup("SIP/202-000000a4", "") in new stack
[Aug  8 14:28:28] VERBOSE[22323] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/202-000000a4' in macro 'hangupcall'
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/202-000000a4'
[Aug  8 14:28:28] VERBOSE[16402] chan_sip.c:   == Extension Changed 202[ext-local] new state Idle for Notify User 207

Basildane · August 10, 2010, 5:41pm

It was dialed from an Aastra 57i.
Dial 325 #.

mickecarlsson · August 11, 2010, 6:25am

I can’t duplicate this, however, I noticed that you have a route pattern entered, could you please post your prepend, prefix and match pattern for the outbound route?

Basildane · August 11, 2010, 2:10pm

Outbound route “10_digits”.
Prepend: “” Prefix: “” Match pattern: "1NXXNXXXXXX"
Prepend: “” Prefix: “” Match pattern: “NXXNXXXXXX”

Trunk "VoicePulse"
Prepend: “” Prefix: “011” Match pattern: "."
Prepend: “” Prefix: “” Match pattern: "1NXXNXXXXXX"
Prepend: “1” Prefix: “” Match pattern: "NXXNXXXXXX"
Prepend: “1410” Prefix: “” Match pattern: “NXXXXXX”

I did another test with another speed dial, and had the same problem. This seems to be a contributing factor. (note, it is hard for me to find busy numbers to test with)

[outrt-4] ; 10_Digits
include => outrt-4-custom
exten => _1NXXNXXXXXX,1,Macro(user-callerid,SKIPTTL,)
exten => _1NXXNXXXXXX,n,Noop(Calling Out Route: 10_Digits)
exten => _1NXXNXXXXXX,n,Set(MOHCLASS=${IF($["${MOHCLASS}"=""]?default:${MOHCLASS})})
exten => _1NXXNXXXXXX,n,Set(_NODEST=)
exten => _1NXXNXXXXXX,n,Macro(record-enable,${AMPUSER},OUT,)
exten => _1NXXNXXXXXX,n,Macro(dialout-trunk,2,${EXTEN},)
exten => _1NXXNXXXXXX,n,Macro(dialout-trunk,3,${EXTEN},)
exten => _1NXXNXXXXXX,n,Macro(outisbusy,)
exten => _NXXNXXXXXX,1,Macro(user-callerid,SKIPTTL,)
exten => _NXXNXXXXXX,n,Noop(Calling Out Route: 10_Digits)
exten => _NXXNXXXXXX,n,Set(MOHCLASS=${IF($["${MOHCLASS}"=""]?default:${MOHCLASS})})
exten => _NXXNXXXXXX,n,Set(_NODEST=)
exten => _NXXNXXXXXX,n,Macro(record-enable,${AMPUSER},OUT,)
exten => _NXXNXXXXXX,n,Macro(dialout-trunk,2,${EXTEN},)
exten => _NXXNXXXXXX,n,Macro(dialout-trunk,3,${EXTEN},)
exten => _NXXNXXXXXX,n,Macro(outisbusy,)

; end of [outrt-4]

[sub-flp-2]
include => sub-flp-2-custom
exten => s,1,ExecIf($[${REGEX("^011[0-9#\\*\\+]+$" ${DIAL_NUMBER})} = 1]?Set(TARGET_FLP42=${DIAL_NUMBER:3}))
exten => s,n,GotoIf($[${LEN(${TARGET_FLP42})} != 0]?match)
exten => s,n,ExecIf($[${REGEX("^1[2-9][0-9][0-9][2-9][0-9][0-9][0-9][0-9][0-9][0-9]$" ${DIAL_NUMBER})} = 1]?Return())
exten => s,n,ExecIf($[${REGEX("^[2-9][0-9][0-9][2-9][0-9][0-9][0-9][0-9][0-9][0-9]$" ${DIAL_NUMBER})} = 1]?Set(TARGET_FLP42=1${DIAL_NUMBER}))
exten => s,n,GotoIf($[${LEN(${TARGET_FLP42})} != 0]?match)
exten => s,n,ExecIf($[${REGEX("^[2-9][0-9][0-9][0-9][0-9][0-9][0-9]$" ${DIAL_NUMBER})} = 1]?Set(TARGET_FLP42=1410${DIAL_NUMBER}))
exten => s,n,GotoIf($[${LEN(${TARGET_FLP42})} != 0]?match)
exten => s,n,Return()
exten => s,n(match),Set(DIAL_NUMBER=${TARGET_FLP42})
exten => s,n,Return()

; end of [sub-flp-2]

Basildane · August 19, 2010, 12:32pm

If not, can you give me any suggestions on where to begin troubleshooting?

witdirect · August 19, 2010, 2:47pm

Try this delete one of those extensions thats doing that apply changes and recreate that extension. I had that issue with extensions I imported from cvs file and once I manually recreated them all work fine.

Basildane · August 19, 2010, 3:04pm

Just to clarify, these are OUTbound calls.
Only seems to happen with speed-dials.

mickecarlsson · August 19, 2010, 6:58pm

I have not been able to test it further, I will do as soon as I find the time.

I have a test server at work where I can test different scenarios, and I will do that, perhaps next week.

witdirect · August 19, 2010, 9:22pm

Have you tried recreating the extension? I had same issue with outbound calling inbound worked fine. Or just make a test extension and add it to phone and see if it works.

mickecarlsson · August 20, 2010, 10:00am

I have tested it and it working as it should.

What is this?

[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:16] Macro("Local/[email protected];2", "dialout-trunk-predial-hook,") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:1] NoOp("Local/[email protected];2", "security check") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "0?Record911") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "0?alarm") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [[email protected]:4] MacroExit("Local/[email protected];2", "") in new stack

Basildane · August 20, 2010, 11:32am

In my predial-hook, I have various code for:

To detect if the alarm system has initiated an alarm call in the past xxx minutes. If it has, then my “telemarketing jammer” software is temporarily disabled and all incoming calls go to the main ring group. This is to prevent missing a return call from the central station or other authorities.
Record911 is a macro that detects if anyone in my house is dialing 911, poison control, or any other number in the emergency call group. If they do, I get an SMS on my blackberry, and after the call is completed, an MP3 of the 911 call is sent to my blackberry as well.

There is also code that checks to see if my kids are dialing “grandma”, and it looks up her location from SQL and routes the call to the appropriate location. She lives in different states summer / winter, I put her flight dates in a table. So there is one button on the phones for Grandma - and it “just works”.

Lots of other stuff going on too.

I guess I should temporarily remove that code and test to see if there is any effect. Its been running for years and I don’t think about it…

oh, and thanks for taking the time to test.

Basildane · August 25, 2010, 2:07pm

Mikael, did you test this using a speed dial?
I’ve been really digging into the code and logs, and for me, it is totally repeatable.

If I direct-dial the busy number, it does a Busy() on my phone.

If I use a speeddial, the Busy() happens on the -destination-, on the Local\xxxx.

I have eliminated the predial-hook and anything else a factor.
When direct dialing, there is one Dial() command, and busy is naturally sent to the correct channel. When speeddialing, you go through TWO Dial() commands, and the resulting busy is sent to the last Dial(), which is incorrect.

From my perspective, this is a bug in speeddial and it cannot possibly work correctly.

mickecarlsson · August 25, 2010, 2:39pm

Actually I did test it with speeddial, but it was from an Asterisk 1.8-beta3 box. I also emulated your setup with dial patterns so that I could compare your output with mine. And it was a close match.

I can test it again and compare the logs and see the actual Dial() if they differ.
I also have USEDEVSTAT=true in my amportal.conf

Basildane · August 25, 2010, 2:50pm

I would love to see your log of the call.
I’m trying to troubleshoot this myself as much as possible…

mickecarlsson · August 31, 2010, 8:15am

OK, so I tested it again on Asterisk 1.8Beta-4 and FreePBX 2.9.0alpha1.1 (yes, I know, beta - alpha, but it is my test server so bear with me)
I don’t get the result that you get.

[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     --- Executing [*[email protected]:1] Macro("SIP/2476-00000005", "user-callerid,") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:1] Set("SIP/2476-00000005", "AMPUSER=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:2] GotoIf("SIP/2476-00000005", "0?report") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:3] ExecIf("SIP/2476-00000005", "1?Set(REALCALLERIDNUM=2476)") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:4] Set("SIP/2476-00000005", "AMPUSER=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:5] Set("SIP/2476-00000005", "AMPUSERCIDNAME=Mikael Carlsson") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:6] GotoIf("SIP/2476-00000005", "0?report") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:7] Set("SIP/2476-00000005", "AMPUSERCID=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:8] Set("SIP/2476-00000005", "CALLERID(all)="Mikael Carlsson" <2476>") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:9] ExecIf("SIP/2476-00000005", "0?Set(CHANNEL(language)=)") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:10] GotoIf("SIP/2476-00000005", "0?continue") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:11] Set("SIP/2476-00000005", "__TTL=64") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:12] GotoIf("SIP/2476-00000005", "1?continue") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Goto (macro-user-callerid,s,19)
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:19] NoOp("SIP/2476-00000005", "Using CallerID "Mikael Carlsson" <2476>") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [*[email protected]:2] Set("SIP/2476-00000005", "SPEEDDIALLOCATION=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [*[email protected]:3] Macro("SIP/2476-00000005", "speeddial-lookup,2476,2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:1] GotoIf("SIP/2476-00000005", "0]?lookupsys") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:2] Set("SIP/2476-00000005", "SPEEDDIALNUMBER=") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:3] Set("SIP/2476-00000005", "SPEEDDIALNUMBER=") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:4] GotoIf("SIP/2476-00000005", "1?lookupsys") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Goto (macro-speeddial-lookup,s,104)
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:104] Set("SIP/2476-00000005", "SPEEDDIALNUMBER=592476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:105] GotoIf("SIP/2476-00000005", "0?failed") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:106] NoOp("SIP/2476-00000005", "Found system speeddial 2476: 592476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:107] Goto("SIP/2476-00000005", "end") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Goto (macro-speeddial-lookup,s,206)
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:206] NoOp("SIP/2476-00000005", "End of Speeddial-lookup") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [*[email protected]:4] GotoIf("SIP/2476-00000005", "0?failed") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [*[email protected]:5] Dial("SIP/2476-00000005", "Local/[email protected]/n,") in new stack
[Aug 31 10:01:19] VERBOSE[8578] app_dial.c:     -- Called [email protected]/n
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] Macro("Local/[email protected];2", "user-callerid,SKIPTTL,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] Set("Local/[email protected];2", "AMPUSER=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "1?report") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Goto (macro-user-callerid,s,10)
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:10] GotoIf("Local/[email protected];2", "1?continue") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Goto (macro-user-callerid,s,19)
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:19] NoOp("Local/[email protected];2", "Using CallerID "Mikael Carlsson" <2476>") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:2] NoOp("Local/[email protected];2", "Calling Out Route: NoName-out") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:3] Set("Local/[email protected];2", "MOHCLASS=default") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:4] Set("Local/[email protected];2", "_NODEST=") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:5] Macro("Local/[email protected];2", "record-enable,2476,OUT,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "1?check") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Goto (macro-record-enable,s,4)
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:4] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:5] GotoIf("Local/[email protected];2", "0?Group:OUT") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Goto (macro-record-enable,s,15)
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:15] GotoIf("Local/[email protected];2", "0?IN") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:16] ExecIf("Local/[email protected];2", "1?MacroExit()") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:6] Macro("Local/[email protected];2", "dialout-trunk,2,592476,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] Set("Local/[email protected];2", "DIAL_TRUNK=2") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:2] GosubIf("Local/[email protected];2", "0?sub-pincheck,s,1") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "0?disabletrunk,1") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:4] Set("Local/[email protected];2", "DIAL_NUMBER=592476") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:5] Set("Local/[email protected];2", "DIAL_TRUNK_OPTIONS=trwW") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:6] Set("Local/[email protected];2", "OUTBOUND_GROUP=OUT_2") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:7] GotoIf("Local/[email protected];2", "1?nomax") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Goto (macro-dialout-trunk,s,9)
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?skipoutcid") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:10] Set("Local/[email protected];2", "DIAL_TRUNK_OPTIONS=") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:11] Macro("Local/[email protected];2", "outbound-callerid,2") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] ExecIf("Local/[email protected];2", "0?Set(CALLERPRES()=)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:2] ExecIf("Local/[email protected];2", "1?Set(REALCALLERIDNUM=2476)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "1?normcid") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Goto (macro-outbound-callerid,s,6)
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:6] Set("Local/[email protected];2", "USEROUTCID="Micke" <0406015986>") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:7] Set("Local/[email protected];2", "EMERGENCYCID=") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:8] Set("Local/[email protected];2", "TRUNKOUTCID=") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "1?trunkcid") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Goto (macro-outbound-callerid,s,12)
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:12] ExecIf("Local/[email protected];2", "0?Set(CALLERID(all)=)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:13] ExecIf("Local/[email protected];2", "1?Set(CALLERID(all)="Micke" <0406015986>)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:14] ExecIf("Local/[email protected];2", "0?Set(CALLERID(all)=)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:15] ExecIf("Local/[email protected];2", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:12] GosubIf("Local/[email protected];2", "1?sub-flp-2,s,1") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] ExecIf("Local/[email protected];2", "1?Set(TARGET_FLP42=040592476)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "1?match") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Goto (sub-flp-2,s,4)
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:4] Set("Local/[email protected];2", "DIAL_NUMBER=040592476") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:5] Return("Local/[email protected];2", "") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:13] Set("Local/[email protected];2", "OUTNUM=040592476") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:14] Set("Local/[email protected];2", "custom=SIP/sip-noname.nodomain.top") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:15] ExecIf("Local/[email protected];2", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:16] Macro("Local/[email protected];2", "dialout-trunk-predial-hook,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] MacroExit("Local/[email protected];2", "") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:17] GotoIf("Local/[email protected];2", "0?bypass,1") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:18] GotoIf("Local/[email protected];2", "0?customtrunk") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:19] Dial("Local/[email protected];2", "SIP/sip-noname.nodomain.top/040592476,300,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] app_dial.c:     -- Called sip-noname.nodomain.top/040592476
[Aug 31 10:01:20] VERBOSE[8579] app_dial.c:     -- SIP/sip-noname.nodomain.top-00000006 is making progress passing it to Local/[email protected];2
[Aug 31 10:01:20] VERBOSE[8578] app_dial.c:     -- Local/[email protected];1 is making progress passing it to SIP/2476-00000005
[Aug 31 10:01:21] VERBOSE[30408] chan_sip.c:     -- Got SIP response 486 "Busy" back from 130.244.190.42:5060
[Aug 31 10:01:21] VERBOSE[8579] app_dial.c:     -- SIP/sip-noname.nodomain.top-00000006 is busy
[Aug 31 10:01:21] VERBOSE[8579] app_dial.c:   == Everyone is busy/congested at this time (1:1/0/0)
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:20] NoOp("Local/[email protected];2", "Dial failed for some reason with DIALSTATUS = BUSY and HANGUPCAUSE = 17") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:21] Goto("Local/[email protected];2", "s-BUSY,1") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Goto (macro-dialout-trunk,s-BUSY,1)
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] NoOp("Local/[email protected];2", "Dial failed due to trunk reporting BUSY - giving up") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:2] PlayTones("Local/[email protected];2", "busy") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:3] Busy("Local/[email protected];2", "20") in new stack
[Aug 31 10:01:21] VERBOSE[8578] app_dial.c:     -- Local/[email protected];1 is busy
[Aug 31 10:01:21] VERBOSE[8578] app_dial.c:   == Everyone is busy/congested at this time (1:1/0/0)
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Auto fallthrough, channel 'SIP/2476-00000005' status is 'BUSY'
[Aug 31 10:01:21] WARNING[8578] channel.c: Prodding channel 'SIP/2476-00000005' failed
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:1] Macro("SIP/2476-00000005", "hangupcall") in new stack
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:1] GotoIf("SIP/2476-00000005", "1?skiprg") in new stack
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:4] GotoIf("SIP/2476-00000005", "1?skipblkvm") in new stack
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:7] GotoIf("SIP/2476-00000005", "1?theend") in new stack
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Executing [[email protected]:9] Hangup("SIP/2476-00000005", "") in new stack
[Aug 31 10:01:21] VERBOSE[8578] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/2476-00000005' in macro 'hangupcall'
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/2476-00000005'
[Aug 31 10:01:21] VERBOSE[8579] app_macro.c:   == Spawn extension (macro-dialout-trunk, s-BUSY, 3) exited non-zero on 'Local/[email protected];2' in macro 'dialout-trunk'
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:   == Spawn extension (from-internal, 592476, 6) exited non-zero on 'Local/[email protected];2'
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] Macro("Local/[email protected];2", "hangupcall") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "1?skiprg") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:4] GotoIf("Local/[email protected];2", "1?skipblkvm") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:7] GotoIf("Local/[email protected];2", "1?theend") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [[email protected]:9] Hangup("Local/[email protected];2", "") in new stack
[Aug 31 10:01:21] VERBOSE[8579] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'Local/[email protected];2' in macro 'hangupcall'
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/[email protected];2'

Basildane · August 31, 2010, 1:05pm

Very interesting.
Your flow and my flow differ at this point.
For me, after the BUSY, I fallthrough into [bad-number:6], which is where it says your call cannot be completed. [bad-number] is the last context at the end of [from-internal].

[Aug  8 14:28:25] VERBOSE[22323] app_dial.c:   == Everyone is busy/congested at this time (1:1/0/0)
[Aug  8 14:28:25] VERBOSE[22323] pbx.c:     -- Executing [[email protected]:6] Playback("SIP/202-000000a4", "silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer") in new stack

system · June 4, 2014, 7:04pm