asterisk users - Dec 2004 - ACK from asterisk not matched to transaction by SER / LCS2005

For reasons unknown to me, SER and subsequently a Microsoft Live
Communcations Server 2005 seems to have problems, matching a SIP ACK
request from asterisk to the ongoing SIP transaction, I have attached
the complete log, but the essential lines are:
 
13(2894) DEBUG: RFC3261 transaction matching failed
13(2894) DEBUG: t_lookup_request: no transaction found
13(2894) SER: forwarding ACK  statelessly

The result is a "half duplex" connection that will break down, as soon
as the timeout for the missing ACK package is reached.
Has anybody an idea how to fix this problem ?
 
The problem only occurs when if a call originates in asterisk. Calls
from the LCS system to asterisk work just fine.
 
chris.
 
 
 
 9(2890) SIP Request:
 9(2890)  method:  <INVITE>
 9(2890)  uri:     <sip:chriz@karlshorst.net>
 9(2890)  version: <SIP/2.0>
 9(2890) parse_headers: flags=1
 9(2890) Found param type 232, <branch> = <z9hG4bK61c24316>;
state=16
 9(2890) end of header reached, state=5
 9(2890) parse_headers: Via found, flags=1
 9(2890) parse_headers: this is the first via
 9(2890) After parse_msg...
 9(2890) preparing to run routing scripts...
 9(2890) DEBUG : is_maxfwd_present: searching for max_forwards header
 9(2890) parse_headers: flags=128
 9(2890) end of header reached, state=9
 9(2890) DEBUG: get_hdr_field: <To> [28]; uri=[sip:chriz@karlshorst.net]
 9(2890) DEBUG: to body [<sip:chriz@karlshorst.net>
]
 9(2890) get_hdr_field: cseq <CSeq>: <102> <INVITE>
 9(2890) DEBUG: get_hdr_body : content_length=364
 9(2890) found end of header
 9(2890) DEBUG: is_maxfwd_present: max_forwards header not found!
 9(2890) DEBUG: add_param: tag=as47998c2b
 9(2890) end of header reached, state=29
 9(2890) parse_headers: flags=256
 9(2890) find_first_route(): No Route headers found
 9(2890) loose_route(): There is no Route HF
 9(2890) parse_headers: flags=2048
 9(2890) check_via_address(192.168.4.39, 192.168.4.39, 0)
 9(2890) Sending:
INVITE sip:chriz@karlshorst.net SIP/2.0
Max-Forwards: 10
Record-Route:
<sip:chriz@192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz@192.168.4.39;r2=on;ftag=as47998c2b;lr>
Via: SIP/2.0/TCP 192.168.4.39;branch=0
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK61c24316
From: "10" <sip:10@fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz@karlshorst.net>
Contact: <sip:10@192.168.4.39:5082>
Call-ID: 3f5512e931c367c566ee7d3420453098@fedora.karlshorst.net
CSeq: 102 INVITE
User-Agent: Babble/0.6.10
Date: Fri, 10 Dec 2004 16:58:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Content-Type: application/sdp
Content-Length: 364
 
v=0
o=root 2442 2442 IN IP4 192.168.4.39
s=session
c=IN IP4 192.168.4.39
t=0 0
m=audio 30016 RTP/AVP 8 0 97 3 2 110
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:97 iLBC/8000
a=rtpmap:3 GSM/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:110 speex/8000
a=silenceSupp:off - - - -
m=video 30000 RTP/AVP 34 31
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000
.
 9(2890) orig. len=841, new_len=1043, proto=2
 9(2890) tcp_send: no open tcp connection found, opening new one
 9(2890) tcpconn_new: new tcp connection: 192.168.4.37
 9(2890) tcpconn_new: on port 5060, type 2
 9(2890) tcp_send: sending...
 9(2890) tcp_send: after write: c= 0xf51740e0 n=1043 fd=15
 9(2890) tcp_send: bufINVITE sip:chriz@karlshorst.net SIP/2.0
Max-Forwards: 10
Record-Route:
<sip:chriz@192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz@192.168.4.39;r2=on;ftag=as47998c2b;lr>
Via: SIP/2.0/TCP 192.168.4.39;branch=0
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK61c24316
From: "10" <sip:10@fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz@karlshorst.net>
Contact: <sip:10@192.168.4.39:5082>
Call-ID: 3f5512e931c367c566ee7d3420453098@fedora.karlshorst.net
CSeq: 102 INVITE
User-Agent: Babble/0.6.10
Date: Fri, 10 Dec 2004 16:58:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Content-Type: application/sdp
Content-Length: 364
 
v=0
o=root 2442 2442 IN IP4 192.168.4.39
s=session
c=IN IP4 192.168.4.39
t=0 0
m=audio 30016 RTP/AVP 8 0 97 3 2 110
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:97 iLBC/8000
a=rtpmap:3 GSM/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:110 speex/8000
a=silenceSupp:off - - - -
m=video 30000 RTP/AVP 34 31
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000
 
 9(2890) DEBUG:destroy_avp_list: destroing list (nil)
 9(2890) receive_msg: cleaning up
27(2908) tcp_main_loop: read response= f51740e0, 2 from 9 (2890)
27(2908) tcpconn_add: hashes: 772, 1
27(2908) tcp_main_loop: data available on 0xf51740e0 [h:772] 41
27(2908) send2child: to tcp child 0 19(2900), 0xf51740e0
19(2900) received n=4 con=0xf51740e0, fd=26
19(2900) tcp_read_req: content-length= 0
19(2900) SIP Reply  (status):
19(2900)  version: <SIP/2.0>
19(2900)  status:  <100>
19(2900)  reason:  <Trying>
19(2900) parse_headers: flags=1
19(2900) Found param type 232, <branch> = <0>; state=6
19(2900) Found param type 237, <ms-received-port> = <42320>; state=6
19(2900) Found param type 237, <ms-received-cid> = <2200>; state=16
19(2900) end of header reached, state=5
19(2900) parse_headers: Via found, flags=1
19(2900) parse_headers: this is the first via
19(2900) After parse_msg...
19(2900) forward_reply: found module tm, passing reply to it
19(2900) DEBUG: t_check: msg id=1 global id=0 T start=0xffffffff
19(2900) parse_headers: flags=17
19(2900) Found param type 232, <branch> = <z9hG4bK61c24316>;
state=16
19(2900) end of header reached, state=5
19(2900) parse_headers: Via found, flags=17
19(2900) parse_headers: this is the second via
19(2900) end of header reached, state=9
19(2900) DEBUG: get_hdr_field: <To> [28]; uri=[sip:chriz@karlshorst.net]
19(2900) DEBUG: to body [<sip:chriz@karlshorst.net>
]
19(2900) get_hdr_field: cseq <CSeq>: <102> <INVITE>
19(2900) parse_headers: flags=4
19(2900) DEBUG: t_reply_matching: failure to match a transaction
19(2900) DEBUG: t_check: msg id=1 global id=1 T end=(nil)
19(2900) parse_headers: flags=2
19(2900)  old size: 357, new size: 273
19(2900) build_res_from_sip_res: copied size: orig:104, new: 20, rest:
253 msgSIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK61c24316
From: "10" <sip:10@fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz@karlshorst.net>
Call-ID: 3f5512e931c367c566ee7d3420453098@fedora.karlshorst.net
CSeq: 102 INVITE
Content-Length: 0
 

19(2900) update_sock_struct_from_via: using via host
19(2900) update_sock_struct_from_via: trying SRV lookup
19(2900)  reply forwarded to 192.168.4.39:5082
19(2900) DEBUG:destroy_avp_list: destroing list (nil)
19(2900) receive_msg: cleaning up
19(2900) tcp_read_req: content-length= 0
19(2900) SIP Reply  (status):
19(2900)  version: <SIP/2.0>
19(2900)  status:  <180>
19(2900)  reason:  <Ringing>
19(2900) parse_headers: flags=1
19(2900) Found param type 232, <branch> = <0>; state=6
19(2900) Found param type 237, <ms-received-port> = <42320>; state=6
19(2900) Found param type 237, <ms-received-cid> = <2200>; state=16
19(2900) end of header reached, state=5
19(2900) parse_headers: Via found, flags=1
19(2900) parse_headers: this is the first via
19(2900) After parse_msg...
19(2900) forward_reply: found module tm, passing reply to it
19(2900) DEBUG: t_check: msg id=2 global id=1 T start=(nil)
19(2900) parse_headers: flags=17
19(2900) Found param type 232, <branch> = <z9hG4bK61c24316>;
state=16
19(2900) end of header reached, state=5
19(2900) parse_headers: Via found, flags=17
19(2900) parse_headers: this is the second via
19(2900) DEBUG: add_param: epid=da7682c206
19(2900) DEBUG: add_param: tag=887adab7a6634995952dcff119280ef8
19(2900) end of header reached, state=29
19(2900) DEBUG: get_hdr_field: <To> [81]; uri=[sip:chriz@karlshorst.net]
19(2900) DEBUG: to body [<sip:chriz@karlshorst.net>]
19(2900) get_hdr_field: cseq <CSeq>: <102> <INVITE>
19(2900) parse_headers: flags=4
19(2900) DEBUG: t_reply_matching: failure to match a transaction
19(2900) DEBUG: t_check: msg id=2 global id=2 T end=(nil)
19(2900) parse_headers: flags=2
19(2900)  old size: 576, new size: 492
19(2900) build_res_from_sip_res: copied size: orig:105, new: 21, rest:
471 msgSIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK61c24316
From: "10" <sip:10@fedora.karlshorst.net>;tag=as47998c2b
To:
<sip:chriz@karlshorst.net>;epid=da7682c206;tag=887adab7a6634995952dcff11
9280ef8
Call-ID: 3f5512e931c367c566ee7d3420453098@fedora.karlshorst.net
CSeq: 102 INVITE
Record-Route:
<sip:chriz@192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz@192.168.4.39;r2=on;ftag=as47998c2b;lr>
User-Agent: RTC/1.3
Content-Length: 0
 

19(2900) update_sock_struct_from_via: using via host
19(2900) update_sock_struct_from_via: trying SRV lookup
19(2900)  reply forwarded to 192.168.4.39:5082
19(2900) DEBUG:destroy_avp_list: destroing list (nil)
19(2900) receive_msg: cleaning up
19(2900) tcp_read_req: content-length= 257
19(2900) SIP Reply  (status):
19(2900)  version: <SIP/2.0>
19(2900)  status:  <200>
19(2900)  reason:  <OK>
19(2900) parse_headers: flags=1
19(2900) Found param type 232, <branch> = <0>; state=6
19(2900) Found param type 237, <ms-received-port> = <42320>; state=6
19(2900) Found param type 237, <ms-received-cid> = <2200>; state=16
19(2900) end of header reached, state=5
19(2900) parse_headers: Via found, flags=1
19(2900) parse_headers: this is the first via
19(2900) After parse_msg...
19(2900) forward_reply: found module tm, passing reply to it
19(2900) DEBUG: t_check: msg id=3 global id=2 T start=(nil)
19(2900) parse_headers: flags=17
19(2900) Found param type 232, <branch> = <z9hG4bK61c24316>;
state=16
19(2900) end of header reached, state=5
19(2900) parse_headers: Via found, flags=17
19(2900) parse_headers: this is the second via
19(2900) DEBUG: add_param: epid=da7682c206
19(2900) DEBUG: add_param: tag=887adab7a6634995952dcff119280ef8
19(2900) end of header reached, state=29
19(2900) DEBUG: get_hdr_field: <To> [81]; uri=[sip:chriz@karlshorst.net]
19(2900) DEBUG: to body [<sip:chriz@karlshorst.net>]
19(2900) get_hdr_field: cseq <CSeq>: <102> <INVITE>
19(2900) parse_headers: flags=4
19(2900) DEBUG: t_reply_matching: failure to match a transaction
19(2900) DEBUG: t_check: msg id=3 global id=3 T end=(nil)
19(2900) parse_headers: flags=2
19(2900)  old size: 1045, new size: 961
19(2900) build_res_from_sip_res: copied size: orig:196, new: 112, rest:
849 msgSIP/2.0 200 OK
Contact:
<sip:chriz@karlshorst.net:3900;maddr=192.168.4.35;transport=tls;ms-recei
ved-cid=1700>
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK61c24316
From: "10" <sip:10@fedora.karlshorst.net>;tag=as47998c2b
To:
<sip:chriz@karlshorst.net>;epid=da7682c206;tag=887adab7a6634995952dcff11
9280ef8
Call-ID: 3f5512e931c367c566ee7d3420453098@fedora.karlshorst.net
CSeq: 102 INVITE
Record-Route:
<sip:KHPOOL.karlshorst.net;transport=tcp;ms-fe=delta6.karlshorst.net;lr>
Record-Route:
<sip:chriz@192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz@192.168.4.39;r2=on;ftag=as47998c2b;lr>
User-Agent: RTC/1.3
Content-Type: application/sdp
Content-Length: 257
 
v=0
o=- 0 0 IN IP4 192.168.4.35
s=session
c=IN IP4 192.168.4.35
b=CT:1000
t=0 0
m=audio 29154 RTP/AVP 8 0 3
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
m=video 64202 RTP/AVP 34 31
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000
 
19(2900) update_sock_struct_from_via: using via host
19(2900) update_sock_struct_from_via: trying SRV lookup
19(2900)  reply forwarded to 192.168.4.39:5082
19(2900) DEBUG:destroy_avp_list: destroing list (nil)
19(2900) receive_msg: cleaning up
13(2894) SIP Request:
13(2894)  method:  <ACK>
13(2894)  uri:     <sip:chriz@karlshorst.net>
13(2894)  version: <SIP/2.0>
13(2894) parse_headers: flags=1
13(2894) Found param type 232, <branch> = <z9hG4bK62d67fa9>;
state=16
13(2894) end of header reached, state=5
13(2894) parse_headers: Via found, flags=1
13(2894) parse_headers: this is the first via
13(2894) After parse_msg...
13(2894) preparing to run routing scripts...
13(2894) DEBUG : sl_filter_ACK: to late to be a local ACK!
13(2894) DEBUG : is_maxfwd_present: searching for max_forwards header
13(2894) parse_headers: flags=128
13(2894) DEBUG: add_param: tag=887adab7a6634995952dcff119280ef8
13(2894) end of header reached, state=29
13(2894) DEBUG: get_hdr_field: <To> [65]; uri=[sip:chriz@karlshorst.net]
13(2894) DEBUG: to body [<sip:chriz@karlshorst.net>]
13(2894) get_hdr_field: cseq <CSeq>: <102> <ACK>
13(2894) DEBUG: get_hdr_body : content_length=0
13(2894) found end of header
13(2894) DEBUG: is_maxfwd_present: max_forwards header not found!
13(2894) DEBUG: add_param: tag=as47998c2b
13(2894) end of header reached, state=29
13(2894) parse_headers: flags=256
13(2894) check_self - checking if host==us: 14==9 &&  [karlshorst.net]
== [127.0.0.1]
13(2894) check_self - checking if port 5060 matches port 5060
13(2894) check_self - checking if host==us: 14==12 &&  [karlshorst.net]
== [192.168.4.39]
13(2894) check_self - checking if port 5060 matches port 5060
13(2894) check_self - checking if host==us: 12==9 &&  [192.168.4.39]
=[127.0.0.1]
13(2894) check_self - checking if port 5060 matches port 5060
13(2894) check_self - checking if host==us: 12==12 &&  [192.168.4.39]
=[192.168.4.39]
13(2894) check_self - checking if port 5060 matches port 5060
13(2894) ras(): Next hop:
'sip:KHPOOL.karlshorst.net;transport=tcp;ms-fe=delta6.karlshorst.net;lr'
is loose router
13(2894) parse_headers: flags=-1
13(2894) ras(): The last route URI:
'sip:chriz@karlshorst.net:3900;maddr=192.168.4.35;transport=tls;ms-recei
ved-cid=1700'
13(2894) DEBUG: t_addifnew: msg id=1 , global msg id=0 , T on
entrance=0xffffffff
13(2894) parse_headers: flags=-1
13(2894) parse_headers: flags=60
13(2894) t_lookup_request: start searching: hash=8792, isACK=1
13(2894) DEBUG: RFC3261 transaction matching failed
13(2894) DEBUG: t_lookup_request: no transaction found
13(2894) SER: forwarding ACK  statelessly
13(2894) DEBUG: mk_proxy: doing DNS lookup...
13(2894) sip_resolvehost: SRV(_sip._tcp.KHPOOL.karlshorst.net)
delta6.karlshorst.net:5060
13(2894) parse_headers: flags=2048
13(2894) check_via_address(192.168.4.39, 192.168.4.39, 0)
13(2894) Sending:
ACK
sip:chriz@karlshorst.net:3900;maddr=192.168.4.35;transport=tls;ms-receiv
ed-cid=1700 SIP/2.0
Max-Forwards: 10
Record-Route:
<sip:chriz@192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz@192.168.4.39;r2=on;ftag=as47998c2b;lr>
Via: SIP/2.0/TCP 192.168.4.39;branch=0
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK62d67fa9
Route:
<sip:KHPOOL.karlshorst.net;transport=tcp;ms-fe=delta6.karlshorst.net;lr>
From: "10" <sip:10@fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz@karlshorst.net>;tag=887adab7a6634995952dcff119280ef8
Contact: <sip:10@192.168.4.39:5082>
Call-ID: 3f5512e931c367c566ee7d3420453098@fedora.karlshorst.net
CSeq: 102 ACK
User-Agent: Babble/0.6.10
Content-Length: 0
 
.
13(2894) orig. len=620, new_len=731, proto=2
13(2894) tcp_send: tcp connection found (0xf51740e0), acquiring fd
13(2894) tcp_send, c= 0xf51740e0, n=8
27(2908) tcp_main_loop: read response= f51740e0, 1 from 13 (2894)
13(2894) tcp_send: after receive_fd: c= 0xf51740e0 n=4 fd=19
13(2894) tcp_send: sending...
13(2894) tcp_send: after write: c= 0xf51740e0 n=731 fd=19
13(2894) tcp_send: bufACK
sip:chriz@karlshorst.net:3900;maddr=192.168.4.35;transport=tls;ms-receiv
ed-cid=1700 SIP/2.0
Max-Forwards: 10
Record-Route:
<sip:chriz@192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz@192.168.4.39;r2=on;ftag=as47998c2b;lr>
Via: SIP/2.0/TCP 192.168.4.39;branch=0
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK62d67fa9
Route:
<sip:KHPOOL.karlshorst.net;transport=tcp;ms-fe=delta6.karlshorst.net;lr>
From: "10" <sip:10@fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz@karlshorst.net>;tag=887adab7a6634995952dcff119280ef8
Contact: <sip:10@192.168.4.39:5082>
Call-ID: 3f5512e931c367c566ee7d3420453098@fedora.karlshorst.net
CSeq: 102 ACK
User-Agent: Babble/0.6.10
Content-Length: 0

-------------- next part --------------
An HTML attachment was scrubbed...
URL:
http://lists.digium.com/pipermail/asterisk-users/attachments/20041211/9e2d59f1/attachment.htm

Public Dump wrote:
> For reasons unknown to me, SER and subsequently a Microsoft Live 
> Communcations Server 2005 seems to have problems, matching a SIP ACK 
> request from asterisk to the ongoing SIP transaction, I have attached 
> the complete log, but the essential lines are:
>  
That's a bug in Asterisk that is in the bug tracker and needs to be
fixed. Asterisk is sending the ACK to the AOR in the invite, not to
the contact address in the 200 OK.

Regards,
/Olle

Thanks for the info !
Is there any way to work around the bug, maybe by rewriting the SIP
Message in SER ? 
Or some kind to temporary third party patch ?

Chris.

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

Message: 9
Date: Sun, 12 Dec 2004 10:34:53 +0100
From: "Olle E. Johansson" <oej@edvina.net>
Subject: Re: [Asterisk-Users] ACK from asterisk not matched to
	transaction	by	SER / LCS2005
To: Asterisk Users Mailing List - Non-Commercial Discussion
	<asterisk-users@lists.digium.com>
Message-ID: <41BC10BD.2030402@edvina.net>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed

Public Dump wrote:
> For reasons unknown to me, SER and subsequently a Microsoft Live 
> Communcations Server 2005 seems to have problems, matching a SIP ACK 
> request from asterisk to the ongoing SIP transaction, I have attached 
> the complete log, but the essential lines are:
>  
That's a bug in Asterisk that is in the bug tracker and needs to be
fixed. Asterisk is sending the ACK to the AOR in the invite, not to the
contact address in the 200 OK.

Regards,
/Olle