[Asterisk-Users] Asterisk-to-IVR Problem

Mon Aug 8 08:21:20 MST 2005

This was submitted to the Dev list last week, but there was no response, and 
perhaps it wasn't the right group.

I am developing an application in which I need asterisk to pass on an 
incoming call to a separate IVR server. The problem is that asterisk appears 
to hang up while the IVR is playing back a sequence of recorded voice and 
systhesized voice prompts.

My setup is:

Analog line ->X100P->asterisk->TDM10B- >phone cord->Dialogic analog 
port->IVR system. 

Asterisk should dial the IVR system, which should answer and play back its 
IVR scenario script to the caller. However, when a call comes in, asterisk 
answers on Zap1-1 and dials Zap2-1. The IVR system answers the call and 
begins to play back its scenario. After 5 to 15 seconds, asterisk apparently 
senses an on-hook condition (exception 17?) and disconnects the connection 
bridge. The logs on the IVR system shows that it is not initially aware of 
the hangup, and continues playing its scenario.

Going to an analog phone in the TDM10B instead of the IVR system appears to 
work OK, with the exception that asterisk is still sending dial tones when 
the analog phone is answered. The phone stays connected to asterisk until it 
really does hang up.

What causes the hangup? What generates the exception? I have looked at the 
chan_zap.c code and can not see how zt_exception gets into the picture. Is 
there a TDMF incompatibility problem? Is this a case where DAX should be 
used?

My config files and sample debug output are given below. Thanks for anyone's 
help.

Rollin Weeks

#
# Zaptel Configuration File
#
# This file is parsed by the Zaptel Configurator, ztcfg
#
fxsks=1 # For the X100P
fxoks=2 # For the TDM400P (TDM10B)
#
loadzone = us
#
defaultzone=us

----------------

;
; Zapata telephony interface
;
; Configuration file

[channels]
;
language=en

context=incoming

switchtype=national

signalling=fxs_ks

rxwink=300 ; Atlas seems to use long (250ms) winks

; Whether or not to use caller ID
;
usecallerid=asreceived

; Whether or not to hide outgoing caller ID (Override with *67 or *82)
;
hidecallerid=no
;
callwaitingcallerid=yes

; for default voicemail context, the example below is fine:
;
mailbox=1234

echocancel=yes

; If you are having trouble with DTMF detection, you can relax the
; DTMF detection parameters. Relaxing them may make the DTMF detector
; more likely to have "talkoff" where DTMF is detected when it
; shouldn't be.
;
relaxdtmf=yes

; You may also set the default receive and transmit gains (in dB)
;
rxgain=0.0
txgain=0.0

immediate=no

; On trunk interfaces (FXS) and E&M interfaces (E&M, Wink, Feature Group D
; etc, it can be useful to perform busy detection either in an effort to 
; detect hangup or for detecting busies
;
busydetect=yes
;
; If busydetect is enabled, is also possible to specify how many
; busy tones to wait before hanging up. The default is 4, but
; better results can be achieved if set to 6 or even 8. Mind that
; higher the number, more time is needed to hangup a channel, but
; lower is probability to get random hangups
;
busycount=40

; Select which class of music to use for music on hold. If not specified
; then the default will be used.
;
musiconhold=default

channel => 1

signalling=fxo_ks

context=internal

channel => 2

----------------

; Home grown extension file
[globals]
;RECEPTIONIST=Zap/1
;

[incoming]
exten => s,1,Wait(1)
exten => s,2,Answer()
exten => s,3,Playback(demo-congrats) ; Plays the demo-congrats file after 
answering the line
exten => s,4,Dial,Zap/2/1000\20
exten => s,5,Hangup

[internal]
exten => 1000,1,Answer()
exten => 1000,2,Wait(2)
exten => 1000,3,Hangup 

-------------------

-- Starting simple switch on 'Zap/1-1'
Urgent handler
Aug 4 15:43:39 DEBUG[5059]: pbx.c:1274 pbx_extension_helper: Launching 
'Wait'
-- Executing Wait("Zap/1-1", "1") in new stack
Urgent handler
Aug 4 15:43:40 DEBUG[5059]: pbx.c:1274 pbx_extension_helper: Launching 
'Answer'
-- Executing Answer("Zap/1-1", "") in new stack
Urgent handler
Aug 4 15:43:40 DEBUG[5059]: chan_zap.c:2301 zt_answer: Took Zap/1-1 off hook
Aug 4 15:43:40 DEBUG[5059]: chan_zap.c:1231 zt_enable_ec: Enabled echo 
cancellation on channel 1
Aug 4 15:43:40 DEBUG[5059]: chan_zap.c:1250 zt_train_ec: No echo training 
requested
Aug 4 15:43:40 DEBUG[5059]: pbx.c:1274 pbx_extension_helper: Launching 
'Playback'
-- Executing Playback("Zap/1-1", "demo-congrats") in new stack
Urgent handler
Aug 4 15:43:40 DEBUG[5059]: channel.c:1719 ast_set_write_format: Set channel 
Zap/1-1 to write format gsm
Aug 4 15:43:40 DEBUG[5059]: channel.c:1128 ast_settimeout: Scheduling timer 
at 160 sample intervals
-- Playing 'demo-congrats' (language 'en')
Urgent handler
Aug 4 15:44:08 DEBUG[5059]: channel.c:1128 ast_settimeout: Scheduling timer 
at 0 sample intervals
Aug 4 15:44:08 DEBUG[5059]: channel.c:1128 ast_settimeout: Scheduling timer 
at 0 sample intervals
Aug 4 15:44:08 DEBUG[5059]: channel.c:1719 ast_set_write_format: Set channel 
Zap/1-1 to write format ulaw
Aug 4 15:44:08 DEBUG[5059]: pbx.c:1274 pbx_extension_helper: Launching 
'Dial'
-- Executing Dial("Zap/1-1", "Zap/2/1000\20") in new stack
Aug 4 15:44:08 DEBUG[5059]: chan_zap.c:6907 zt_request: Using channel 2
Aug 4 15:44:08 DEBUG[5059]: chan_zap.c:1563 zt_call: FXO: setup deferred 
dialstring: 1000\20
-- Called 2/1000\20
Aug 4 15:44:08 DEBUG[5059]: channel.c:1752 ast_set_read_format: Set channel 
Zap/2-1 to read format ulaw
Aug 4 15:44:08 DEBUG[5059]: channel.c:1719 ast_set_write_format: Set channel 
Zap/1-1 to write format ulaw
Aug 4 15:44:08 DEBUG[5059]: channel.c:1719 ast_set_write_format: Set channel 
Zap/2-1 to write format ulaw
Aug 4 15:44:08 DEBUG[5059]: channel.c:1752 ast_set_read_format: Set channel 
Zap/1-1 to read format ulaw
Urgent handler
Urgent handler
Aug 4 15:44:08 DEBUG[5059]: chan_zap.c:4187 zt_write: Dropping frame since 
I'm still dialing on Zap/2-1...
-- Zap/2-1 is ringing

*****

-- Zap/2-1 is ringing
Urgent handler
Aug 4 15:44:08 DEBUG[5059]: chan_zap.c:4187 zt_write: Dropping frame since 
I'm still dialing on Zap/2-1...
Aug 4 15:44:08 DEBUG[5059]: chan_zap.c:4187 zt_write: Dropping frame since 
I'm still dialing on Zap/2-1...

******

ug 4 15:44:10 DEBUG[5059]: chan_zap.c:4187 zt_write: Dropping frame since 
I'm still dialing on Zap/2-1...
Aug 4 15:44:10 DEBUG[5059]: chan_zap.c:4187 zt_write: Dropping frame since 
I'm still dialing on Zap/2-1...
Aug 4 15:44:10 DEBUG[5059]: chan_zap.c:3786 __zt_exception: Exception on 17, 
channel 2
Aug 4 15:44:10 DEBUG[5059]: chan_zap.c:3089 zt_handle_event: Got event 
Ringer Off(11) on channel 2 (index 0)
-- Zap/2-1 is ringing
Urgent handler
Aug 4 15:44:10 DEBUG[5059]: chan_zap.c:4187 zt_write: Dropping frame since 
I'm still dialing on Zap/2-1...

******

ug 4 15:44:12 DEBUG[5059]: chan_zap.c:3786 __zt_exception: Exception on 17, 
channel 2
Aug 4 15:44:12 DEBUG[5059]: chan_zap.c:3089 zt_handle_event: Got event 
Ring/Answered(2) on channel 2 (index 0)
Aug 4 15:44:12 DEBUG[5059]: chan_zap.c:1231 zt_enable_ec: Enabled echo 
cancellation on channel 2
Aug 4 15:44:12 DEBUG[5059]: chan_zap.c:1250 zt_train_ec: No echo training 
requested
Aug 4 15:44:12 DEBUG[5059]: chan_zap.c:3352 zt_handle_event: channel 2 
answered
Aug 4 15:44:12 DEBUG[5059]: chan_zap.c:3372 zt_handle_event: Sent FXO 
deferred digit string: Tw1000\20
Aug 4 15:44:12 DEBUG[5059]: chan_zap.c:4187 zt_write: Dropping frame since 
I'm still dialing on Zap/2-1...

******

Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:4187 zt_write: Dropping frame since 
I'm still dialing on Zap/2-1...
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:3786 __zt_exception: Exception on 17, 
channel 2
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:3089 zt_handle_event: Got event Dial 
Complete(9) on channel 2 (index 0)
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:1215 zt_enable_ec: Echo cancellation 
already on
Aug 4 15:44:13 DEBUG[5059]: channel.c:1366 ast_read: Dropping duplicate 
answer!
-- Zap/2-1 answered Zap/1-1
Aug 4 15:44:13 DEBUG[5059]: channel.c:1752 ast_set_read_format: Set channel 
Zap/1-1 to read format ulaw
Aug 4 15:44:13 DEBUG[5059]: channel.c:1719 ast_set_write_format: Set channel 
Zap/2-1 to write format ulaw
Aug 4 15:44:13 DEBUG[5059]: channel.c:1719 ast_set_write_format: Set channel 
Zap/1-1 to write format ulaw
Aug 4 15:44:13 DEBUG[5059]: channel.c:1752 ast_set_read_format: Set channel 
Zap/2-1 to read format ulaw
-- Attempting native bridge of Zap/1-1 and Zap/2-1
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:2677 zt_bridge: master: 1, slave: 2, 
nothingok: 0
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:2692 zt_bridge: Stoping tones on 1/0 
talking to 2/0
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:2704 zt_bridge: Stoping tones on 2/0 
talking to 1/0
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:1263 zt_disable_ec: disabled echo 
cancellation on channel 1
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:1263 zt_disable_ec: disabled echo 
cancellation on channel 2
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:2567 zt_link: Making 2 slave to 
master 1 at 0
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:1061 conf_add: Added 17 to conference 
9/1
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:1061 conf_add: Added 15 to conference 
9/2
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:1206 update_conf: Updated 
conferencing on 1, with 0 conference users
Aug 4 15:44:13 DEBUG[5059]: chan_zap.c:1206 update_conf: Updated 
conferencing on 2, with 0 conference users
Urgent handler
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:3786 __zt_exception: Exception on 17, 
channel 2
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:3089 zt_handle_event: Got event On 
hook(1) on channel 2 (index 0)
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1263 zt_disable_ec: disabled echo 
cancellation on channel 2
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:2511 zt_unlink: Unlinking slave 2 
from 1
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1093 conf_del: Removed 17 from 
conference 9/1
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1093 conf_del: Removed 15 from 
conference 9/2
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1206 update_conf: Updated 
conferencing on 1, with 0 conference users
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1231 zt_enable_ec: Enabled echo 
cancellation on channel 1
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1231 zt_enable_ec: Enabled echo 
cancellation on channel 2
Aug 4 15:44:26 DEBUG[5059]: channel.c:2640 ast_channel_bridge: Returning 
from native bridge, channels: Zap/1-1, Zap/2-1
Aug 4 15:44:26 DEBUG[5059]: channel.c:739 ast_hangup: Hanging up channel 
'Zap/2-1'
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1959 zt_hangup: zt_hangup(Zap/2-1)
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1987 zt_hangup: Hangup: channel: 2 
index = 0, normal = 17, callwait = -1, thirdcall = -1
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1263 zt_disable_ec: disabled echo 
cancellation on channel 2
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:2390 zt_setoption: Set option TDD 
MODE, value: OFF(0) on Zap/2-1
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1206 update_conf: Updated 
conferencing on 2, with 0 conference users
-- Hungup 'Zap/2-1'
Aug 4 15:44:26 DEBUG[5059]: app_dial.c:1054 dial_exec: Exiting with 
DIALSTATUS=ANSWER.
Aug 4 15:44:26 DEBUG[5059]: pbx.c:1851 ast_pbx_run: Spawn extension 
(incoming,s,4) exited non-zero on 'Zap/1-1'
Aug 4 15:44:26 DEBUG[5059]: channel.c:739 ast_hangup: Hanging up channel 
'Zap/1-1'
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1959 zt_hangup: zt_hangup(Zap/1-1)
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1987 zt_hangup: Hangup: channel: 1 
index = 0, normal = 15, callwait = -1, thirdcall = -1
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1263 zt_disable_ec: disabled echo 
cancellation on channel 1
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:2390 zt_setoption: Set option TDD 
MODE, value: OFF(0) on Zap/1-1
Aug 4 15:44:26 DEBUG[5059]: chan_zap.c:1206 update_conf: Updated 
conferencing on 1, with 0 conference users
-- Hungup 'Zap/1-1'
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-users/attachments/20050808/49279004/attachment.htm