OpenSIPS 2.4 lookup() failing

[sekil75]

Hello,

I have OS 2.4 on latest git rev. I've spotted that lookup every now and then is not routing a call properly rather routing as if if condition didn't fulllfil.

Here's config snippet:

                    if (!lookup("location","m"))
                     ...
                     ...

                   } else { 
                            # when routing via usrloc, log the missed calls also
                            do_accounting("db","missed");
                            route(relay);

Relevant call log:

Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_msg: method:
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_msg: uri: sip:381114240903@res.iqtel.rs
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_msg: version: <SIP/2.0>
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=2
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_via_param: found param type 235, = <n/a>; state=6
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_via_param: found param type 232, = ; state=16
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_via: end of header reached, state=5
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: via found, flags=2
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: this is the first via
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:receive_msg: After parse_msg...
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:receive_msg: preparing to run routing scripts...
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=100
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:maxfwd:is_maxfwd_present: value = 67
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=10
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_to_param: tag=BceZ74B3jQeXS
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:_parse_to: end of header reached, state=29
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:_parse_to: display={"0656666888"}, ruri={sip:0656666888@172.27.26.4}
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=8
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:_parse_to: end of header reached, state=10
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:_parse_to: display={}, ruri={sip:381114240903@res.iqtel.rs}
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:get_hdr_field: [33]; uri=[sip:381114240903@res.iqtel.rs]
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:get_hdr_field: to body [sip:381114240903@res.iqtel.rs#15#012]
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:uri:has_totag: no totag
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=78
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:get_hdr_field: cseq : <123804148>
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:tm:t_lookup_request: start searching: hash=56041, isACK=0
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:tm:t_lookup_request: no transaction found
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=200
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:get_hdr_field: content_length=218
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:get_hdr_field: found end of header
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:rr:find_first_route: No Route headers found
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:rr:loose_route: There is no Route HF
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=200000000
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:sst:sst_check_min: No Session-Expires header found. retuning false (-1)
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:uri:has_totag: no totag
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=78
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:dialog:build_new_dlg: new dialog 0x7f2766a85a30 (c=11276eea-e416-1236-189b-0cc47a7d9ec8,f=sip:0656666888@172.27.26.4,t=sip:381114240903@res.iqtel.rs,ft=BceZ74B3jQeXS) on hash 3135
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:parse_headers: flags=ffffffffffffffff
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:dialog:update_leg_info: route_set , contact sip:mod_sofia@172.27.26.4:5060, cseq 123804148 and bind_addr udp:172.27.26.35:5060
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:dialog:dlg_update_leg_info: set leg 0 for 0x7f2766a85a30: tag= rcseq=<0>
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:dialog:link_dlg: ref dlg 0x7f2766a85a30 with 3 -> 3 in h_entry 0x7f2766965800 - 3135
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:rr:add_rr_param: adding (;did=f3c.be532926)
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:rr:add_rr_param: second RR lump found
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:subst_run: running. r=1
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:subst_str: no match
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:dialog:w_create_dialog2: bye on timeout activated
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:dialog:w_set_dlg_shtag: Dialog replication not configured
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: Inbound call from gws
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:comp_scriptvar: str 29 : res.iqtel.rs
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:comp_scriptvar: str 20 : res.iqtel.rs
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:core:comp_scriptvar: str 20 : res.iqtel.rs
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:registrar:parse_lookup_flags: final flags: 1
Jun 6 12:20:24 db1 /usr/local/sbin/opensips[25679]: DBG:registrar:select_contacts: ct: sip:381114240903@172.27.20.12:5060

Looks like the contact is found, but OpenSIPS is pushing to a script part that happens when lookup is negative.

[liviuchircu]

Hi @sekil75!

This could be a dumb question, but: are you sure the sip:381114240903@172.27.20.12:5060 contact does not get filtered out by the m (method filtering) flag provided to lookup()?

Regardless of the answer to the above, please add some $rc logging to your script, so we understand exactly what error code lookup() exits with. If you could also list out the cached contact (using something like opensipsctl ul show | grep -A15 'sip:381114240903@172.27.20.12:5060'), that would be even better!

[sekil75]

Hi Liviu,
$retcode is returning on these ocassions -1, which is definitely not the case (phone as registering in a very short period od 300-600 secs). Also, cached contact is there as well.

Contact:: sip:381114240903@172.27.20.12:5060 Q=
ContactID:: 1423559694714145976
Expires:: 473
Callid:: 815ae8d6-d370a422fa4a6892539e0080f0ce8e3f@172.27.20.12
Cseq:: 126
User-agent:: Panasonic_KX-UT113NE/01.302 (0080F0CE8E3F)
State:: CS_NEW
Flags:: 0
Cflags::
Socket:: udp:172.27.26.35:5060
Methods:: 5247

I'm using full-sharing-cluster usrloc replication btw.