thr3ads.net - asterisk users - [asterisk-users] Debugging some DTMF Weirdness. [Feb 2015]

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

John Kiniston

2015-Feb-13 01:01 UTC

[asterisk-users] Debugging some DTMF Weirdness.

I'm attempting to find where my extra long DTMF  Tones are coming from.

I'm dialing from my sip handset through my proxy to my Asterisk box which
is my PSTN Gateway.

I'm pressing 4 to select a menu and everything is fine.

[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF begin '4' received on
SIP/trunk-0a02dee0
[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF begin passthrough '4' on
SIP/trunk-0a02dee0
[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF end '4' received on
SIP/trunk-0a02dee0, duration 150 ms
[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF end accepted with begin
'4'
on SIP/trunk-0a02dee0
[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF end passthrough '4' on
SIP/trunk-0a02dee0
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF begin '4' received on
SIP/trunk-0a03aaa0
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF begin passthrough '4' on
SIP/trunk-0a03aaa0
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF end '4' received on
SIP/trunk-0a03aaa0, duration 170 ms
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF end accepted with begin
'4'
on SIP/trunk-0a03aaa0
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF end passthrough '4' on
SIP/trunk-0a03aaa0

I'm, pressing 9 to select an option and I hear an extra long DTMF burst
from my handset.

[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF begin '9' received on
SIP/trunk-0a02dee0
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF begin passthrough '9' on
SIP/trunk-0a02dee0
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF begin '9' received on
Zap/59-1
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF begin passthrough '9' on
Zap/59-1
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end '9' received on
SIP/trunk-0a02dee0, duration 1700 ms
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end accepted with begin
'9'
on SIP/trunk-0a02dee0
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end passthrough '9' on
SIP/trunk-0a02dee0
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end '9' received on
Zap/59-1,
duration 32 ms
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end accepted with begin
'9'
on Zap/59-1
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end '9' has duration 32
but
want minimum 80, emulating on Zap/59-1
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end emulation of '9'
queued
on Zap/59-1

Can someone explain the received passthrough parts of my output here?

If I send my call out through a different Asterisk box I have my calls are
working fine, Looking at the two boxes I have the same version of asterisk
but the machine with the extra long DTMF is using hardware DTMF decoding
where the working machine is using software only.

-- 
A human being should be able to change a diaper, plan an invasion, butcher
a hog, conn a ship, design a building, write a sonnet, balance accounts,
build a wall, set a bone, comfort the dying, take orders, give orders,
cooperate, act alone, solve equations, analyze a new problem, pitch manure,
program a computer, cook a tasty meal, fight efficiently, die gallantly.
Specialization is for insects.
---Heinlein
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20150212/7a2fb76d/attachment.html>

Yves A.

2015-Feb-13 12:39 UTC

head link

[asterisk-users] call failed... but why? What means SIP_ALREADYGONE?

Hi,

I have watched a phenomen, that I can not explain... maybe one of you 
can see the reason why the call failed, and if the cause
is the Snom Hardphone, or the asterisk, or the SIP-Provider... the debug 
log given below is all I have...
What does "Setting SIP_ALREADYGONE on dialog.." mean?

thanks for watching,
yves

SIP Phone 110 (callerid 061444018110) tried to call the external Phone 
Number 0616677823 and gets an hangup after 2 seconds. Another try 
immediately
after the failed call goes fine. The failed call did not arrive at the 
destination.

[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Begin: 
parsing SIP "Supported: timer, 100rel, replaces, from-change"
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Found 
SIP option: -timer-
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Matched 
SIP option: timer
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Found 
SIP option: -100rel-
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Matched 
SIP option: 100rel
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Found 
SIP option: -replaces-
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Matched 
SIP option: replaces
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Found 
SIP option: -from-change-
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] sip/reqresp_parser.c: Matched 
SIP option: from-change
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Trying to put 
'SIP/2.0 401' onto UDP socket destined for 192.168.0.165:3072
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Connection okay.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 
'00616677823' AND h
ost = 'dynamic'
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Connection okay.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name =
'00616677823'
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Stopping 
retransmission on '9a6bdc548d19-goay25ioz0nd' of Response 1: Match Found
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Using engine 
'asterisk' for RTP instance '0x7f2a74158788'
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_rtp_asterisk.c: Allocated 
port 19528 for RTP instance '0x7f2a74158788'
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: RTP instance 
'0x7f2a74158788' is setup and ready to go
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_rtp_asterisk.c: Setup RTCP 
on RTP instance '0x7f2a74158788'
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Setting NAT on RTP 
to On
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP v=0... UNSUPPORTED OR FAILED.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP o=root 871055034 871055034 IN IP4 192.168.0.165... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP s=call... UNSUPPORTED OR FAILED.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP c=IN IP4 192.168.0.165... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
9 based on m type on 0x7f2a80b1a620
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
0 based on m type on 0x7f2a80b1a620
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
8 based on m type on 0x7f2a80b1a620
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
99 based on m type on 0x7f2a80b1a620
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
108 based on m type on 0x7f2a80b1a620
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
18 based on m type on 0x7f2a80b1a620
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
101 based on m type on 0x7f2a80b1a620
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:9 G722/8000... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:99 G726-32/8000... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:108 AAL2-G726-32/8000... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=fmtp:18 annexb=no... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=ptime:20... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=sendrecv... OK.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_rtp_asterisk.c: Setting 
RTCP address on RTP instance '0x7f2a74158788'
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
0 from 0x7f2a80b1a620 to 0x7f2a74158950
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
8 from 0x7f2a80b1a620 to 0x7f2a74158950
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
9 from 0x7f2a80b1a620 to 0x7f2a74158950
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
18 from 0x7f2a80b1a620 to 0x7f2a74158950
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
99 from 0x7f2a80b1a620 to 0x7f2a74158950
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
101 from 0x7f2a80b1a620 to 0x7f2a74158950
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
108 from 0x7f2a80b1a620 to 0x7f2a74158950
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_rtp_asterisk.c: Ignoring 
duplicate RTCP property on RTP instance '0x7f2a74158788'
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: We're settling 
with these formats: (ulaw|alaw)
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Checking SIP call 
limits for device 110
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Updating call 
counter for incoming call
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Incoming INVITE 
with 'timer' option supported
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: INVITE also has 
"Session-Expires" header.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Session-Expires: 3600
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Refresher: UAS
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: INVITE also has 
"Min-SE" header.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Received Min-SE: 90
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: *** Our native 
formats are (ulaw)
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: *** Joint 
capabilities are (ulaw|alaw)
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: *** Our 
capabilities are (ulaw|alaw)
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: *** 
AST_CODEC_CHOOSE formats are ulaw
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: This channel will 
not be able to handle video.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: build_route: 
Contact hop: <sip:110 at 192.168.0.165:3072;line=vznkar3t>;reg-id=1
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Session timer 
started: 999276 - 9a6bdc548d19-goay25ioz0nd 1800000ms
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: SIP/110-000031c1: 
New call is still down.... Trying...
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Trying to put 
'SIP/2.0 100' onto UDP socket destined for 192.168.0.165:3072
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Connection okay.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 
'00616677823' AND h
ost = 'dynamic'
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Connection okay.
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name =
'00616677823'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] pbx.c: Launching 'NoOp'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] pbx.c: Function CALLERID(num) 
result is '061444018110'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] pbx.c: Expression result is
'0'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] pbx.c: Launching 'GotoIf'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] pbx.c: Launching
'SIPAddHeader'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] pbx.c: Launching 'Dial'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Asked to create a 
SIP channel with formats: (ulaw)
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Allocating new 
SIP dialog for 58c487563a47d54f41cba6c77a1867cb at 192.168.1.211:5060 - 
INVITE (No
RTP)
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] rtp_engine.c: Using engine 
'asterisk' for RTP instance '0x7f2abc118f18'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Allocated 
port 10202 for RTP instance '0x7f2abc118f18'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] rtp_engine.c: RTP instance 
'0x7f2abc118f18' is setup and ready to go
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Setup 
RTCP on RTP instance '0x7f2abc118f18'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Setting NAT on 
RTP to On
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] acl.c: For destination 
'213.148.136.178', our source address is '192.168.1.211'.
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Setting 
SIP_TRANSPORT_UDP with address 192.168.1.211:5060
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Setting NAT on 
RTP to On
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: SIP call-id 
changed from '58c487563a47d54f41cba6c77a1867cb at 192.168.1.211:5060' to
'0d9afe6232c9
5f5200d3bdc1628f038a at 192.168.1.211:5060'
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: *** Our native 
formats are (ulaw)
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: *** Joint 
capabilities are (ulaw)
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: *** Our 
capabilities are (ulaw|alaw)
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: *** 
AST_CODEC_CHOOSE formats are ulaw
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: *** Our preferred 
formats from the incoming channel are (ulaw)
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: This channel will 
not be able to handle video.
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] channel_internal_api.c: 
Channel Call ID changing from [C-0000380e] to [C-0000380e]
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] channel.c: Inheriting 
variable SIPADDHEADER01 from SIP/110-000031c1 to 
SIP/qsc_backoffice-000031c2.
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Outgoing Call for 
0616677823
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Updating call 
counter for outgoing call
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: ** Our 
capability: (ulaw|alaw) Video flag: False Text flag: False
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: ** Our prefcodec: 
(ulaw)
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: -- Done with 
adding codecs to SDP
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Done building 
SDP. Settling with this capability: (ulaw|alaw)
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Initializing 
initreq for method INVITE - callid 
0d9afe6232c95f5200d3bdc1628f038a at 192.168.1.211:
5060
[Feb 12 10:00:11] DEBUG[10873][C-0000380e] chan_sip.c: Trying to put 
'INVITE sip:' onto UDP socket destined for 213.148.136.178:5060
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: (Provisional) 
Stopping retransmission (but retaining packet) on 
'0d9afe6232c95f5200d3bdc1628f038
a at 192.168.1.211:5060' Request 102: Found
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Acked pending 
invite 102
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Stopping 
retransmission on '0d9afe6232c95f5200d3bdc1628f038a at
192.168.1.211:5060'
of Request 102:
  Match Found
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Trying to put 'ACK 
sip:062' onto UDP socket destined for 213.148.136.178:5060
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Auth attempt 1 on 
INVITE
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: ** Our capability: 
(ulaw|alaw) Video flag: False Text flag: False
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: ** Our prefcodec: 
(ulaw)
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: -- Done with 
adding codecs to SDP
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Done building SDP. 
Settling with this capability: (ulaw|alaw)
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: Trying to put 
'INVITE sip:' onto UDP socket destined for 213.148.136.178:5060
[Feb 12 10:00:11] DEBUG[1567][C-0000380e] chan_sip.c: (Provisional) 
Stopping retransmission (but retaining packet) on 
'0d9afe6232c95f5200d3bdc1628f038
a at 192.168.1.211:5060' Request 103: Found
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: (Provisional) 
Stopping retransmission (but retaining packet) on 
'0d9afe6232c95f5200d3bdc1628f038
a at 192.168.1.211:5060' Request 103: Found
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: build_route: 
Contact hop: <sip:213.148.136.178:5060;transport=udp>
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP v=0... UNSUPPORTED OR FAILED.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP o=HuaweiSoftX3000 19676565 19676565 IN IP4 
213.148.136.178... OK.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP s=Sip Call... UNSUPPORTED OR FAILED.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP c=IN IP4 213.148.136.178... OK.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
0 based on m type on 0x7f2a80b19a00
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] rtp_engine.c: Setting payload 
101 based on m type on 0x7f2a80b19a00
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=ptime:20... OK.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: Processing 
media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED.
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] res_rtp_asterisk.c: Setting 
RTCP address on RTP instance '0x7f2abc118f18'
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
0 from 0x7f2a80b19a00 to 0x7f2abc1190e0
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] rtp_engine.c: Copying payload 
101 from 0x7f2a80b19a00 to 0x7f2abc1190e0
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] res_rtp_asterisk.c: Ignoring 
duplicate RTCP property on RTP instance '0x7f2abc118f18'
[Feb 12 10:00:12] DEBUG[1567][C-0000380e] chan_sip.c: We're settling 
with these formats: (ulaw)
[Feb 12 10:00:12] DEBUG[10873][C-0000380e] rtp_engine.c: Setting early 
bridge SDP of 'SIP/110-000031c1' with that of
'SIP/qsc_backoffice-000031c2'
[Feb 12 10:00:12] DEBUG[10873][C-0000380e] chan_sip.c: Setting framing 
from config on incoming call
[Feb 12 10:00:12] DEBUG[10873][C-0000380e] chan_sip.c: ** Our 
capability: (ulaw|alaw) Video flag: True Text flag: True
[Feb 12 10:00:12] DEBUG[10873][C-0000380e] chan_sip.c: ** Our prefcodec: 
(nothing)
[Feb 12 10:00:12] DEBUG[10873][C-0000380e] chan_sip.c: -- Done with 
adding codecs to SDP
[Feb 12 10:00:12] DEBUG[10873][C-0000380e] chan_sip.c: Done building 
SDP. Settling with this capability: (ulaw|alaw)
[Feb 12 10:00:12] DEBUG[10873][C-0000380e] chan_sip.c: Trying to put 
'SIP/2.0 183' onto UDP socket destined for 192.168.0.165:3072
[Feb 12 10:00:12] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Got RTCP 
report of 44 bytes
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: 
0x7f2a7415ccd0 -- Probation learning mode pass with source address 
192.168.0.165:54426
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Ooh, 
format changed from unknown to ulaw
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Created 
smoother: format: ulaw ms: 20 len: 160
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Starting 
RTCP transmission on RTP instance '0x7f2abc118f18'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: 
0x7f2abc22f2e0 -- Probation learning mode pass with source address 
213.148.136.178:4386
2
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Ooh, 
format changed from unknown to ulaw
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Created 
smoother: format: ulaw ms: 20 len: 160
[Feb 12 10:00:13] DEBUG[1567][C-0000380e] chan_sip.c: Acked pending 
invite 103
[Feb 12 10:00:13] DEBUG[1567][C-0000380e] chan_sip.c: Stopping 
retransmission on '0d9afe6232c95f5200d3bdc1628f038a at
192.168.1.211:5060'
of Request 103:
  Match Found
[Feb 12 10:00:13] DEBUG[1567][C-0000380e] res_rtp_asterisk.c: Setting 
RTCP address on RTP instance '0x7f2abc118f18'
[Feb 12 10:00:13] DEBUG[1567][C-0000380e] chan_sip.c: Trying to put 'ACK 
sip:213' onto UDP socket destined for 213.148.136.178:5060
[Feb 12 10:00:13] DEBUG[1567][C-0000380e] chan_sip.c: Setting 
SIP_ALREADYGONE on dialog 
0d9afe6232c95f5200d3bdc1628f038a at 192.168.1.211:5060
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] channel.c: Hanging up channel 
'SIP/qsc_backoffice-000031c2'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] chan_sip.c: Hangup call 
SIP/qsc_backoffice-000031c2, SIP callid 
0d9afe6232c95f5200d3bdc1628f038a at 192.168.1.
211:5060
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Setting 
RTCP address on RTP instance '0x7f2abc118f18'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] app_dial.c: Exiting with 
DIALSTATUS=CHANUNAVAIL.
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] pbx.c: Launching 'Hangup'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] channel.c: Soft-Hanging up 
channel 'SIP/110-000031c1'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] pbx.c: Spawn extension 
(from-backoffice,00616677823,6) exited non-zero on 'SIP/110-000031c1'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] channel.c: Soft-Hanging up 
channel 'SIP/110-000031c1'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Connection okay.
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = 'h' AND 
context 'from-backoffice' AND priority = '1'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Connection okay.
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_config_mysql.c: MySQL 
RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten LIKE '\\_%'
AND cont
ext = 'from-backoffice' AND priority = '1' ORDER BY exten
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] channel.c: Hanging up channel 
'SIP/110-000031c1'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] chan_sip.c: Hangup call 
SIP/110-000031c1, SIP callid 9a6bdc548d19-goay25ioz0nd
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] res_rtp_asterisk.c: Setting 
RTCP address on RTP instance '0x7f2a74158788'
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] chan_sip.c: Session timer 
stopped: 999276 - 9a6bdc548d19-goay25ioz0nd
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] chan_sip.c: Trying to put 
'SIP/2.0 484' onto UDP socket destined for 192.168.0.165:3072
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] cdr_mysql.c: Inserting a CDR 
record.
[Feb 12 10:00:13] DEBUG[10873][C-0000380e] cdr_mysql.c: SQL command as 
follows: INSERT INTO cdr 
(`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`d
stchannel`,`lastapp`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) 
VALUES ('2015-02-12 10:00:11','\"110\"
<061444018110>','061444018110','
00616677823','from-backoffice','SIP/110-000031c1','SIP/qsc_backoffice-000031c2','Hangup','2','0','NO
ANSWER','3','1423731611.39996')
[Feb 12 10:00:13] DEBUG[1567][C-0000380e] chan_sip.c: Stopping 
retransmission on '9a6bdc548d19-goay25ioz0nd' of Response 2: Match Found

Eric Wieling

2015-Feb-14 15:57 UTC

head link

[asterisk-users] Debugging some DTMF Weirdness.

Is it possible your transmit or receive gain is too high and Asterisk is
detecting the echo of a DTMF as a new digit cause by an analog leg of the call
somewhere?


From: asterisk-users-bounces at lists.digium.com [mailto:asterisk-users-bounces
at lists.digium.com] On Behalf Of John Kiniston
Sent: Thursday, February 12, 2015 8:01 PM
To: Asterisk Users Mailing List - Non-Commercial Discussion
Subject: [asterisk-users] Debugging some DTMF Weirdness.

I'm attempting to find where my extra long DTMF  Tones are coming from.

I'm dialing from my sip handset through my proxy to my Asterisk box which is
my PSTN Gateway.
I'm pressing 4 to select a menu and everything is fine.

[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF begin '4' received on
SIP/trunk-0a02dee0
[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF begin passthrough '4' on
SIP/trunk-0a02dee0
[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF end '4' received on
SIP/trunk-0a02dee0, duration 150 ms
[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF end accepted with begin
'4' on SIP/trunk-0a02dee0
[Feb 12 16:58:18] DTMF[29762] channel.c: DTMF end passthrough '4' on
SIP/trunk-0a02dee0
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF begin '4' received on
SIP/trunk-0a03aaa0
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF begin passthrough '4' on
SIP/trunk-0a03aaa0
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF end '4' received on
SIP/trunk-0a03aaa0, duration 170 ms
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF end accepted with begin
'4' on SIP/trunk-0a03aaa0
[Feb 12 16:58:19] DTMF[29760] channel.c: DTMF end passthrough '4' on
SIP/trunk-0a03aaa0
I'm, pressing 9 to select an option and I hear an extra long DTMF burst from
my handset.

[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF begin '9' received on
SIP/trunk-0a02dee0
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF begin passthrough '9' on
SIP/trunk-0a02dee0
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF begin '9' received on
Zap/59-1
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF begin passthrough '9' on
Zap/59-1
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end '9' received on
SIP/trunk-0a02dee0, duration 1700 ms
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end accepted with begin
'9' on SIP/trunk-0a02dee0
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end passthrough '9' on
SIP/trunk-0a02dee0
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end '9' received on
Zap/59-1, duration 32 ms
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end accepted with begin
'9' on Zap/59-1
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end '9' has duration 32
but want minimum 80, emulating on Zap/59-1
[Feb 12 16:58:20] DTMF[29762] channel.c: DTMF end emulation of '9'
queued on Zap/59-1
Can someone explain the received passthrough parts of my output here?
If I send my call out through a different Asterisk box I have my calls are
working fine, Looking at the two boxes I have the same version of asterisk but
the machine with the extra long DTMF is using hardware DTMF decoding where the
working machine is using software only.
--
A human being should be able to change a diaper, plan an invasion, butcher a
hog, conn a ship, design a building, write a sonnet, balance accounts, build a
wall, set a bone, comfort the dying, take orders, give orders, cooperate, act
alone, solve equations, analyze a new problem, pitch manure, program a computer,
cook a tasty meal, fight efficiently, die gallantly. Specialization is for
insects.
---Heinlein
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20150214/a723dae4/attachment.html>

Reasonably Related Threads

Search for more possibly parallel threads

asterisk users - Feb 2015 - Debugging some DTMF Weirdness.

[asterisk-users] Debugging some DTMF Weirdness.

[asterisk-users] call failed... but why? What means SIP_ALREADYGONE?

[asterisk-users] Debugging some DTMF Weirdness.

Reasonably Related Threads