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 [s@macro-dialout-trunk:20] NoOp("Local/9999999999@from-internal-a998;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 [s@macro-dialout-trunk:21] Goto("Local/9999999999@from-internal-a998;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 [s-BUSY@macro-dialout-trunk:1] NoOp("Local/9999999999@from-internal-a998;2", "Dial failed due to trunk reporting BUSY - giving up") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [s-BUSY@macro-dialout-trunk:2] PlayTones("Local/9999999999@from-internal-a998;2", "busy") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [s-BUSY@macro-dialout-trunk:3] Busy("Local/9999999999@from-internal-a998;2", "20") in new stack
[Aug  8 14:28:25] VERBOSE[22323] app_dial.c:     -- Local/9999999999@from-internal-a998;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 [325@from-internal: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 [325@from-internal:1] Macro("SIP/202-000000a4", "user-callerid,") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/202-000000a4", "AMPUSER=202") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/202-000000a4", "0?report") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/202-000000a4", "0?Set(REALCALLERIDNUM=202)") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/202-000000a4", "AMPUSER=202") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/202-000000a4", "AMPUSERCIDNAME=Phil") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/202-000000a4", "0?report") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:7] Set("SIP/202-000000a4", "AMPUSERCID=202") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:8] Set("SIP/202-000000a4", "CALLERID(all)="Phil" <202>") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:9] ExecIf("SIP/202-000000a4", "0?Set(CHANNEL(language)=)") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/202-000000a4", "0?continue") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/202-000000a4", "__TTL=63") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:19] NoOp("SIP/202-000000a4", "Using CallerID "Phil" <202>") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [325@from-internal:2] Set("SIP/202-000000a4", "SPEEDDIALLOCATION=25") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [325@from-internal:3] Macro("SIP/202-000000a4", "speeddial-lookup,25,202") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-speeddial-lookup:1] GotoIf("SIP/202-000000a4", "0]?lookupsys") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-speeddial-lookup:2] Set("SIP/202-000000a4", "SPEEDDIALNUMBER=") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-speeddial-lookup:3] Set("SIP/202-000000a4", "SPEEDDIALNUMBER=") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-speeddial-lookup: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 [s@macro-speeddial-lookup:104] Set("SIP/202-000000a4", "SPEEDDIALNUMBER=4109999999") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-speeddial-lookup:105] GotoIf("SIP/202-000000a4", "0?failed") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-speeddial-lookup:106] NoOp("SIP/202-000000a4", "Found system speeddial 25: 4109999999") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [s@macro-speeddial-lookup: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 [s@macro-speeddial-lookup:206] NoOp("SIP/202-000000a4", "End of Speeddial-lookup") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [325@from-internal:4] GotoIf("SIP/202-000000a4", "0?failed") in new stack
[Aug  8 14:28:21] VERBOSE[22323] pbx.c:     -- Executing [325@from-internal:5] Dial("SIP/202-000000a4", "Local/4109999999@from-internal/n,") in new stack
[Aug  8 14:28:21] VERBOSE[22323] app_dial.c:     -- Called 4109999999@from-internal/n
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [4109999999@from-internal:1] Macro("Local/4109999999@from-internal-a998;2", "user-callerid,SKIPTTL,") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("Local/4109999999@from-internal-a998;2", "AMPUSER=202") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-user-callerid:10] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-user-callerid:19] NoOp("Local/4109999999@from-internal-a998;2", "Using CallerID "Phil" <202>") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [4109999999@from-internal:2] NoOp("Local/4109999999@from-internal-a998;2", "Calling Out Route: 10_Digits") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [4109999999@from-internal:3] Set("Local/4109999999@from-internal-a998;2", "MOHCLASS=default") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [4109999999@from-internal:4] Set("Local/4109999999@from-internal-a998;2", "_NODEST=") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [4109999999@from-internal:5] Macro("Local/4109999999@from-internal-a998;2", "record-enable,202,OUT,") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-record-enable:1] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-record-enable:4] ExecIf("Local/4109999999@from-internal-a998;2", "0?MacroExit()") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-record-enable:5] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-record-enable:15] GotoIf("Local/4109999999@from-internal-a998;2", "0?IN") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-record-enable:16] ExecIf("Local/4109999999@from-internal-a998;2", "1?MacroExit()") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [4109999999@from-internal:6] Macro("Local/4109999999@from-internal-a998;2", "dialout-trunk,2,4109999999,") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("Local/4109999999@from-internal-a998;2", "DIAL_TRUNK=2") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("Local/4109999999@from-internal-a998;2", "0?sub-pincheck,s,1") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("Local/4109999999@from-internal-a998;2", "0?disabletrunk,1") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("Local/4109999999@from-internal-a998;2", "DIAL_NUMBER=4109999999") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("Local/4109999999@from-internal-a998;2", "DIAL_TRUNK_OPTIONS=tTrwWkK") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("Local/4109999999@from-internal-a998;2", "OUTBOUND_GROUP=OUT_2") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("Local/4109999999@from-internal-a998;2", "0?nomax") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:8] GotoIf("Local/4109999999@from-internal-a998;2", "0?chanfull") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:9] GotoIf("Local/4109999999@from-internal-a998;2", "0?skipoutcid") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("Local/4109999999@from-internal-a998;2", "DIAL_TRUNK_OPTIONS=tTwWkK") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("Local/4109999999@from-internal-a998;2", "outbound-callerid,2") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("Local/4109999999@from-internal-a998;2", "0?Set(CALLERPRES()=)") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("Local/4109999999@from-internal-a998;2", "1?Set(REALCALLERIDNUM=202)") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-outbound-callerid:6] Set("Local/4109999999@from-internal-a998;2", "USEROUTCID=") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("Local/4109999999@from-internal-a998;2", "EMERGENCYCID=") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("Local/4109999999@from-internal-a998;2", "TRUNKOUTCID=4105551234") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-outbound-callerid:12] ExecIf("Local/4109999999@from-internal-a998;2", "1?Set(CALLERID(all)=4105551234)") in new stack
[Aug  8 14:28:21] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:13] ExecIf("Local/4109999999@from-internal-a998;2", "0?Set(CALLERID(all)=)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("Local/4109999999@from-internal-a998;2", "0?Set(CALLERID(all)=)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("Local/4109999999@from-internal-a998;2", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("Local/4109999999@from-internal-a998;2", "1?sub-flp-2,s,1") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@sub-flp-2:1] ExecIf("Local/4109999999@from-internal-a998;2", "0?Set(TARGET_FLP42=9999999)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@sub-flp-2:2] GotoIf("Local/4109999999@from-internal-a998;2", "0?match") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@sub-flp-2:3] ExecIf("Local/4109999999@from-internal-a998;2", "0?Return()") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@sub-flp-2:4] ExecIf("Local/4109999999@from-internal-a998;2", "1?Set(TARGET_FLP42=14109999999)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@sub-flp-2:5] GotoIf("Local/4109999999@from-internal-a998;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 [s@sub-flp-2:9] Set("Local/4109999999@from-internal-a998;2", "DIAL_NUMBER=14109999999") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@sub-flp-2:10] Return("Local/4109999999@from-internal-a998;2", "") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("Local/4109999999@from-internal-a998;2", "OUTNUM=14109999999") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("Local/4109999999@from-internal-a998;2", "custom=SIP/VoicePulse") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("Local/4109999999@from-internal-a998;2", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)tTwWkK)") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:16] Macro("Local/4109999999@from-internal-a998;2", "dialout-trunk-predial-hook,") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] NoOp("Local/4109999999@from-internal-a998;2", "security check") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:2] GotoIf("Local/4109999999@from-internal-a998;2", "0?Record911") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:3] GotoIf("Local/4109999999@from-internal-a998;2", "0?alarm") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:4] MacroExit("Local/4109999999@from-internal-a998;2", "") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:17] GotoIf("Local/4109999999@from-internal-a998;2", "0?bypass,1") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("Local/4109999999@from-internal-a998;2", "0?customtrunk") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk:19] Dial("Local/4109999999@from-internal-a998;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 [s@macro-dialout-trunk:20] NoOp("Local/4109999999@from-internal-a998;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 [s@macro-dialout-trunk:21] Goto("Local/4109999999@from-internal-a998;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 [s-BUSY@macro-dialout-trunk:1] NoOp("Local/4109999999@from-internal-a998;2", "Dial failed due to trunk reporting BUSY - giving up") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [s-BUSY@macro-dialout-trunk:2] PlayTones("Local/4109999999@from-internal-a998;2", "busy") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [s-BUSY@macro-dialout-trunk:3] Busy("Local/4109999999@from-internal-a998;2", "20") in new stack
[Aug  8 14:28:25] VERBOSE[22323] app_dial.c:     -- Local/4109999999@from-internal-a998;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 [325@from-internal: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/4109999999@from-internal-a998;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/4109999999@from-internal-a998;2'
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [h@from-internal:1] Macro("Local/4109999999@from-internal-a998;2", "hangupcall") in new stack
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-hangupcall:4] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-hangupcall:7] GotoIf("Local/4109999999@from-internal-a998;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 [s@macro-hangupcall:9] Hangup("Local/4109999999@from-internal-a998;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/4109999999@from-internal-a998;2' in macro 'hangupcall'
[Aug  8 14:28:25] VERBOSE[22324] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/4109999999@from-internal-a998;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 [h@from-internal:1] Macro("SIP/202-000000a4", "hangupcall") in new stack
[Aug  8 14:28:28] VERBOSE[22323] pbx.c:     -- Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-dialout-trunk:16] Macro("Local/4109999999@from-internal-a998;2", "dialout-trunk-predial-hook,") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] NoOp("Local/4109999999@from-internal-a998;2", "security check") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:2] GotoIf("Local/4109999999@from-internal-a998;2", "0?Record911") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:3] GotoIf("Local/4109999999@from-internal-a998;2", "0?alarm") in new stack
[Aug  8 14:28:22] VERBOSE[22324] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:4] MacroExit("Local/4109999999@from-internal-a998;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 [*32476@from-internal:1] Macro("SIP/2476-00000005", "user-callerid,") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/2476-00000005", "AMPUSER=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/2476-00000005", "0?report") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/2476-00000005", "1?Set(REALCALLERIDNUM=2476)") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/2476-00000005", "AMPUSER=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/2476-00000005", "AMPUSERCIDNAME=Mikael Carlsson") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/2476-00000005", "0?report") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:7] Set("SIP/2476-00000005", "AMPUSERCID=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:8] Set("SIP/2476-00000005", "CALLERID(all)="Mikael Carlsson" <2476>") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:9] ExecIf("SIP/2476-00000005", "0?Set(CHANNEL(language)=)") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/2476-00000005", "0?continue") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/2476-00000005", "__TTL=64") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:19] NoOp("SIP/2476-00000005", "Using CallerID "Mikael Carlsson" <2476>") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [*32476@from-internal:2] Set("SIP/2476-00000005", "SPEEDDIALLOCATION=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [*32476@from-internal:3] Macro("SIP/2476-00000005", "speeddial-lookup,2476,2476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-speeddial-lookup:1] GotoIf("SIP/2476-00000005", "0]?lookupsys") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-speeddial-lookup:2] Set("SIP/2476-00000005", "SPEEDDIALNUMBER=") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-speeddial-lookup:3] Set("SIP/2476-00000005", "SPEEDDIALNUMBER=") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-speeddial-lookup: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 [s@macro-speeddial-lookup:104] Set("SIP/2476-00000005", "SPEEDDIALNUMBER=592476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-speeddial-lookup:105] GotoIf("SIP/2476-00000005", "0?failed") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-speeddial-lookup:106] NoOp("SIP/2476-00000005", "Found system speeddial 2476: 592476") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [s@macro-speeddial-lookup: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 [s@macro-speeddial-lookup:206] NoOp("SIP/2476-00000005", "End of Speeddial-lookup") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [*32476@from-internal:4] GotoIf("SIP/2476-00000005", "0?failed") in new stack
[Aug 31 10:01:19] VERBOSE[8578] pbx.c:     -- Executing [*32476@from-internal:5] Dial("SIP/2476-00000005", "Local/592476@from-internal/n,") in new stack
[Aug 31 10:01:19] VERBOSE[8578] app_dial.c:     -- Called 592476@from-internal/n
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [592476@from-internal:1] Macro("Local/592476@from-internal-5854;2", "user-callerid,SKIPTTL,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-user-callerid:1] Set("Local/592476@from-internal-5854;2", "AMPUSER=2476") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-user-callerid:2] GotoIf("Local/592476@from-internal-5854;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 [s@macro-user-callerid:10] GotoIf("Local/592476@from-internal-5854;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 [s@macro-user-callerid:19] NoOp("Local/592476@from-internal-5854;2", "Using CallerID "Mikael Carlsson" <2476>") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [592476@from-internal:2] NoOp("Local/592476@from-internal-5854;2", "Calling Out Route: NoName-out") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [592476@from-internal:3] Set("Local/592476@from-internal-5854;2", "MOHCLASS=default") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [592476@from-internal:4] Set("Local/592476@from-internal-5854;2", "_NODEST=") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [592476@from-internal:5] Macro("Local/592476@from-internal-5854;2", "record-enable,2476,OUT,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-record-enable:1] GotoIf("Local/592476@from-internal-5854;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 [s@macro-record-enable:4] ExecIf("Local/592476@from-internal-5854;2", "0?MacroExit()") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-record-enable:5] GotoIf("Local/592476@from-internal-5854;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 [s@macro-record-enable:15] GotoIf("Local/592476@from-internal-5854;2", "0?IN") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-record-enable:16] ExecIf("Local/592476@from-internal-5854;2", "1?MacroExit()") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [592476@from-internal:6] Macro("Local/592476@from-internal-5854;2", "dialout-trunk,2,592476,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:1] Set("Local/592476@from-internal-5854;2", "DIAL_TRUNK=2") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:2] GosubIf("Local/592476@from-internal-5854;2", "0?sub-pincheck,s,1") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:3] GotoIf("Local/592476@from-internal-5854;2", "0?disabletrunk,1") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:4] Set("Local/592476@from-internal-5854;2", "DIAL_NUMBER=592476") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:5] Set("Local/592476@from-internal-5854;2", "DIAL_TRUNK_OPTIONS=trwW") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:6] Set("Local/592476@from-internal-5854;2", "OUTBOUND_GROUP=OUT_2") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:7] GotoIf("Local/592476@from-internal-5854;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 [s@macro-dialout-trunk:9] GotoIf("Local/592476@from-internal-5854;2", "0?skipoutcid") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:10] Set("Local/592476@from-internal-5854;2", "DIAL_TRUNK_OPTIONS=") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:11] Macro("Local/592476@from-internal-5854;2", "outbound-callerid,2") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:1] ExecIf("Local/592476@from-internal-5854;2", "0?Set(CALLERPRES()=)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:2] ExecIf("Local/592476@from-internal-5854;2", "1?Set(REALCALLERIDNUM=2476)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:3] GotoIf("Local/592476@from-internal-5854;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 [s@macro-outbound-callerid:6] Set("Local/592476@from-internal-5854;2", "USEROUTCID="Micke" <0406015986>") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:7] Set("Local/592476@from-internal-5854;2", "EMERGENCYCID=") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:8] Set("Local/592476@from-internal-5854;2", "TRUNKOUTCID=") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:9] GotoIf("Local/592476@from-internal-5854;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 [s@macro-outbound-callerid:12] ExecIf("Local/592476@from-internal-5854;2", "0?Set(CALLERID(all)=)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:13] ExecIf("Local/592476@from-internal-5854;2", "1?Set(CALLERID(all)="Micke" <0406015986>)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:14] ExecIf("Local/592476@from-internal-5854;2", "0?Set(CALLERID(all)=)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-outbound-callerid:15] ExecIf("Local/592476@from-internal-5854;2", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:12] GosubIf("Local/592476@from-internal-5854;2", "1?sub-flp-2,s,1") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@sub-flp-2:1] ExecIf("Local/592476@from-internal-5854;2", "1?Set(TARGET_FLP42=040592476)") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@sub-flp-2:2] GotoIf("Local/592476@from-internal-5854;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 [s@sub-flp-2:4] Set("Local/592476@from-internal-5854;2", "DIAL_NUMBER=040592476") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@sub-flp-2:5] Return("Local/592476@from-internal-5854;2", "") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:13] Set("Local/592476@from-internal-5854;2", "OUTNUM=040592476") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:14] Set("Local/592476@from-internal-5854;2", "custom=SIP/sip-noname.nodomain.top") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:15] ExecIf("Local/592476@from-internal-5854;2", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:16] Macro("Local/592476@from-internal-5854;2", "dialout-trunk-predial-hook,") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("Local/592476@from-internal-5854;2", "") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:17] GotoIf("Local/592476@from-internal-5854;2", "0?bypass,1") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:18] GotoIf("Local/592476@from-internal-5854;2", "0?customtrunk") in new stack
[Aug 31 10:01:19] VERBOSE[8579] pbx.c:     -- Executing [s@macro-dialout-trunk:19] Dial("Local/592476@from-internal-5854;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/592476@from-internal-5854;2
[Aug 31 10:01:20] VERBOSE[8578] app_dial.c:     -- Local/592476@from-internal-5854;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 [s@macro-dialout-trunk:20] NoOp("Local/592476@from-internal-5854;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 [s@macro-dialout-trunk:21] Goto("Local/592476@from-internal-5854;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 [s-BUSY@macro-dialout-trunk:1] NoOp("Local/592476@from-internal-5854;2", "Dial failed due to trunk reporting BUSY - giving up") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [s-BUSY@macro-dialout-trunk:2] PlayTones("Local/592476@from-internal-5854;2", "busy") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [s-BUSY@macro-dialout-trunk:3] Busy("Local/592476@from-internal-5854;2", "20") in new stack
[Aug 31 10:01:21] VERBOSE[8578] app_dial.c:     -- Local/592476@from-internal-5854;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 [h@from-internal:1] Macro("SIP/2476-00000005", "hangupcall") in new stack
[Aug 31 10:01:21] VERBOSE[8578] pbx.c:     -- Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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/592476@from-internal-5854;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/592476@from-internal-5854;2'
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [h@from-internal:1] Macro("Local/592476@from-internal-5854;2", "hangupcall") in new stack
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("Local/592476@from-internal-5854;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 [s@macro-hangupcall:4] GotoIf("Local/592476@from-internal-5854;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 [s@macro-hangupcall:7] GotoIf("Local/592476@from-internal-5854;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 [s@macro-hangupcall:9] Hangup("Local/592476@from-internal-5854;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/592476@from-internal-5854;2' in macro 'hangupcall'
[Aug 31 10:01:21] VERBOSE[8579] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/592476@from-internal-5854;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 [325@from-internal:6] Playback("SIP/202-000000a4", "silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer") in new stack