Long DTMF tone duration on outbound PSTN calls

[ivo.ivanov]

Hello,

We have problems with dtmf on outbound pstn calls: the duration of the generated dtmf tones is inconsistent, generally way too long (2-3 seconds or more). Sending new dtmf digit while the previous one is still playing changes the tone frequencies; any voice input from the SIP client (speaking into or simply touching the mic) ends the tone immediately, and the first dtmf digit that follows is perfectly short… but only the first one.

We use Asterisk as voip gateway sip → pstn on Dell ML370 G2 running Slackware 12.3 / Asterisk 1.4.26 / DAHDI Linux 2.2.0.1 / Wildcard TE410P (3rd Gen). Same issues with Asterisk 1.4.22.1 and Asterisk 1.6.1.0

The sip clients are configured to send sip info (same problem using rfc2238).
Same behaviour on calls originated at the console:

CLI>console dial 91NPANXXxxxx
… answer the call …
CLI>console dial 1
… long dtmf tone …

Below is the Asterisk log showing (1) the sip info events with duration 80 and (2) the long interval between Started / Ending VLDTMF entries. On this particular call the SIP client sent dtfm ‘1’, ‘2’ and ‘3’ with pauses in between, and the digit ‘3’ played for 4 seconds…

Any help/suggestions are appeciated. Thanks, Ivo.

[Jul 22 19:42:19] NOTICE[32090] cdr.c: CDR simple logging enabled.
[Jul 22 19:42:19] NOTICE[32090] loader.c: 146 modules will be loaded.
[Jul 22 19:42:19] WARNING[32090] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener.
[Jul 22 19:42:19] VERBOSE[32090] logger.c: Loading [Sub]Agent Module
[Jul 22 19:42:19] NOTICE[32090] pbx_ael.c: Starting AEL load process.
[Jul 22 19:42:19] NOTICE[32090] pbx_ael.c: AEL load process: calculated config file name ‘/etc/asterisk/extensions.ael’.
[Jul 22 19:42:19] NOTICE[32090] pbx_ael.c: AEL load process: parsed config file name ‘/etc/asterisk/extensions.ael’.
[Jul 22 19:42:19] NOTICE[32090] pbx_ael.c: AEL load process: checked config file name ‘/etc/asterisk/extensions.ael’.
[Jul 22 19:42:19] NOTICE[32090] pbx_ael.c: AEL load process: compiled config file name ‘/etc/asterisk/extensions.ael’.
[Jul 22 19:42:19] NOTICE[32090] pbx_ael.c: AEL load process: merged config file name ‘/etc/asterisk/extensions.ael’.
[Jul 22 19:42:19] NOTICE[32090] pbx_ael.c: AEL load process: verified config file name ‘/etc/asterisk/extensions.ael’.
[Jul 22 19:42:37] VERBOSE[32113] logger.c:
<— SIP read from 192.168.1.155:5060 —>
INVITE sip:913198922480@192.168.1.192:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK2109433702
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060
Call-ID: 2501839055@192.168.1.155
CSeq: 1 INVITE
Contact: sip:192.168.1.155:5060
Supported: timer
max-forwards: 70
user-agent: CosmoCom-VCS-1.0
Session-Expires: 180
Content-Type: application/sdp
Content-Length: 225

v=0
o=CosmoCom-VCS-1.0 3457298669 3457298669 IN IP4 192.168.1.155
s=session
c=IN IP4 192.168.1.155
t=0 0
m=audio 60404 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15,66,70,72,74

<------------->
[Jul 22 19:42:37] VERBOSE[32113] logger.c: — (13 headers 9 lines) —
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Sending to 192.168.1.155 : 5060 (no NAT)
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Using INVITE request as basis request - 2501839055@192.168.1.155
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Found peer ‘8888’
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Found RTP audio format 0
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Found RTP audio format 101
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Peer audio RTP is at port 192.168.1.155:60404
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Found audio description format PCMU for ID 0
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Found audio description format telephone-event for ID 101
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x1 (telephone-event), combined - 0x0 (nothing)
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Peer audio RTP is at port 192.168.1.155:60404
[Jul 22 19:42:37] VERBOSE[32113] logger.c: Looking for 913198922480 in voip (domain 192.168.1.192)
[Jul 22 19:42:37] VERBOSE[32113] logger.c: list_route: hop: sip:192.168.1.155:5060
[Jul 22 19:42:37] VERBOSE[32113] logger.c:
<— Transmitting (no NAT) to 192.168.1.155:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK2109433702;received=192.168.1.155
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060
Call-ID: 2501839055@192.168.1.155
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: sip:913198922480@192.168.1.192
Content-Length: 0

<------------>
[Jul 22 19:42:37] VERBOSE[32122] logger.c: – Executing [913198922480@voip:1] Dial(“SIP/8888-08212538”, “DAHDI/g0/13198922480”) in new stack
[Jul 22 19:42:37] DEBUG[32122] chan_dahdi.c: Dialing ‘13198922480’
[Jul 22 19:42:37] DEBUG[32122] chan_dahdi.c: Deferring dialing…
[Jul 22 19:42:37] VERBOSE[32122] logger.c: – Called g0/13198922480
[Jul 22 19:42:37] DEBUG[32122] chan_dahdi.c: Ignoring wink on channel 1
[Jul 22 19:42:37] DEBUG[32122] chan_dahdi.c: Sent deferred digit string: T13198922480w
[Jul 22 19:42:49] VERBOSE[32122] logger.c: Audio is at 192.168.1.192 port 17338
[Jul 22 19:42:49] VERBOSE[32122] logger.c: Adding codec 0x4 (ulaw) to SDP
[Jul 22 19:42:49] VERBOSE[32122] logger.c:
<— Transmitting (no NAT) to 192.168.1.155:5060 —>
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK2109433702;received=192.168.1.155
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: sip:913198922480@192.168.1.192
Content-Type: application/sdp
Content-Length: 186

v=0
o=root 32090 32090 IN IP4 192.168.1.192
s=session
c=IN IP4 192.168.1.192
t=0 0
m=audio 17338 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[Jul 22 19:42:52] VERBOSE[32122] logger.c: – DAHDI/1-1 answered SIP/8888-08212538
[Jul 22 19:42:52] VERBOSE[32122] logger.c: Audio is at 192.168.1.192 port 17338
[Jul 22 19:42:52] VERBOSE[32122] logger.c: Adding codec 0x4 (ulaw) to SDP
[Jul 22 19:42:52] VERBOSE[32122] logger.c:
<— Reliably Transmitting (no NAT) to 192.168.1.155:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK2109433702;received=192.168.1.155
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Contact: sip:913198922480@192.168.1.192
Content-Type: application/sdp
Content-Length: 186

v=0
o=root 32090 32091 IN IP4 192.168.1.192
s=session
c=IN IP4 192.168.1.192
t=0 0
m=audio 17338 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[Jul 22 19:42:52] VERBOSE[32113] logger.c:
<— SIP read from 192.168.1.155:5060 —>
ACK sip:913198922480@192.168.1.192 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK2058959697
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 1 ACK
max-forwards: 70
user-agent: CosmoCom-VCS-1.0
Content-Length: 0

<------------->
[Jul 22 19:42:52] VERBOSE[32113] logger.c: — (9 headers 0 lines) —
[Jul 22 19:42:57] VERBOSE[32113] logger.c:
<— SIP read from 192.168.1.155:5060 —>
INFO sip:913198922480@192.168.1.192 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK466206592
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 2 INFO
max-forwards: 70
user-agent: CosmoCom-VCS-1.0
Content-Type: application/dtmf-relay
Content-Length: 23

Signal=1
Duration=80

<------------->
[Jul 22 19:42:57] VERBOSE[32113] logger.c: — (10 headers 2 lines) —
[Jul 22 19:42:57] VERBOSE[32113] logger.c: Receiving INFO!
[Jul 22 19:42:57] VERBOSE[32113] logger.c: * DTMF-relay event received: 1
[Jul 22 19:42:57] VERBOSE[32113] logger.c:
<— Transmitting (no NAT) to 192.168.1.155:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK466206592;received=192.168.1.155
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 2 INFO
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0

<------------>
[Jul 22 19:42:57] DTMF[32122] channel.c: DTMF end ‘1’ received on SIP/8888-08212538, duration 80 ms
[Jul 22 19:42:57] DTMF[32122] channel.c: DTMF begin emulation of ‘1’ with duration 80 queued on SIP/8888-08212538
[Jul 22 19:42:57] DEBUG[32122] chan_dahdi.c: Started VLDTMF digit ‘1’
[Jul 22 19:42:59] DTMF[32122] channel.c: DTMF end emulation of ‘1’ queued on SIP/8888-08212538
[Jul 22 19:42:59] DEBUG[32122] chan_dahdi.c: Ending VLDTMF digit ‘1’
[Jul 22 19:43:03] VERBOSE[32113] logger.c:
<— SIP read from 192.168.1.155:5060 —>
INFO sip:913198922480@192.168.1.192 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK3531011619
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 3 INFO
max-forwards: 70
user-agent: CosmoCom-VCS-1.0
Content-Type: application/dtmf-relay
Content-Length: 23

Signal=2
Duration=80

<------------->
[Jul 22 19:43:03] VERBOSE[32113] logger.c: — (10 headers 2 lines) —
[Jul 22 19:43:03] VERBOSE[32113] logger.c: Receiving INFO!
[Jul 22 19:43:03] VERBOSE[32113] logger.c: * DTMF-relay event received: 2
[Jul 22 19:43:03] VERBOSE[32113] logger.c:
<— Transmitting (no NAT) to 192.168.1.155:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK3531011619;received=192.168.1.155
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 3 INFO
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0

<------------>
[Jul 22 19:43:03] DTMF[32122] channel.c: DTMF end ‘2’ received on SIP/8888-08212538, duration 80 ms
[Jul 22 19:43:03] DTMF[32122] channel.c: DTMF begin emulation of ‘2’ with duration 80 queued on SIP/8888-08212538
[Jul 22 19:43:03] DEBUG[32122] chan_dahdi.c: Started VLDTMF digit ‘2’
[Jul 22 19:43:04] DTMF[32122] channel.c: DTMF end emulation of ‘2’ queued on SIP/8888-08212538
[Jul 22 19:43:04] DEBUG[32122] chan_dahdi.c: Ending VLDTMF digit ‘2’
[Jul 22 19:43:05] VERBOSE[32113] logger.c:
<— SIP read from 192.168.1.155:5060 —>
INFO sip:913198922480@192.168.1.192 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK4178849706
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 4 INFO
max-forwards: 70
user-agent: CosmoCom-VCS-1.0
Content-Type: application/dtmf-relay
Content-Length: 23

Signal=3
Duration=80

<------------->
[Jul 22 19:43:05] VERBOSE[32113] logger.c: — (10 headers 2 lines) —
[Jul 22 19:43:05] VERBOSE[32113] logger.c: Receiving INFO!
[Jul 22 19:43:05] VERBOSE[32113] logger.c: * DTMF-relay event received: 3
[Jul 22 19:43:05] VERBOSE[32113] logger.c:
<— Transmitting (no NAT) to 192.168.1.155:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.155:5060;branch=z9hG4bK4178849706;received=192.168.1.155
From: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
To: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
Call-ID: 2501839055@192.168.1.155
CSeq: 4 INFO
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0

<------------>
[Jul 22 19:43:05] DTMF[32122] channel.c: DTMF end ‘3’ received on SIP/8888-08212538, duration 80 ms
[Jul 22 19:43:05] DTMF[32122] channel.c: DTMF begin emulation of ‘3’ with duration 80 queued on SIP/8888-08212538
[Jul 22 19:43:05] DEBUG[32122] chan_dahdi.c: Started VLDTMF digit ‘3’
[Jul 22 19:43:09] DTMF[32122] channel.c: DTMF end emulation of ‘3’ queued on SIP/8888-08212538
[Jul 22 19:43:09] DEBUG[32122] chan_dahdi.c: Ending VLDTMF digit ‘3’
[Jul 22 19:43:13] VERBOSE[32122] logger.c: – Hungup ‘DAHDI/1-1’
[Jul 22 19:43:13] VERBOSE[32122] logger.c: == Spawn extension (voip, 913198922480, 1) exited non-zero on ‘SIP/8888-08212538’
[Jul 22 19:43:13] VERBOSE[32122] logger.c: Scheduling destruction of SIP dialog ‘2501839055@192.168.1.155’ in 32000 ms (Method: INFO)
[Jul 22 19:43:13] DEBUG[32122] chan_sip.c: Strict routing enforced for session 2501839055@192.168.1.155
[Jul 22 19:43:13] VERBOSE[32122] logger.c: set_destination: Parsing sip:192.168.1.155:5060 for address/port to send to
[Jul 22 19:43:13] VERBOSE[32122] logger.c: set_destination: set destination to 192.168.1.155, port 5060
[Jul 22 19:43:13] VERBOSE[32122] logger.c: Reliably Transmitting (no NAT) to 192.168.1.155:5060:
BYE sip:192.168.1.155:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.192:5060;branch=z9hG4bK7310be3e;rport
From: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
To: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
Call-ID: 2501839055@192.168.1.155
CSeq: 102 BYE
User-Agent: Asterisk PBX
Max-Forwards: 70
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

---

[Jul 22 19:43:13] VERBOSE[32113] logger.c:
<— SIP read from 192.168.1.155:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.192:5060;branch=z9hG4bK7310be3e;rport=5060;received=192.168.1.192
From: sip:913198922480@192.168.1.192:5060;tag=as36904ecf
To: “DefaultTenant” sip:192.168.1.155:5060;tag=239208668
Call-ID: 2501839055@192.168.1.155
CSeq: 102 BYE
Content-Length: 0

<------------->
[Jul 22 19:43:13] VERBOSE[32113] logger.c: — (7 headers 0 lines) —
[Jul 22 19:43:13] VERBOSE[32113] logger.c: SIP Response message for INCOMING dialog BYE arrived
[Jul 22 19:43:13] VERBOSE[32113] logger.c: Really destroying SIP dialog ‘2501839055@192.168.1.155’ Method: INFO
[Jul 22 19:43:18] VERBOSE[32121] logger.c: Executing last minute cleanups
[Jul 22 19:43:18] VERBOSE[32121] logger.c: == Destroying musiconhold processes