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