[asterisk-bugs] [Asterisk 0015777]: Reinvite before channel state is changed to up.
Asterisk Bug Tracker
noreply at bugs.digium.com
Mon Sep 14 12:01:46 CDT 2009
The following issue has been ASSIGNED.
======================================================================
https://issues.asterisk.org/view.php?id=15777
======================================================================
Reported By: milos
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 15777
Category: Channels/chan_sip/General
Reproducibility: always
Severity: minor
Priority: normal
Status: assigned
Asterisk Version: SVN
Regression: No
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Request Review:
======================================================================
Date Submitted: 2009-08-25 04:02 CDT
Last Modified: 2009-09-14 12:01 CDT
======================================================================
Summary: Reinvite before channel state is changed to up.
Description:
Hi
I have a problem. When i make outbound calls over SIP trunk it sometimes
happens that call gets disconnected after fer seconds. This happens on
different numbers and various times but not always.
ITSP peer is SIP/VOIP_AMIS-peer and ip class is 10.22.0.0/16
Asterisk ip address is 10.61.16.2
I made a lot of traces and found out that the problem is following
Asterisk sends invite message to ITSP authentication is made.
Than ringing message is sent back to Asterisk
Next message is Media Change from ITSP and immediatly after Media change
OK is sent from ITSP
Asterisk sends ACK back to ITSP
now the problem
ITSP sends INVITE message again
and now Asterisk sometimes sends message Trying and sometimes message
INVITE.
If Asterisk sends Trying call is sucessfull and everything is ok. If
Asterisk sends Invite another authentication is made and call is droped by
ITSP seconds later.
I found out from logs that Asterisk sends INVITE response if channel is
not in state UP.
Is this normal behaviour that channel is still in state down after ACK is
sent to OK message?
You can check this in log files i attached.
In file reinvite_normal.txt you can see that channel is in state UP before
processing REINVITE from ITSP
[Aug 18 16:06:23] VERBOSE[20022] logger.c: --
SIP/VOIP_AMIS-peer-082a1d60 answered SIP/91.199.174.215-082c0d28
[Aug 18 16:06:23] DEBUG[20022] devicestate.c: Notification of state change
to be queued on device/channel SIP/91.199.174.215
[Aug 18 16:06:23] DEBUG[20022] chan_sip.c: SIP answering channel:
SIP/91.199.174.215-082c0d28
[Aug 18 16:06:23] DEBUG[20022] chan_sip.c: Setting framing from config on
incoming call
[Aug 18 16:06:23] DEBUG[20022] chan_sip.c: ** Our capability: 0xc
(ulaw|alaw) Video flag: True Text flag: True
[Aug 18 16:06:23] DEBUG[20022] chan_sip.c: ** Our prefcodec: 0x0
(nothing)
[Aug 18 16:06:23] DEBUG[20022] chan_sip.c: -- Done with adding codecs to
SDP
[Aug 18 16:06:23] DEBUG[20022] channel.c: Internal timing is disabled
(option_internal_timing=0 chan->timingfd=-1)
[Aug 18 16:06:23] DEBUG[20022] chan_sip.c: Done building SDP. Settling
with this capability: 0xc (ulaw|alaw)
[Aug 18 16:06:23] DEBUG[20022] chan_sip.c: *** SIP TIMER: Initializing
retransmit timer on packet: Id https://issues.asterisk.org/view.php?id=26483
[Aug 18 16:06:23] DEBUG[20022] chan_sip.c: Trying to put 'SIP/2.0 20' onto
UDP socket destined for 91.199.174.215:5060
[Aug 18 16:06:23] DEBUG[20022] features.c: bridge answer set, chan answer
set
[Aug 18 16:06:23] DEBUG[20022] rtp.c: Forcing Marker bit, because SSRC has
changed
[Aug 18 16:06:23] DEBUG[19067] devicestate.c: No provider found, checking
channel drivers for SIP - VOIP_AMIS-peer
[Aug 18 16:06:23] DEBUG[19067] chan_sip.c: Checking device state for peer
VOIP_AMIS-peer
[Aug 18 16:06:23] DEBUG[19067] devicestate.c: Changing state for
SIP/VOIP_AMIS-peer - state 1 (Not in use)
[Aug 18 16:06:23] DEBUG[19067] devicestate.c: No provider found, checking
channel drivers for SIP - 91.199.174.215
[Aug 18 16:06:23] DEBUG[19067] chan_sip.c: Checking device state for peer
91.199.174.215
[Aug 18 16:06:23] DEBUG[19067] devicestate.c: Changing state for
SIP/91.199.174.215 - state 2 (In use)
[Aug 18 16:06:23] DEBUG[19083] app_queue.c: Device 'SIP/VOIP_AMIS-peer'
changed to state '1' (Not in use) but we don't care because they're not a
member of any queue.
[Aug 18 16:06:23] DEBUG[19083] app_queue.c: Device 'SIP/91.199.174.215'
changed to state '2' (In use) but we don't care because they're not a
member of any queue.
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 1 [ 51]: o=cp10
125060437808 125060437812 IN IP4 10.22.12.32
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 2 [ 10]: s=SIP Call
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 3 [ 20]: c=IN IP4
10.22.12.32
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 4 [ 5]: t=0 0
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 5 [ 25]: m=audio 32210
RTP/AVP 8 0
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 6 [ 7]: b=AS:64
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 7 [ 22]: a=rtpmap:8
PCMA/8000/1
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 8 [ 22]: a=rtpmap:0
PCMU/8000/1
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 9 [ 10]: a=ptime:20
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Body 10 [ 10]: a=sendrecv
[Aug 18 16:06:23] VERBOSE[19084] logger.c: --- (12 headers 11 lines) ---
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: = Found Their Call ID:
47b41b9f601cfe453c9eae6a3b93d8e0 at 10.61.16.2 Their Tag
02-08136-008d9b96-1a6395973 Our tag: as19020706
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: **** Received INVITE (5) -
Command in SIP INVITE
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Sending to 10.22.11.20 : 5060
(no NAT)
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Initializing initreq for method
INVITE - callid 47b41b9f601cfe453c9eae6a3b93d8e0 at 10.61.16.2
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Found RTP audio format 8
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Found RTP audio format 0
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Peer audio RTP is at port
10.22.12.32:32210
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Found audio description format
PCMA for ID 8
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Found audio description format
PCMU for ID 0
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Capabilities: us - 0xc
(ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing)/text=0x0
(nothing), combined - 0xc (ulaw|alaw)
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Non-codec capabilities (dtmf):
us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing)
[Aug 18 16:06:23] VERBOSE[19084] logger.c: Peer audio RTP is at port
10.22.12.32:32210
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: We're settling with these
formats: 0xc (ulaw|alaw)
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: We have an owner, now see if we
need to change this call
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: Got a SIP re-invite for call
47b41b9f601cfe453c9eae6a3b93d8e0 at 10.61.16.2
[Aug 18 16:06:23] DEBUG[19084] chan_sip.c: SIP/VOIP_AMIS-peer-082a1d60:
This call is UP....
[Aug 18 16:06:23] VERBOSE[19084] logger.c:
<--- Transmitting (no NAT) to 10.22.11.20:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP
10.22.11.20:5060;branch=z9hG4bK-1608-1A21A2;received=10.22.11.20
From: <sip:026208309 at 10.22.11.20>;tag=02-08136-008d9b96-1a6395973
To: "Kocbek Milos" <sip:036203559 at 10.61.16.2>;tag=as19020706
Call-ID: 47b41b9f601cfe453c9eae6a3b93d8e0 at 10.61.16.2
CSeq: 9052209 INVITE
User-Agent: Asterisk PBX 1.6.0.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
Contact: <sip:036203559 at 10.61.16.2>
Content-Length: 0
in file reinvite before_channel_up.txt you can see that REINVITE is
processed before channel is UP.
[Aug 18 15:55:11] VERBOSE[19084] logger.c: Transmitting (no NAT) to
10.22.11.20:5060:
ACK sip:10.22.11.20:5060 SIP/2.0
Via: SIP/2.0/UDP 10.61.16.2:5060;branch=z9hG4bK42615417;rport
Max-Forwards: 70
From: "Kocbek Milos" <sip:036203559 at 10.61.16.2>;tag=as09d56ebc
To: <sip:026208309 at 10.22.11.20>;tag=02-08067-008d3349-65e715141
Contact: <sip:036203559 at 10.61.16.2>
Call-ID: 0f1e533008905417497809f127add60f at 10.61.16.2
CSeq: 103 ACK
User-Agent: Asterisk PBX 1.6.0.13
Content-Length: 0
---
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Trying to put 'ACK sip:10' onto
UDP socket destined for 10.22.11.20:5060
[Aug 18 15:55:11] VERBOSE[19084] logger.c:
drugi invite
<--- SIP read from UDP://10.22.11.20:5060 --->
INVITE sip:036203559 at 10.61.16.2 SIP/2.0
Allow:
UPDATE,INFO,REFER,INVITE,ACK,OPTIONS,REGISTER,SUBSCRIBE,MESSAGE,NOTIFY,BYE,CANCEL,PRACK
Call-ID: 0f1e533008905417497809f127add60f at 10.61.16.2
Contact: <sip:10.22.11.20:5060>
Content-Type: application/sdp
CSeq: 9026164 INVITE
From: <sip:026208309 at 10.22.11.20>;tag=02-08067-008d3349-65e715141
Max-Forwards: 31
To: "Kocbek Milos" <sip:036203559 at 10.61.16.2>;tag=as09d56ebc
User-Agent: Cirpack/v4.42d (gw_sip)
Via: SIP/2.0/UDP 10.22.11.20:5060;branch=z9hG4bK-2A04-1A0733
Content-Length: 207
v=0
o=cp10 125060370729 125060370733 IN IP4 10.22.12.32
s=SIP Call
c=IN IP4 10.22.12.32
t=0 0
m=audio 32634 RTP/AVP 8 0
b=AS:64
a=rtpmap:8 PCMA/8000/1
a=rtpmap:0 PCMU/8000/1
a=ptime:20
a=sendrecv
<------------->
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 0 [ 39]: INVITE
sip:036203559 at 10.61.16.2 SIP/2.0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 1 [ 94]: Allow:
UPDATE,INFO,REFER,INVITE,ACK,OPTIONS,REGISTER,SUBSCRIBE,MESSAGE,NOTIFY,BYE,CANCEL,PRACK
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 2 [ 52]: Call-ID:
0f1e533008905417497809f127add60f at 10.61.16.2
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 3 [ 31]: Contact:
<sip:10.22.11.20:5060>
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 4 [ 29]: Content-Type:
application/sdp
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 5 [ 20]: CSeq: 9026164
INVITE
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 6 [ 65]: From:
<sip:026208309 at 10.22.11.20>;tag=02-08067-008d3349-65e715141
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 7 [ 16]: Max-Forwards:
31
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 8 [ 60]: To: "Kocbek
Milos" <sip:036203559 at 10.61.16.2>;tag=as09d56ebc
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 9 [ 35]: User-Agent:
Cirpack/v4.42d (gw_sip)
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 10 [ 60]: Via:
SIP/2.0/UDP 10.22.11.20:5060;branch=z9hG4bK-2A04-1A0733
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 11 [ 19]:
Content-Length: 207
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 12 [ 0]:
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 0 [ 3]: v=0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 1 [ 51]: o=cp10
125060370729 125060370733 IN IP4 10.22.12.32
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 2 [ 10]: s=SIP Call
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 3 [ 20]: c=IN IP4
10.22.12.32
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 4 [ 5]: t=0 0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 5 [ 25]: m=audio 32634
RTP/AVP 8 0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 6 [ 7]: b=AS:64
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 7 [ 22]: a=rtpmap:8
PCMA/8000/1
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 8 [ 22]: a=rtpmap:0
PCMU/8000/1
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 9 [ 10]: a=ptime:20
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 10 [ 10]: a=sendrecv
[Aug 18 15:55:11] VERBOSE[19084] logger.c: --- (12 headers 11 lines) ---
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: = Found Their Call ID:
0f1e533008905417497809f127add60f at 10.61.16.2 Their Tag
02-08067-008d3349-65e715141 Our tag: as09d56ebc
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: **** Received INVITE (5) -
Command in SIP INVITE
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Potential spiral detected.
Original RURI was sip:026208309 at 10.22.11.20, new RURI is
sip:036203559 at 10.61.16.2
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: OBPROXY: Not applying OBproxy
to this call
[Aug 18 15:55:11] WARNING[19084] chan_sip.c: No such host: 036203559
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Adding SIP Header
"X-route_name" with content ::
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Adding SIP Header "X-srcuid"
with content :1250603706.67:
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: ** Our capability: 0xc
(ulaw|alaw) Video flag: True Text flag: True
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: ** Our prefcodec: 0x8 (alaw)
[Aug 18 15:55:11] VERBOSE[19084] logger.c: Audio is at 10.61.16.2 port
10098
[Aug 18 15:55:11] VERBOSE[19084] logger.c: Adding codec 0x8 (alaw) to SDP
[Aug 18 15:55:11] VERBOSE[19084] logger.c: Adding codec 0x4 (ulaw) to SDP
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: -- Done with adding codecs to
SDP
[Aug 18 15:55:11] DEBUG[19084] channel.c: Internal timing is disabled
(option_internal_timing=0 chan->timingfd=-1)
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Done building SDP. Settling
with this capability: 0xc (ulaw|alaw)
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Initializing already
initialized SIP dialog 0f1e533008905417497809f127add60f at 10.61.16.2
(presumably reinvite)
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 0 [ 35]: INVITE
sip:10.22.11.20:5060 SIP/2.0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 1 [ 61]: Via:
SIP/2.0/UDP 10.61.16.2:5060;branch=z9hG4bK6db96123;rport
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 2 [ 16]: Max-Forwards:
70
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 3 [ 62]: From: "Kocbek
Milos" <sip:036203559 at 10.61.16.2>;tag=as09d56ebc
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 4 [ 26]: To:
<sip:10.22.11.20:5060>
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 5 [ 35]: Contact:
<sip:036203559 at 10.61.16.2>
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 6 [ 52]: Call-ID:
0f1e533008905417497809f127add60f at 10.61.16.2
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 7 [ 16]: CSeq: 104
INVITE
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 8 [ 33]: User-Agent:
Asterisk PBX 1.6.0.13
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 9 [ 21]:
Proxy-Authorization:
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 10 [ 35]: Date: Tue, 18
Aug 2009 13:55:11 GMT
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 11 [ 66]: Allow:
INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 12 [ 26]: Supported:
replaces, timer
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 13 [ 14]:
X-route_name:
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 14 [ 23]: X-srcuid:
1250603706.67
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 15 [ 29]: Content-Type:
application/sdp
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 16 [ 19]:
Content-Length: 226
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 17 [ 0]:
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 0 [ 3]: v=0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 1 [ 44]: o=root
475840445 475840447 IN IP4 10.61.16.2
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 2 [ 23]: s=Asterisk
PBX 1.6.0.13
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 3 [ 19]: c=IN IP4
10.61.16.2
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 4 [ 5]: t=0 0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 5 [ 25]: m=audio 10098
RTP/AVP 8 0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 6 [ 20]: a=rtpmap:8
PCMA/8000
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 7 [ 20]: a=rtpmap:0
PCMU/8000
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 8 [ 25]:
a=silenceSupp:off - - - -
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 9 [ 10]: a=ptime:20
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Body 10 [ 10]: a=sendrecv
[Aug 18 15:55:11] VERBOSE[19084] logger.c: Reliably Transmitting (no NAT)
to 10.22.11.20:5060:
INVITE sip:10.22.11.20:5060 SIP/2.0
Via: SIP/2.0/UDP 10.61.16.2:5060;branch=z9hG4bK6db96123;rport
Max-Forwards: 70
From: "Kocbek Milos" <sip:036203559 at 10.61.16.2>;tag=as09d56ebc
To: <sip:10.22.11.20:5060>
Contact: <sip:036203559 at 10.61.16.2>
Call-ID: 0f1e533008905417497809f127add60f at 10.61.16.2
CSeq: 104 INVITE
User-Agent: Asterisk PBX 1.6.0.13
Proxy-Authorization:
Date: Tue, 18 Aug 2009 13:55:11 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces, timer
X-route_name:
X-srcuid: 1250603706.67
Content-Type: application/sdp
Content-Length: 226
v=0
o=root 475840445 475840447 IN IP4 10.61.16.2
s=Asterisk PBX 1.6.0.13
c=IN IP4 10.61.16.2
t=0 0
m=audio 10098 RTP/AVP 8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
---
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: *** SIP TIMER: Initializing
retransmit timer on packet: Id https://issues.asterisk.org/view.php?id=18570
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Trying to put 'INVITE sip' onto
UDP socket destined for 10.22.11.20:5060
[Aug 18 15:55:11] VERBOSE[19084] logger.c:
<--- SIP read from UDP://10.22.11.20:5060 --->
SIP/2.0 407 authentication required
Allow:
UPDATE,INFO,REFER,INVITE,ACK,OPTIONS,REGISTER,SUBSCRIBE,MESSAGE,NOTIFY,BYE,CANCEL,PRACK
Call-ID: 0f1e533008905417497809f127add60f at 10.61.16.2
Contact: <sip:10.22.11.20:5060>
CSeq: 104 INVITE
From: "Kocbek Milos" <sip:036203559 at 10.61.16.2>;tag=as09d56ebc
Proxy-Authenticate: Digest
realm="sip-priv.amis.net",nonce="008d33201ac9dbf0619afd3b13eb9686",opaque="008b66360984230",stale=false,algorithm=MD5
Server: Cirpack/v4.42d (gw_sip)
To: <sip:10.22.11.20:5060>;tag=02-08127-008d3411-1c5b96ee0
Via: SIP/2.0/UDP
10.61.16.2:5060;received=10.61.16.2;rport=5060;branch=z9hG4bK6db96123
Content-Length: 0
<------------->
[Aug 18 15:55:11] DEBUG[19793] devicestate.c: Notification of state change
to be queued on device/channel SIP/VOIP_AMIS-peer
[Aug 18 15:55:11] DEBUG[19067] devicestate.c: No provider found, checking
channel drivers for SIP - VOIP_AMIS-peer
[Aug 18 15:55:11] DEBUG[19067] chan_sip.c: Checking device state for peer
VOIP_AMIS-peer
[Aug 18 15:55:11] DEBUG[19067] devicestate.c: Changing state for
SIP/VOIP_AMIS-peer - state 1 (Not in use)
[Aug 18 15:55:11] DEBUG[19083] app_queue.c: Device 'SIP/VOIP_AMIS-peer'
changed to state '1' (Not in use) but we don't care because they're not a
member of any queue.
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 0 [ 35]: SIP/2.0 407
authentication required
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 1 [ 94]: Allow:
UPDATE,INFO,REFER,INVITE,ACK,OPTIONS,REGISTER,SUBSCRIBE,MESSAGE,NOTIFY,BYE,CANCEL,PRACK
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 2 [ 52]: Call-ID:
0f1e533008905417497809f127add60f at 10.61.16.2
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 3 [ 31]: Contact:
<sip:10.22.11.20:5060>
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 4 [ 16]: CSeq: 104
INVITE
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 5 [ 62]: From: "Kocbek
Milos" <sip:036203559 at 10.61.16.2>;tag=as09d56ebc
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 6 [144]:
Proxy-Authenticate: Digest
realm="sip-priv.amis.net",nonce="008d33201ac9dbf0619afd3b13eb9686",opaque="008b66360984230",stale=false,algorithm=MD5
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 7 [ 31]: Server:
Cirpack/v4.42d (gw_sip)
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 8 [ 58]: To:
<sip:10.22.11.20:5060>;tag=02-08127-008d3411-1c5b96ee0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 9 [ 86]: Via:
SIP/2.0/UDP
10.61.16.2:5060;received=10.61.16.2;rport=5060;branch=z9hG4bK6db96123
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 10 [ 17]:
Content-Length: 0
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Header 11 [ 0]:
[Aug 18 15:55:11] VERBOSE[19084] logger.c: --- (11 headers 0 lines) ---
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: = Found Their Call ID:
0f1e533008905417497809f127add60f at 10.61.16.2 Their Tag Our tag: as09d56ebc
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Acked pending invite 104
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: ** SIP TIMER: Cancelling
retransmit of packet (reply received) Retransid
https://issues.asterisk.org/view.php?id=18570
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Stopping retransmission on
'0f1e533008905417497809f127add60f at 10.61.16.2' of Request 104: Match Found
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: SIP response 407 to RE-invite
on outgoing call 0f1e533008905417497809f127add60f at 10.61.16.2
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Strict routing enforced for
session 0f1e533008905417497809f127add60f at 10.61.16.2
[Aug 18 15:55:11] VERBOSE[19084] logger.c: set_destination: Parsing
<sip:10.22.11.20:5060> for address/port to send to
[Aug 18 15:55:11] VERBOSE[19084] logger.c: set_destination: set
destination to 10.22.11.20, port 5060
[Aug 18 15:55:11] VERBOSE[19084] logger.c: Transmitting (no NAT) to
10.22.11.20:5060:
ACK sip:10.22.11.20:5060 SIP/2.0
Via: SIP/2.0/UDP 10.61.16.2:5060;branch=z9hG4bK6db96123;rport
Max-Forwards: 70
From: "Kocbek Milos" <sip:036203559 at 10.61.16.2>;tag=as09d56ebc
To: <sip:10.22.11.20:5060>;tag=02-08127-008d3411-1c5b96ee0
Contact: <sip:036203559 at 10.61.16.2>
Call-ID: 0f1e533008905417497809f127add60f at 10.61.16.2
CSeq: 104 ACK
User-Agent: Asterisk PBX 1.6.0.13
Content-Length: 0
---
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Trying to put 'ACK sip:10' onto
UDP socket destined for 10.22.11.20:5060
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Auth attempt 1 on INVITE
[Aug 18 15:55:11] VERBOSE[19793] logger.c: --
SIP/VOIP_AMIS-peer-082c0d28 answered SIP/91.199.174.215-082ab508
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Strict routing enforced for
session
======================================================================
Issue History
Date Modified Username Field Change
======================================================================
2009-09-14 12:01 lmadsen Assigned To dvossel =>
======================================================================
More information about the asterisk-bugs
mailing list