[asterisk-users] DTMF incorrectly sent ( RFC2833 or SIPInfo )

David asterisk.org at spam.lublink.net
Sun Apr 24 12:16:25 CDT 2011


Hello,

I will summarize the current situation. I have reduced the bug to two 
asterisk machines. One of which has a PRI card ( DAHDI channels).

The first server calls the second server with SIP. The second server 
bridges the SIP channel to a DAHDI channel. When I send DTMFs from the 
first server ( SIP Info or RFC2833) they are incorrectly sent.

I setup a second scenario where the first server calls the second with 
SIP and the second server uses the dialplan to answer, it plays back a 
message to generate audio. The DTMFs are received perfectly.

Asterisk server that is dialing ( first server ):

exten => 22,1,Dial(SIP/6 at pri1.omnity.net,30,D(132412983#))
exten => 24,1,Dial(SIP/5 at pri1.omnity.net,30,D(132412983#))

Asterisk server that is answering ( second server ):

exten => 5,1,Dial(DAHDI/g1/14186939930,30)
exten => 6,1,Progress
exten => 6,n,Wait(5)
exten => 6,n,Answer
exten => 6,n,Playback(vm-login&vm-login&vm-login&vm-login&vm-login)
exten => 6,n,Wait(30)

Here is the latest console output, notice that the # was sent several 
times but in reality it was only sent once by the first server.

This is the scenario where I dialed 22, the DTMF ( SIP Info ) is sent 
properly.

[Apr 24 12:49:46] DTMF[2844]: channel.c:2907 __ast_read: DTMF end 
emulation of '1' queued on SIP/omnity-00000022
[Apr 24 12:49:46] DTMF[2844]: channel.c:2874 __ast_read: DTMF begin '1' 
received on SIP/omnity-00000022
[Apr 24 12:49:46] DTMF[2844]: channel.c:2878 __ast_read: DTMF begin 
ignored '1' on SIP/omnity-00000022
[Apr 24 12:49:46] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '3' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:46] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '3' on SIP/omnity-00000022
[Apr 24 12:49:46] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '2' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:46] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '2' on SIP/omnity-00000022
[Apr 24 12:49:46] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '4' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:46] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '4' on SIP/omnity-00000022
[Apr 24 12:49:46] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '1' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:46] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '1' on SIP/omnity-00000022
[Apr 24 12:49:47] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '2' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:47] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '2' on SIP/omnity-00000022
[Apr 24 12:49:47] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '9' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:47] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '9' on SIP/omnity-00000022
[Apr 24 12:49:47] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '8' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:47] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '8' on SIP/omnity-00000022
[Apr 24 12:49:47] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '3' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:47] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '3' on SIP/omnity-00000022
[Apr 24 12:49:48] DTMF[2844]: channel.c:2802 __ast_read: DTMF end '#' 
received on SIP/omnity-00000022, duration 100 ms
[Apr 24 12:49:48] DTMF[2844]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on SIP/omnity-00000022

==================================================

Here is the console from the first scenario using SIP Info :

[Apr 24 12:50:18] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '1' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:18] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '1' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:18] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '1' 
received on DAHDI/1-1
[Apr 24 12:50:18] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '1' on DAHDI/1-1
[Apr 24 12:50:18] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '1' 
received on DAHDI/1-1, duration 39 ms
[Apr 24 12:50:18] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '1' on DAHDI/1-1
[Apr 24 12:50:18] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '1' queued on SIP/omnity-00000023
[Apr 24 12:50:18] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '1' 
received on DAHDI/1-1
[Apr 24 12:50:18] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '1' on DAHDI/1-1
[Apr 24 12:50:18] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '1' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:18] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '1' on DAHDI/1-1
[Apr 24 12:50:18] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '3' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:18] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '3' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:18] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '3' queued on SIP/omnity-00000023
[Apr 24 12:50:18] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '2' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:18] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '2' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:19] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '2' queued on SIP/omnity-00000023
[Apr 24 12:50:19] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '4' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:19] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '4' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:19] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '4' queued on SIP/omnity-00000023
[Apr 24 12:50:19] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '1' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:19] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '1' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:19] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '1' queued on SIP/omnity-00000023
[Apr 24 12:50:19] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '2' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:19] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '2' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:19] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '2' queued on SIP/omnity-00000023
[Apr 24 12:50:19] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '9' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:19] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '9' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:20] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '9' 
received on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '9' on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '9' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:20] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '9' on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '9' queued on SIP/omnity-00000023
[Apr 24 12:50:20] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '9' 
received on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '9' on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '8' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:20] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '8' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:20] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '9' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:20] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '9' on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '8' queued on SIP/omnity-00000023
[Apr 24 12:50:20] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '3' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:20] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '3' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:20] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '3' queued on SIP/omnity-00000023
[Apr 24 12:50:20] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on SIP/omnity-00000023, duration 100 ms
[Apr 24 12:50:20] DTMF[2845]: channel.c:2828 __ast_read: DTMF begin 
emulation of '#' with duration 100 queued on SIP/omnity-00000023
[Apr 24 12:50:20] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:20] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:20] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:21] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:21] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:21] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:21] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:21] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:21] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:22] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:22] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:22] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:22] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2874 __ast_read: DTMF begin '#' 
received on DAHDI/1-1
[Apr 24 12:50:22] DTMF[2845]: channel.c:2878 __ast_read: DTMF begin 
ignored '#' on DAHDI/1-1
[Apr 24 12:50:23] DTMF[2845]: channel.c:2802 __ast_read: DTMF end '#' 
received on DAHDI/1-1, duration 80 ms
[Apr 24 12:50:23] DTMF[2845]: channel.c:2858 __ast_read: DTMF end 
passthrough '#' on DAHDI/1-1
[Apr 24 12:50:23] DTMF[2845]: channel.c:2907 __ast_read: DTMF end 
emulation of '#' queued on SIP/omnity-00000023

I notice that the # key was repeated several times by the DTMF even 
though the dialplan only calls # once. Why are these two different when 
the DTMF sequence is exactly the same ?

Any ideas?

David






More information about the asterisk-users mailing list