Hi,
I've nearly completed the process of upgrading our ancient v1.7 deployment to
v3.7. The new deployment is installed on Ubuntu 24.04 from the OpenSIPS repos.
These servers are our inbound hand-off from our upstream supplier, they take a
call, inspect the called number element against the database, and then pass it
on to the target system with the internal reference or decline the call.
I've never been a programmer and am much more familiar with Asterisk, having
inherited the platform & 'maintained' these hosts for about ten years I'm far
from fluent in the configuration syntax but also much less terrified than I was
when I first opened the opensips.cfg file. Having said that, I've updated most
of the configuration and database backend to successfully accept, process &
pass on a call to our core voice platform with 2-way audio.
Unfortunately, when a call is terminated by either the called or calling party
the BYE signal is not passed to the other party leaving the call hanging until
they also hang up or an intermediate system decides the call is in a stale
state & drops it.
From what I can tell, this is the v1.7 code which would capture the session
related traffic and associate a BYE with a particular call.
I think the problem is related to my attempt to convert the depreciated
allow_source_address_group() function:
--- v1.7 code ---
if(is_method("INVITE")) {
setflag("1");
setflag("2");
>> $var(group) = allow_source_address_group();
xlog("L_ERR", "LOG: The value of var(group) = [$var(group)]");
if ($var(group) != -1) {
if(!alias_db_lookup("dbaliases")) {
xlog("L_ERR", "LOG: Alias not found time=[$Ts] from uri=[$fu] to
uri=[$ru]");
sl_send_reply("404", "Not Found");
};
$avp(s:site)=$(ruri.user{s.substr,0,5});
route(3);
exit;
}
else if ($var(group) == -1) {
log(1, "Permissions RECORD FAIL\n");
sl_send_reply("403", "Forbidden");
exit;
};
};
--- v3.7 code ---
if (is_method("INVITE")) {
$acc_extra(si) = $si;
$acc_extra(fU) = $fU;
$acc_extra(fd) = $fd;
$acc_extra(rU) = $rU;
$acc_extra(rd) = $rd;
do_accounting("log|db","cdr|missed");
xlog("L_ERR", "LOG: The value of si = [$si]");
>> $var(srcgrp) = get_source_group($si);
xlog("L_ERR", "LOG: The value of var(srcgrp) = [$var(srcgrp)]");
>> $var(group) = check_source_address($var(srcgrp));
xlog("L_ERR", "LOG: The value of var(group) = [$var(group)]");
if ($var(group) != -1) {
if (!alias_db_lookup("dbaliases")) {
xlog("L_ERR", "LOG: DDI Alias not found, time=[$Ts] from
uri=[$fu] to uri=[$ru]");
sl_send_reply(404, "Not Found");
};
$avp(site)=$(ruri.user{s.substr,0,5});
route(ALLOW);
exit;
}
else if ($var(group) == -1) {
log(1, "Permissions RECORD FAIL\n");
sl_send_reply(403, "Forbidden");
exit;
};
};
The logging on the hosts indicates that my substitution isn't working.
--- v1.7 log ---
Jan 26 17:28:28 routing-1 /../opensips[1956]: --== SIP message body - INVITE
==-- v=0#015#012o=Sonus_UAC 828539 387688 IN IP4 <UPSTREAM_PEER>#015#012s=SIP
Media Capabilities#015#012c=IN IP4 141.170.50.21#015#012t=0 0#015#012m=audio
25014 RTP/AVP 8 98#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:98
telephone-event/8000#015#012a=fmtp:98
0-15#015#012a=sendrecv#015#012a=maxptime:20#015
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:permissions:allow_source_address_group: looking for <8460ef6d, 5060> in
address table
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:permissions:allow_source_address_group: Found <-1>
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:permissions:allow_source_address_group: looking for <8460ef6d, 5060> in
subnet table
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:permissions:allow_source_address_group: Found <1>
Jan 26 17:28:28 routing-1 /../opensips[1956]: LOG: The value of var(group) = [1]
Jan 26 17:28:28 routing-1 /../opensips[1956]: DBG:core:comp_scriptvar: int 29 :
1 / -1
Jan 26 17:28:28 routing-1 /../opensips[1956]: DBG:db_mysql:has_stmt_ctx: ctx
found for dbaliases
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:db_mysql:db_mysql_do_prepared_query: conn=0x787e70 (tail=7895720)
MC=0x786208
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Jan 26 17:28:28 routing-1 /../opensips[1956]: DBG:db_mysql:db_mysql_val2bind:
added val (0): len=12; type=254; is_null=0
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:db_mysql:db_mysql_do_prepared_query: prepared statement has 2 columns in
result
Jan 26 17:28:28 routing-1 /../opensips[1956]: DBG:core:db_new_result: allocate
48 bytes for result set at 0x789bf0
Jan 26 17:28:28 routing-1 /../opensips[1956]:
DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Jan 26 17:28:28 routing-1 /../opensips[1956]: DBG:core:db_allocate_columns:
allocate 56 bytes for result columns at 0x789618
--- v 3.7 log ---
01-26 17:43:30.891281 a /../opensips[4010750]: ERROR:--== SIP message body -
INVITE ==-- v=0#015#012o=Sonus_UAC 565884 3698 IN IP4
<UPSTREAM_PEER>#015#012s=SIP Media Capabilities#015#012c=IN IP4
<UPSTREAM_PEER>#015#012t=0 0#015#012m=audio 27052 RTP/AVP 8
96#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:96
telephone-event/8000#015#012a=fmtp:96
0-15#015#012a=sendrecv#015#012a=maxptime:20#015
01-26 17:43:30.891298 a /../opensips[4010750]: DBG:core:parse_to_param:
tag=gK085d4ab6
01-26 17:43:30.891313 a /../opensips[4010750]: DBG:core:parse_to_param: end of
header reached, state=11
01-26 17:43:30.891327 a /../opensips[4010750]: DBG:core:_parse_to: end of
header reached, state=29
01-26 17:43:30.891342 a /../opensips[4010750]: DBG:core:_parse_to: display={},
ruri={sip:<CALLER_DDI>@<UPSTREAM_PEER>;user=phone}
01-26 17:43:30.891425 a /../opensips[4010750]: DBG:core:parse_headers_aux:
flags=78
01-26 17:43:30.891441 a /../opensips[4010750]: DBG:core:has_totag: no totag
01-26 17:43:30.891459 a /../opensips[4010750]: DBG:dialog:build_new_dlg: new
dialog 0x71cbfe3b64b0
(c=352862312_66830718@<UPSTREAM_PEER>,f=sip:<CALLER_DDI>@<UPSTREAM_PEER>;user=phone,t=sip:<OUR_DDI>@<UPSTREAM_PEER>;user=phone,ft=gK085d4ab6)
on hash 3981
01-26 17:43:30.891481 a /../opensips[4010750]: DBG:core:parse_headers_aux:
flags=ffffffffffffffff
01-26 17:43:30.891502 a /../opensips[4010750]: DBG:core:print_rr_body: current
rr is <sip:<UPSTREAM_PEER>;lr;ftag=gK085d4ab6;did=d8f.40748994>
01-26 17:43:30.891517 a /../opensips[4010750]: DBG:core:print_rr_body: skipping
0 route records
01-26 17:43:30.891533 a /../opensips[4010750]: DBG:core:print_rr_body: out rr
[<sip:<UPSTREAM_PEER>;lr;ftag=gK085d4ab6;did=d8f.40748994>]
01-26 17:43:30.891546 a /../opensips[4010750]: DBG:core:print_rr_body: we have
1 records
01-26 17:43:30.891562 a /../opensips[4010750]: DBG:dialog:update_leg_info:
route_set <sip:<UPSTREAM_PEER>;lr;ftag=gK085d4ab6;did=d8f.40748994>, contact
sip:<CALLER_DDI>@<UPSTREAM_PEER>:5060, cseq 494280 and bind_addr
udp:<THIS_HOST>:5060
01-26 17:43:30.891582 a /../opensips[4010750]: DBG:core:parse_headers_aux:
flags=ffffffffffffffff
01-26 17:43:30.891594 a /../opensips[4010750]: DBG:dialog:dlg_update_leg_info:
set leg 0 for 0x71cbfe3b64b0: tag=<gK085d4ab6> rcseq=<0>
01-26 17:43:30.891610 a /../opensips[4010750]: DBG:dialog:link_dlg: ref dlg
0x71cbfe3b64b0 with 3 -> 3 in h_entry 0x71cbfe377c08 - 3981
01-26 17:43:30.891627 a /../opensips[4010750]: DBG:rr:add_rr_param: adding
(;did=d8f.57669b46)
01-26 17:43:30.891643 a /../opensips[4010750]: DBG:rr:add_rr_param: second RR
lump found
01-26 17:43:30.891660 a /../opensips[4010750]: DBG:rr:add_rr_param: second RR
lump found
01-26 17:43:30.891772 a /../opensips[4010750]: ERROR:LOG: The value of si =
[<UPSTREAM_PEER>]
01-26 17:43:30.891784 a /../opensips[4010750]:
DBG:permissions:get_source_group: Looking for <<UPSTREAM_PEER>, 5060> in
address table
01-26 17:43:30.891799 a /../opensips[4010750]:
DBG:permissions:get_source_group: Found <1>
>> 01-26 17:43:30.891814 a /../opensips[4010750]: ERROR:core:pv_set_value:
>> bad parameters
>> 01-26 17:43:30.891832 a /../opensips[4010750]:
>> ERROR:permissions:get_source_group: setting of pvar failed
01-26 17:43:30.891849 a /../opensips[4010750]: ERROR:LOG: The value of
var(srcgrp) = [-1]
01-26 17:43:30.891861 a /../opensips[4010750]: DBG:permissions:check_src_addr:
Looking for : <default:-1, <UPSTREAM_PEER>, 1, 5060, >
01-26 17:43:30.891879 a /../opensips[4010750]: DBG:permissions:pm_hash_match:
specified group '4294967295' does not exist in hash table
01-26 17:43:30.891895 a /../opensips[4010750]: ERROR:LOG: The value of
var(group) = [-2]
01-26 17:43:30.891907 a /../opensips[4010750]: DBG:core:comp_scriptvar: int 29:
-2 / -1
01-26 17:43:30.893310 a /../opensips[4010750]: DBG:db_mysql:mysql_raise_event:
MySQL status has not changed: connected
01-26 17:43:30.893349 a /../opensips[4010750]: DBG:core:db_new_result: allocate
48 bytes for result set at 0x71cc020e4730
01-26 17:43:30.893367 a /../opensips[4010750]:
DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
01-26 17:43:30.893382 a /../opensips[4010750]: DBG:core:db_allocate_columns:
allocate 56 bytes for result columns at 0x71cc020e4798
As I've been looking through the logs I've noticed that following the OK reply
once a call is answered the v3.7 host does some accounting to the database &
then sends OK messages related to the INVITE, after four packets the
transaction is destroyed. Seven more OK messages are sent with tm logging that
'no matching transaction exists' before it gives up.
Any help would be gratefully received.
Many thanks,
Al Cleminson.
_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
