[Home]

Summary:ASTERISK-11999: DTMF transmission is randomly ignored during SIP-SIP calls
Reporter:adeel (adeel)Labels:
Date Opened:2008-05-09 00:30:49Date Closed:2011-06-07 14:03:03
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:It seems that Asterisk is randomly ignoring DTMF generated from the locally connected Polycom 601's/650's/330's. This problem occurs randomly irrespective of which ITSP I use or what number I call. Furthermore, one digit maybe ignored while the next is passed through (in the same call). I've also experienced DTMF troubles even when checking voicemail, so I don't think it's a network/connectivity issue. The DTMF logs indicate that the digit was received but ignored (doesn't mention why, maybe we should put in more descriptive error messages?).

I'm running Asterisk 1.4.18, and have applied a DTMF patch i found on this bugzilla relating to DTMF and bridging calls, which seems to have helped, but not totally solve the problem. The device & user peer definition is set to use RFC2833, while sip.conf defaults to using AUTO and relaxdtmf IS currently set in sip.conf.

it seems that one of the if tests on line 2156 of channels.c is failing, but not sure which one. I'm wondering if Polycom handles DTMF in a non-standard way, or something. I tried testing with another vendor phone (all i had was a grandstream) and still had mixed results (some calls handled DTMF just fine, a few calls wouldn't recognize the DTMF).

I've had this problem ever since I switched to 1.4 (might have had it in 1.2, but it was never as prominent/problematic as it is now), and I'm close to my wits end on the problem.

Unfortunately I don't have the sip debug messages, but do have the CLI verbose output and the DTMF logs, so I'm including them below.

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

[May  6 13:32:55] DTMF[29746] channel.c: DTMF begin '2' received on SIP/6010-b68f8508
[May  6 13:32:55] DTMF[29746] channel.c: DTMF begin ignored '2' on SIP/6010-b68f8508
[May  6 13:32:55] DTMF[29746] channel.c: DTMF end '2' received on SIP/6010-b68f8508, duration 220 ms
[May  6 13:32:55] DTMF[29746] channel.c: DTMF end passthrough '2' on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF begin '5' received on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF begin ignored '5' on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF end '5' received on SIP/6010-b68f8508, duration 150 ms
[May  6 13:32:56] DTMF[29746] channel.c: DTMF end passthrough '5' on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF begin '5' received on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF begin ignored '5' on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF end '5' received on SIP/6010-b68f8508, duration 170 ms
[May  6 13:32:56] DTMF[29746] channel.c: DTMF end passthrough '5' on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF begin '1' received on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF begin ignored '1' on SIP/6010-b68f8508
[May  6 13:32:56] DTMF[29746] channel.c: DTMF end '1' received on SIP/6010-b68f8508, duration 250 ms
[May  6 13:32:56] DTMF[29746] channel.c: DTMF end passthrough '1' on SIP/6010-b68f8508
[May  6 13:33:02] DTMF[29746] channel.c: DTMF begin '1' received on SIP/6010-b68f8508
[May  6 13:33:02] DTMF[29746] channel.c: DTMF begin ignored '1' on SIP/6010-b68f8508
[May  6 13:33:03] DTMF[29746] channel.c: DTMF end '1' received on SIP/6010-b68f8508, duration 260 ms
[May  6 13:33:03] DTMF[29746] channel.c: DTMF end passthrough '1' on SIP/6010-b68f8508
[May  6 13:33:24] DTMF[29746] channel.c: DTMF begin '7' received on SIP/6010-b68f8508
[May  6 13:33:24] DTMF[29746] channel.c: DTMF begin ignored '7' on SIP/6010-b68f8508
[May  6 13:33:25] DTMF[29746] channel.c: DTMF end '7' received on SIP/6010-b68f8508, duration 260 ms
[May  6 13:33:25] DTMF[29746] channel.c: DTMF end passthrough '7' on SIP/6010-b68f8508
[May  6 13:32:52] VERBOSE[29746] logger.c:     -- Executing [*97@from-internal:1] Answer("SIP/6010-b68f8508", "") in new stack
[May  6 13:32:52] VERBOSE[29746] logger.c:     -- Executing [*97@from-internal:2] Wait("SIP/6010-b68f8508", "1") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [*97@from-internal:3] Macro("SIP/6010-b68f8508", "user-callerid|") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:1] NoOp("SIP/6010-b68f8508", "user-callerid: device 6010") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:2] Set("SIP/6010-b68f8508", "AMPUSER=6010") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:3] GotoIf("SIP/6010-b68f8508", "0?report") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:4] ExecIf("SIP/6010-b68f8508", "1|Set|REALCALLERIDNUM=6010") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:5] NoOp("SIP/6010-b68f8508", "REALCALLERIDNUM is 6010") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:6] Set("SIP/6010-b68f8508", "AMPUSER=6010") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:7] Set("SIP/6010-b68f8508", "AMPUSERCIDNAME=Pam Higdon") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:8] GotoIf("SIP/6010-b68f8508", "0?report") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:9] Set("SIP/6010-b68f8508", "AMPUSERCID=6010") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:10] Set("SIP/6010-b68f8508", "CALLERID(all)="Pam Higdon" <6010>") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/6010-b68f8508", "REALCALLERIDNUM=6010") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:12] ExecIf("SIP/6010-b68f8508", "0|Set|CHANNEL(language)=") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:13] NoOp("SIP/6010-b68f8508", "TTL:  ARG1: ") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:14] GotoIf("SIP/6010-b68f8508", "0?continue") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:15] Set("SIP/6010-b68f8508", "__TTL=64") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:16] GotoIf("SIP/6010-b68f8508", "1?continue") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-user-callerid:23] NoOp("SIP/6010-b68f8508", "Using CallerID "Pam" <6010>") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [*97@from-internal:4] Macro("SIP/6010-b68f8508", "get-vmcontext|6010") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-get-vmcontext:1] Set("SIP/6010-b68f8508", "VMCONTEXT=default") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/6010-b68f8508", "0?200:300") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/6010-b68f8508", "") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [*97@from-internal:5] MailboxExists("SIP/6010-b68f8508", "6010@default") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [*97@from-internal:6] GotoIf("SIP/6010-b68f8508", "1?mbexist") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- Executing [*97@from-internal:106] VoiceMailMain("SIP/6010-b68f8508", "6010@default") in new stack
[May  6 13:32:53] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-password' (language 'en')
[May  6 13:32:58] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-youhave' (language 'en')
[May  6 13:32:59] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/1' (language 'en')
[May  6 13:33:00] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-Old' (language 'en')
[May  6 13:33:00] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-message' (language 'en')
[May  6 13:33:01] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-onefor' (language 'en')
[May  6 13:33:03] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-Old' (language 'en')
[May  6 13:33:03] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-first' (language 'en')
[May  6 13:33:03] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-message' (language 'en')
[May  6 13:33:04] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-received' (language 'en')
[May  6 13:33:05] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/day-5' (language 'en')
[May  6 13:33:06] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/mon-3' (language 'en')
[May  6 13:33:07] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/20' (language 'en')
[May  6 13:33:08] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/h-5' (language 'en')
[May  6 13:33:08] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/at' (language 'en')
[May  6 13:33:09] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/9' (language 'en')
[May  6 13:33:10] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/20' (language 'en')
[May  6 13:33:10] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/a-m' (language 'en')
[May  6 13:33:11] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-from-phonenumber' (language 'en')
[May  6 13:33:13] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/1' (language 'en')
[May  6 13:33:14] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/5' (language 'en')
[May  6 13:33:14] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/3' (language 'en')
[May  6 13:33:15] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/0' (language 'en')
[May  6 13:33:16] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/5' (language 'en')
[May  6 13:33:16] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/8' (language 'en')
[May  6 13:33:17] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/3' (language 'en')
[May  6 13:33:18] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/4' (language 'en')
[May  6 13:33:19] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/8' (language 'en')
[May  6 13:33:19] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/0' (language 'en')
[May  6 13:33:20] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'digits/1' (language 'en')
[May  6 13:33:21] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing '/var/spool/asterisk/voicemail/default/6010/Old/msg0000' (language 'en')
[May  6 13:33:25] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-deleted' (language 'en')
[May  6 13:33:26] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-nomore' (language 'en')
[May  6 13:33:27] VERBOSE[29746] logger.c:     -- <SIP/6010-b68f8508> Playing 'vm-advopts' (language 'en')
[May  6 13:33:28] VERBOSE[29746] logger.c:   == Spawn extension (from-internal, *97, 106) exited non-zero on 'SIP/6010-b68f8508'
[May  6 13:33:28] VERBOSE[29746] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/6010-b68f8508", "hangupcall") in new stack
[May  6 13:33:28] VERBOSE[29746] logger.c:     -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/6010-b68f8508", "w") in new stack
[May  6 13:33:28] VERBOSE[29746] logger.c:     -- Executing [s@macro-hangupcall:2] NoCDR("SIP/6010-b68f8508", "") in new stack
[May  6 13:33:28] VERBOSE[29746] logger.c:     -- Executing [s@macro-hangupcall:3] GotoIf("SIP/6010-b68f8508", "1?skiprg") in new stack
[May  6 13:33:28] VERBOSE[29746] logger.c:     -- Executing [s@macro-hangupcall:6] GotoIf("SIP/6010-b68f8508", "1?skipblkvm") in new stack
[May  6 13:33:28] VERBOSE[29746] logger.c:     -- Executing [s@macro-hangupcall:9] GotoIf("SIP/6010-b68f8508", "1?theend") in new stack
[May  6 13:33:28] VERBOSE[29746] logger.c:     -- Executing [s@macro-hangupcall:11] Hangup("SIP/6010-b68f8508", "") in new stack
[May  6 13:33:28] VERBOSE[29746] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/6010-b68f8508' in macro 'hangupcall'
[May  6 13:33:28] VERBOSE[29746] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/6010-b68f8508'


Let me know if there's any more information I can provide
Comments:By: Joshua C. Colp (jcolp) 2008-05-13 15:02:34

Please use an unpatched version of Asterisk with rfc2833compensate set to yes in the general section and report back. If this does not solve the issue please attach (as a file) complete console log output including rtp debug.
By: Joshua C. Colp (jcolp) 2008-06-10 09:23:56

Any update on this?
By: Joshua C. Colp (jcolp) 2008-07-02 21:44:16

Suspended due to lack of response. If you can provide the info this will get looked at.