I have been working an issue on a PIF 1.2 configuration.
I have 24 inbound Zap Channels (POTS). I used the “ZAP Channel DIDs” function to set up DIDs based on the lead number in each of four hunt groups spead over the 24 channels. Then I added “Inbound Routes” for these numbers.
This all works Great !!
Issue has to do with a route that results in a Congestion() as a result of “DIALSTATUS=CHANUNAVAIL”. The code that get’s executed in this stack never actually executes an Answer() so the calling party never hears the Congestion tones. An ever after the 10 sec timeout and "Hangup ‘Zap/48-1’ the caller just hears ringing, and infact Asterisk will just start over if the Caller does not get frustrated and hang up.
Anyone else see this? Anyone working with this code in detail that can verify this ?
TIA.
[Aug 13 16:25:44] VERBOSE[13056] logger.c: – Executing [s-CHANUNAVAIL@macro-exten-vm:1] PlayTones(“Zap/48-1”, “congestion”) in new stack
[Aug 13 16:26:13] VERBOSE[13062] logger.c: – Starting simple switch on ‘Zap/48-1’
plindheimer
August 13, 2008, 9:37pm
2
a bit more of the dialplan that shows how it got there would be useful
Here is a long Code trace –
At the end you see a Hungup/ ZAP/48-1 and then another Starting Switch.
Well, there was no answer on the calling phone, just a continuous ring through three cycles of this loop.
The congestion issue is not a problem, I epected it, just did not expect that the incoming call would never get answered.
[Aug 13 22:19:29] VERBOSE[15550] logger.c: -- Starting simple switch on 'Zap/48-1'
[Aug 13 22:19:33] NOTICE[15550] chan_zap.c: Got event 18 (Ring Begin)...
[Aug 13 22:19:35] NOTICE[15550] chan_zap.c: Got event 2 (Ring/Answered)...
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:1] NoOp("Zap/48-1", "Entering from-zaptel with DID
== ") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:2] Ringing("Zap/48-1", "") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:3] Set("Zap/48-1", "DID=s") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:4] NoOp("Zap/48-1", "DID is now s") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:5] GotoIf("Zap/48-1", "1?zapok:notzap") in new stac
k
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Goto (from-zaptel,s,8)
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:8] NoOp("Zap/48-1", "Is a Zaptel Channel") in new s
tack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:9] Set("Zap/48-1", "CHAN=48-1") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:10] Set("Zap/48-1", "CHAN=48") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@from-zaptel:11] Macro("Zap/48-1", "from-zaptel-48|s|1") in new
stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-from-zaptel-48:1] NoOp("Zap/48-1", "Entering macro-from-z
aptel-48 with DID = s and setting to: 4041231234") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Noop
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-from-zaptel-48:2] Set("Zap/48-1", "__FROM_DID=4041231234"
) in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-from-zaptel-48:3] Goto("Zap/48-1", "from-trunk|4041231234
|1") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Goto (from-trunk,4041231234,1)
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Goto
[Aug 13 22:19:35] VERBOSE[15550] logger.c: == Channel 'Zap/48-1' jumping out of macro 'from-zaptel-48'
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:1] Set("Zap/48-1", "__FROM_DID=4041231234")
in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:2] Gosub("Zap/48-1", "cidlookup|cidlookup_1
|1") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [cidlookup_1@cidlookup:1] Set("Zap/48-1", "CALLERID(name)=") in ne
w stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [cidlookup_1@cidlookup:2] Return("Zap/48-1", "") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:3] Gosub("Zap/48-1", "app-blacklist-check|s
|1") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@app-blacklist-check:1] LookupBlacklist("Zap/48-1", "") in new s
tack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@app-blacklist-check:2] GotoIf("Zap/48-1", "0?blacklisted") in n
ew stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@app-blacklist-check:3] Return("Zap/48-1", "") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:4] GotoIf("Zap/48-1", "0 ?cidok") in new st
ack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:5] Set("Zap/48-1", "CALLERID(name)=") in ne
w stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:6] NoOp("Zap/48-1", "CallerID is "" <>") in
new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:7] Set("Zap/48-1", "__CALLINGPRES_SV=allowe
d_not_screened") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:8] SetCallerPres("Zap/48-1", "allowed_not_s
creened") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [4041231234@from-trunk:9] Goto("Zap/48-1", "from-did-direct|2199|1
") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Goto (from-did-direct,2199,1)
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [2199@from-did-direct:1] Macro("Zap/48-1", "exten-vm|novm|2199") i
n new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:1] Macro("Zap/48-1", "user-callerid") in new sta
ck
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:1] NoOp("Zap/48-1", "user-callerid: ") in
new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Noop
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:2] Set("Zap/48-1", "AMPUSER=") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:3] GotoIf("Zap/48-1", "0?report") in new st
ack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GotoIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:4] ExecIf("Zap/48-1", "1|Set|REALCALLERIDNU
M=") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: ExecIf
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Last app: Set|REALCALLERIDNUM=
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:5] NoOp("Zap/48-1", "REALCALLERIDNUM is ")
in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Noop
[Aug 13 22:19:35] DEBUG[15550] func_db.c: DB: DEVICE//user not found in database.
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:6] Set("Zap/48-1", "AMPUSER=") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] DEBUG[15550] func_db.c: DB: AMPUSER//cidname not found in database.
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:7] Set("Zap/48-1", "AMPUSERCIDNAME=") in ne
w stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:8] GotoIf("Zap/48-1", "1?report") in new st
ack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Goto (macro-user-callerid,s,13)
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GotoIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:13] NoOp("Zap/48-1", "TTL: ARG1: novm") in
new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Noop
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:14] GotoIf("Zap/48-1", "0?continue") in new
stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GotoIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:15] Set("Zap/48-1", "__TTL=64") in new stac
k
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:16] GotoIf("Zap/48-1", "1?continue") in new
stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Goto (macro-user-callerid,s,23)
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GotoIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-user-callerid:23] NoOp("Zap/48-1", "Using CallerID "" <>"
) in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Noop
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Macro
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:2] Set("Zap/48-1", "RingGroupMethod=none") in ne
w stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:3] Set("Zap/48-1", "VMBOX=novm") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:4] Set("Zap/48-1", "EXTTOCALL=2199") in new stac
k
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] DEBUG[15550] func_db.c: DB: CFU/2199 not found in database.
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:5] Set("Zap/48-1", "CFUEXT=") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] DEBUG[15550] func_db.c: DB: CFB/2199 not found in database.
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:6] Set("Zap/48-1", "CFBEXT=") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:7] Set("Zap/48-1", "RT=""") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:8] Macro("Zap/48-1", "record-enable|2199|IN") in
new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("Zap/48-1", "0?2:4") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Goto (macro-record-enable,s,4)
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GotoIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-record-enable:4] AGI("Zap/48-1", "recordingcheck|20080813
-221935|1218680369.79") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Aug 13 22:19:35] VERBOSE[15550] logger.c: recordingcheck|20080813-221935|1218680369.79: Inbound recording not enabled
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- AGI Script recordingcheck completed, returning 0
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: AGI
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-record-enable:5] NoOp("Zap/48-1", "No recording needed")
in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Noop
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Macro
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:9] Macro("Zap/48-1", "dial||tr|2199") in new sta
ck
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-dial:1] GotoIf("Zap/48-1", "1?dial") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Goto (macro-dial,s,3)
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GotoIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-dial:3] AGI("Zap/48-1", "dialparties.agi") in new stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Aug 13 22:19:35] VERBOSE[15550] logger.c: dialparties.agi: Starting New Dialparties.agi
[Aug 13 22:19:35] VERBOSE[15555] logger.c: == Parsing '/etc/asterisk/manager.conf': [Aug 13 22:19:35] VERBOSE[15555] logger.
c: Found
[Aug 13 22:19:35] VERBOSE[15555] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Aug 13 22:19:35] VERBOSE[155
55] logger.c: Found
[Aug 13 22:19:35] VERBOSE[15555] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Aug 13 22:19:35] VERBOSE[15555]
logger.c: Found
[Aug 13 22:19:35] VERBOSE[15555] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Aug 13 22:19:35] VERBOSE[15550] logger.c: dialparties.agi: Caller ID name is 'unknown' number is 'unknown'
[Aug 13 22:19:35] VERBOSE[15550] logger.c: dialparties.agi: USE_CONFIRMATION: 'FALSE'
[Aug 13 22:19:35] VERBOSE[15550] logger.c: dialparties.agi: RINGGROUP_INDEX: ''
[Aug 13 22:19:35] VERBOSE[15550] logger.c: dialparties.agi: Methodology of ring is 'none'
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- dialparties.agi: Added extension 2199 to extension map
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- dialparties.agi: Extension 2199 cf is disabled
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- dialparties.agi: Extension 2199 do not disturb is disabled
[Aug 13 22:19:35] VERBOSE[15550] logger.c: > dialparties.agi: extnum 2199 has: cw: 1; hascfb: 0 [] hascfu: 0 []
[Aug 13 22:19:35] VERBOSE[15550] logger.c: > dialparties.agi: ExtensionState: 4
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- dialparties.agi: DbDel CALLTRACE/2199 - Caller ID is not defined
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- dialparties.agi: Filtered ARG3: 2199
[Aug 13 22:19:35] VERBOSE[15555] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- AGI Script dialparties.agi completed, returning 0
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: AGI
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-dial:7] Dial("Zap/48-1", "Local/7701231234@outbound-allro
utes||tr") in new stack
[Aug 13 22:19:35] NOTICE[15550] chan_local.c: No such extension/context 7701231234@outbound-allroutes creating local channel
[Aug 13 22:19:35] WARNING[15550] app_dial.c: Unable to create channel of type 'Local' (cause 0 - Unknown)
[Aug 13 22:19:35] VERBOSE[15550] logger.c: == Everyone is busy/congested at this time (1:0/0/1)
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Dial
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-dial:8] Set("Zap/48-1", "DIALSTATUS=CHANUNAVAIL") in new
stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Macro
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:10] Set("Zap/48-1", "SV_DIALSTATUS=CHANUNAVAIL")
in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:11] GosubIf("Zap/48-1", "0?docfu|1") in new stac
k
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GosubIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:12] GosubIf("Zap/48-1", "0?docfb|1") in new stac
k
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GosubIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:13] Set("Zap/48-1", "DIALSTATUS=CHANUNAVAIL") in
new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Set
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:14] NoOp("Zap/48-1", "Voicemail is novm") in new
stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: NoOp
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s@macro-exten-vm:15] GotoIf("Zap/48-1", "1?s-CHANUNAVAIL|1") in n
ew stack
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Goto (macro-exten-vm,s-CHANUNAVAIL,1)
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: GotoIf
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s-CHANUNAVAIL@macro-exten-vm:1] PlayTones("Zap/48-1", "congestion
") in new stack
[Aug 13 22:19:35] DEBUG[15550] app_macro.c: Executed application: Playtones
[Aug 13 22:19:35] VERBOSE[15550] logger.c: -- Executing [s-CHANUNAVAIL@macro-exten-vm:2] Congestion("Zap/48-1", "10") in n
ew stack
[Aug 13 22:19:41] WARNING[15550] chan_zap.c: Ring/Off-hook in strange state 7 on channel 48
[Aug 13 22:19:43] VERBOSE[15550] logger.c: == Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 2) exited non-zero on 'Zap/48-
1' in macro 'exten-vm'
[Aug 13 22:19:43] VERBOSE[15550] logger.c: == Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 2) exited non-zero on 'Zap/48-
1'
[Aug 13 22:19:43] VERBOSE[15550] logger.c: -- Hungup 'Zap/48-1'
[Aug 13 22:19:47] VERBOSE[15559] logger.c: – Starting simple switch on ‘Zap/48-1’