[OpenSIPS-Users] Re-invite ACK Troubles - Not going to my NAT Handling route

[Marc Leurent]

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:0245667...@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:0245667...@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:0245667...@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:0227077...@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:0227077...@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:0227077...@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:0245667...@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:0245667...@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:0245667...@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:0245667...@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:0227077...@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:0227077...@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:0227077...@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:0245667...@212.147.0.191:3844>;tag=FJkNzIDMBJE
From: "0227077410" <sip:0227077...@212.147.46.90>;tag=as540161fe
Call-ID: 685c98e92c885ae33d8ab4e51779a...@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:0245667...@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:0245667...@212.147.0.191:3844>;tag=FJkNzIDMBJE
From: "0227077410" <sip:0227077...@212.147.46.81>;tag=as540161fe
Call-ID: 685c98e92c885ae33d8ab4e51779a...@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:0245667...@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:0245667...@212.147.0.191:3844>;tag=FJkNzIDMBJE
From: "0227077410" <sip:0227077...@212.147.46.90>;tag=as540161fe
Call-ID: 685c98e92c885ae33d8ab4e51779a...@212.147.46.81
CSeq: 103 INVITE
Record-Route: <sip:212.147.46.90;lr=on;ftag=as540161fe>
Contact: <sip:0245667...@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:0245667...@212.147.0.191:3844>;tag=FJkNzIDMBJE
From: "0227077410" <sip:0227077...@212.147.46.81>;tag=as540161fe
Call-ID: 685c98e92c885ae33d8ab4e51779a...@212.147.46.81
CSeq: 103 INVITE
Record-Route: <sip:212.147.46.90;lr=on;ftag=as540161fe>
Contact: <sip:0245667...@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
lf...@leurent.eu




_______________________________________________
Users mailing list
Users@lists.opensips.org
http://lists.opensips.org/cgi-bin/mailman/listinfo/users