Hi,
ideas anyone?
BR,
Andrew
On 06/17/2015 12:12 PM, Andrew Pogrebennyk wrote:
Daniel,
I'm reviving this old thread..
On 05/27/2015 01:40 PM, Andrew Pogrebennyk wrote:
thanks for the answer, that's what I was
thinking - maybe the flags do
not persist or are destroyed after the per-branch failure route.
However, the t_flush_flags description says this function can be used in
any route, so in should be fixed in the long term.. Let me check if I
can come up with some workaround in config script for the time being.
I didn't manage to come up with any workaround so far.
The problem appears if the initial call leg coming from, let's say, the
application server didn't have the accounting flags set. Long story put
short, if the UA responds with the 302 response and we are going to
process that, we want to create an acc record for the new target from
302 message because this call may incur additional costs.
I'm setting the accounting flags and even calling t_flush_flags() but
that doesn't work (no accounting record for INVITE with Call-ID:
rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1).
if($var(redirected_forward) == 1)
{
setflag(FLAG_ACC_FAILED);
setflag(FLAG_ACC_DB);
t_flush_flags();
}
From attached log:
root@sp2:~# grep -i acc kamailio.log
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set callee dialogs: user, account
to 'e59611e6-01de-424c-a04f-e977409c54f6/64' - R=sip:test1@demo.mylocal.com
ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set callee dialogs: totaluser,
totalaccount to 'e59611e6-01de-424c-a04f-e977409c54f6/64' -
R=sip:test1@demo.mylocal.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set caller dialogs: totaluser,
totaluserout, totalaccount, totalaccountout to
'0214786f-eb1c-4865-95ba-65d8c1c0bf32/48' - R=sip:test1@demo.mylocal.com
ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: INFO: <script>: Set caller dialogs: user,
userout, account, accountout to '0214786f-eb1c-4865-95ba-65d8c1c0bf32/48' -
R=sip:test1@demo.mylocal.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Setting acc source-leg for uuid
'0214786f-eb1c-4865-95ba-65d8c1c0bf32':
'0214786f-eb1c-4865-95ba-65d8c1c0bf32|phone2|xxx.demo.mylocal.com|43221000202|||48|||0|call|77.244.249.126|1434534578.107169|||||||||||'
- R=sip:test1@demo.mylocal.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: ++++++ 2. ACC flag is set -
R=sip:test1@demo.mylocal.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12702]: NOTICE: <script>: Setting acc destination-leg for
uuid 'e59611e6-01de-424c-a04f-e977409c54f6':
'0||comx|64|0004399111111|e59611e6-01de-424c-a04f-e977409c54f6|test1|demo.mylocal.com|4399111111|xxx.demo.mylocal.com|0|||||||||||'
- R=sip:test1@demo.mylocal.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
Jun 17 11:49:38 sp2 proxy[12695]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback
called for t(0x7f421c8da308) event type 2, reply code 100
Jun 17 11:49:38 sp2 proxy[12698]: INFO: <script>: Skip accounting for call from PBX
to device - R=sip:test1@demo.mylocal.com ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: acc
[acc_logic.c:615]: tmcb_func(): acc callback called for t(0x7f421c8da308) event type 2,
reply code 180
Jun 17 11:49:38 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback
called for t(0x7f421c8da308) event type 512, reply code 180
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: ------ 1. ACC flag is NOT set -
R=sip:test1@10.15.20.112:5060 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Set callee dialogs: user, account
to '72d04db7-6fd2-47c3-95a7-5685a5297715/64' -
R=sip:test2@demo.mylocal.com;alias=77.244.249.126~6774~1
ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Set callee dialogs: totaluser,
totalaccount to '72d04db7-6fd2-47c3-95a7-5685a5297715/64' -
R=sip:test2@demo.mylocal.com;alias=77.244.249.126~6774~1
ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Set caller dialogs: totaluser,
totaluserout, totalaccount, totalaccountout to
'e59611e6-01de-424c-a04f-e977409c54f6/64' - R=sip:25704386@10.10.8.52:46637
ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: INFO: <script>: Set caller dialogs: user,
userout, account, accountout to 'e59611e6-01de-424c-a04f-e977409c54f6/64' -
R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting acc source-leg for uuid
'e59611e6-01de-424c-a04f-e977409c54f6':
'e59611e6-01de-424c-a04f-e977409c54f6|test1|xxx.demo.mylocal.com|phone2||comx|64|||<null>|cfb|77.244.249.126|1434534580.186507|||||||||||'
- R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: ++++++ 2. ACC flag is set -
R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:40 sp2 proxy[12695]: NOTICE: <script>: Setting acc destination-leg for
uuid '72d04db7-6fd2-47c3-95a7-5685a5297715':
'0||comx|64|4399111112|72d04db7-6fd2-47c3-95a7-5685a5297715|test2|demo.mylocal.com|4399111112|demo.mylocal.com|0|||||||||||'
- R=sip:25704386@10.10.8.52:46637 ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback
called for t(0x7f421c8da308) event type 2, reply code 200
Jun 17 11:49:43 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback
called for t(0x7f421c8da308) event type 512, reply code 200
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback
called for t(0x7f421c8d2998) event type 2, reply code 200
Jun 17 11:49:52 sp2 proxy[12699]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback
called for t(0x7f421c8d2998) event type 512, reply code 200
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback
called for t(0x7f421c8ce000) event type 2, reply code 200
Jun 17 11:49:52 sp2 proxy[12696]: DEBUG: acc [acc_logic.c:615]: tmcb_func(): acc callback
called for t(0x7f421c8ce000) event type 512, reply code 200
Note there are two different calls:
Call-ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV
is ingress one, which goes through sems application server and comes
back as Call-ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
We're accounting the ingress one but not the one with
Call-ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1 (due to highlighted line
above: Skip accounting for call from PBX to device...), but if the
device responds with 302 we want to account the INVITE and the BYE -
this is what I'm trying to achieve.
I see that callback is invoked for the 200 OK to INVITE so in theory it
should work, shouldn't it? But in fact I'm getting the BYE with
Call-ID=rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
but not the INVITE accounted.
mysql> select * from acc where id>11416\G
*************************** 1. row ***************************
id: 11420
method: INVITE
from_tag: .gX8uom0bP5ROJMaEt1lxZbQpmknoGxP
to_tag: 7F09755D-558142B20001BCFA-555E8700
callid: rOemTINsCbQspe1Vlje9nAK15SNy0DdV
sip_code: 200
sip_reason: OK
time: 2015-06-17 11:49:43
time_hires: 1434534583.250
src_leg:
0214786f-eb1c-4865-95ba-65d8c1c0bf32|phone2|xxx.demo.mylocal.com|43221000202|||48|||0|call|77.244.249.126|1434534578.107210|||||||||||
dst_leg:
0||comx|64|0004399111111|e59611e6-01de-424c-a04f-e977409c54f6|test1|demo.mylocal.com|4399111111|xxx.demo.mylocal.com|0|||||||||||
dst_user: test1
dst_ouser: test1
dst_domain:
demo.mylocal.com
src_user: phone2
src_domain:
xxx.demo.mylocal.com
*************************** 2. row ***************************
id: 11422
method: BYE
from_tag: 60106B3B-558142B20001C04C-54DE0700
to_tag: 7B3C0FA6-558142B40002EE78-EB1F1700
callid: rOemTINsCbQspe1Vlje9nAK15SNy0DdV_pbx-1
sip_code: 200
sip_reason: OK
time: 2015-06-17 11:49:52
time_hires: 1434534592.380
src_leg:
dst_leg:
dst_user: 25704386
dst_ouser: test1
dst_domain: 127.0.0.1
src_user: phone2
src_domain:
xxx.demo.mylocal.com
*************************** 3. row ***************************
id: 11424
method: BYE
from_tag: .gX8uom0bP5ROJMaEt1lxZbQpmknoGxP
to_tag: 7F09755D-558142B20001BCFA-555E8700
callid: rOemTINsCbQspe1Vlje9nAK15SNy0DdV
sip_code: 200
sip_reason: OK
time: 2015-06-17 11:49:52
time_hires: 1434534592.380
src_leg:
dst_leg:
dst_user:
dst_ouser: 0004399111111
dst_domain: 127.0.0.1
src_user: phone2
src_domain:
xxx.demo.mylocal.com
3 rows in set (0.00 sec)
root@sp2:~# kamailio -V
version: kamailio 4.1.8 (x86_64/linux)
flags: STATS: Off, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS,
DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC,
DBG_QM_MALLOC, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE,
USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16,
MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: unknown
compiled on 14:44:30 May 21 2015 with gcc 4.7.2
Here are the module parameters:
modparam("acc", "early_media", 0)
modparam("acc", "report_ack", 0)
modparam("acc", "report_cancels", 1)
modparam("acc", "detect_direction", 1)
modparam("acc", "db_flag", 1)
modparam("acc", "db_missed_flag", 2)
modparam("acc", "failed_transaction_flag", 3)
modparam("acc", "db_url", PAIR_URL)
modparam("acc", "db_extra",
"src_user=$fU;src_domain=$fd;dst_ouser=$tU;dst_user=$rU;dst_domain=$rd")
modparam("acc", "multi_leg_info",
"src_leg=$avp(i:901);dst_leg=$avp(i:902)")
modparam("acc", "time_mode", 2)
modparam("acc", "time_attr", "time_hires")
modparam("acc", "cdr_log_enable", 0)
And the relevant config code parts (with flags defined like this:
flags FLAG_ACC_DB:1, FLAG_ACC_MISSED:2, FLAG_ACC_FAILED:3, ...):
event_route[tm:branch-failure:redirect]
{
[% debug_dump('start', 'redirect') %]
route(ROUTE_STOP_RTPPROXY_BRANCH);
if($T_rpl($rs) == 301 || $T_rpl($rs) == 302)
{
# initialise variables when entering failure route
route(ROUTE_INITVARS);
# these need to be avps because we need it in reply/failure-route
$(avp(s:from_faxserver)[*]) = 0;
$(avp(s:to_faxserver)[*]) = 0;
$(avp(s:cf_from_pstn)[*]) = 0;
$(avp(s:from_pstn)[*]) = 0;
$(avp(s:proxylu_from_pstn)[*]) = 0;
$(avp(s:lcr_flags)[*]) = 0;
$(avp(s:em_call)[*]) = 0;
$(avp(s:from_pbx)[*]) = 0;
$(avp(s:p_to_device)[*]) = 0;
$(avp(s:p_to_group)[*]) = 0;
$(avp(s:is_primary)[*]) = 0;
# now let's process a 30x
$(avp(s:acc_state)[*]) = "cfb";
$(avp(s:orig_acc_caller_user)[*]) = $avp(s:acc_caller_user);
$(avp(s:orig_acc_caller_domain)[*]) = $avp(s:acc_caller_domain);
$(avp(s:acc_caller_user)[*]) = $avp(s:acc_callee_user);
$(avp(s:acc_caller_domain)[*]) = $avp(s:acc_callee_domain);
$(avp(s:caller_uuid)[*]) = $avp(s:callee_uuid);
$(avp(s:callee_uuid)[*]) = $null;
$var(no_acc) = 0;
if(isflagset(FLAG_ACC_DB)) {
xlog("L_NOTICE", "++++++ 1. ACC flag is set - [% logreq
-%]\n");
} else {
xlog("L_NOTICE", "------ 1. ACC flag is NOT set - [% logreq
-%]\n");
}
# get last URI from destination-set and set it as R-URI
$var(contact) = $T_rpl($ct);
$var(contact) = $(var(contact){nameaddr.uri});
if($var(contact) == 0 || $var(contact) == $null)
{
xlog("L_ERROR", "Failed to fetch contact '$ct' from
301/302
- [% logreq -%]\n");
acc_db_request("480", "acc");
$var(announce_handle) = "callee_tmp_unavailable";
$var(announce_set) = $xavp(callee_real_prefs[0]=>sound_set);
$(avp(s:announce_code)[*]) = 480;
$(avp(s:announce_reason)[*]) = "Temporarily Unavailable";
route(ROUTE_EARLY_REJECT);
}
$ru = $var(contact);
# not needed in per-branch failure route?
#append_branch();
#t_on_branch("BRANCH_ROUTE_SBC");
xlog("L_NOTICE", "Redirect from UAC intercepted - [% logreq
-%]\n");
$(avp(s:forwarder_cli_userprov)[*]) = $T_rpl($tU);
$(avp(s:forwarder_domain_userprov)[*]) = $T_rpl($td);
$var(forward) = 1;
$var(redirected_forward) = 1;
route(ROUTE_LOAD_CALLER_PREF);
route(ROUTE_FIND_CALLEE);
}
[% debug_dump('end', 'redirect') %]
}
########################################################################
# Request route 'usr-preferences-caller'
########################################################################
route[ROUTE_LOAD_CALLER_PREF]
{
[% debug_dump('start', 'ROUTE_LOAD_CALLER_PREF') %]
route(ROUTE_CLEAR_CALLER_PREF);
# if we're coming from 302 redirect route we want acc now
#even if previously the flags may have been NOT set
if($var(redirected_forward) == 1)
{
setflag(FLAG_ACC_FAILED);
setflag(FLAG_ACC_DB);
t_flush_flags();
}
xlog("L_INFO", "Load caller preferences for uuid
'$avp(s:caller_uuid)' and domain '$var(pref_domain)' - [% logreq
-%]\n");
if (!lua_run("ngcp_caller_usr_load", "$avp(s:caller_uuid)",
"$var(pref_domain)"))
{
route(ROUTE_ADD_CALLINFO_REPLY);
sl_send_reply("500", "Internal Error");
[% debug_dump('exit', 'ROUTE_LOAD_CALLER_PREF') %]
exit;
}
...
}
########################################################################
# Request route 'acc-callee'
########################################################################
route[ROUTE_ACC_CALLEE]
{
[% debug_dump('start', 'ROUTE_ACC_CALLEE') %]
if($var(proxylu_src) == 1 || $var(proxylu_dst_callee == 1))
{
$(avp(s:callee_acc_proxylu)[*]) = 1;
}
else
{
$(avp(s:callee_acc_proxylu)[*]) = 0;
}
if(isflagset(FLAG_ACC_DB)) {
xlog("L_NOTICE", "++++++ 2. ACC flag is set - [% logreq
-%]\n");
} else {
xlog("L_NOTICE", "------ 2. ACC flag is NOT set - [% logreq
-%]\n");
}
$var(gpp) = $xavp(callee_real_prefs[0]=>gpp0);
...
xlog("L_NOTICE", "Setting acc destination-leg for uuid
'$avp(s:callee_uuid)':
'$avp(s:callee_acc_proxylu)|$var(callee_ext_subscriber_id)|$var(callee_ext_contract_id)|$var(callee_account_id)|$avp(s:acc_callee_dialed)|$avp(s:callee_uuid)|$avp(s:acc_callee_user)|$avp(s:acc_callee_domain)|$avp(s:acc_callee_user_in)|$avp(s:acc_callee_domain_in)|$avp(s:lcr_flags)|$var(gpp)|'
- [% logreq -%]\n");
$avp(i:902) =
$_s($avp(s:callee_acc_proxylu)|$var(callee_ext_subscriber_id)|$var(callee_ext_contract_id)|$var(callee_account_id)|$avp(s:acc_callee_dialed)|$avp(s:callee_uuid)|$avp(s:acc_callee_user)|$avp(s:acc_callee_domain)|$avp(s:acc_callee_user_in)|$avp(s:acc_callee_domain_in)|$avp(s:lcr_flags)|)
+ $var(gpp) + "|";
[% debug_dump('end', 'ROUTE_ACC_CALLEE') %]
}
Attaching debug with debug=4 for tm and acc.
Hope that I've provided enough information to check this.
Regards,
Andrew