[Home]

Summary:ASTERISK-13365: [patch] 491-request pending is sent out of dialog
Reporter:klaus3000 (klaus3000)Labels:
Date Opened:2009-01-14 07:33:39.000-0600Date Closed:2009-07-23 14:36:30
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 14239.patch
Description:Hi!

Asterisk does not handle the following scenario correctly:

--INVITE-->
<-407------
[ACK is lost]

--INVITE w/credentials-->
<-----------491----------

The 491 is wrong as the 491 is only allowed for in-dialog requests. As the first INVITE is not accepted there is no dialog set up. Thus, Asterisk may retransmit the 407 to trigger retransmission of the ACK, but this must be independet from the second INVITE which should be accepted instead of rejecting with 491 - even if the ACK was not received.

I checked lates SVN commits in chan_sip and itlooks like the problem is still there.

This issue is maybe related to ASTERISK-13025 (although in ASTERISK-13025 the second INVITE is in-dialog).

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

Here a detailed log:

<--- SIP read from 11.111.11.3:2051 --->
INVITE sip:01505641636@app.example.at:5160 SIP/2.0
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u9l4nvmwefgw;rport
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 1 INVITE
Max-Forwards: 70
Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1
P-Key-Flags: keys="3"
User-Agent: snom320/7.3.7
Accept: application/sdp
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO
Allow-Events: talk, hold, refer, call-info
Supported: timer, 100rel, replaces, from-change
Session-Expires: 3600;refresher=uas
Min-SE: 90
Content-Type: application/sdp
Content-Length: 339

v=0
o=root 1665513580 1665513580 IN IP4 11.111.11.3
s=call
c=IN IP4 11.111.11.3
t=0 0
m=audio 57384 RTP/AVP 0 8 9 3 18 4 101
a=rtpmap:0 pcmu/8000
a=rtpmap:8 pcma/8000
a=rtpmap:9 g722/8000
a=rtpmap:3 gsm/8000
a=rtpmap:18 g729/8000
a=rtpmap:4 g723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------->
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 0: INVITE sip:01505641636@app.example.at:5160 SIP/2.0 (51)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 1: Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u9l4nvmwefgw;rport (67)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 2: From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya (62)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 3: To: <sip:01505641636@app.example.at:5160> (42)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 4: Call-ID: 3ca4f870f28b-9kimtkr0jx9b (34)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 5: CSeq: 1 INVITE (14)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 6: Max-Forwards: 70 (16)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 7: Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1 (69)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 8: P-Key-Flags: keys="3" (21)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 9: User-Agent: snom320/7.3.7 (25)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 10: Accept: application/sdp (23)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 15: Min-SE: 90 (10)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 16: Content-Type: application/sdp (29)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 17: Content-Length: 339 (19)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 18:  (0)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: v=0 (3)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: o=root 1665513580 1665513580 IN IP4 11.111.11.3 (47)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: s=call (6)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: c=IN IP4 11.111.11.3 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: t=0 0 (5)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: m=audio 57384 RTP/AVP 0 8 9 3 18 4 101 (38)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:0 pcmu/8000 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:9 g722/8000 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:3 gsm/8000 (19)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:18 g729/8000 (21)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:4 g723/8000 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=fmtp:101 0-16 (15)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=ptime:20 (10)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=sendrecv (10)
[Jan 14 14:15:10] VERBOSE[22394] logger.c: --- (18 headers 16 lines) ---
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: = No match Their Call ID: 3c9e48569d58-0vcm34ygiqhw Their Tag ss0sftmftq Our tag: as0e96670f
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Setting NAT on RTP to Off
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Allocating new SIP dialog for 3ca4f870f28b-9kimtkr0jx9b - INVITE (With RTP)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Begin: parsing SIP "Supported: timer, 100rel, replaces, from-change"
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Found SIP option: -timer-
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Matched SIP option: timer
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Found SIP option: -100rel-
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Matched SIP option: 100rel
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Found SIP option: -replaces-
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Matched SIP option: replaces
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Found SIP option: -from-change-
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Found no match for SIP option: from-change (Please file bug report!)
[Jan 14 14:15:10] VERBOSE[22394] logger.c: Sending to 11.111.11.3 : 2051 (NAT)
[Jan 14 14:15:10] VERBOSE[22394] logger.c: Using INVITE request as basis request - 3ca4f870f28b-9kimtkr0jx9b
[Jan 14 14:15:10] VERBOSE[22394] logger.c: Found peer '+4372062007301'
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Setting NAT on RTP to On
[Jan 14 14:15:10] VERBOSE[22394] logger.c:
<--- Reliably Transmitting (NAT) to 11.111.11.3:2051 --->
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u9l4nvmwefgw;received=11.111.11.3;rport=2051
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 1 INVITE
User-Agent: InnoSIP-app
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="43352ffe"
Content-Length: 0


<------------>
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #-1
[Jan 14 14:15:10] VERBOSE[22394] logger.c: Scheduling destruction of SIP dialog '3ca4f870f28b-9kimtkr0jx9b' in 32000 ms (Method: INVITE)
[Jan 14 14:15:10] VERBOSE[22394] logger.c:
<--- SIP read from 11.111.11.3:2051 --->
INVITE sip:01505641636@app.example.at:5160 SIP/2.0
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;rport
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 2 INVITE
Max-Forwards: 70
Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1
P-Key-Flags: keys="3"
User-Agent: snom320/7.3.7
Accept: application/sdp
Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO
Allow-Events: talk, hold, refer, call-info
Supported: timer, 100rel, replaces, from-change
Session-Expires: 3600;refresher=uas
Min-SE: 90
Proxy-Authorization: Digest username="+4372062007301",realm="asterisk",nonce="43352ffe",uri="sip:01505641636@app.example.at:5160",response="546ab92fa2c7260ec85c53df1b7d39bd",algorithm=MD5
Content-Type: application/sdp
Content-Length: 339

v=0
o=root 1665513580 1665513580 IN IP4 11.111.11.3
s=call
c=IN IP4 11.111.11.3
t=0 0
m=audio 57384 RTP/AVP 0 8 9 3 18 4 101
a=rtpmap:0 pcmu/8000
a=rtpmap:8 pcma/8000
a=rtpmap:9 g722/8000
a=rtpmap:3 gsm/8000
a=rtpmap:18 g729/8000
a=rtpmap:4 g723/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------->
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 0: INVITE sip:01505641636@app.example.at:5160 SIP/2.0 (51)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 1: Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;rport (67)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 2: From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya (62)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 3: To: <sip:01505641636@app.example.at:5160> (42)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 4: Call-ID: 3ca4f870f28b-9kimtkr0jx9b (34)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 5: CSeq: 2 INVITE (14)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 6: Max-Forwards: 70 (16)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 7: Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1 (69)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 8: P-Key-Flags: keys="3" (21)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 9: User-Agent: snom320/7.3.7 (25)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 10: Accept: application/sdp (23)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 12: Allow-Events: talk, hold, refer, call-info (42)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 13: Supported: timer, 100rel, replaces, from-change (47)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 14: Session-Expires: 3600;refresher=uas (35)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 15: Min-SE: 90 (10)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 16: Proxy-Authorization: Digest username="+4372062007301",realm="asterisk",nonce="43352ffe",uri="sip:01505641636@app.example.at:5160",response="546ab92fa2c7260ec85c53df1b7d39bd",algorithm=MD5 (188)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 17: Content-Type: application/sdp (29)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 18: Content-Length: 339 (19)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 19:  (0)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: v=0 (3)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: o=root 1665513580 1665513580 IN IP4 11.111.11.3 (47)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: s=call (6)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: c=IN IP4 11.111.11.3 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: t=0 0 (5)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: m=audio 57384 RTP/AVP 0 8 9 3 18 4 101 (38)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:0 pcmu/8000 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:8 pcma/8000 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:9 g722/8000 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:3 gsm/8000 (19)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:18 g729/8000 (21)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:4 g723/8000 (20)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=fmtp:101 0-16 (15)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=ptime:20 (10)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Line: a=sendrecv (10)
[Jan 14 14:15:10] VERBOSE[22394] logger.c: --- (19 headers 16 lines) ---
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: = Found Their Call ID: 3ca4f870f28b-9kimtkr0jx9b Their Tag 16jovsenya Our tag: as008ef361
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Jan 14 14:15:10] VERBOSE[22394] logger.c:
<--- Reliably Transmitting (NAT) to 11.111.11.3:2051 --->
SIP/2.0 491 Request Pending
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;received=11.111.11.3;rport=2051
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 2 INVITE
User-Agent: InnoSIP-app
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


<------------>
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #-1
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Got INVITE on call where we already have pending INVITE, deferring that - 3ca4f870f28b-9kimtkr0jx9b
[Jan 14 14:15:10] VERBOSE[22394] logger.c:
<--- SIP read from 11.111.11.3:2051 --->
ACK sip:01505641636@app.example.at:5160 SIP/2.0
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;rport
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 2 ACK
Max-Forwards: 70
Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1
Content-Length: 0


<------------->
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 0: ACK sip:01505641636@app.example.at:5160 SIP/2.0 (48)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 1: Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;rport (67)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 2: From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya (62)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 3: To: <sip:01505641636@app.example.at:5160>;tag=as008ef361 (57)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 4: Call-ID: 3ca4f870f28b-9kimtkr0jx9b (34)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 5: CSeq: 2 ACK (11)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 6: Max-Forwards: 70 (16)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 7: Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1 (69)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 8: Content-Length: 0 (17)
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: Header 9:  (0)
[Jan 14 14:15:10] VERBOSE[22394] logger.c: --- (9 headers 0 lines) ---
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: = Found Their Call ID: 3ca4f870f28b-9kimtkr0jx9b Their Tag 16jovsenya Our tag: as008ef361
[Jan 14 14:15:10] DEBUG[22394] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: SIP TIMER: Rescheduling retransmission ASTERISK-17326 (1) SIP/2.0 - 1
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id ASTERISK-17326))
[Jan 14 14:15:11] VERBOSE[22394] logger.c: Retransmitting #1 (NAT) to 11.111.11.3:2051:
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u9l4nvmwefgw;received=11.111.11.3;rport=2051
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 1 INVITE
User-Agent: InnoSIP-app
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="43352ffe"
Content-Length: 0


---
[Jan 14 14:15:11] VERBOSE[22394] logger.c:
<--- SIP read from 11.111.11.3:2051 --->
ACK sip:01505641636@app.example.at:5160 SIP/2.0
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u9l4nvmwefgw;rport
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 1 ACK
Max-Forwards: 70
Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1
Content-Length: 0


<------------->
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 0: ACK sip:01505641636@app.example.at:5160 SIP/2.0 (48)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 1: Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u9l4nvmwefgw;rport (67)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 2: From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya (62)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 3: To: <sip:01505641636@app.example.at:5160>;tag=as008ef361 (57)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 4: Call-ID: 3ca4f870f28b-9kimtkr0jx9b (34)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 5: CSeq: 1 ACK (11)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 6: Max-Forwards: 70 (16)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 7: Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1 (69)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 8: Content-Length: 0 (17)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 9:  (0)
[Jan 14 14:15:11] VERBOSE[22394] logger.c: --- (9 headers 0 lines) ---
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: = Found Their Call ID: 3ca4f870f28b-9kimtkr0jx9b Their Tag 16jovsenya Our tag: as008ef361
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Got CANCEL or ACK on INVITE with transactions in between.
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid ASTERISK-17326
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Stopping retransmission on '3ca4f870f28b-9kimtkr0jx9b' of Response 1: Match Found
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: SIP TIMER: Rescheduling retransmission ASTERISK-17328 (1) SIP/2.0 - 1
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id ASTERISK-17328))
[Jan 14 14:15:11] VERBOSE[22394] logger.c: Retransmitting #1 (NAT) to 11.111.11.3:2051:
SIP/2.0 491 Request Pending
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;received=11.111.11.3;rport=2051
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 2 INVITE
User-Agent: InnoSIP-app
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


---
[Jan 14 14:15:11] VERBOSE[22394] logger.c:
<--- SIP read from 11.111.11.3:2051 --->
ACK sip:01505641636@app.example.at:5160 SIP/2.0
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;rport
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 2 ACK
Max-Forwards: 70
Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1
Content-Length: 0


<------------->
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 0: ACK sip:01505641636@app.example.at:5160 SIP/2.0 (48)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 1: Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;rport (67)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 2: From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya (62)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 3: To: <sip:01505641636@app.example.at:5160>;tag=as008ef361 (57)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 4: Call-ID: 3ca4f870f28b-9kimtkr0jx9b (34)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 5: CSeq: 2 ACK (11)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 6: Max-Forwards: 70 (16)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 7: Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1 (69)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 8: Content-Length: 0 (17)
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: Header 9:  (0)
[Jan 14 14:15:11] VERBOSE[22394] logger.c: --- (9 headers 0 lines) ---
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: = Found Their Call ID: 3ca4f870f28b-9kimtkr0jx9b Their Tag 16jovsenya Our tag: as008ef361
[Jan 14 14:15:11] DEBUG[22394] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jan 14 14:15:12] DEBUG[22394] chan_sip.c: SIP TIMER: Rescheduling retransmission ASTERISK-17328 (2) SIP/2.0 - 1
[Jan 14 14:15:12] DEBUG[22394] chan_sip.c: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id ASTERISK-17328))
[Jan 14 14:15:12] VERBOSE[22394] logger.c: Retransmitting #2 (NAT) to 11.111.11.3:2051:
SIP/2.0 491 Request Pending
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;received=11.111.11.3;rport=2051
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 2 INVITE
User-Agent: InnoSIP-app
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


---

[Jan 14 14:15:12] DEBUG[22394] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #-1
[Jan 14 14:15:12] VERBOSE[22394] logger.c:
<--- SIP read from 11.111.11.3:2051 --->
ACK sip:01505641636@app.example.at:5160 SIP/2.0
Via: SIP/2.0/UDP 11.111.11.3:2051;branch=z9hG4bK-u0cekanff9q7;rport
From: <sip:+4372062007301@app.example.at:5160>;tag=16jovsenya
To: <sip:01505641636@app.example.at:5160>;tag=as008ef361
Call-ID: 3ca4f870f28b-9kimtkr0jx9b
CSeq: 2 ACK
Max-Forwards: 70
Contact: <sip:+4372062007301@11.111.11.3:2051;line=r95ux3uz>;reg-id=1
Content-Length: 0


Comments:By: Leif Madsen (lmadsen) 2009-05-20 09:09:10

Curious if this is still an issue now that 13849 has been closed. It appears they may have been related, but not the same issue, but never hurts to ask since this issue has not been updated in some time. Thanks!
By: klaus3000 (klaus3000) 2009-06-19 11:05:23

Hi! I just tested Asterisk 1.4.25 (which contains the fix to 13849) but Asterisk is still behaving buggy and replies with 491 request pending.

There is also a problem with this scenario in 1.6.2.0-beta3 which locks up chan_sip. I will open another bug report for 1.6
By: klaus3000 (klaus3000) 2009-06-19 12:26:34

I just verified again: The above scenario cause buggy 491 in Asterisk 1.4.25 and svn-trunk

In 1.6.2.0-beta3 it causes chan_sip do not process incoming SIP requests anymore: ASTERISK-14344
By: Mark Michelson (mmichelson) 2009-07-09 11:08:24

klaus3000: It appears that this bug may be easy to fix, simply by modifying what was done for ASTERISK-13025 to behave the same way for this scenario as well.

I just need to verify that this is correct. Is it acceptable to just accept the INVITE with credentials as though it is serving as both the ACK for the previous INVITE transaction and as the start of a new INVITE transaction? If so, then this can probably be done with a one-line change.
By: Mark Michelson (mmichelson) 2009-07-09 11:26:44

I've uploaded 14239.patch for testing, just in case you say that the method I described for handling the situation is sufficient.
By: Mark Michelson (mmichelson) 2009-07-09 11:30:49

I know it's of no consequence to the actual mechanics of the patch, but it's bugging me that I used the term "terminated dialog" when I meant to say "terminated transaction" in the big comment block.
By: klaus3000 (klaus3000) 2009-07-13 11:40:54

I've tested the patch and it works: I tested:
- dropped ACK
- delayed ACK (2 seconds too late)

I did not made extensive tests, but the "491 request pending" problem in the described scenario is solved now.

I also re-tested the scenario in ASTERISK-1374849 (reINVITE overtakes ACK) and it still behaves correct.
By: Digium Subversion (svnbot) 2009-07-23 14:24:27

Repository: asterisk
Revision: 208386

U   branches/1.4/channels/chan_sip.c

------------------------------------------------------------------------
r208386 | mmichelson | 2009-07-23 14:24:26 -0500 (Thu, 23 Jul 2009) | 17 lines

Fix a problem where a 491 response could be sent out of dialog.

This generalizes the fix for issue 13849. The initial fix corrected the
problem that Asterisk would reply with a 491 if a reinvite were received
from an endpoint and we had not yet received an ACK from that endpoint
for the initial INVITE it had sent us. This expansion also allows Asterisk
to appropriately handle an INVITE with authorization credentials if Asterisk
had not received an ACK from the previous transaction in which Asterisk had
responded to an unauthorized INVITE with a 407.

(closes issue ASTERISK-13365)
Reported by: klaus3000
Patches:
     14239.patch uploaded by mmichelson (license 60)
Tested by: klaus3000
 

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=208386
By: Digium Subversion (svnbot) 2009-07-23 14:34:54

Repository: asterisk
Revision: 208388

_U  trunk/
U   trunk/channels/chan_sip.c

------------------------------------------------------------------------
r208388 | mmichelson | 2009-07-23 14:34:54 -0500 (Thu, 23 Jul 2009) | 24 lines

Merged revisions 208386 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r208386 | mmichelson | 2009-07-23 14:24:21 -0500 (Thu, 23 Jul 2009) | 17 lines
 
 Fix a problem where a 491 response could be sent out of dialog.
 
 This generalizes the fix for issue 13849. The initial fix corrected the
 problem that Asterisk would reply with a 491 if a reinvite were received
 from an endpoint and we had not yet received an ACK from that endpoint
 for the initial INVITE it had sent us. This expansion also allows Asterisk
 to appropriately handle an INVITE with authorization credentials if Asterisk
 had not received an ACK from the previous transaction in which Asterisk had
 responded to an unauthorized INVITE with a 407.
 
 (closes issue ASTERISK-13365)
 Reported by: klaus3000
 Patches:
       14239.patch uploaded by mmichelson (license 60)
 Tested by: klaus3000
   
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=208388
By: Digium Subversion (svnbot) 2009-07-23 14:35:33

Repository: asterisk
Revision: 208389

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_sip.c

------------------------------------------------------------------------
r208389 | mmichelson | 2009-07-23 14:35:32 -0500 (Thu, 23 Jul 2009) | 31 lines

Merged revisions 208388 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r208388 | mmichelson | 2009-07-23 14:34:49 -0500 (Thu, 23 Jul 2009) | 24 lines
 
 Merged revisions 208386 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r208386 | mmichelson | 2009-07-23 14:24:21 -0500 (Thu, 23 Jul 2009) | 17 lines
   
   Fix a problem where a 491 response could be sent out of dialog.
   
   This generalizes the fix for issue 13849. The initial fix corrected the
   problem that Asterisk would reply with a 491 if a reinvite were received
   from an endpoint and we had not yet received an ACK from that endpoint
   for the initial INVITE it had sent us. This expansion also allows Asterisk
   to appropriately handle an INVITE with authorization credentials if Asterisk
   had not received an ACK from the previous transaction in which Asterisk had
   responded to an unauthorized INVITE with a 407.
   
   (closes issue ASTERISK-13365)
   Reported by: klaus3000
   Patches:
         14239.patch uploaded by mmichelson (license 60)
   Tested by: klaus3000
     
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=208389
By: Digium Subversion (svnbot) 2009-07-23 14:36:02

Repository: asterisk
Revision: 208390

_U  branches/1.6.1/
U   branches/1.6.1/channels/chan_sip.c

------------------------------------------------------------------------
r208390 | mmichelson | 2009-07-23 14:36:02 -0500 (Thu, 23 Jul 2009) | 31 lines

Merged revisions 208388 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r208388 | mmichelson | 2009-07-23 14:34:49 -0500 (Thu, 23 Jul 2009) | 24 lines
 
 Merged revisions 208386 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r208386 | mmichelson | 2009-07-23 14:24:21 -0500 (Thu, 23 Jul 2009) | 17 lines
   
   Fix a problem where a 491 response could be sent out of dialog.
   
   This generalizes the fix for issue 13849. The initial fix corrected the
   problem that Asterisk would reply with a 491 if a reinvite were received
   from an endpoint and we had not yet received an ACK from that endpoint
   for the initial INVITE it had sent us. This expansion also allows Asterisk
   to appropriately handle an INVITE with authorization credentials if Asterisk
   had not received an ACK from the previous transaction in which Asterisk had
   responded to an unauthorized INVITE with a 407.
   
   (closes issue ASTERISK-13365)
   Reported by: klaus3000
   Patches:
         14239.patch uploaded by mmichelson (license 60)
   Tested by: klaus3000
     
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=208390
By: Digium Subversion (svnbot) 2009-07-23 14:36:29

Repository: asterisk
Revision: 208391

_U  branches/1.6.2/
U   branches/1.6.2/channels/chan_sip.c

------------------------------------------------------------------------
r208391 | mmichelson | 2009-07-23 14:36:29 -0500 (Thu, 23 Jul 2009) | 31 lines

Merged revisions 208388 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
 r208388 | mmichelson | 2009-07-23 14:34:49 -0500 (Thu, 23 Jul 2009) | 24 lines
 
 Merged revisions 208386 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r208386 | mmichelson | 2009-07-23 14:24:21 -0500 (Thu, 23 Jul 2009) | 17 lines
   
   Fix a problem where a 491 response could be sent out of dialog.
   
   This generalizes the fix for issue 13849. The initial fix corrected the
   problem that Asterisk would reply with a 491 if a reinvite were received
   from an endpoint and we had not yet received an ACK from that endpoint
   for the initial INVITE it had sent us. This expansion also allows Asterisk
   to appropriately handle an INVITE with authorization credentials if Asterisk
   had not received an ACK from the previous transaction in which Asterisk had
   responded to an unauthorized INVITE with a 407.
   
   (closes issue ASTERISK-13365)
   Reported by: klaus3000
   Patches:
         14239.patch uploaded by mmichelson (license 60)
   Tested by: klaus3000
     
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=208391