thr3ads.net - asterisk users - [asterisk-users] Duplicated DTMF with bridged IAX channels maybe? [Apr 2010]

If this information is useful, please help other people find it:
Share via:

James Lamanna

2010-Apr-29 01:57 UTC

[asterisk-users] Duplicated DTMF with bridged IAX channels maybe?

Hi,
I have a duplicated DTMF issue with, it appears, bridged IAX channels.
I have the following setup:

   PRI                  IAX
<-------->* PSTN <------->* Dialplan

I've configured a number on the dialplan server to make and outbound
call to the pstn. This call then comes back into the dialplan server
to SayDigits().
I'm seeing that a few of my digits are being duplicated every so often.
I've attached an IAX trace from the PSTN server to this message where
you can see the duplication (digits 9 & 3). The digits entered were
258963.

Thank you.

-- James

[Apr 28 18:43:42] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 005 ISeqno: 004 Type: DTMF_B  Subclass: 2
[Apr 28 18:43:42] VERBOSE[2806] logger.c:    Timestamp: 14504ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:42] VERBOSE[2799] logger.c: Rx-Frame Retry[ No] --
OSeqno: 005 ISeqno: 004 Type: DTMF_B  Subclass: 2
[Apr 28 18:43:42] VERBOSE[2799] logger.c:    Timestamp: 14504ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:42] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 008 ISeqno: 007 Type: DTMF_B  Subclass: 2
[Apr 28 18:43:42] VERBOSE[2806] logger.c:    Timestamp: 13363ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:42] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 006 ISeqno: 004 Type: DTMF_E  Subclass: 2
[Apr 28 18:43:42] VERBOSE[2806] logger.c:    Timestamp: 14828ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:42] VERBOSE[2799] logger.c: Rx-Frame Retry[ No] --
OSeqno: 006 ISeqno: 004 Type: DTMF_E  Subclass: 2
[Apr 28 18:43:42] VERBOSE[2799] logger.c:    Timestamp: 14828ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:42] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 009 ISeqno: 007 Type: DTMF_E  Subclass: 2
[Apr 28 18:43:42] VERBOSE[2806] logger.c:    Timestamp: 13700ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:43] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 007 ISeqno: 004 Type: DTMF_B  Subclass: 5
[Apr 28 18:43:43] VERBOSE[2806] logger.c:    Timestamp: 15263ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:43] VERBOSE[2797] logger.c: Rx-Frame Retry[ No] --
OSeqno: 007 ISeqno: 004 Type: DTMF_B  Subclass: 5
[Apr 28 18:43:43] VERBOSE[2797] logger.c:    Timestamp: 15263ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:43] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 010 ISeqno: 007 Type: DTMF_B  Subclass: 5
[Apr 28 18:43:43] VERBOSE[2806] logger.c:    Timestamp: 14103ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:43] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 008 ISeqno: 004 Type: DTMF_E  Subclass: 5
[Apr 28 18:43:43] VERBOSE[2806] logger.c:    Timestamp: 15613ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:43] VERBOSE[2798] logger.c: Rx-Frame Retry[ No] --
OSeqno: 008 ISeqno: 004 Type: DTMF_E  Subclass: 5
[Apr 28 18:43:43] VERBOSE[2798] logger.c:    Timestamp: 15613ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:43] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 011 ISeqno: 007 Type: DTMF_E  Subclass: 5
[Apr 28 18:43:43] VERBOSE[2806] logger.c:    Timestamp: 14460ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:43] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 009 ISeqno: 004 Type: DTMF_B  Subclass: 8
[Apr 28 18:43:43] VERBOSE[2806] logger.c:    Timestamp: 15983ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:43] VERBOSE[2799] logger.c: Rx-Frame Retry[ No] --
OSeqno: 009 ISeqno: 004 Type: DTMF_B  Subclass: 8
[Apr 28 18:43:43] VERBOSE[2799] logger.c:    Timestamp: 15983ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:43] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 012 ISeqno: 007 Type: DTMF_B  Subclass: 8
[Apr 28 18:43:43] VERBOSE[2806] logger.c:    Timestamp: 14823ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:44] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 010 ISeqno: 004 Type: DTMF_E  Subclass: 8
[Apr 28 18:43:44] VERBOSE[2806] logger.c:    Timestamp: 16351ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:44] VERBOSE[2804] logger.c: Rx-Frame Retry[ No] --
OSeqno: 010 ISeqno: 004 Type: DTMF_E  Subclass: 8
[Apr 28 18:43:44] VERBOSE[2804] logger.c:    Timestamp: 16351ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:44] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 013 ISeqno: 007 Type: DTMF_E  Subclass: 8
[Apr 28 18:43:44] VERBOSE[2806] logger.c:    Timestamp: 15200ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:44] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 011 ISeqno: 004 Type: DTMF_B  Subclass: 9
[Apr 28 18:43:44] VERBOSE[2806] logger.c:    Timestamp: 16763ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:44] VERBOSE[2801] logger.c: Rx-Frame Retry[ No] --
OSeqno: 011 ISeqno: 004 Type: DTMF_B  Subclass: 9
[Apr 28 18:43:44] VERBOSE[2801] logger.c:    Timestamp: 16763ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:44] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 014 ISeqno: 007 Type: DTMF_B  Subclass: 9
[Apr 28 18:43:44] VERBOSE[2806] logger.c:    Timestamp: 15603ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:44] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 015 ISeqno: 007 Type: DTMF_E  Subclass: 9
[Apr 28 18:43:44] VERBOSE[2806] logger.c:    Timestamp: 15606ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:44] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 012 ISeqno: 004 Type: DTMF_E  Subclass: 9
[Apr 28 18:43:44] VERBOSE[2806] logger.c:    Timestamp: 17087ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:44] VERBOSE[2797] logger.c: Rx-Frame Retry[ No] --
OSeqno: 012 ISeqno: 004 Type: DTMF_E  Subclass: 9
[Apr 28 18:43:44] VERBOSE[2804] logger.c: Rx-Frame Retry[Yes] --
OSeqno: 228 ISeqno: 000 Type: IAX     Subclass: PING
--
[Apr 28 18:43:44] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 016 ISeqno: 007 Type: DTMF_B  Subclass: 9
[Apr 28 18:43:44] VERBOSE[2806] logger.c:    Timestamp: 15743ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:45] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 017 ISeqno: 007 Type: DTMF_E  Subclass: 9
[Apr 28 18:43:45] VERBOSE[2806] logger.c:    Timestamp: 15746ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:45] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 013 ISeqno: 004 Type: DTMF_B  Subclass: 6
[Apr 28 18:43:45] VERBOSE[2806] logger.c:    Timestamp: 17503ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:45] VERBOSE[2797] logger.c: Rx-Frame Retry[ No] --
OSeqno: 013 ISeqno: 004 Type: DTMF_B  Subclass: 6
[Apr 28 18:43:45] VERBOSE[2797] logger.c:    Timestamp: 17503ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:45] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 018 ISeqno: 007 Type: DTMF_B  Subclass: 6
[Apr 28 18:43:45] VERBOSE[2806] logger.c:    Timestamp: 16103ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:45] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 014 ISeqno: 004 Type: DTMF_E  Subclass: 6
[Apr 28 18:43:45] VERBOSE[2806] logger.c:    Timestamp: 17855ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:45] VERBOSE[2800] logger.c: Rx-Frame Retry[ No] --
OSeqno: 014 ISeqno: 004 Type: DTMF_E  Subclass: 6
[Apr 28 18:43:45] VERBOSE[2800] logger.c:    Timestamp: 17855ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:45] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 019 ISeqno: 007 Type: DTMF_E  Subclass: 6
[Apr 28 18:43:45] VERBOSE[2806] logger.c:    Timestamp: 16519ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:46] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 015 ISeqno: 004 Type: DTMF_B  Subclass: 3
[Apr 28 18:43:46] VERBOSE[2806] logger.c:    Timestamp: 18263ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:46] VERBOSE[2804] logger.c: Rx-Frame Retry[ No] --
OSeqno: 015 ISeqno: 004 Type: DTMF_B  Subclass: 3
[Apr 28 18:43:46] VERBOSE[2804] logger.c:    Timestamp: 18263ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:46] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 020 ISeqno: 007 Type: DTMF_B  Subclass: 3
[Apr 28 18:43:46] VERBOSE[2806] logger.c:    Timestamp: 16883ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:46] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 021 ISeqno: 007 Type: DTMF_E  Subclass: 3
[Apr 28 18:43:46] VERBOSE[2806] logger.c:    Timestamp: 16886ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:46] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 022 ISeqno: 007 Type: DTMF_B  Subclass: 3
[Apr 28 18:43:46] VERBOSE[2806] logger.c:    Timestamp: 16923ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:46] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 016 ISeqno: 004 Type: DTMF_E  Subclass: 3
[Apr 28 18:43:46] VERBOSE[2806] logger.c:    Timestamp: 18591ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:46] VERBOSE[2804] logger.c: Rx-Frame Retry[ No] --
OSeqno: 016 ISeqno: 004 Type: DTMF_E  Subclass: 3
[Apr 28 18:43:46] VERBOSE[2804] logger.c:    Timestamp: 18591ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:46] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 023 ISeqno: 007 Type: DTMF_E  Subclass: 3
[Apr 28 18:43:46] VERBOSE[2806] logger.c:    Timestamp: 17248ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:46] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 017 ISeqno: 004 Type: DTMF_B  Subclass: #
[Apr 28 18:43:46] VERBOSE[2806] logger.c:    Timestamp: 19003ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:46] VERBOSE[2798] logger.c: Rx-Frame Retry[ No] --
OSeqno: 017 ISeqno: 004 Type: DTMF_B  Subclass: #
[Apr 28 18:43:46] VERBOSE[2798] logger.c:    Timestamp: 19003ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:46] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 024 ISeqno: 007 Type: DTMF_B  Subclass: #
[Apr 28 18:43:46] VERBOSE[2806] logger.c:    Timestamp: 17623ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]
--
[Apr 28 18:43:47] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 018 ISeqno: 004 Type: DTMF_E  Subclass: #
[Apr 28 18:43:47] VERBOSE[2806] logger.c:    Timestamp: 19327ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
[Apr 28 18:43:47] VERBOSE[2804] logger.c: Rx-Frame Retry[ No] --
OSeqno: 018 ISeqno: 004 Type: DTMF_E  Subclass: #
[Apr 28 18:43:47] VERBOSE[2804] logger.c:    Timestamp: 19327ms
SCall: 12052  DCall: 04642 [208.90.184.4:4569]
--
[Apr 28 18:43:47] VERBOSE[2806] logger.c: Tx-Frame Retry[000] --
OSeqno: 025 ISeqno: 007 Type: DTMF_E  Subclass: #
[Apr 28 18:43:47] VERBOSE[2806] logger.c:    Timestamp: 17998ms
SCall: 09503  DCall: 09749 [208.90.184.3:4569]

James Lamanna

2010-Apr-30 00:23 UTC

head link

[asterisk-users] Duplicated DTMF with bridged IAX channels maybe?

On Wed, Apr 28, 2010 at 6:57 PM, James Lamanna <jlamanna at gmail.com>
wrote:> Hi,
> I have a duplicated DTMF issue with, it appears, bridged IAX channels.
> I have the following setup:
>
> ? PRI ? ? ? ? ? ? ? ? ?IAX
> <-------->* PSTN <------->* Dialplan
>
> I've configured a number on the dialplan server to make and outbound
> call to the pstn. This call then comes back into the dialplan server
> to SayDigits().
> I'm seeing that a few of my digits are being duplicated every so often.
> I've attached an IAX trace from the PSTN server to this message where
> you can see the duplication (digits 9 & 3). The digits entered were
> 258963.
[snip]

Testing the following scenario:
Call --(from pstn PRI)--> (PSTN box) --IAX--> (PBX box) --IAX--> (PSTN
box) --(to/from pstn PRI)--> (PSTN box)
Results in Duplication.
Here are 2 traces from the PSTN box's DTMF log:
'8' was not duplicated, '9' was.
Zap/42-1 is the first inbound leg from the PSTN
IAX2/w2bpstn-8399 is the leg from the PBX box to the PSTN box
Zap/53-1 is the inbound leg from the PSTN

[Apr 29 17:02:15] DTMF[16062] channel.c: DTMF begin '8' received on
Zap/42-1
[Apr 29 17:02:15] DTMF[16062] channel.c: DTMF begin passthrough '8' on
Zap/42-1
[Apr 29 17:02:15] DTMF[16065] channel.c: DTMF begin '8' received on
IAX2/w2bpstn-8399
[Apr 29 17:02:15] DTMF[16065] channel.c: DTMF begin passthrough '8' on
IAX2/w2bpstn-8399
[Apr 29 17:02:15] DTMF[16071] channel.c: DTMF begin '8' received on
Zap/53-1
[Apr 29 17:02:15] DTMF[16071] channel.c: DTMF begin ignored '8' on
Zap/53-1
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF end '8' received on
Zap/42-1, duration 63 ms
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF end accepted with begin
'8' on Zap/42-1
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF end '8' has duration 63
but want minimum 80, emulating on Zap/42-1
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF end emulation of '8'
queued on Zap/42-1
[Apr 29 17:02:16] DTMF[16065] channel.c: DTMF end '8' received on
IAX2/w2bpstn-8399, duration 0 ms
[Apr 29 17:02:16] DTMF[16065] channel.c: DTMF end accepted with begin
'8' on IAX2/w2bpstn-8399
[Apr 29 17:02:16] DTMF[16065] channel.c: DTMF end passthrough '8' on
IAX2/w2bpstn-8399
[Apr 29 17:02:16] DTMF[16071] channel.c: DTMF end '8' received on
Zap/53-1, duration 223 ms
[Apr 29 17:02:16] DTMF[16071] channel.c: DTMF end passthrough '8' on
Zap/53-1

[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF begin '9' received on
Zap/42-1
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF begin passthrough '9' on
Zap/42-1
[Apr 29 17:02:16] DTMF[16065] channel.c: DTMF begin '9' received on
IAX2/w2bpstn-8399
[Apr 29 17:02:16] DTMF[16065] channel.c: DTMF begin passthrough '9' on
IAX2/w2bpstn-8399
[Apr 29 17:02:16] DTMF[16071] channel.c: DTMF begin '9' received on
Zap/53-1
[Apr 29 17:02:16] DTMF[16071] channel.c: DTMF begin ignored '9' on
Zap/53-1
[Apr 29 17:02:16] DTMF[16071] channel.c: DTMF end '9' received on
Zap/53-1, duration 223 ms
[Apr 29 17:02:16] DTMF[16071] channel.c: DTMF end passthrough '9' on
Zap/53-1
[Apr 29 17:02:16] DTMF[16071] channel.c: DTMF begin '9' received on
Zap/53-1
[Apr 29 17:02:16] DTMF[16071] channel.c: DTMF begin ignored '9' on
Zap/53-1
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF end '9' received on
Zap/42-1, duration 63 ms
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF end accepted with begin
'9' on Zap/42-1
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF end '9' has duration 63
but want minimum 80, emulating on Zap/42-1
[Apr 29 17:02:16] DTMF[16062] channel.c: DTMF end emulation of '9'
queued on Zap/42-1
[Apr 29 17:02:16] DTMF[16065] channel.c: DTMF end '9' received on
IAX2/w2bpstn-8399, duration 0 ms
[Apr 29 17:02:16] DTMF[16065] channel.c: DTMF end accepted with begin
'9' on IAX2/w2bpstn-8399
[Apr 29 17:02:16] DTMF[16065] channel.c: DTMF end passthrough '9' on
IAX2/w2bpstn-8399
[Apr 29 17:02:17] DTMF[16071] channel.c: DTMF end '9' received on
Zap/53-1, duration 223 ms
[Apr 29 17:02:17] DTMF[16071] channel.c: DTMF end passthrough '9' on
Zap/53-1

-- James

Possibly Parallel Threads

Search for more apparently analagous threads

asterisk users - Apr 2010 - Duplicated DTMF with bridged IAX channels maybe?

[asterisk-users] Duplicated DTMF with bridged IAX channels maybe?

[asterisk-users] Duplicated DTMF with bridged IAX channels maybe?

Possibly Parallel Threads