[Home]

Summary:ASTERISK-14714: Reinvite before channel state is changed to up.
Reporter:Milos Kocbek (milos)Labels:
Date Opened:2009-08-25 04:02:45Date Closed:2011-06-07 14:07:52
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) reinvite_before_channel_up.txt
( 1) reinvite_normal.txt
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  #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@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@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@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@10.22.11.20>;tag=02-08136-008d9b96-1a6395973
To: "Kocbek Milos" <sip:036203559@10.61.16.2>;tag=as19020706
Call-ID: 47b41b9f601cfe453c9eae6a3b93d8e0@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@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@10.61.16.2>;tag=as09d56ebc
To: <sip:026208309@10.22.11.20>;tag=02-08067-008d3349-65e715141
Contact: <sip:036203559@10.61.16.2>
Call-ID: 0f1e533008905417497809f127add60f@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@10.61.16.2 SIP/2.0
Allow: UPDATE,INFO,REFER,INVITE,ACK,OPTIONS,REGISTER,SUBSCRIBE,MESSAGE,NOTIFY,BYE,CANCEL,PRACK
Call-ID: 0f1e533008905417497809f127add60f@10.61.16.2
Contact: <sip:10.22.11.20:5060>
Content-Type: application/sdp
CSeq: 9026164 INVITE
From: <sip:026208309@10.22.11.20>;tag=02-08067-008d3349-65e715141
Max-Forwards: 31
To: "Kocbek Milos" <sip:036203559@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@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@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@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@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@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@10.22.11.20, new RURI is sip:036203559@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@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@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@10.61.16.2>
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c:  Header  6 [ 52]: Call-ID: 0f1e533008905417497809f127add60f@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@10.61.16.2>;tag=as09d56ebc
To: <sip:10.22.11.20:5060>
Contact: <sip:036203559@10.61.16.2>
Call-ID: 0f1e533008905417497809f127add60f@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  ASTERISK-17197
[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@10.61.16.2
Contact: <sip:10.22.11.20:5060>
CSeq: 104 INVITE
From: "Kocbek Milos" <sip:036203559@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@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@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@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 ASTERISK-17197
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Stopping retransmission on '0f1e533008905417497809f127add60f@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@10.61.16.2
[Aug 18 15:55:11] DEBUG[19084] chan_sip.c: Strict routing enforced for session 0f1e533008905417497809f127add60f@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@10.61.16.2>;tag=as09d56ebc
To: <sip:10.22.11.20:5060>;tag=02-08127-008d3411-1c5b96ee0
Contact: <sip:036203559@10.61.16.2>
Call-ID: 0f1e533008905417497809f127add60f@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


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

I am using debian etch linux.kernel 2.6.18-6-686 #1 SMP
Asterisk version 1.6.0.13. Tried also 1.6.0.10 and same problem.
Comments:By: Leif Madsen (lmadsen) 2009-08-31 08:48:23

Assigned to dvossel for review. If you are unable to move this issue forward, please unassign yourself and set it back to status of New. Thanks!
By: Paul Belanger (pabelanger) 2010-06-02 13:29:18

Please retest with 1.6.2
--
Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.6.0 and 1.6.1 branches has ended. For continued maintenance support please move to the 1.6.2 branch.

More information on this change can be found in the release announcement: http://www.asterisk.org/node/49924
By: Leif Madsen (lmadsen) 2010-06-08 10:42:14

Because this issue is so old now, and because maintenance on 1.6.0 and 1.6.1 branches of Asterisk is no longer supported, I am going to close this issue. If the reporter is still having this issue on the latest 1.6.2 release, then please open a new issue along with debug information. Thanks!