[sr-dev] [kamailio/kamailio] cnxcc: when credit reach the limit non confirmed calls of the same customer fail to terminate (#2346)
Victor Seva
notifications at github.com
Thu Jun 4 09:24:20 CEST 2020
### Description
when credit reach the limit non confirmed calls of the same customer fail to terminate
#### Reproduction
Sending a call of the same customer while there's another call of the same customer consuming all the quota assigned to it.
#### Log Messages
first call ``[450708880-22683-45 at BAA.BAE.BJF.BDF]`` established:
```
Jun 3 12:05:39 kamailio[21658]: DEBUG: cnxcc [cnxcc_mod.c:446]: __dialog_created_callback(): Flag is not set for this message. Ignoring
Jun 3 12:05:39 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:1583]: ki_set_max_credit(): Setting up new call for client [zs_00000], max-credit[1.000000], connect-cost[0.000000], cost-per-sec[0.100000], initial-pulse [1], final-pulse [1], call-id[450708880-22683-45 at BAA.BAE.BJF.BDF]
Jun 3 12:05:39 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:1521]: set_ctrl_flag(): Flag set!
Jun 3 12:05:39 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:1183]: __get_or_create_credit_data_entry(): Credit entry didn't exist. Allocated new entry [0x7f508161ed40]
Jun 3 12:05:39 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:1312]: __alloc_new_call_by_money(): New call allocated for client [zs_00000]
Jun 3 12:05:39 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:450]: __dialog_created_callback(): Dialog created for CID [450708880-22683-45 at BAA.BAE.BJF.BDF]
Jun 3 12:05:39 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:758]: __setup_billing(): Creating dialog for [450708880-22683-45 at BAA.BAE.BJF.BDF], h_id [4406], h_entry [1215]
Jun 3 12:05:39 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:797]: __setup_billing(): Call [450708880-22683-45 at BAA.BAE.BJF.BDF] from client [zs_00000], created
Jun 3 12:05:48 kamailio[21657]: DEBUG: cnxcc [cnxcc_mod.c:464]: __dialog_confirmed_callback(): Dialog confirmed for CID [450708880-22683-45 at BAA.BAE.BJF.BDF]
Jun 3 12:05:48 kamailio[21657]: DEBUG: cnxcc [cnxcc_mod.c:811]: __start_billing(): Billing started for call [450708880-22683-45 at BAA.BAE.BJF.BDF]
Jun 3 12:05:48 kamailio[21657]: DEBUG: cnxcc [cnxcc_mod.c:927]: __start_billing(): Call [450708880-22683-45 at BAA.BAE.BJF.BDF] from client [zs_00000], confirmed. from=<sip:zs_pruebas201 at pepelux.zoonsuite.com>;tag=1931637637, to=<sip:anonymous at pepelux.zoonsuite.com>;tag=as7138b4b8
Jun 3 12:05:48 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [0], consumed credit [0.100000]
Jun 3 12:05:48 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.100000/1.000000
Jun 3 12:05:49 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [1], consumed credit [0.100000]
Jun 3 12:05:49 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.100000/1.000000
Jun 3 12:05:50 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [2], consumed credit [0.300000]
Jun 3 12:05:50 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.300000/1.000000
```
Second call ``[d85f4ff9c923c9ea]``, first one is alive and consuming:
```
Jun 3 12:05:50 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:446]: __dialog_created_callback(): Flag is not set for this message. Ignoring
Jun 3 12:05:50 kamailio[21659]: DEBUG: cnxcc [cnxcc_mod.c:1583]: ki_set_max_credit(): Setting up new call for client [zs_00000], max-credit[1.000000], connect-cost[0.000000], cost-per-sec[0.100000], initial-pulse [1], final-pulse [1], call-id[d85f4ff9c923c9ea]
Jun 3 12:05:50 kamailio[21659]: DEBUG: cnxcc [cnxcc_mod.c:1521]: set_ctrl_flag(): Flag set!
Jun 3 12:05:50 kamailio[21659]: DEBUG: cnxcc [cnxcc_mod.c:1164]: __get_or_create_credit_data_entry(): Found key zs_00000 in hash table
Jun 3 12:05:50 kamailio[21659]: DEBUG: cnxcc [cnxcc_mod.c:1312]: __alloc_new_call_by_money(): New call allocated for client [zs_00000]
Jun 3 12:05:50 kamailio[21659]: DEBUG: cnxcc [cnxcc_mod.c:450]: __dialog_created_callback(): Dialog created for CID [d85f4ff9c923c9ea]
Jun 3 12:05:50 kamailio[21659]: DEBUG: cnxcc [cnxcc_mod.c:758]: __setup_billing(): Creating dialog for [d85f4ff9c923c9ea], h_id [1000], h_entry [1526]
Jun 3 12:05:50 kamailio[21659]: DEBUG: cnxcc [cnxcc_mod.c:797]: __setup_billing(): Call [d85f4ff9c923c9ea] from client [zs_00000], created
```
first call ``[450708880-22683-45 at BAA.BAE.BJF.BDF]`` will consume all the customer credit and trigger ``terminate_all_calls`` :
```
Jun 3 12:05:51 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [3], consumed credit [0.400000]
Jun 3 12:05:51 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.400000/1.000000
Jun 3 12:05:52 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [4], consumed credit [0.500000]
Jun 3 12:05:52 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.500000/1.000000
Jun 3 12:05:53 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [5], consumed credit [0.600000]
Jun 3 12:05:53 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.600000/1.000000
Jun 3 12:05:54 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [6], consumed credit [0.700000]
Jun 3 12:05:54 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.700000/1.000000
Jun 3 12:05:55 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [7], consumed credit [0.800000]
Jun 3 12:05:55 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.800000/1.000000
Jun 3 12:05:56 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [8], consumed credit [0.900000]
Jun 3 12:05:56 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 0.900000/1.000000
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:93]: check_calls_by_money(): CID [450708880-22683-45 at BAA.BAE.BJF.BDF], start_timestamp [1591178748], seconds alive [9], consumed credit [1.000000]
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_check.c:122]: check_calls_by_money(): Client [zs_00000] | Ended-Calls-Credit-Spent: 0.000000 TotalCredit/MaxCredit: 1.000000/1.000000
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:974]: terminate_all_calls(): Killing call with CID [d85f4ff9c923c9ea]
```
second ``[d85f4ff9c923c9ea]`` non-confirmed call doesn't have call->from_uri, call->from_tag, call->to_uri, call->to_tag so...:
```
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:1095]: terminate_call(): Got kill signal for call [d85f4ff9c923c9ea] client [zs_00000] h_id [1000] h_entry [1526]. Dropping it now
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_sip_msg_faker.c:48]: cnxcc_faked_msg_init_with_dlg_info(): fake msg:#012OPTIONS sip:you at kamailio.org SIP/2.0#015#012Via: SIP/2.0/UDP 127.0.0.1#015#012From: <>;tag=#015#012To: <>;tag=#015#012Call-ID: d85f4ff9c923c9ea#015#012CSeq: 1 OPTIONS#015#012Content-Length: 0
Jun 3 12:05:57 kamailio[21673]: ERROR: <core> [core/parser/parse_addr_spec.c:739]: parse_addr_spec(): unexpected char [>] in status 5: [<] .
Jun 3 12:05:57 kamailio[21673]: ERROR: <core> [core/parser/msg_parser.c:164]: get_hdr_field(): bad to header
Jun 3 12:05:57 kamailio[21673]: ERROR: <core> [core/parser/msg_parser.c:337]: parse_headers(): bad header field [To: <>;tag=#015#012Call-ID: d85f4ff9c923c9ea#015#012CSeq: 1 OPTIONS#015#012Content-Length: 0#015#012#015#012]
Jun 3 12:05:57 kamailio[21673]: ERROR: dialog [dlg_handlers.c:709]: pre_match_parse(): bad request or missing CALLID/TO hdr :-/
Jun 3 12:05:57 kamailio[21673]: ERROR: cnxcc [cnxcc_mod.c:1112]: terminate_call(): [d85f4ff9c923c9ea]: cannot get dialog
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:1029]: __free_call(): Freeing call [d85f4ff9c923c9ea]
```
but the call ``[d85f4ff9c923c9ea]`` is been freed. The first call ``[450708880-22683-45 at BAA.BAE.BJF.BDF]`` is been terminated properly and freed
```
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:974]: terminate_all_calls(): Killing call with CID [450708880-22683-45 at BAA.BAE.BJF.BDF]
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:1095]: terminate_call(): Got kill signal for call [450708880-22683-45 at BAA.BAE.BJF.BDF] client [zs_00000] h_id [4406] h_entry [1215]. Dropping it now
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_sip_msg_faker.c:48]: cnxcc_faked_msg_init_with_dlg_info(): fake msg:#012OPTIONS sip:you at kamailio.org SIP/2.0#015#012Via: SIP/2.0/UDP 127.0.0.1#015#012From: <sip:zs_pruebas201 at pepelux.zoonsuite.com>;tag=1931637637#015#012To: <sip:anonymous at pepelux.zoonsuite.com>;tag=as7138b4b8#015#012Call-ID: 450708880-22683-45 at BAA.BAE.BJF.BDF#015#012CSeq: 1 OPTIONS#015#012Content-Length: 0
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:473]: __dialog_terminated_callback(): Dialog terminated for CID [450708880-22683-45 at BAA.BAE.BJF.BDF]
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:656]: __stop_billing(): Call [450708880-22683-45 at BAA.BAE.BJF.BDF] of client-ID [zs_00000], ended
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:1117]: terminate_call(): dlg_end_dlg sent to call [450708880-22683-45 at BAA.BAE.BJF.BDF]
Jun 3 12:05:57 kamailio[21673]: INFO: <script>: [450708880-22683-45 at BAA.BAE.BJF.BDF]: call killed zs_pruebas201->anonymous ... No credit available
Jun 3 12:05:57 kamailio[21673]: DEBUG: cnxcc [cnxcc_mod.c:1029]: __free_call(): Freeing call [450708880-22683-45 at BAA.BAE.BJF.BDF]
```
second call ``[d85f4ff9c923c9ea]`` is confirmed but call info was already freed
```
Jun 3 12:06:03 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:464]: __dialog_confirmed_callback(): Dialog confirmed for CID [d85f4ff9c923c9ea]
Jun 3 12:06:03 kamailio[21660]: DEBUG: cnxcc [cnxcc_mod.c:811]: __start_billing(): Billing started for call [d85f4ff9c923c9ea]
Jun 3 12:06:03 kamailio[21660]: ERROR: cnxcc [cnxcc_mod.c:819]: __start_billing(): Call [d85f4ff9c923c9ea] not found
```
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
kamailio master with #2343 applied
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2346
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20200604/e091b2fb/attachment-0001.html>
More information about the sr-dev
mailing list