[Home]

Summary:ASTERISK-11209: DTMF problem on 1.4.17
Reporter:Giovanni Serra (gserra)Labels:
Date Opened:2008-01-11 05:55:38.000-0600Date Closed:2008-02-18 17:55:11.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Interoperability
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) aragon_dtmfevents.txt
( 1) aragon_features.conf
( 2) aragon_sip.conf
( 3) arnd-debug.log
( 4) arnd-debug+dtmf2.log
( 5) arnd-debug+v1-feature-debug.log
( 6) arnd-features.conf
( 7) asteriskSIPinfoDTMFfail.log
( 8) grandstream-dtmf.txt
( 9) gserra-from-fixed.txt
(10) gserra-from-mobile.txt
(11) gserra-sip-conf.txt
(12) incomingPRIfeatureDTMFdebug.txt
(13) incomingPRIfeatureDTMFdebugPlain.txt
(14) incomingSIPfeaturesDTMF.txt
(15) sip.conf.txt
(16) snom_asterisk_dtmf_rfc2833.txt
(17) snom-dtmf.txt
(18) snomSIPINFOdtmf.txt
(19) snomSIPinfoDTMFfail.txt
(20) snomSIPINFOdtmfSIPDEBUG.txt
(21) test_fixed_line-1.txt
(22) v1-11740.patch
(23) v1-feature-debug.patch
Description:Hi,

when a call is being passed over from AS5400 via PRI to SIP into asterisk, dtmf is working in 1.4.11 but not on 1.4.17
Comments:By: Olle Johansson (oej) 2008-01-11 08:58:28.000-0600

Ok. Did you actually read the bug guidelines?

We need much more information from you to help you in any way.
By: Joshua C. Colp (jcolp) 2008-01-11 10:01:57.000-0600

As oej mentioned please provide much more information such as console output with core debug enabled and sip.conf configuration.
By: Giovanni Serra (gserra) 2008-01-11 10:48:46.000-0600

I have upload the console output we currently have and also the current sip.conf
By: Giovanni Serra (gserra) 2008-01-11 11:04:25.000-0600

We are currently working on a console output with core debug enabled, as this is on a live system. that has been rolled back to 1.4.11
By: Giovanni Serra (gserra) 2008-01-11 11:31:43.000-0600

Just to confirm

core set verbose 10

will be enough for the console output?
By: Joshua C. Colp (jcolp) 2008-01-11 11:33:48.000-0600

As well as core set debug 9 with debug set in logger.conf to go to console.
By: David Brillert (aragon) 2008-01-11 18:42:07.000-0600

I'm having issues with DTMF since my upgrade to 1.4.17 too
I was not having DTMF issues with 1.4.13

Here are the symptoms under 1.4.17
Native attended transfer (*2 in my configuration) no longer prompts for transfer.
Automon code no longer works (configured as *999)
Express messaging transfer no longer works.

All used to work using a variety of SIP phones including Aastra Polycom Hitachi Snom.

Now nothing works

I'm attaching three logs:
aragon_dtmfevents.txt
aragon_sip.conf
aragon_features.conf

The files have been edited to remove private information.

The console screams when it receives info from the Snom phone
Snom sends 60 ms DTMF and Asterisk wants minimum 80 ms
Astra and Hitachi both send 160 ms
But the timers (inter-digit DTMF timers I assume) are so finicky that the atxfer is hardly ever invoked.


By: David Brillert (aragon) 2008-01-11 18:46:02.000-0600

After reviewing the SIP messages in aragon_dtmfevents.txt I noticed there were no rfc2833 messages.
This is when I noticed that my Aastra phone was provisioned to use SIP INFO mode DTMF and in my sip.conf the ext 220 was configured to use rfc2833.

1.4.13 allowed this configuration to work where 1.4.17 does not.
This does not appear to be a bug in Asterisk 1.4.17. I assume some work was done in 1.4.17 to forcefully restrict the DTMF mode used.

I retested the Aastra 57i in both SIP INFO mode and rfc2833 and the Aastra passed both tests (when the provisioning file in the Aastra and sip.conf have matching DTMF configurations).

I retested the Snom with interesting results:
Snom passed the retest when rfc2833 is used in its configuration file and sip.conf is configured to use rfc2833

Snom fails atxfer and automon tests if SIP INFO mode is used.
This is obviously a Snom bug and I have opened a bug report with Snom regarding this issue.


By: David Brillert (aragon) 2008-01-13 21:54:41.000-0600

One thing I do find odd in 1.4.17

Asterisk 1.4.13 did used to generate an audible DTMF tone in the following scenario:
ext 200 calls 233
neither extension invokes atxfer or automon code (any code which would normally suppress DTMF).
Normal DTMF event occurs like either extensions pressing 7
In 1.4.13 the remote end of the call would hear the DTMF tone being issued from the other end.
Now with 1.4.17 I never hear DTMF when the remote end generates a tone but I can see the tone in the Asterisk logs.

This would make traditional DTMF debugging (listening for audible DTMF) very difficult.
By: Joshua C. Colp (jcolp) 2008-01-14 08:39:05.000-0600

How about the output for a Snom INFO based DTMF so we can confirm it is their fault before bothering them? As for audible DTMF... Asterisk should never generate audible DTMF unless configured to do so using inband, otherwise it is transported out of band and it is up to the device to generate it. If we didn't mute the audible DTMF depending on the remote equipment we'd get double DTMF.
By: David Brillert (aragon) 2008-01-14 09:26:02.000-0600

I am happy to upload some failed Snom SIP INFO output.
I'll post soon...

I just tested audible DTMF on my Nortel SL1 and Nortel Norstar and Nortel BCM and this does work. And I'm sure this was supported in Asterisk at one time or another.
We suppress DTMF when we do automon or similar native Asterisk feature code and I think it is the interdigit timers between DTMF digits which tells/told Asterisk to suppress DTMF playback when we invoke a feature.

For what its worth I think DTMF suppression is a minor issue as and it isn't service affecting. I just noticed the audio is now suppressed and thought it was a bit weird.
By: David Brillert (aragon) 2008-01-14 10:03:17.000-0600

Snom is only partially buggy in SIP INFO mode:
Snom allows a softkey to be programmed as a DTMF event
So I program my automon code *999 to a key in SIP INFO mode and the automon is not activated.
By dialing the digits *999 manually I can trigger Asterisk to record the call.
The snomSIPinfoDTMFfail.txt captures both events.

Another test of Snom V7 7.1.30 firmware provided bizarre DTMF results using rfc2833 regardless of whether softkey or manually pressing DTMF keys.

All of these tests were done over a PRI trunk.

So I ran a slightly different test using rfc2833 invoking DTMF from local extension to local extension and the DTMF was properly invoked.

I'm beginning to believe there is a problem with DTMF over zaptel (at least on my PRI span). Possibly only with Snom phones???

Span is a Digium TE412P connected to a Nortel BCM.

Configured in my lab and remote access can be arranged.
By: Joshua C. Colp (jcolp) 2008-01-14 10:07:06.000-0600

Now I'm confused about what the scenario is... can you describe it step by step along with options to Dial used?
By: David Brillert (aragon) 2008-01-14 10:14:09.000-0600

I run a few tests:
step 1
configure a snom to use sip info
use the snom to call over the PRI trunk
dial the code to start recording a call *999
The recording doesnt start and I can hear DTMF echoed to me through the snom handset.
I make another call to a local extension and dial *999 and the recording is successful

I get the same results using rfc2833 configuration.

I'm now just as confused as you are because it has taken a lot of testing and observation to arrive to where I am now.

It looks like both DTMF modes work locally using SIP.
It looks like both DTMF modes fail over the PRI.

Now I feel obliged to redo the tests with an Aastra phone to see if I can reproduce with Aastra...


By: David Brillert (aragon) 2008-01-14 10:21:17.000-0600

I retested rfc2833 and SIP INFO on the Aastra and it worked flawlessy.

I have to assume this is a buggy DTMF issue with Snom phones and I am using 7.1.30 firmware.
By: David Brillert (aragon) 2008-01-14 10:49:57.000-0600

I downgraded my Snom 360 to version 6.5.13 and the DTMF is much better.
There is some audible noise when you invoke call recording on the Snom where the Aastra is absolutely silent.
However a new feature was introduced to Snom V7 to fix major transfer problems.
I cant live with either firmware version.
In version 7.1.30
"Allow incoming calls redirection through programmable keys: no"
Prevents two outside parties from being bridged when you press a softkey while your phone is ringing.
By: David Brillert (aragon) 2008-01-14 11:10:19.000-0600

I'm following up with Snom regarding my open Snom bug report.
please let me know if you see anything weird in the logs I uploaded.
By: Giovanni Serra (gserra) 2008-01-15 09:06:21.000-0600

Ok i got console trace.

When i test calling from mobile phone all is working in the right way, while calling from fixed line it doesnt work.

Please find:

gserra-from-mobile.txt
gserra-from-fixed.txt
gserra-sip-conf.txt


By: Joshua C. Colp (jcolp) 2008-01-15 19:40:32.000-0600

aragon: I can't see anything strange...

gserra: does rfc2833compensate=yes in the general section of sip.conf fix things?
By: Giovanni Serra (gserra) 2008-01-17 04:43:59.000-0600

Hi there,

we added rfc2833compensate=yes in the general section of sip.conf and it fix things

thanks alot
By: Olle Johansson (oej) 2008-01-17 04:53:00.000-0600

file: Can you explain what rfc2833compensate=yes really does?
By: David Brillert (aragon) 2008-01-17 09:30:06.000-0600

There is a feature in the Snom phone you can disable.
DTMF echo on Speaker Phone ?   no
DTMF echo on Speaker Phone ?   yes

When set to yes the DTMF is heard over the Snom handsfree.
When set to no DTMF is suppressed but ONLY during initial call setup. DTMF is always played back after a call is established; regardless if you press the keypad or press a softkey programmed to issue DTMF (a minor bug in the Snom firmware; DTMF echo= off SHOULD mean DTMF echo= off ALWAYS).

During my tests I would call a PSTN phone over PRI (or another SIP phone)
The PSTN phone was in my lab and I would answer by picking up the handset.
Then I would press a softkey on the Snom to invoke automon
The Snom would play DTMF over the handsfree
Although I would pick up the PSTN phone by using the handset the mic in that handset was sensitive enough to pick up the DTMF playback from the Snom handsfree. In some cases the DTMF playback would  be loud enough from the Snom handset even when taken off handsfree to be picked up by the handset on the PSTN phone. And thus the DTMF was echoed.
I reconfirmed this by covering the microphone on the PSTN handset in order to reproduce my theory.
My conclusion:
Snom v 7.1.30 firmware works happily with Asterisk when the DTMF mode = rfc2833

I ran all of the tests again with a Snom 360 v7.1.30 in SIP INFO mode.
I called the PSTN handset over a PRI from a Snom 360 upgraded to v7.1.30 firmware and the automon feature fails every time.
My conclusion:
Snom v 7.1.30 firmware is not interoperable with Asterisk when using SIP INFO mode.

Snom has my traces.
By: David Brillert (aragon) 2008-01-17 10:13:30.000-0600

Here is Snom's response..
1. Does your system (asterisk) receive these SIP INFO messages (when you check in its trace (because they are certainly being sent out).
2. If so, why is the system then not acting on them?

r it could be the SIP INFO messages are being sent too quickly for the system (but that should not be the case since its SIP messages). If you could confirm the above two questions we can investigate further. We appreciate your help.
Thanks.

Sent to tls:192.168.0.86:5061 at 21/12/2007 17:59:15:656 (477 bytes):

INFO sip:250@192.168.0.86:5061;transport=tls SIP/2.0
Via: SIP/2.0/TLS 192.168.10.93:5060;branch=z9hG4bK-sf9wxiqyhuym;rport
From: "250 PBX" <sip:250@localhost>;tag=hdp3x0uy7w
To: <sip:251@localhost;user=phone>;tag=3541c0b07b
Call-ID: acf06b47b240-zwf7xn8780xc
CSeq: 6 INFO
Max-Forwards: 70
Contact: <sip:250@192.168.10.93:5060;transport=tls;line=21tq03ix>;flow-id=1
User-Agent: snom370/
Content-Type: application/dtmf-relay
Content-Length: 22

Signal=7
Duration=160


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


Sent to tls:192.168.0.86:5061 at 21/12/2007 17:59:15:671 (477 bytes):

INFO sip:250@192.168.0.86:5061;transport=tls SIP/2.0
Via: SIP/2.0/TLS 192.168.10.93:5060;branch=z9hG4bK-uixxv9owokm9;rport
From: "250 PBX" <sip:250@localhost>;tag=hdp3x0uy7w
To: <sip:251@localhost;user=phone>;tag=3541c0b07b
Call-ID: acf06b47b240-zwf7xn8780xc
CSeq: 7 INFO
Max-Forwards: 70
Contact: <sip:250@192.168.10.93:5060;transport=tls;line=21tq03ix>;flow-id=1
User-Agent: snom370/
Content-Type: application/dtmf-relay
Content-Length: 22

Signal=8
Duration=160


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


Sent to tls:192.168.0.86:5061 at 21/12/2007 17:59:15:671 (477 bytes):

INFO sip:250@192.168.0.86:5061;transport=tls SIP/2.0
Via: SIP/2.0/TLS 192.168.10.93:5060;branch=z9hG4bK-yl2d4hdhmows;rport
From: "250 PBX" <sip:250@localhost>;tag=hdp3x0uy7w
To: <sip:251@localhost;user=phone>;tag=3541c0b07b
Call-ID: acf06b47b240-zwf7xn8780xc
CSeq: 8 INFO
Max-Forwards: 70
Contact: <sip:250@192.168.10.93:5060;transport=tls;line=21tq03ix>;flow-id=1
User-Agent: snom370/
Content-Type: application/dtmf-relay
Content-Length: 22

Signal=6
Duration=160


I have uploaded asteriskSIPinfoDTMFfail.log
Maybe the answer is in the Asterisk trace
If the trace is not sufficient please let me know and I will provide another trace with more options set.
By: tbsky (tbsky) 2008-01-31 05:01:05.000-0600

hi:
  another report. my snom 300 can not send DTMF  correctly to PSTN with asterisk 1.4.17.
and it sometime would trigger some bugs of asterisk. when the bug is triggered,  other ip phones are infected and can not send correct DTMF. i must reload asterisk to clear the situation.
  my asterisk is rfc2833. snom DTMF payload type is 101.
  i check the asterisk log about snom DTMF, it looks bad, it seem queued in asterisk and never send out. log like below:

[Jan 31 19:08:13] DTMF[32106] channel.c: DTMF end '1' received on SIP/3340-08214d48, duration 160 ms
[Jan 31 19:08:13] DTMF[32106] channel.c: DTMF end '1' put into dtmf queue on SIP/3340-08214d48
[Jan 31 19:08:17] DTMF[32106] channel.c: DTMF end '1' received on SIP/3340-08214d48, duration 160 ms
[Jan 31 19:08:17] DTMF[32106] channel.c: DTMF end '1' put into dtmf queue on SIP/3340-08214d48
[Jan 31 19:08:19] DTMF[32106] channel.c: DTMF end '1' received on SIP/3340-08214d48, duration 320 ms
[Jan 31 19:08:19] DTMF[32106] channel.c: DTMF end '1' put into dtmf queue on SIP/3340-08214d48
[Jan 31 19:08:21] DTMF[32106] channel.c: DTMF end '2' received on SIP/3340-08214d48, duration 480 ms
[Jan 31 19:08:21] DTMF[32106] channel.c: DTMF end '2' put into dtmf queue on SIP/3340-08214d48
[Jan 31 19:08:23] DTMF[32106] channel.c: DTMF end '1' received on SIP/3340-08214d48, duration 480 ms
[Jan 31 19:08:23] DTMF[32106] channel.c: DTMF end '1' put into dtmf queue on SIP/3340-08214d48
[Jan 31 19:08:24] DEBUG[32106] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
[Jan 31 19:08:24] DEBUG[32106] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
[Jan 31 19:08:24] DEBUG[32106] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
[Jan 31 19:08:24] VERBOSE[32106] logger.c: -- Hungup 'Zap/1-1'
[Jan 31 19:08:24] VERBOSE[32106] logger.c: -- fixed jitterbuffer destroyed on channel Zap/1-1


By: Arnd Schmitter (arnd) 2008-02-06 02:54:12.000-0600

Hi,

i have also a Problem when sending DTMF from SIP to ZAP since upgrade from 1.4.11 to 1.4.17.

First, when I don't use feature codes, all functions well.

But when I use feature codes [for example: DIAL(xxx||TWK)] and sending some digits in a short time, the order of Digits changed.
Example:
originate sip/test application dial ZAP/g1/XXX||TWK
I now enter (fast) 123456 on my SIP Phone (Siemens btw)
Asterisk sends 123465 out on ZAP Channel.
If I enter 1234 wait a second and then 56 all went well.
If I enter 12345 and wait Zap send 1234 i continue to wait for some secs and then enter 6. Zap send 65

I've attached a debuglog where you can see, that the order changed.
By: Dmitry Andrianov (dimas) 2008-02-06 03:32:07.000-0600

Arnd,
please do the following:
1. apply v1-feature-debug.patch (attached) - this just fixes res_feature to display digit sequence it currently processes.
2. Attach your features.conf

Also, at the first glance it looks like the issue MAY be caused bu the way autoservice works. If it is not your production system, you may want trying patch from http://bugs.digium.com/view.php?id=11635 - sorry it was NOT tested yet.
By: Arnd Schmitter (arnd) 2008-02-06 04:26:39.000-0600

Hi Dimas,

I've attached a new log with first patch applied:
arnd-debug+v1-feature-debug.log

Also, i've attached my features.conf

I will see if I'm able to test the other Patch you mentioned at the end of your note
By: Arnd Schmitter (arnd) 2008-02-06 04:53:47.000-0600

I've now also tested the second patch, but the Problem still exists.
By: Dmitry Andrianov (dimas) 2008-02-06 05:29:24.000-0600

arnd,
well, it means that issue is unrelated :)

Ok, from the log it seems that start of DTMF 6 is ignored for some reason. I would assume there is something wrong in the ast_read function of channel.c

Would you please add DTMF logging as well (edit /etc/asterisk/logger.conf ) and make sure either console of messages line contains ",dtmf" at the end.
By: Arnd Schmitter (arnd) 2008-02-06 05:56:37.000-0600

Hi dimas,

i've attached a new log with dtmf logging enabled.

I hope i've understood you correctly and appended ",dtmf" at the end of each DTMF line
By: Dmitry Andrianov (dimas) 2008-02-06 06:09:12.000-0600

arnd, please try v1-11740.patch.

The patch is far from being ideal but at least it will allow checking if I understand the root cause of the problem...
By: Arnd Schmitter (arnd) 2008-02-06 06:17:43.000-0600

This seems to work. With the patch i'm not able to reproduce the error anymore.
By: Dmitry Andrianov (dimas) 2008-02-06 06:31:48.000-0600

Okay, it means we know why error happens.

To whom it may concers: the DTMF post-processing code of ast_read although being in emulation mode still allowed passthu of DTMF_BEGIN which is something it should NOT be doing. In emulation mode it can only queue stuff nothing more.

In the arnd's case emulation started on digit '4' because it was going too close (without proper gap) to the previous '3'. So when later DTMF_BEGIN of '5' arrived, ast_read passed it thru and updated status variables (like chan->dtmf_tv) although it was still in the middle of emulation '4'.
By: David Brillert (aragon) 2008-02-06 12:34:06.000-0600

Dimas

I applied your patch for testing another problem I was having.

Description:
Incoming zap call via PST (analog or PRI-ISDN)
SIP extension would answer and dial *2 to atxfer or *999 to record
No features would work on incoming zap.

After applying your patch all of my features now work!!!
I am very grateful :)

What is the status of your patch?
Will it be merged to 1.4.18?
Does it need more work (it seems to be working for me)?
By: Dmitry Andrianov (dimas) 2008-02-06 14:28:45.000-0600

I'm glad my patch fixes your case too.

As of its status - I think it is pretty much finished for a quick fix.

Speaking about long-term solution... Well, to me the DTMF post-processing code in ast_read look way too complex and prone to errors. Sinse there are more issues in this code (see 11911), I'm going to rewrite it completely and offer a patch for review. But that is another story - I do not think such a patch can be applied to stable 1.4, only trunk...
By: David Brillert (aragon) 2008-02-06 14:59:07.000-0600

Dimas

Thanks again, I didn't open ticket 11740 but for me it could be closed out with your patch.

I'll keep monitoring this ticket and 11911
Do you suggest I apply each patch separately to avoid the issues in 11740 and 11911?

I'd still like to know if either of these patches will make it into 1.4.18?
By: David Brillert (aragon) 2008-02-07 11:18:04.000-0600

Hi Dimas

I was a little hasty in saying my problems with atxfer and automon were fixed.
I did not test both analog zap and ISDN PRI scenarios until today after your patch.
Your patch fixed a problem using atxfer and automon on analog PSTN zap lines BUT did not fix the same problem on a PRI circuit I am using for my tests.
Outgoing PRI I am able to do an attended transfer or automon perfectly but on incoming PRI calls I cannot get the atxfer or automon codes to work.
Instead of recording the call on the incoming call when I press my DTMF *999 the caller hears the DTMF tones and the call is never recorded. Same applies to atxfer when I dial *2.

I tested this exact scenario on a SIP trunk and it works perfectly incoming and outgoing so I don't think this is a configuration problem.

I have absolutely no idea what would cause the incoming PRI call to behave in this way.
Your patch fixed this problem on my analog lines, but not PRI so I suspect a bug somewhere.
By: Dmitry Andrianov (dimas) 2008-02-07 11:29:33.000-0600

agaron,
please apply v1-feature-debug.patch to extend debug info a bit, turn on dtmf and debug logging in /etc/asterisk/logger.conf and collect debug log.
By: David Brillert (aragon) 2008-02-07 11:35:52.000-0600

I have attached a DTMF trace for help with my incoming PRI DTMF problem when I try to use automon or *2
incomingPRIfeatureDTMF.txt

My features.conf looks like this:

[general]
parkext         => 7000
parkpos         => 7001-7010
parkingtime     => 18
context         => parkedcalls
transferdigittimeout => 3
pickupexten     =  *71
featuredigittimeout =  500


[featuremap]
blindxfer       => *1
atxfer          => *2
automon         => *999
disconnect      => *0
parkcall        => ASTERISK-68
By: Dmitry Andrianov (dimas) 2008-02-07 12:26:42.000-0600

Aragon,
I do not see any debug messages. Have you executed "core set debug 1" from the CLI ? Also, please make a file which does not have terminal color sequances. Plain text would be preferable.
By: David Brillert (aragon) 2008-02-07 12:39:21.000-0600

Dimas

I have uploaded incomingPRIfeatureDTMFdebugPlain.txt but not yet applied your v1 patch.

I hope this helps
By: David Brillert (aragon) 2008-02-07 12:47:43.000-0600

I dont know if this will be helpful but I am uploading a log from successful automon during incoming SIP call.

incomingSIPfeaturesDTMF.txt
By: Dmitry Andrianov (dimas) 2008-02-07 12:52:30.000-0600

aragon,
from your log I would say Asterisk is not checkin features at all. Could you test really simple dialplan which calls SIP/something|Ww on receipt of the PRI call? This would quickly identify if the problem somehow caused by dialplan/AGI or something else.
By: Dmitry Andrianov (dimas) 2008-02-07 12:55:12.000-0600

Oh, sorry!
you should do "set core debug 3" not 1. This is why I do not see any feature stuff...

Sorry again
By: David Brillert (aragon) 2008-02-07 13:47:53.000-0600

Hi Dimas

Thanks for pointing to us to dialplan... we have made some test and see that we using Local channel to reach SIP and since we add /n to local channels, all problems look fixed
By: David Brillert (aragon) 2008-02-07 13:57:56.000-0600

BTW even with /n fix...
Snom still fails atxfer and automon if SIP INFO method is used.
Snom works OK if rfc2833 is used for DTMF.
By: Dmitry Andrianov (dimas) 2008-02-07 14:13:55.000-0600

I can take a look at your logs if you can "core set debug 3" and make simple dialplan (ideally two-liner: Accept + Dial)
By: David Brillert (aragon) 2008-02-07 15:44:37.000-0600

Dimas

I have uploaded snomSIPINFOdtmf.txt

The file is a little busy... but is captures a single call from 6002(Aastra) to 6000(Snom360 v7.1.30)
By: Dmitry Andrianov (dimas) 2008-02-08 03:52:46.000-0600

Aragon,
there is no single mention of "dtmf" at all in your last file.

If I were you I would turn SIP debug and made sure Asterisk actually receives these SIP INFO messages.
By: David Brillert (aragon) 2008-02-08 08:18:18.000-0600

Dimas

I didnt see any DTMF messages in last trace either.
I can definitely hear the DTMF when it is issued over the handset of a Aastra 480i so I know it is being sent from the Snom 360.
I enabled sip set debug in my trace but I dont see any evidence of DTMF captured in this log either (but I'm not familiar with debugging SIP INFO DTMF)

Call from 6004 to 6000
New log snomSIPINFOdtmfSIPDEBUG.txt with:
core set debug 3
sip set debug
etc...

I hope this one hits the mark ;)
By: Dmitry Andrianov (dimas) 2008-02-08 08:40:52.000-0600

I'm not the best help here. The only thing I can think of is that RTP stream goes through Asterisk while INFO messages are sent directly between phones. Honestly I'm not even sure it is possible - I'm not very familar with SIP.

This can be easily checked if you capture SIP trace on your Snom phone (it allows this ight from the web UI).

Another thing I can think of (which is real) is that DTMF tones are passed inband (that is as sounds in the voice stream). That is why you hear them and that is why Asterisk does not react to them.

Also, are you sure DTMF mode of Asterisk match to one configured on both phones?
By: Norman Franke (norman) 2008-02-09 23:31:29.000-0600

I'm using asterisk-1.4.18-rc4 and 1.4.17 and I can't get DTMF recognition to work at all. An older version, I think pre-1.4.10 does work.
By: Dmitry Andrianov (dimas) 2008-02-11 01:51:47.000-0600

norman, words "does not work at all" do not provide good description of a problem really. Try applying v1-11740.patch first. If it does not fix your problem please provide:
1. scenario which does not work
2. related configuration files
3. console log with "core set debug 3" and both "debug" and "dtmf" logging turned on for the console (see /etc/asterisk/logger.conf)
By: Norman Franke (norman) 2008-02-11 10:03:14.000-0600

"norman, words "does not work at all" do not provide good description of a problem really. Try applying v1-11740.patch first."

I'm applying the patch now. What I meant was, "I can't get a single DTMF digit to be recognized under any circumstances. Log files show absolutely nothing, as if nothing happened. If the remote client sends DTMF as SIP INFO, it works. I'll let you know how the patched version goes.
By: Norman Franke (norman) 2008-02-11 12:46:28.000-0600

Patch applied. No change. Nothing is displayed with verbose 3, just:

   -- Executing [7709@smcx:3] Read("SIP/station300-06ed7800", "TEST||7") in new stack
   -- Executing [7709@smcx:4] SayDigits("SIP/station300-06ed7800", "") in new stack

Dial plain:

exten => 7709,1,Answer()
exten => 7709,n,Playback(high)
exten => 7709,n,Read(TEST||7)
exten => 7709,n,SayDigits(${TEST})
By: Dmitry Andrianov (dimas) 2008-02-11 14:56:01.000-0600

verbose is not enough.
1. you need to edit /etc/asterisk/logger.conf to make sure "debug" and "dtmf" go either to file or console
2. reload asterisk and issue "core set debug 3". Debug level is NOT the same as vervose level

And collect new logs with these settings. Also, could you clarify your "If the remote client sends DTMF as SIP INFO, it works" ? How does it NOT work? With RFC2833 or inband?
By: David Brillert (aragon) 2008-02-11 15:33:36.000-0600

Hi Dimas,

You were right on some issues regarding SIP INFO
Both endpoints must support SIP INFO before DTMF will be passed even if re-invite is disabled.
At least this was the case in my testing between Snom 360 v7.1.30 and Aastra 480i v1.4.2.3000
When both phones were configured for SIP INFO method I got automon and atxfer to work.
And this is where things got strange...
I could not suppress DTMF to the remote party when I invoked automon using SIP INFO.
I could suppress DTMF to the remote party when I invoked automon using rfc2833.

For what its worth I will only use rfc2833 from now on.
I dont know if it is a bug or not but I dont want my PSTN callers to hear my DTMF tones when I activate features and this is what happened when I got SIP INFO to work.
DTMF played to the other caller during atxfer and automon using SIP INFO.
By: David Brillert (aragon) 2008-02-11 15:38:58.000-0600

For the record I am letting Snom "off the hook"
Since I was able to get the Snom working with SIP INFO I don't think the phone is buggy.
In fact I love my Snom phones :)
Also for anyone who runs into my problem...
Prio to Snom releases 7.1.30 DTMF was sent by rfc2833 and SIP INFO at the same time. In 7.1.30 Snom only sends rfc2833 or SIP INFO and not both.
It was this change in behavior that sent me on this hunt in the first place.
By: Norman Franke (norman) 2008-02-11 20:01:28.000-0600

I think I'm talking about a different issue. I misread. I'm using inline DTMF, which doesn't work via phone or SIP client.

Using RTP 2833 Event from a PJSIP client does work just fine.
By: tbsky (tbsky) 2008-02-12 22:27:01.000-0600

hi:
   today i try asterisk 1.4.18 with v1-11740.patch. but snom 300 phones still can not send DTMF correctly.
other ip phones like grandstream, fanvil is ok. DTMF still queued forever like below:

726] channel.c: DTMF end '1' received on SIP/3340-0820e220, duration 86880 ms
[Feb 13 12:24:42] DTMF[3726] channel.c: DTMF begin emulation of '1' with duration 86880 queued on SIP/3340-0820e220
[Feb 13 12:24:56] DTMF[3726] channel.c: DTMF end '1' received on SIP/3340-0820e220, duration 160 ms
[Feb 13 12:24:56] DTMF[3726] channel.c: DTMF end '1' put into dtmf queue on SIP/3340-0820e220
[Feb 13 12:25:12] DTMF[3726] channel.c: DTMF end '1' received on SIP/3340-0820e220, duration 160 ms
[Feb 13 12:25:12] DTMF[3726] channel.c: DTMF end '1' put into dtmf queue on SIP/3340-0820e220
[Feb 13 12:25:18] DTMF[3726] channel.c: DTMF end '1' received on SIP/3340-0820e220, duration 160 ms
[Feb 13 12:25:18] DTMF[3726] channel.c: DTMF end '1' put into dtmf queue on SIP/3340-0820e220
[Feb 13 12:25:22] DTMF[3726] channel.c: DTMF end '2' received on SIP/3340-0820e220, duration 160 ms
[Feb 13 12:25:22] DTMF[3726] channel.c: DTMF end '2' put into dtmf queue on SIP/3340-0820e220
[Feb 13 12:25:31] DTMF[3726] channel.c: DTMF end '1' received on SIP/3340-0820e220, duration 160 ms
[Feb 13 12:25:31] DTMF[3726] channel.c: DTMF end '1' put into dtmf queue on SIP/3340-0820e220
By: Dmitry Andrianov (dimas) 2008-02-13 01:56:01.000-0600

tbsky,
to me it looks like completely unrelated issue and I would fill another issue on Mantis.
The key here is the following log line:

726] channel.c: DTMF end '1' received on SIP/3340-0820e220, duration 86880 ms

which means frame's len field value is way too large. This looks like bug in rtp.c or something. If I had to investigate such an issue, I would be interested in:
1. inclusion of rtp debug into debug output in addition to DTMF debug
2. value of rfc2833compensate parameter for the peer.

But again, I would fill another issue.
By: tbsky (tbsky) 2008-02-13 03:14:32.000-0600

dimas:
    i think that explains why sometimes the whole DTMF suddenly stop working. when snom triggers the bug, others ip phones can not use DTMF also. maybe because asterisk is waiting the "86880 ms" duration time over?
By: Dmitry Andrianov (dimas) 2008-02-13 03:18:06.000-0600

it basically means that asterisk will also try to generate DTMF_BEGIN + DTMF_END with 86 seconds between them ignoring (actually queueing) any DTMF it receives between them. So yes, during these 86 seconds NO DTMF will work at all.
By: tbsky (tbsky) 2008-02-13 09:57:40.000-0600

dimas:
  i also try zoiper 2.13 & 2.14 with iax2 to test DTMF problem. still using asterisk 1.4.18 with your patch. i press the key fast and sometimes asterisk recognize the key sequence incorrectly. i found the dtmf duration would be "0" ms if everything is correct. but when problem occurs, it would become some random value. i don't know the problem comes from asterisk or zoiper. problem log like below:

[Feb 13 23:46:41] DTMF[4525] channel.c: DTMF end emulation of '3' queued on IAX2/96021-1
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end '6' received on IAX2/96021-1, duration 431 ms
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end '6' put into dtmf queue on IAX2/96021-1
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end '3' received on IAX2/96021-1, duration 431 ms
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end '3' put into dtmf queue on IAX2/96021-1
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF begin emulation of '2' with duration 130 queued on IAX2/96021-1
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end emulation of '2' queued on IAX2/96021-1
[Feb 13 23:46:41] DEBUG[4616] chan_zap.c: Started VLDTMF digit '2'
[Feb 13 23:46:41] DTMF[4525] channel.c: DTMF end emulation of '6' queued on IAX2/96021-1
[Feb 13 23:46:41] DEBUG[4616] chan_zap.c: Ending VLDTMF digit '2'
[Feb 13 23:46:41] DTMF[4525] channel.c: DTMF end emulation of '3' queued on IAX2/96021-1
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end '6' received on IAX2/96021-1, duration 253 ms
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end '6' put into dtmf queue on IAX2/96021-1
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end '3' received on IAX2/96021-1, duration 253 ms
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF end '3' put into dtmf queue on IAX2/96021-1
[Feb 13 23:46:41] DTMF[4616] channel.c: DTMF begin emulation of '6' with duration 130 queued on IAX2/96021-1
[Feb 13 23:46:42] DTMF[4616] channel.c: DTMF end emulation of '6' queued on IAX2/96021-1


By: Dmitry Andrianov (dimas) 2008-02-13 15:22:07.000-0600

tbsky, I have no idea what number you actually trying to enter using DTMF so it is somewhat difficult to understand what is wrong.
Also, you are providing only piece of the log so it is difficult to understand where problem occurs - something may be already wrong before the peace you show.
By: Dmitry Andrianov (dimas) 2008-02-13 15:36:20.000-0600

... and also there is another related issue which may affact you - http://bugs.digium.com/view.php?id=11911
By: tbsky (tbsky) 2008-02-13 19:01:55.000-0600

dimas:
  sorry i should upload the full log. i will attach snom and zoiper log later. this morning i met a new DTMF problem. i use grandstream and press keys quickly. most times it is ok, but one time when i press "12345678". asterisk received it but send out as "12245678". you can see it in the bottom of "grandstream-dtmf.txt". is this the problem related to bug 11911?
By: tbsky (tbsky) 2008-02-13 19:24:08.000-0600

dimas:
   upload the snom log "snom-dtmf.txt". i press "1" and "2" slowly.  the remote system do receive the "1", but the log didn't show asterisk send it out. asterisk then fall into the long duration waiting, and DTMF is not working anymore.
By: Dmitry Andrianov (dimas) 2008-02-14 17:54:44.000-0600

tbsky,
I really-really suggest you open another issue titled "DTMF duration detected wrong", put your last comment there and attach snom-dtmf.txt

Otherwise this (11740) gonna stay forever attaching all DTMF related problems to itself. So none of them will be closed.

You definitely has reproducible case when DTMF_END frame len field gets improperly initialized for some reason.

[Feb 14 09:09:14] DTMF[20816] channel.c: DTMF end '1' received on SIP/3340-0825f060, duration 74617280 ms

An I would repeat myself:

"...which means frame's len field value is way too large. This looks like bug in rtp.c or something. If I had to investigate such an issue, I would be interested in:
1. inclusion of rtp debug into debug output in addition to DTMF debug
2. value of rfc2833compensate parameter for the peer.

But again, I would fill another issue. "
By: tbsky (tbsky) 2008-02-15 03:14:00.000-0600

dimas:
  it seems i met 3 different kinds of DTMF problems. i already open an issue for snom phones as you advised.  can you identify if my grandstream problem "grandstream-dtmf.txt" (12345678 sent as 12245678) is related to bug 11911?

 i will create another DTMF issue for zoiper later.

 thanks a lot for your help!!
By: tbsky (tbsky) 2008-02-17 20:19:59.000-0600

dimas:
   after applying the patch in bug 11911, the grandstream DTMF seems working fine now. i tried hundreds of fast DTMF keys. all of them are correct.
  thanks a lot for your hint!!
By: Digium Subversion (svnbot) 2008-02-18 17:53:24.000-0600

Repository: asterisk
Revision: 103801

U   branches/1.4/main/channel.c

------------------------------------------------------------------------
r103801 | file | 2008-02-18 17:53:22 -0600 (Mon, 18 Feb 2008) | 10 lines

Ensure that emulated DTMFs do not get interrupted by another begin frame.
(closes issue ASTERISK-11209)
Reported by: gserra
Patches:
     v1-11740.patch uploaded by dimas (license 88)
(closes issue ASTERISK-11403)
Reported by: tsearle
(closes issue ASTERISK-10143)
Reported by: xmarksthespot

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

http://svn.digium.com/view/asterisk?view=rev&revision=103801
By: Digium Subversion (svnbot) 2008-02-18 17:55:11.000-0600

Repository: asterisk
Revision: 103802

_U  trunk/
U   trunk/main/channel.c

------------------------------------------------------------------------
r103802 | file | 2008-02-18 17:55:10 -0600 (Mon, 18 Feb 2008) | 18 lines

Merged revisions 103801 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r103801 | file | 2008-02-18 19:56:48 -0400 (Mon, 18 Feb 2008) | 10 lines

Ensure that emulated DTMFs do not get interrupted by another begin frame.
(closes issue ASTERISK-11209)
Reported by: gserra
Patches:
     v1-11740.patch uploaded by dimas (license 88)
(closes issue ASTERISK-11403)
Reported by: tsearle
(closes issue ASTERISK-10143)
Reported by: xmarksthespot

........

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

http://svn.digium.com/view/asterisk?view=rev&revision=103802