[OpenSIPS-Users] TLS NOTIFY transmit fails

[Andrew Yager]

Hi All,

Hoping someone can help me with this - I think it should be pretty simple.

We're using mid_registrar to provide a Proxy between Asterisk and clients
(mixed UDP, TCP and TLS).

Calls in/out work fine, but I'm having some difficulties with NOTIFY
messages being transmitted back to the client a "period" of time after the
register event. This period of time seems to be 2 minutes or so. It looks
like even though the $ru is set correctly, it's not reusing the TLS socket,
but instead trying to create a new transaction/socket which doesn't work.
I'm assuming from the logs the important thing is the
"DBG:tm:t_lookup_request: no transaction found"; and that what has happened
is the original register transaction has "expired" and so it needs to
create a new one, despite the TCP_NO_CONNECT bflag being set.

INVITEs are properly relayed and reuse the socket without fail; it "seems"
it's only NOTIFY messages that are causing me grief.

Our config looks like this:

...

tcp_no_new_conn_bflag = TCP_NO_CONNECT
tcp_keepidle = 30
...
loadmodule "tm.so"
modparam("tm", "fr_timeout", 5)
modparam("tm", "fr_inv_timeout", 30)
modparam("tm", "restart_fr_on_each_reply", 0)
modparam("tm", "onreply_avp_mode", 1)

loadmodule "mid_registrar.so"
modparam("mid_registrar", "mode", 2) /* 0 = mirror / 1 = ct / 2 = AoR */
modparam("mid_registrar", "outgoing_expires", 3600)
modparam("mid_registrar", "contact_id_insertion", "ct-param")
modparam("mid_registrar", "tcp_persistent_flag",
"TCP_PERSIST_REGISTRATIONS")
...

            if ($si == "asterisk.ip" && $sp == 5060) {
                xlog("about to do mid_registrar_lookup\n");
                if (!mid_registrar_lookup("location")) {
                    xlog("mid registrar lookup failed\n");
                    xlog("RU is $ru FU is $fu TU is $tu\n");
                    $ru = "sip:"+$tU+"@asterisk.ip";
                    xlog("Rewrote to $ru\n"); # This deal with NOTIFY
requests that don't have the user in the SIP message
                    if (!mid_registrar_lookup("location")) {
                        xlog("Could not find user, going to reply 404 and
drop the request.\n");
                        sl_send_reply(404,"Contact is not here anymore");

                        exit;
                    }
                }
            } else {
                fix_nated_contact();
                $ru = "sip:"+$tU+"@asterisk.ip:5060";
            }
            if ( is_method("NOTIFY")) {
                setbflag("TCP_NO_CONNECT");
                xlog("Notify with to tag\n");
                xlog("Ru is $ru\n");
                sl_send_reply(200, "OK, we got this!");
                t_relay();
                exit;
            }

...

Debug Logs:

May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: about to do
mid_registrar_lookup
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:unescape_user:
unescaped string is <>
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:mid_registrar:lookup:
'' Not found in usrloc
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: mid registrar lookup
failed
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:parse_to_param:
tag=f7a75172-f02b-419e-89a0-ad2481768e88
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:_parse_to: end
of header reached, state=29
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:_parse_to:
display={}, ruri={sip:1014 at x.x.x.x}
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: RU is
sip:y,y,y,y,y:5061;transport=tls;lr;r2=on;ftag=2210321712 FU is
sip:1014 at x.x.x.x TU is sip:1003-test at x.x.x.x
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: Rewrote to
sip:1003-test at x.x.x.x
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:unescape_user:
unescaped string is <1003-test>
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]:
DBG:mid_registrar:select_contacts: ct: sip:1003-test at z.z.z.z
:3353;transport=TLS
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]:
DBG:mid_registrar:push_branch: setting msg R-URI <sip:1003-test at z.z.z.z
:3353;transport=TLS>
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: Notify with to tag
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: Ru is
sip:1003-test at z.z.z.z:3353;transport=TLS
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:parse_headers:
flags=ffffffffffffffff
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:tm:t_newtran:
transaction on entrance=0xffffffffffffffff
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:parse_headers:
flags=ffffffffffffffff
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:parse_headers:
flags=78
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:tm:t_lookup_request:
start searching: hash=65460, isACK=0
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:tm:matching_3261:
RFC3261 transaction matching failed
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:tm:t_lookup_request:
no transaction found
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:mk_proxy: doing
DNS lookup...
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:parse_headers:
flags=2000
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: DBG:core:parse_headers:
flags=ffffffffffffffff
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]: ERROR:tm:msg_send: send()
to x.x.x.x:5061 for proto tls/3 failed
May  2 04:59:42 hvprxy /usr/sbin/opensips[96845]:
ERROR:tm:t_forward_nonack: sending request failed

Any help would be appreciated :)

Thanks,
Andrew
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20210502/fdee626e/attachment.html>