[OpenSIPS-Users] Re-invite ACK Troubles - Not going to my NAT Handling route
Marc Leurent
lftsy at leurent.eu
Fri Jul 31 10:14:37 CEST 2009
Hello everybody, for those who are not in holidays under the sun...
I have already checked, on no previous exchange on the mailing list seems to answer to this problem..
My version of OpenSIPs is OpenSIPS (1.4.5-notls (x86_64/linux))
I have a problem when a 200 OK of a re-INVITE. Indeed, I use a route(2) to handle NAT correction, I have put the route(2) at the beginning
of main route, on onreply_route, on failure_route, and on branch_route. So, for each packets, it should go inside the route(2)...
So usually I get SIP headers Contact rewritten when it's necessary like for the 1st 200 OK before a re-INVITE. Once it has been rewritten,
ACK messages are correctly routed using the Route and Contact Header!
But after the re-INVITE, for the 200 OK SIP message, route(2) is not triggered anymore, so Contact Header remains with a Private IP, and so
ACK message is not routed correctly! So I'm wondering which route is used... To be able to rewrite the Contact Header with
fax_nated_contact()
Thanks for your help!!
Debug 6 is below with route(2) in bold characters:
ul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_msg: SIP Reply (status):
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_msg: version: <SIP/2.0>
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_msg: status: <200>
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_msg: reason: <OK>
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=2
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bKeaa5.f2c33656.0>; state=16
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_via: end of header reached, state=5
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: via found, flags=2
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: this is the first via
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:receive_msg: After parse_msg...
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:forward_reply: found module nathelper, passing reply to it
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=4
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_via_param: found param type 234, <received> = <212.147.46.81>;
state=6
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7d4078d1>;
state=16
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_via: end of header reached, state=5
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: via found, flags=4
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: parse_headers: this is the second via
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:forward_reply: found module tm, passing reply to it
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:t_check: start=0xffffffffffffffff
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=22
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_to_param: tag=FJkNzIDMBJE
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_to: end of header reached, state=29
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_to: display={}, ruri={sip:0245667945 at 212.147.0.191:3844}
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:get_hdr_field: <To> [53]; uri=[sip:0245667945 at 212.147.0.191:3844]
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:get_hdr_field: to body [<sip:0245667945 at 212.147.0.191:3844>]
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=8
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:t_reply_matching: hash 23214 label 1701002287 branch 0
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:t_reply_matching: reply matched (T=0x2b6d744f4c78)!
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=8
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:run_trans_callbacks: trans=0x2b6d744f4c78, callback type 2, id 2 entered
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=8
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:run_trans_callbacks: trans=0x2b6d744f4c78, callback type 2, id 0 entered
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_to_param: tag=as540161fe
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_to: end of header reached, state=29
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_to: display={"0227077410"}, ruri={sip:0227077410 at 212.147.46.90}
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:uac:restore_from_reply: removing <From: "0227077410"
<sip:0227077410 at 212.147.46.90>;tag=as540161fe^M >
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:uac:restore_from_reply: inserting <From: "0227077410"
<sip:0227077410 at 212.147.46.81>;tag=as540161fe^M >
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:t_check: end=0x2b6d744f4c78
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: Default - Incoming Reply
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: STARTING TEST NAT^M
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=80
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: NAT Detected - Fixing Contact <sip:0245667945 at 192.168.1.47:5060>^M
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=80
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:parse_headers: flags=20
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:t_should_relay_response: T_code=180, new_code=200
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:tm:run_trans_callbacks: trans=0x2b6d744f4c78, callback type 16, id 1 entered
Jul 30 15:33:11 zue-tix-vp-pro-02 /usr/sbin/opensips[9560]: DBG:core:build_res_buf_from_sip_res: old size: 793, new size: 732
But after the re-INVITE, for the 200 OK, route(2) is not triggered, so I'm wondering which route is used...
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9564]: DBG:core:receive_msg: cleaning up
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_msg: SIP Reply (status):
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_msg: version: <SIP/2.0>
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_msg: status: <200>
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_msg: reason: <OK>
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_headers: flags=2
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bKfaa5.4ac6bfe5.0>; state=16
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_via: end of header reached, state=5
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_headers: via found, flags=2
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_headers: this is the first via
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:receive_msg: After parse_msg...
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:forward_reply: found module nathelper, passing reply to it
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_headers: flags=4
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_via_param: found param type 234, <received> = <212.147.46.81>;
state=6
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7ee0d618>;
state=16
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_via: end of header reached, state=5
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_headers: via found, flags=4
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_headers: parse_headers: this is the second via
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:forward_reply: found module tm, passing reply to it
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:t_check: start=0xffffffffffffffff
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_headers: flags=22
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_to_param: tag=FJkNzIDMBJE
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_to: end of header reached, state=29
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_to: display={}, ruri={sip:0245667945 at 212.147.0.191:3844}
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:get_hdr_field: <To> [53]; uri=[sip:0245667945 at 212.147.0.191:3844]
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:get_hdr_field: to body [<sip:0245667945 at 212.147.0.191:3844>]
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:get_hdr_field: cseq <CSeq>: <103> <INVITE>
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_headers: flags=8
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:t_reply_matching: hash 23215 label 1593535652 branch 0
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:t_reply_matching: reply matched (T=0x2b6d744f4c78)!
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:run_trans_callbacks: trans=0x2b6d744f4c78, callback type 2, id 0 entered
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_to_param: tag=as540161fe
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_to: end of header reached, state=29
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:parse_to: display={"0227077410"}, ruri={sip:0227077410 at 212.147.46.90}
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:uac:restore_from_reply: removing <From: "0227077410"
<sip:0227077410 at 212.147.46.90>;tag=as540161fe^M >
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:uac:restore_from_reply: inserting <From: "0227077410"
<sip:0227077410 at 212.147.46.81>;tag=as540161fe^M >
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:t_check: end=0x2b6d744f4c78
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:t_should_relay_response: T_code=100, new_code=200
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Jul 30 15:33:16 zue-tix-vp-pro-02 /usr/sbin/opensips[9548]: DBG:core:build_res_buf_from_sip_res: old size: 863, new size: 801
The only difference I have seen is that on the first 200OK, I have
DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
and on the second one, I have:
DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
so second 200 OK is answered without any previous 100 or 180 SIP message
And CallId is the same for the all SIP exchange! Of course!
Here is my route(2)
route[2]{
xlog("L_DBG", "STARTING TEST NAT\r\n");
if (nat_uac_test("19")) {
force_rport();
xlog("L_DBG", "NAT Detected - Fixing Contact $ct\r\n");
fix_nated_contact();
if (is_method("REGISTER")) {
fix_nated_register(); # Creates a URI consisting of the source IP, port, and protocol appended as "received"
parameter to Contact
setflag(6); # Mark user as NAT'ed to start branch ping
};
};
}
and all my other routes:
# main request routing logic
route{
# Reject Packet if SIP TTL is too low
if (!mf_process_maxfwd_header("10")) {
sl_send_reply("483","Too Many Hops");
exit;
}
# Test NATed contact
route(2);
if (has_totag()) { # Check To Header field uri contains tag parameter.
# sequential request withing a dialog should
# take the path determined by record-routing
if (loose_route()) { # The function performs routing of SIP requests which contain a route set.
if (is_method("BYE")) {
setflag(1); # do accounting ...
setflag(3); # ... even if the transaction fails
} else if (is_method("INVITE")) {
# even if in most of the cases is useless, do RR for
# re-INVITEs alos, as some buggy clients do change route set
# during the dialog.
record_route();
...
...
}
branch_route[1] {
xlog("L_DBG", "Default - New Branch $rm At $ru from $si\n");
# Test NATed contact
route(2);
}
onreply_route[1] {
xlog("L_DBG", "Default - Incoming Reply\n");
# Test NATed contact
route(2);
}
failure_route[1] {
xlog("L_DBG", "Default - Failure Route $rm\n");
# Test NATed contact
route(2);
if (t_was_cancelled()) {
exit;
}
}
Here is the first 200 OK before and after the proxy without SDP section. You will notice that the Contact Header is rewritten:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 212.147.46.90;branch=z9hG4bKeaa5.f2c33656.0
Via: SIP/2.0/UDP 212.147.46.81:5060;received=212.147.46.81;branch=z9hG4bK7d4078d1
To: <sip:0245667945 at 212.147.0.191:3844>;tag=FJkNzIDMBJE
From: "0227077410" <sip:0227077410 at 212.147.46.90>;tag=as540161fe
Call-ID: 685c98e92c885ae33d8ab4e51779a2a2 at 212.147.46.81
CSeq: 102 INVITE
Record-Route: <sip:212.147.46.90;lr=on;ftag=as540161fe;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABAQ--;did=799.50d5763>
Contact: <sip:0245667945 at 192.168.1.47:5060>
Content-Type: application/sdp
Content-Length: 217
SIP/2.0 200 OK
Via: SIP/2.0/UDP 212.147.46.81:5060;received=212.147.46.81;branch=z9hG4bK7d4078d1
To: <sip:0245667945 at 212.147.0.191:3844>;tag=FJkNzIDMBJE
From: "0227077410" <sip:0227077410 at 212.147.46.81>;tag=as540161fe
Call-ID: 685c98e92c885ae33d8ab4e51779a2a2 at 212.147.46.81
CSeq: 102 INVITE
Record-Route: <sip:212.147.46.90;lr=on;ftag=as540161fe;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAABAQ--;did=799.50d5763>
Contact: <sip:0245667945 at 212.147.0.191:3844>
Content-Type: application/sdp
Content-Length: 217
and here is the second 200 OK after re-INVITE, before and after the proxy. and Contact is not rewritten:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 212.147.46.90;branch=z9hG4bKfaa5.4ac6bfe5.0
Via: SIP/2.0/UDP 212.147.46.81:5060;received=212.147.46.81;branch=z9hG4bK7ee0d618
To: <sip:0245667945 at 212.147.0.191:3844>;tag=FJkNzIDMBJE
From: "0227077410" <sip:0227077410 at 212.147.46.90>;tag=as540161fe
Call-ID: 685c98e92c885ae33d8ab4e51779a2a2 at 212.147.46.81
CSeq: 103 INVITE
Record-Route: <sip:212.147.46.90;lr=on;ftag=as540161fe>
Contact: <sip:0245667945 at 192.168.1.47:5060>
Content-Type: application/sdp
Content-Length: 348
SIP/2.0 200 OK
Via: SIP/2.0/UDP 212.147.46.81:5060;received=212.147.46.81;branch=z9hG4bK7ee0d618
To: <sip:0245667945 at 212.147.0.191:3844>;tag=FJkNzIDMBJE
From: "0227077410" <sip:0227077410 at 212.147.46.81>;tag=as540161fe
Call-ID: 685c98e92c885ae33d8ab4e51779a2a2 at 212.147.46.81
CSeq: 103 INVITE
Record-Route: <sip:212.147.46.90;lr=on;ftag=as540161fe>
Contact: <sip:0245667945 at 192.168.1.47:5060>
Content-Type: application/sdp
Content-Length: 348
Thank you for your help if you have read this message until here....
Have a nice day!
--
-- --
Marc LEURENT
lftsy at leurent.eu
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.opensips.org/pipermail/users/attachments/20090731/3008302c/attachment-0001.htm
More information about the Users
mailing list