[Asterisk-Users] ACK from asterisk not matched to transaction by SER / LCS2005

Public Dump pbd at suspiria.net
Sat Dec 11 16:39:51 MST 2004 

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 at 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 at karlshorst.net]
 9(2890) DEBUG: to body [<sip:chriz at 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 at karlshorst.net SIP/2.0
Max-Forwards: 10
Record-Route:
<sip:chriz at 192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz at 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 at fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz at karlshorst.net>
Contact: <sip:10 at 192.168.4.39:5082>
Call-ID: 3f5512e931c367c566ee7d3420453098 at 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: buf=
INVITE sip:chriz at karlshorst.net SIP/2.0
Max-Forwards: 10
Record-Route:
<sip:chriz at 192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz at 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 at fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz at karlshorst.net>
Contact: <sip:10 at 192.168.4.39:5082>
Call-ID: 3f5512e931c367c566ee7d3420453098 at 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 at karlshorst.net]
19(2900) DEBUG: to body [<sip:chriz at 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 msg=
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK61c24316
From: "10" <sip:10 at fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz at karlshorst.net>
Call-ID: 3f5512e931c367c566ee7d3420453098 at 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 at karlshorst.net]
19(2900) DEBUG: to body [<sip:chriz at 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 msg=
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.4.39:5082;branch=z9hG4bK61c24316
From: "10" <sip:10 at fedora.karlshorst.net>;tag=as47998c2b
To:
<sip:chriz at karlshorst.net>;epid=da7682c206;tag=887adab7a6634995952dcff11
9280ef8
Call-ID: 3f5512e931c367c566ee7d3420453098 at fedora.karlshorst.net
CSeq: 102 INVITE
Record-Route:
<sip:chriz at 192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz at 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 at karlshorst.net]
19(2900) DEBUG: to body [<sip:chriz at 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 msg=
SIP/2.0 200 OK
Contact:
<sip:chriz at 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 at fedora.karlshorst.net>;tag=as47998c2b
To:
<sip:chriz at karlshorst.net>;epid=da7682c206;tag=887adab7a6634995952dcff11
9280ef8
Call-ID: 3f5512e931c367c566ee7d3420453098 at fedora.karlshorst.net
CSeq: 102 INVITE
Record-Route:
<sip:KHPOOL.karlshorst.net;transport=tcp;ms-fe=delta6.karlshorst.net;lr>
Record-Route:
<sip:chriz at 192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz at 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 at 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 at karlshorst.net]
13(2894) DEBUG: to body [<sip:chriz at 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 at 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 at 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 at 192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz at 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 at fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz at karlshorst.net>;tag=887adab7a6634995952dcff119280ef8
Contact: <sip:10 at 192.168.4.39:5082>
Call-ID: 3f5512e931c367c566ee7d3420453098 at 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: buf=
ACK
sip:chriz at 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 at 192.168.4.39;transport=tcp;r2=on;ftag=as47998c2b;lr>
Record-Route: <sip:chriz at 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 at fedora.karlshorst.net>;tag=as47998c2b
To: <sip:chriz at karlshorst.net>;tag=887adab7a6634995952dcff119280ef8
Contact: <sip:10 at 192.168.4.39:5082>
Call-ID: 3f5512e931c367c566ee7d3420453098 at 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

More information about the asterisk-users mailing list