[Home]

Summary:DAHLIN-00200: Outbound call hits dialplan before called party answers
Reporter:Jeevan Reddy Gaddam (jeevan7302)Labels:
Date Opened:2010-07-13 08:49:28Date Closed:2011-07-20 03:24:38
Priority:MajorRegression?No
Status:Closed/CompleteComponents:wctdm
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Using asterisk 1.6.1.20, DAHDI Version: 2.3.0.1 and Cent OS 5. Outbound call hitting a dialplan before called party answers.

Can you please provide information about this issue.



****** ADDITIONAL INFORMATION ******

[root@localhost asterisk]# dahdi_cfg -vvvvvvvvvvvvvvvvv
DAHDI Tools Version - 2.3.0

DAHDI Version: 2.3.0.1
Echo Canceller(s): MG2
Configuration
======================


Channel map:

Channel 01: FXS Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 01)
Channel 02: FXS Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 02)
Channel 03: FXS Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 03)
Channel 04: FXS Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 04)
Channel 05: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 05)
Channel 06: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 06)
Channel 08: FXO Kewlstart (Default) (Echo Canceler: mg2) (Slaves: 08)

7 channels to configure.

Setting echocan for channel 1 to mg2
Setting echocan for channel 2 to mg2
Setting echocan for channel 3 to mg2
Setting echocan for channel 4 to mg2
Setting echocan for channel 5 to mg2
Setting echocan for channel 6 to mg2
Setting echocan for channel 8 to mg2


localhost*CLI> originate Dahdi/1/9989784567 extension 201@sip
[Jul 14 00:25:28] DEBUG[25749]: chan_dahdi.c:9664 dahdi_request: Using channel 1
[Jul 14 00:25:28] DEBUG[25749]: dsp.c:468 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jul 14 00:25:28] DEBUG[25749]: dsp.c:468 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jul 14 00:25:28] DEBUG[25749]: devicestate.c:466 devstate_event: device 'DAHDI/1-1' state '2'
[Jul 14 00:25:28] DEBUG[25749]: chan_dahdi.c:2582 dahdi_call: Ignore possible polarity reversal on line seizure
[Jul 14 00:25:28] DEBUG[25749]: chan_dahdi.c:2627 dahdi_call: Dialing '9989784567'
[Jul 14 00:25:28] DEBUG[25749]: chan_dahdi.c:2705 dahdi_call: Deferring dialing...
[Jul 14 00:25:28] DEBUG[25604]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[Jul 14 00:25:28] DEBUG[25604]: devicestate.c:486 do_state_change: Changing state for DAHDI/1 - state 2 (In use)
[Jul 14 00:25:28] DEBUG[25604]: devicestate.c:466 devstate_event: device 'DAHDI/1' state '2'
[Jul 14 00:25:28] DEBUG[25621]: app_queue.c:808 handle_statechange: Device 'DAHDI/1-1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 14 00:25:28] DEBUG[25621]: app_queue.c:808 handle_statechange: Device 'DAHDI/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 14 00:25:28] DEBUG[25749]: chan_dahdi.c:5646 __dahdi_exception: Exception on 17, channel 1
[Jul 14 00:25:28] DEBUG[25749]: chan_dahdi.c:4711 dahdi_handle_event: Got event Hook Transition Complete(12) on channel 1 (index 0)
[Jul 14 00:25:28] DEBUG[25749]: chan_dahdi.c:5448 dahdi_handle_event: Sent deferred digit string: T9989784567w
[Jul 14 00:25:31] DEBUG[25749]: chan_dahdi.c:5646 __dahdi_exception: Exception on 17, channel 1
[Jul 14 00:25:31] DEBUG[25749]: chan_dahdi.c:4711 dahdi_handle_event: Got event Dial Complete(9) on channel 1 (index 0)
[Jul 14 00:25:31] DEBUG[25749]: chan_dahdi.c:2027 dahdi_enable_ec: Enabled echo cancellation on channel 1
[Jul 14 00:25:31] DEBUG[25749]: chan_dahdi.c:4783 dahdi_handle_event: Done dialing, but waiting for progress detection before doing more...
[Jul 14 00:25:31] DEBUG[25749]: dsp.c:1057 __ast_dsp_call_progress: Stop state 0 with duration 19
[Jul 14 00:25:31] DEBUG[25749]: dsp.c:1058 __ast_dsp_call_progress: Start state 3
[Jul 14 00:25:31] DEBUG[25751]: pbx.c:3203 pbx_extension_helper: Launching 'Answer'
   -- Executing [201@sip:1] Answer("DAHDI/1-1", "") in new stack
[Jul 14 00:25:31] DEBUG[25751]: pbx.c:3203 pbx_extension_helper: Launching 'Playback'
   -- Executing [201@sip:2] Playback("DAHDI/1-1", "hello-world") in new stack
[Jul 14 00:25:31] DEBUG[25751]: channel.c:3708 set_format: Set channel DAHDI/1-1 to write format gsm
[Jul 14 00:25:31] DEBUG[25751]: channel.c:2407 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
   -- <DAHDI/1-1> Playing 'hello-world.gsm' (language 'en')
[Jul 14 00:25:31] DEBUG[25604]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[Jul 14 00:25:31] DEBUG[25604]: devicestate.c:486 do_state_change: Changing state for DAHDI/1 - state 2 (In use)
[Jul 14 00:25:31] DEBUG[25604]: devicestate.c:466 devstate_event: device 'DAHDI/1' state '2'
[Jul 14 00:25:31] DEBUG[25621]: app_queue.c:808 handle_statechange: Device 'DAHDI/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jul 14 00:25:33] DEBUG[25751]: channel.c:2407 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul 14 00:25:33] DEBUG[25751]: channel.c:2407 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul 14 00:25:33] DEBUG[25751]: channel.c:2407 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul 14 00:25:33] DEBUG[25751]: channel.c:3708 set_format: Set channel DAHDI/1-1 to write format ulaw
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3203 pbx_extension_helper: Launching 'Hangup'
   -- Executing [201@sip:3] Hangup("DAHDI/1-1", "") in new stack
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3813 __ast_pbx_run: Spawn extension (sip,201,3) exited non-zero on 'DAHDI/1-1'
 == Spawn extension (sip, 201, 3) exited non-zero on 'DAHDI/1-1'
[Jul 14 00:25:33] DEBUG[25751]: channel.c:1634 ast_softhangup_nolock: Soft-Hanging up channel 'DAHDI/1-1'
[Jul 14 00:25:33] DEBUG[25751]: channel.c:1739 ast_hangup: Hanging up channel 'DAHDI/1-1'
[Jul 14 00:25:33] DEBUG[25751]: chan_dahdi.c:3386 dahdi_hangup: dahdi_hangup(DAHDI/1-1)
[Jul 14 00:25:33] DEBUG[25751]: chan_dahdi.c:3422 dahdi_hangup: Hangup: channel: 1 index = 0, normal = 17, callwait = -1, thirdcall = -1
[Jul 14 00:25:33] DEBUG[25751]: chan_dahdi.c:2062 dahdi_disable_ec: Disabled echo cancellation on channel 1
[Jul 14 00:25:33] DEBUG[25751]: chan_dahdi.c:3895 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/1-1
[Jul 14 00:25:33] DEBUG[25751]: chan_dahdi.c:1997 update_conf: Updated conferencing on 1, with 0 conference users
   -- Hungup 'DAHDI/1-1'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '2010-07-14 00:25:28'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is 'sip'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is 'DAHDI/1-1'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is 'Hangup'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '5'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '2'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '1279047328.1'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jul 14 00:25:33] DEBUG[25751]: pbx.c:3035 pbx_substitute_variables_helper_full: Function result is '(null)'
[Jul 14 00:25:33] DEBUG[25751]: cdr_sqlite3_custom.c:265 write_cdr: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2010-07-14 00:25:28','','sip','DAHDI/1-1','','Hangup','','5','2','ANSWERED','DOCUMENTATION','','1279047328.1','','')
[Jul 14 00:25:33] DEBUG[25604]: devicestate.c:368 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[Jul 14 00:25:33] DEBUG[25604]: devicestate.c:486 do_state_change: Changing state for DAHDI/1 - state 0 (Unknown)
[Jul 14 00:25:33] DEBUG[25604]: devicestate.c:466 devstate_event: device 'DAHDI/1' state '0'
[Jul 14 00:25:33] DEBUG[25621]: app_queue.c:808 handle_statechange: Device 'DAHDI/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
Comments:By: David Woolley (davidw) 2010-07-13 09:54:45

There doesn't seem to be evidence of a bug here.  It looks much more likely that answer supervision is misconfigured and/or unavailable.  You probaby need to follow this up on a support channel, at least until you have evidence of a bug.
By: Shaun Ruffell (sruffell) 2010-07-13 17:31:38

I'll second davidw's comment.  I'm going to close this out.  Please feel free to reopen if you have evidence that your configuration is correct and this is a bug.
By: Jeevan Reddy Gaddam (jeevan7302) 2010-07-14 03:05:33

tried all the combination , but still getting the same problem.

country = in in indication.conf

dmesg
-------
dahdi: Registered tone zone 28 (India)
Freed a Wildcard
Freed a Wildcard
dahdi: Telephony Interface Unloaded
dahdi: Telephony Interface Registered on major 196
dahdi: Version: 2.3.0.1
Freshmaker version: 71
Freshmaker passed register test
Module 0: Installed -- AUTO FXO (INDIA mode)
Module 1: Installed -- AUTO FXO (INDIA mode)
Module 2: Installed -- AUTO FXO (INDIA mode)
Module 3: Installed -- AUTO FXO (INDIA mode)
Found a Wildcard TDM: Wildcard TDM400P REV E/F (4 modules)
Freshmaker version: 71
Freshmaker passed register test
Module 0: Installed -- AUTO FXS/DPO
Module 1: Installed -- AUTO FXS/DPO
Module 2: Not installed
Module 3: Installed -- AUTO FXS/DPO
Found a Wildcard TDM: Wildcard TDM400P REV E/F (3 modules)
dahdi: Registered tone zone 0 (United States / North America)
dahdi_echocan_mg2: Registered echo canceler 'MG2'
dahdi: Registered tone zone 28 (India)

chan_dahdi.conf
----------------
[channels]
context=default
usecallerid=yes
hidecallerid=no
callwaiting=yes
usecallingpres=yes
callwaitingcallerid=yes
threewaycalling=yes
transfer=yes
canpark=yes
cancallforward=yes
callreturn=yes
echocancel=yes
echocancelwhenbridged=yes
relaxdtmf=yes
rxgain=1.0
txgain=0.0
;progzone=in
;tonezone=in
;group=1
;callgroup=1
;pickupgroup=1
immediate=no
callprogress = yes
answeronpolarityswitch=yes
;hanguponpolarityswitch=yes
;polarityonanswerdelay=600ms

#include dahdi-channels.conf

dahdi-channels.conf
--------------------
; Autogenerated by /usr/sbin/dahdi_genconf on Tue Jul 13 20:12:03 2010
; If you edit this file and execute /usr/sbin/dahdi_genconf again,
; your manual changes will be LOST.
; Dahdi Channels Configurations (chan_dahdi.conf)
;
; This is not intended to be a complete chan_dahdi.conf. Rather, it is intended
; to be #include-d by /etc/chan_dahdi.conf that will include the global settings
;

; Span 1: WCTDM/4 "Wildcard TDM400P REV E/F Board 5" (MASTER)
;;; line="1 WCTDM/4/0 FXSKS"
signalling=fxs_ks
callerid=asreceived
group=2
context=incoming
channel => 1
tonezone = in
progzone = in
;callerid=
;group=
;context=default

;;; line="2 WCTDM/4/1 FXSKS"
signalling=fxs_ks
callerid=asreceived
group=2
context=incoming
channel => 2
;callerid=
;group=
;context=default

;;; line="3 WCTDM/4/2 FXSKS"
signalling=fxs_ks
callerid=asreceived
group=2
context=incoming
channel => 3
;callerid=
;group=
;context=default

;;; line="4 WCTDM/4/3 FXSKS"
signalling=fxs_ks
callerid=asreceived
group=2
context=incoming
channel => 4
;callerid=
;group=
;context=default


; Span 2: WCTDM/4 "Wildcard TDM400P REV E/F Board 5"
;;; line="5 WCTDM/4/0 FXOKS"
signalling=fxo_ks
callerid="Channel 5" <4005>
mailbox=4005
group=5
context=sip
channel => 5
;callerid=
;mailbox=
;group=
;context=default

;;; line="6 WCTDM/4/1 FXOKS"
signalling=fxo_ks
callerid="Channel 6" <4006>
mailbox=4006
group=5
context=sip
channel => 6
;callerid=
;mailbox=
;group=
;context=default

;;; line="8 WCTDM/4/3 FXOKS"
signalling=fxo_ks
callerid="Channel 8" <4008>
mailbox=4008
group=5
context=sip
channel => 8
;callerid=
;mailbox=
;group=
;context=default

system.conf
-----------
# Autogenerated by /usr/sbin/dahdi_genconf on Tue Jul 13 20:12:03 2010
# If you edit this file and execute /usr/sbin/dahdi_genconf again,
# your manual changes will be LOST.
# Dahdi Configuration File
#
# This file is parsed by the Dahdi Configurator, dahdi_cfg
#
# Span 1: WCTDM/4 "Wildcard TDM400P REV E/F Board 5" (MASTER)
fxsks=1
echocanceller=mg2,1
fxsks=2
echocanceller=mg2,2
fxsks=3
echocanceller=mg2,3
fxsks=4
echocanceller=mg2,4

# Span 2: WCTDM/4 "Wildcard TDM400P REV E/F Board 5"
fxoks=5
echocanceller=mg2,5
fxoks=6
echocanceller=mg2,6
# channel 7, WCTDM/4/2, no module.
fxoks=8
echocanceller=mg2,8

# Global data

loadzone = in
defaultzone = in

By: Jeevan Reddy Gaddam (jeevan7302) 2010-07-22 07:32:15

Any Updates ?
By: David Woolley (davidw) 2010-07-22 07:36:03

You need to provide a low level dahdi trace to prove that there is not actually a polarity reversal and that dahdi is responding as though there had been one.
By: Jeevan Reddy Gaddam (jeevan7302) 2010-07-22 07:39:24

How can i do a low level trace ?
By: David Woolley (davidw) 2010-07-22 07:56:24

I only know general principles, so I'll leave it to someone else to specify exactly what options are needed to get good debugging output.  In general, make sure core set debug is appropriately set and make sure logger.conf arranges for debug output to be captured.  You may also have to set debugging options on the kernel module.
By: Jeevan Reddy Gaddam (jeevan7302) 2010-07-22 08:01:43

i set debugging level to 20 using core set debug 20 at the CLI, Do i need to set any ?
By: David Woolley (davidw) 2010-07-22 10:41:04

If you have got it to the right level and your telephony supplier is providing answer supervision, you will be able to see a relevant event when the call is answered.  If you don't, either they are not providing answer supervision, or you haven't got enough debugging enabled.  To do what you want to do, they must provide some form of answer supervision.

I would also check the log from startup, to make sure there are no errors relating to the line relating to enabling answer supervision.
By: Alec Davis (alecdavis) 2010-07-30 17:27:27

to enable wctdm debug

in /etc/modprobe.d/dahdi set
options wctdm debug=1

restart dahdi and asterisk.

Then monitor /var/log/kern.log while making a call

on a TDM800P I get
wctdm24xxp 0000:05:04.0: 52630528 Polarity reversed (-1 -> 1)

If you find you have polarity reversals happening, then I'd set

in /etc/asterisk/chan_dahdi.conf
callprogress=no