[Home]

Summary:ASTERISK-12359: Called Party's inband DTMF removed almost entirely with overlapdial and non-native bridging
Reporter:seb7 (seb7)Labels:
Date Opened:2008-07-10 09:50:53Date Closed:2009-01-22 14:14:21.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_dahdi
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:If you are using inband DTMF (tested on two Zap channels), and two bridged channels are not bridged natively (e.g. because you are using MixMonitor), and the incoming call used overlap dialing, and the Called Party tries sending DTMF, you hear a blip and perhaps a few milliseconds of tone, but not enough for the DTMF to be recognised by an application on the Calling Party side. (Asterisk does not recognize the DTMF either). It is being trimmed to within a millisecond of its life. Note, that the Calling Party's DTMF is OK.

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

A log is below, but I can also reproduce this without the "-- Starting simple switch" line if I remap "020" to e.g. my mobile. However this may mean more than 1 call going through at the same time, muddying the logs.

Core debug at level 0.

[Jul 10 15:38:15] VERBOSE[19719] logger.c: Asterisk Event Logger restarted
[Jul 10 15:38:15] VERBOSE[19719] logger.c: Asterisk Queue Logger restarted
[Jul 10 15:38:21] VERBOSE[19637] logger.c:     -- Accepting overlap call from '' to '020' on channel 0/7, span 1
[Jul 10 15:38:21] VERBOSE[19749] logger.c:     -- Starting simple switch on 'Zap/7-1'
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end '0' received on Zap/7-1, duration 0 ms
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end accepted without begin '0' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end passthrough '0' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end '5' received on Zap/7-1, duration 0 ms
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end accepted without begin '5' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end passthrough '5' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end '0' received on Zap/7-1, duration 0 ms
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end accepted without begin '0' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end passthrough '0' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end '0' received on Zap/7-1, duration 0 ms
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end accepted without begin '0' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end passthrough '0' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end '6' received on Zap/7-1, duration 0 ms
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end accepted without begin '6' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end passthrough '6' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end '0' received on Zap/7-1, duration 0 ms
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end accepted without begin '0' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end passthrough '0' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end '8' received on Zap/7-1, duration 0 ms
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end accepted without begin '8' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end passthrough '8' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end '4' received on Zap/7-1, duration 0 ms
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end accepted without begin '4' on Zap/7-1
[Jul 10 15:38:22] DTMF[19749] channel.c: DTMF end passthrough '4' on Zap/7-1
[Jul 10 15:38:25] VERBOSE[19749] logger.c:     -- Executing [02005006084@outbound:1] NoOp("Zap/7-1", "Inbound call for relay to Outbound call. CHANNEL(transfercapability) is SPEECH.") in new stack
[Jul 10 15:38:25] VERBOSE[19749] logger.c:     -- Executing [02005006084@outbound:2] NoOp("Zap/7-1", "CALLERID is . CALLERID(name) is . CALLERID(num) is . CALLINGPRES is -1.") in new stack
[Jul 10 15:38:25] VERBOSE[19749] logger.c:     -- Executing [02005006084@outbound:3] MixMonitor("Zap/7-1", "SebTest-1215700701.36.WAV|b") in new stack
[Jul 10 15:38:25] VERBOSE[19749] logger.c:     -- Executing [02005006084@outbound:4] Dial("Zap/7-1", "Zap/g2/MyMobileNumberCensored") in new stack
[Jul 10 15:38:25] VERBOSE[19749] logger.c:     -- Requested transfer capability: 0x00 - SPEECH
[Jul 10 15:38:25] VERBOSE[19749] logger.c:     -- Called g2/MyMobileNumberCensored
[Jul 10 15:38:25] VERBOSE[19750] logger.c:   == Begin MixMonitor Recording Zap/7-1
[Jul 10 15:38:32] VERBOSE[19749] logger.c:     -- Zap/32-1 is ringing
[Jul 10 15:38:35] DEBUG[19638] chan_zap.c: Echo cancellation already on
[Jul 10 15:38:35] VERBOSE[19749] logger.c:     -- Zap/32-1 answered Zap/7-1
[Jul 10 15:38:50] VERBOSE[19638] logger.c:     -- Channel 0/1, span 2 got hangup request, cause 16
[Jul 10 15:38:50] DEBUG[19749] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/32-1
[Jul 10 15:38:50] DEBUG[19749] chan_zap.c: Not yet hungup...  Calling hangup once with icause, and clearing call
[Jul 10 15:38:50] DEBUG[19749] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/32-1
[Jul 10 15:38:50] VERBOSE[19749] logger.c:     -- Hungup 'Zap/32-1'
[Jul 10 15:38:50] VERBOSE[19749] logger.c:   == Spawn extension (outbound, 02005006084, 4) exited non-zero on 'Zap/7-1'
[Jul 10 15:38:50] DEBUG[19749] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/7-1
[Jul 10 15:38:50] DEBUG[19749] chan_zap.c: Not yet hungup...  Calling hangup once with icause, and clearing call
[Jul 10 15:38:50] DEBUG[19749] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/7-1
[Jul 10 15:38:50] VERBOSE[19749] logger.c:     -- Hungup 'Zap/7-1'
[Jul 10 15:38:50] VERBOSE[19750] logger.c:   == End MixMonitor Recording Zap/7-1
Comments:By: seb7 (seb7) 2008-07-10 09:54:44

Note that if I take out the MixMonitor, it works fine, presumably due to native bridging.
By: Jeff Peeler (jpeeler) 2008-11-13 17:25:01.000-0600

Is this still a problem? I've tried reproducing this across a PRI to an analog phone but haven't seen DTMF not making it from the called side.
By: seb7 (seb7) 2008-12-10 12:19:52.000-0600

If the code hasn't been changed then I don't see why it should not still be a problem! Or are there changes you think may have fixed this? jpeeler, did you test with Asterisk 1.4.19? It would probably be quite a work-up for me to retest this now and it would be difficult to convince my boss that I should spend an afternoon reproducing the same results I posted in the first place (especially if there is no evidence to suggest it may be fixed)...


By: Jeff Peeler (jpeeler) 2008-12-10 12:35:27.000-0600

No, I tested with the latest 1.4 as is usually the common practice to not waste time on reproducing old fixed problems. However, since you do not have the resources to try the latest version, I'll see if I can revisit testing and confirm the issue broken and now fixed.
By: Jeff Peeler (jpeeler) 2008-12-10 19:55:59.000-0600

Well, I have not so far been able to reproduce the bug on 1.4.19 either. Any additional information about your setup such as your dialplan would be helpful.
By: seb7 (seb7) 2008-12-11 10:01:33.000-0600

Well, my dial plan is basically visible from the log above, but as far as I can deduce from what is now commented out in the config, this was the dial plan I used:

[outbound]
exten => _020.,1,NoOp(Inbound call for relay to Outbound call. CHANNEL(transfercapability) is ${CHANNEL(transfercapability)}.)
exten => _020.,n,NoOp(CALLERID is ${CALLERID}. CALLERID(name) is ${CALLERID(name)}. CALLERID(num) is ${CALLERID(num)}. CALLINGPRES is ${CALLINGPRES}.)
exten => _020.,n(record),MixMonitor(SebTest-${UNIQUEID}.WAV|b)
exten => _020.,n(justdial),Dial(Zap/g2/MyMobileNumberCensored)

zapata.conf - this is my best guess as to what the config the box from which the log was taken had, but it certainly had overlapdial on on span 1 (inbound call); I can't remember about span 2 (outbound call):

[channels]
switchtype=national
resetinterval = never
rxwink=300
usecallerid=yes
hidecallerid=no
callwaiting=yes
usecallingpres=yes
callwaitingcallerid=yes
threewaycalling=yes
transfer=yes
canpark=yes
cancallforward=yes
callreturn=yes
echocancel=yes
echocancelwhenbridged=yes
rxgain=0.0
txgain=0.0
group=1
callgroup=1
pickupgroup=1

immediate=no

group = 1
context=outbound
signalling = pri_cpe
overlapdial=yes
; overlapdial=no
channel => 1-15,17-31

group = 2
; context=default
signalling = pri_cpe
; overlapdial=yes
overlapdial=no
channel => 32-39
channel => 40-46,48-62


I think it is important that the equipment that sends the call into span 1 also uses overlapdialing (but I can't remember for sure). What phone and equipment did you have originating the call in your test? I think, in my log above, I used an analog phone connected to some non-asterisk gear. This gear was connected to Asterisk via PRI, but with overlapdialing enabled on the 'gear' (sending) side - otherwise, even though overlap dialing is enabled on the receiving side, the call set-up is still sent enbloc (I think). Then asterisk sent out the call again on span 2 into a British Telecom PRI span to my GSM mobile phone, which is where I was sending the DTMF. When I took out the MixMonitor or switched off overlapdialing I could hear decent length tones coming through to the originating phone, but otherwise hardly anything.

Maybe you could post, or attach, your log file from your test so we can compare the two?
By: Russell Bryant (russell) 2008-12-11 16:24:58.000-0600

I'm not sure that there is going to be anything we can do in this case.  When the call is not native bridged, and DTMF is going through the core, this is how it is going to work.  The inband DTMF detector listens for DTMF and mutes it as soon as it detects the digit.  Then, it passes it through the core as a signaling frame in case it needs to be acted on.  Then, it will get regenerated in the technology specific method on other side of the bridge if it gets passed along.

There will always be a little bit of the digit that leaks through.
By: Jeff Peeler (jpeeler) 2008-12-11 16:33:59.000-0600

My setup is a lot more complicated because I'm only using one server.

*CLI>     -- Starting simple switch on 'Zap/126-1'
[Dec 11 16:14:07] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '4' received on Zap/126-1, duration 0 ms
[Dec 11 16:14:07] DTMF[17705]: channel.c:2206 __ast_read: DTMF end accepted without begin '4' on Zap/126-1
[Dec 11 16:14:07] DTMF[17705]: channel.c:2217 __ast_read: DTMF end passthrough '4' on Zap/126-1
[Dec 11 16:14:07] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '9' received on Zap/126-1, duration 0 ms
[Dec 11 16:14:07] DTMF[17705]: channel.c:2206 __ast_read: DTMF end accepted without begin '9' on Zap/126-1
[Dec 11 16:14:07] DTMF[17705]: channel.c:2217 __ast_read: DTMF end passthrough '9' on Zap/126-1
[Dec 11 16:14:07] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '9' received on Zap/126-1, duration 0 ms
[Dec 11 16:14:07] DTMF[17705]: channel.c:2206 __ast_read: DTMF end accepted without begin '9' on Zap/126-1
[Dec 11 16:14:07] DTMF[17705]: channel.c:2217 __ast_read: DTMF end passthrough '9' on Zap/126-1
[Dec 11 16:14:08] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '9' received on Zap/126-1, duration 0 ms
[Dec 11 16:14:08] DTMF[17705]: channel.c:2206 __ast_read: DTMF end accepted without begin '9' on Zap/126-1
[Dec 11 16:14:08] DTMF[17705]: channel.c:2217 __ast_read: DTMF end passthrough '9' on Zap/126-1
   -- Executing [4999@default:1] NoOp("Zap/126-1", "") in new stack
   -- Executing [4999@default:2] MixMonitor("Zap/126-1", "jefftest.wav") in new stack
 == Begin MixMonitor Recording Zap/126-1
   -- Executing [4999@default:3] Dial("Zap/126-1", "Zap/32/11111||tT") in new stack
   -- Requested transfer capability: 0x00 - SPEECH
   -- Called 32/11111
   -- Executing [11111@default:1] NoOp("Zap/1-1", "") in new stack
   -- Executing [11111@default:2] MixMonitor("Zap/1-1", "jefftest2.wav") in new stack
 == Begin MixMonitor Recording Zap/1-1
   -- Accepting call from '' to '11111' on channel 0/1, span 1
   -- Executing [11111@default:3] Dial("Zap/1-1", "Zap/63/11112") in new stack
   -- Requested transfer capability: 0x00 - SPEECH
   -- Called 63/11112
   -- Executing [11112@default:1] NoOp("Zap/94-1", "") in new stack
   -- Executing [11112@default:2] MixMonitor("Zap/94-1", "jefftest3.wav") in new stack
 == Begin MixMonitor Recording Zap/94-1
   -- Executing [11112@default:3] Dial("Zap/94-1", "Zap/125") in new stack
   -- Called 125
   -- Accepting call from '' to '11112' on channel 0/1, span 4
   -- Zap/125-1 is ringing
[Dec 11 16:14:08] DEBUG[17635]: chan_dahdi.c:9249 pri_dchannel: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 3
   -- Zap/63-1 is proceeding passing it to Zap/1-1
[Dec 11 16:14:08] DEBUG[17707]: chan_dahdi.c:5202 dahdi_indicate: Received AST_CONTROL_PROCEEDING on Zap/1-1
   -- Zap/63-1 is ringing
[Dec 11 16:14:08] DEBUG[17634]: chan_dahdi.c:9249 pri_dchannel: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 2
   -- Zap/32-1 is proceeding passing it to Zap/126-1
[Dec 11 16:14:08] DEBUG[17705]: chan_dahdi.c:5202 dahdi_indicate: Received AST_CONTROL_PROCEEDING on Zap/126-1
   -- Zap/32-1 is making progress passing it to Zap/126-1
[Dec 11 16:14:08] DEBUG[17705]: chan_dahdi.c:5220 dahdi_indicate: Received AST_CONTROL_PROGRESS on Zap/126-1
   -- Zap/32-1 is ringing
   -- Zap/125-1 is ringing
[Dec 11 16:14:12] DEBUG[17709]: chan_dahdi.c:1504 dahdi_train_ec: No echo training requested
[Dec 11 16:14:12] DEBUG[17709]: chan_dahdi.c:4135 dahdi_handle_event: channel 125 answered
   -- Zap/125-1 answered Zap/94-1
[Dec 11 16:14:12] DEBUG[17635]: chan_dahdi.c:1464 dahdi_enable_ec: Echo cancellation already on
   -- Zap/63-1 answered Zap/1-1
[Dec 11 16:14:12] DEBUG[17634]: chan_dahdi.c:1464 dahdi_enable_ec: Echo cancellation already on
   -- Zap/32-1 answered Zap/126-1
[Dec 11 16:14:12] DEBUG[17705]: chan_dahdi.c:2880 dahdi_answer: Took Zap/126-1 off hook
[Dec 11 16:14:20] DTMF[17709]: channel.c:2154 __ast_read: DTMF end '1' received on Zap/125-1, duration 0 ms
[Dec 11 16:14:20] DTMF[17709]: channel.c:2190 __ast_read: DTMF begin emulation of '1' with duration 100 queued on Zap/125-1
[Dec 11 16:14:20] DEBUG[17709]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '1'
[Dec 11 16:14:20] DTMF[17709]: channel.c:2302 __ast_read: DTMF end emulation of '1' queued on Zap/125-1
[Dec 11 16:14:20] DEBUG[17709]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '1'
[Dec 11 16:14:20] DTMF[17707]: channel.c:2154 __ast_read: DTMF end '1' received on Zap/63-1, duration 0 ms
[Dec 11 16:14:20] DTMF[17707]: channel.c:2190 __ast_read: DTMF begin emulation of '1' with duration 100 queued on Zap/63-1
[Dec 11 16:14:20] DEBUG[17707]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '1'
[Dec 11 16:14:20] DTMF[17707]: channel.c:2302 __ast_read: DTMF end emulation of '1' queued on Zap/63-1
[Dec 11 16:14:20] DEBUG[17707]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '1'
[Dec 11 16:14:20] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '1' received on Zap/32-1, duration 0 ms
[Dec 11 16:14:20] DTMF[17705]: channel.c:2190 __ast_read: DTMF begin emulation of '1' with duration 100 queued on Zap/32-1
[Dec 11 16:14:20] DTMF[17705]: channel.c:2302 __ast_read: DTMF end emulation of '1' queued on Zap/32-1
[Dec 11 16:14:20] DEBUG[17705]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '1'
[Dec 11 16:14:20] DEBUG[17705]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '1'
[Dec 11 16:14:22] DTMF[17709]: channel.c:2154 __ast_read: DTMF end '2' received on Zap/125-1, duration 0 ms
[Dec 11 16:14:22] DTMF[17709]: channel.c:2190 __ast_read: DTMF begin emulation of '2' with duration 100 queued on Zap/125-1
[Dec 11 16:14:22] DEBUG[17709]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '2'
[Dec 11 16:14:22] DTMF[17709]: channel.c:2302 __ast_read: DTMF end emulation of '2' queued on Zap/125-1
[Dec 11 16:14:22] DEBUG[17709]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '2'
[Dec 11 16:14:22] DTMF[17707]: channel.c:2154 __ast_read: DTMF end '2' received on Zap/63-1, duration 0 ms
[Dec 11 16:14:22] DTMF[17707]: channel.c:2190 __ast_read: DTMF begin emulation of '2' with duration 100 queued on Zap/63-1
[Dec 11 16:14:22] DEBUG[17707]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '2'
[Dec 11 16:14:22] DTMF[17707]: channel.c:2302 __ast_read: DTMF end emulation of '2' queued on Zap/63-1
[Dec 11 16:14:22] DEBUG[17707]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '2'
[Dec 11 16:14:22] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '2' received on Zap/32-1, duration 0 ms
[Dec 11 16:14:22] DTMF[17705]: channel.c:2190 __ast_read: DTMF begin emulation of '2' with duration 100 queued on Zap/32-1
[Dec 11 16:14:22] DTMF[17705]: channel.c:2302 __ast_read: DTMF end emulation of '2' queued on Zap/32-1
[Dec 11 16:14:22] DEBUG[17705]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '2'
[Dec 11 16:14:22] DEBUG[17705]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '2'
[Dec 11 16:14:32] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '#' received on Zap/126-1, duration 0 ms
[Dec 11 16:14:32] DTMF[17705]: channel.c:2190 __ast_read: DTMF begin emulation of '#' with duration 100 queued on Zap/126-1
[Dec 11 16:14:32] DTMF[17705]: channel.c:2302 __ast_read: DTMF end emulation of '#' queued on Zap/126-1
   -- Started music on hold, class 'default', on Zap/32-1
   -- <Zap/126-1> Playing 'pbx-transfer' (language 'en')
[Dec 11 16:14:33] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '5' received on Zap/126-1, duration 0 ms
[Dec 11 16:14:33] DTMF[17705]: channel.c:2206 __ast_read: DTMF end accepted without begin '5' on Zap/126-1
[Dec 11 16:14:33] DTMF[17705]: channel.c:2217 __ast_read: DTMF end passthrough '5' on Zap/126-1
[Dec 11 16:14:34] DTMF[17705]: channel.c:2154 __ast_read: DTMF end '1' received on Zap/126-1, duration 0 ms
[Dec 11 16:14:34] DTMF[17705]: channel.c:2206 __ast_read: DTMF end accepted without begin '1' on Zap/126-1
[Dec 11 16:14:34] DTMF[17705]: channel.c:2217 __ast_read: DTMF end passthrough '1' on Zap/126-1
   -- Stopped music on hold on Zap/32-1
   -- Transferring Zap/32-1 to '51' (context default) priority 1
[Dec 11 16:14:34] DEBUG[17705]: chan_dahdi.c:3542 dahdi_fixup: New owner for channel 32 is Zap/32-1
   -- Executing [51@default:1] Answer("Zap/32-1", "") in new stack
   -- Executing [51@default:2] Read("Zap/32-1", "digits|||||10") in new stack
 == Spawn extension (default, 4999, 3) exited non-zero on 'Zap/126-1'
 == End MixMonitor Recording Zap/126-1
   -- Hungup 'Zap/126-1'

*CLI> [Dec 11 16:14:40] DTMF[17709]: channel.c:2154 __ast_read: DTMF end '1' received on Zap/125-1, duration 0 ms
[Dec 11 16:14:40] DTMF[17709]: channel.c:2190 __ast_read: DTMF begin emulation of '1' with duration 100 queued on Zap/125-1
[Dec 11 16:14:40] DEBUG[17709]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '1'
[Dec 11 16:14:40] DTMF[17709]: channel.c:2302 __ast_read: DTMF end emulation of '1' queued on Zap/125-1
[Dec 11 16:14:40] DEBUG[17709]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '1'
[Dec 11 16:14:40] DTMF[17707]: channel.c:2154 __ast_read: DTMF end '1' received on Zap/63-1, duration 0 ms
[Dec 11 16:14:40] DTMF[17707]: channel.c:2190 __ast_read: DTMF begin emulation of '1' with duration 100 queued on Zap/63-1
[Dec 11 16:14:40] DEBUG[17707]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '1'
[Dec 11 16:14:40] DTMF[17707]: channel.c:2302 __ast_read: DTMF end emulation of '1' queued on Zap/63-1
[Dec 11 16:14:40] DEBUG[17707]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '1'
[Dec 11 16:14:40] DTMF[17711]: channel.c:2154 __ast_read: DTMF end '1' received on Zap/32-1, duration 0 ms
[Dec 11 16:14:40] DTMF[17711]: channel.c:2206 __ast_read: DTMF end accepted without begin '1' on Zap/32-1
[Dec 11 16:14:40] DTMF[17711]: channel.c:2217 __ast_read: DTMF end passthrough '1' on Zap/32-1
[Dec 11 16:14:41] DTMF[17709]: channel.c:2154 __ast_read: DTMF end '2' received on Zap/125-1, duration 0 ms
[Dec 11 16:14:41] DTMF[17709]: channel.c:2190 __ast_read: DTMF begin emulation of '2' with duration 100 queued on Zap/125-1
[Dec 11 16:14:41] DEBUG[17709]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '2'
[Dec 11 16:14:41] DTMF[17709]: channel.c:2302 __ast_read: DTMF end emulation of '2' queued on Zap/125-1
[Dec 11 16:14:41] DEBUG[17709]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '2'
[Dec 11 16:14:41] DTMF[17707]: channel.c:2154 __ast_read: DTMF end '2' received on Zap/63-1, duration 0 ms
[Dec 11 16:14:41] DTMF[17707]: channel.c:2190 __ast_read: DTMF begin emulation of '2' with duration 100 queued on Zap/63-1
[Dec 11 16:14:41] DEBUG[17707]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '2'
[Dec 11 16:14:41] DTMF[17707]: channel.c:2302 __ast_read: DTMF end emulation of '2' queued on Zap/63-1
[Dec 11 16:14:41] DEBUG[17707]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '2'
[Dec 11 16:14:41] DTMF[17711]: channel.c:2154 __ast_read: DTMF end '2' received on Zap/32-1, duration 0 ms
[Dec 11 16:14:41] DTMF[17711]: channel.c:2206 __ast_read: DTMF end accepted without begin '2' on Zap/32-1
[Dec 11 16:14:41] DTMF[17711]: channel.c:2217 __ast_read: DTMF end passthrough '2' on Zap/32-1
[Dec 11 16:14:42] DTMF[17709]: channel.c:2154 __ast_read: DTMF end '3' received on Zap/125-1, duration 0 ms
[Dec 11 16:14:42] DTMF[17709]: channel.c:2190 __ast_read: DTMF begin emulation of '3' with duration 100 queued on Zap/125-1
[Dec 11 16:14:42] DEBUG[17709]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '3'
[Dec 11 16:14:42] DTMF[17709]: channel.c:2302 __ast_read: DTMF end emulation of '3' queued on Zap/125-1
[Dec 11 16:14:42] DEBUG[17709]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '3'
[Dec 11 16:14:42] DTMF[17707]: channel.c:2154 __ast_read: DTMF end '3' received on Zap/63-1, duration 0 ms
[Dec 11 16:14:42] DTMF[17707]: channel.c:2190 __ast_read: DTMF begin emulation of '3' with duration 100 queued on Zap/63-1
[Dec 11 16:14:42] DEBUG[17707]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '3'
[Dec 11 16:14:42] DTMF[17707]: channel.c:2302 __ast_read: DTMF end emulation of '3' queued on Zap/63-1
[Dec 11 16:14:42] DEBUG[17707]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '3'
[Dec 11 16:14:42] DTMF[17711]: channel.c:2154 __ast_read: DTMF end '3' received on Zap/32-1, duration 0 ms
[Dec 11 16:14:42] DTMF[17711]: channel.c:2206 __ast_read: DTMF end accepted without begin '3' on Zap/32-1
[Dec 11 16:14:42] DTMF[17711]: channel.c:2217 __ast_read: DTMF end passthrough '3' on Zap/32-1
[Dec 11 16:14:43] DTMF[17709]: channel.c:2154 __ast_read: DTMF end '4' received on Zap/125-1, duration 0 ms
[Dec 11 16:14:43] DTMF[17709]: channel.c:2190 __ast_read: DTMF begin emulation of '4' with duration 100 queued on Zap/125-1
[Dec 11 16:14:43] DEBUG[17709]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '4'
[Dec 11 16:14:43] DTMF[17709]: channel.c:2302 __ast_read: DTMF end emulation of '4' queued on Zap/125-1
[Dec 11 16:14:43] DEBUG[17709]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '4'
[Dec 11 16:14:43] DTMF[17707]: channel.c:2154 __ast_read: DTMF end '4' received on Zap/63-1, duration 0 ms
[Dec 11 16:14:43] DTMF[17707]: channel.c:2190 __ast_read: DTMF begin emulation of '4' with duration 100 queued on Zap/63-1
[Dec 11 16:14:43] DEBUG[17707]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '4'
[Dec 11 16:14:43] DTMF[17707]: channel.c:2302 __ast_read: DTMF end emulation of '4' queued on Zap/63-1
[Dec 11 16:14:43] DEBUG[17707]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '4'
[Dec 11 16:14:43] DTMF[17711]: channel.c:2154 __ast_read: DTMF end '4' received on Zap/32-1, duration 0 ms
[Dec 11 16:14:43] DTMF[17711]: channel.c:2206 __ast_read: DTMF end accepted without begin '4' on Zap/32-1
[Dec 11 16:14:43] DTMF[17711]: channel.c:2217 __ast_read: DTMF end passthrough '4' on Zap/32-1
[Dec 11 16:14:44] DTMF[17709]: channel.c:2154 __ast_read: DTMF end '5' received on Zap/125-1, duration 0 ms
[Dec 11 16:14:44] DTMF[17709]: channel.c:2190 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/125-1
[Dec 11 16:14:44] DEBUG[17709]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '5'
[Dec 11 16:14:44] DTMF[17709]: channel.c:2302 __ast_read: DTMF end emulation of '5' queued on Zap/125-1
[Dec 11 16:14:44] DEBUG[17709]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '5'
[Dec 11 16:14:44] DTMF[17707]: channel.c:2154 __ast_read: DTMF end '5' received on Zap/63-1, duration 0 ms
[Dec 11 16:14:44] DTMF[17707]: channel.c:2190 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/63-1
[Dec 11 16:14:44] DEBUG[17707]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '5'
[Dec 11 16:14:44] DTMF[17707]: channel.c:2302 __ast_read: DTMF end emulation of '5' queued on Zap/63-1
[Dec 11 16:14:44] DEBUG[17707]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '5'
[Dec 11 16:14:44] DTMF[17711]: channel.c:2154 __ast_read: DTMF end '5' received on Zap/32-1, duration 0 ms
[Dec 11 16:14:44] DTMF[17711]: channel.c:2206 __ast_read: DTMF end accepted without begin '5' on Zap/32-1
[Dec 11 16:14:44] DTMF[17711]: channel.c:2217 __ast_read: DTMF end passthrough '5' on Zap/32-1
[Dec 11 16:14:44] DTMF[17709]: channel.c:2154 __ast_read: DTMF end '6' received on Zap/125-1, duration 0 ms
[Dec 11 16:14:44] DTMF[17709]: channel.c:2190 __ast_read: DTMF begin emulation of '6' with duration 100 queued on Zap/125-1
[Dec 11 16:14:44] DEBUG[17709]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '6'
[Dec 11 16:14:44] DTMF[17709]: channel.c:2302 __ast_read: DTMF end emulation of '6' queued on Zap/125-1
[Dec 11 16:14:44] DEBUG[17709]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '6'
[Dec 11 16:14:44] DTMF[17707]: channel.c:2154 __ast_read: DTMF end '6' received on Zap/63-1, duration 0 ms
[Dec 11 16:14:44] DTMF[17707]: channel.c:2190 __ast_read: DTMF begin emulation of '6' with duration 100 queued on Zap/63-1
[Dec 11 16:14:44] DEBUG[17707]: chan_dahdi.c:1099 dahdi_digit_begin: Started VLDTMF digit '6'
[Dec 11 16:14:44] DTMF[17707]: channel.c:2302 __ast_read: DTMF end emulation of '6' queued on Zap/63-1
[Dec 11 16:14:44] DEBUG[17707]: chan_dahdi.c:1134 dahdi_digit_end: Ending VLDTMF digit '6'
[Dec 11 16:14:45] DTMF[17711]: channel.c:2154 __ast_read: DTMF end '6' received on Zap/32-1, duration 0 ms
[Dec 11 16:14:45] DTMF[17711]: channel.c:2206 __ast_read: DTMF end accepted without begin '6' on Zap/32-1
[Dec 11 16:14:45] DTMF[17711]: channel.c:2217 __ast_read: DTMF end passthrough '6' on Zap/32-1
   -- User entered '123456'
   -- Executing [51@default:3] NoOp("Zap/32-1", ""Read finished"") in new stack
   -- Executing [51@default:4] NoOp("Zap/32-1", "123456") in new stack
 == Auto fallthrough, channel 'Zap/32-1' status is 'UNKNOWN'
[Dec 11 16:14:55] DEBUG[17711]: chan_dahdi.c:3071 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on Zap/32-1
[Dec 11 16:14:55] DEBUG[17711]: chan_dahdi.c:2704 dahdi_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[Dec 11 16:14:55] DEBUG[17711]: chan_dahdi.c:3067 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/32-1
   -- Hungup 'Zap/32-1'
   -- Channel 0/1, span 1 got hangup request, cause 16
[Dec 11 16:14:55] DEBUG[17707]: chan_dahdi.c:3071 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on Zap/63-1
[Dec 11 16:14:55] DEBUG[17707]: chan_dahdi.c:2704 dahdi_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[Dec 11 16:14:55] DEBUG[17707]: chan_dahdi.c:3067 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/63-1
   -- Hungup 'Zap/63-1'
 == Spawn extension (default, 11111, 3) exited non-zero on 'Zap/1-1'
[Dec 11 16:14:55] DEBUG[17707]: chan_dahdi.c:3071 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on Zap/1-1
 == End MixMonitor Recording Zap/1-1
[Dec 11 16:14:55] DEBUG[17707]: chan_dahdi.c:2704 dahdi_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[Dec 11 16:14:55] DEBUG[17707]: chan_dahdi.c:3067 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
   -- Hungup 'Zap/1-1'
   -- Channel 0/1, span 4 got hangup request, cause 16
   -- Hungup 'Zap/125-1'
 == Spawn extension (default, 11112, 3) exited non-zero on 'Zap/94-1'
 == End MixMonitor Recording Zap/94-1
[Dec 11 16:14:55] DEBUG[17709]: chan_dahdi.c:3071 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on Zap/94-1
[Dec 11 16:14:55] DEBUG[17709]: chan_dahdi.c:2704 dahdi_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[Dec 11 16:14:55] DEBUG[17709]: chan_dahdi.c:3067 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/94-1
   -- Hungup 'Zap/94-1'


I have two analog phones and 4 pri spans. I tried to duplicate your setup as closely as possible with both CPE endpoints terminating at Asterisk. So the call flow is as follows: the first analog phone calls the NET side (span 2) which is looped back to the CPE (span 1), which dials the CPE side (span 3) which is looped back to the net side (span 4), which dials the second analog phone.

You'll see I dialed a few digits, just to see how that went. Then I transfered the first analog phone to an extension which reads digits. All the digits from the called/second phone made it to the other side. I'm using MixMonitor between all the Zap channels to prevent native bridging and do have overlapdial turned on.

Thoughts? I tested with both 1.4.19 and current 1.4 with no difference in behavior.
By: seb7 (seb7) 2008-12-12 11:55:50.000-0600

russell wrote: 'The inband DTMF detector listens for DTMF and mutes it as soon as it detects the digit.'
What you describe does seem like it might be what is happening (with some leakage), except that the Asterisk core does not detect the DTMF: you can see from my log that DTMF is not being detected - I was pressing DTMF keys on my phone after I answered the call, and you can see that I have DTMF logging switched on. (This is in contrast to jpeeler's log which shows that DTMF is being detected, and looks like what I saw with MixMonitor but without overlapdial on (because we can see that VLDTMF is not in use as the tones are all 0 or 100 ms).) The fact that in my log DTMF was not being logged is probably the reason the DTMF is not being regenerated either (or another symptom of the same issue). So why would asterisk be muting the DTMF but not really detecting it, or the detection not being passed all the way though? Could it be an interaction with MixMonitor?

I do remember an issue where I complained on #asterisk-bugs that VLDTMF didn't work with MixMonitor, [i.e. non-native bridging?], and DTMF was converted into fixed durations (search for Seb7 in http://ibot.rikers.org/%23asterisk-bugs/20080708.html.gz ), but I think what you have described explains this. Might be worth reading my thoughts / findings at the time though. It looks like I didn't file this as a bug though since no-one said it was one (although they didn't say it wasn't either).

Edit: Trying to fix link by adding a space after it.


By: Jeff Peeler (jpeeler) 2009-01-20 10:51:10.000-0600

Sorry for the lapse in time here, but I'm not to sure how to proceed.

Seb7: Have you gained any more information either through an upgrade or more experimentation?
By: Jeff Peeler (jpeeler) 2009-01-22 14:14:21.000-0600

I'm closing this issue since I have no further data to work with. If anybody can reproduce the DTMF detection problem, please reopen. Make sure to include the DTMF logs as well as recordings so that they can be analyzed using some DTMF detection tests.