[Spce-user] Calls between subscribers are duplicated in the call list

Wed Oct 19 08:28:12 EDT 2022

Hi Henk,

I spin up a new mr9.5.5 CE system like your.
I cannot reproduce the kamailio crash on my side, but I'm glad to hear 
that a "ngcp-update" fixed the issue.

About the rate-o-mat problem we are aware of that and it is already 
being internally addressed. The internal ticket numbers are TT#190250 
and MT#55275.
Please try to execute the command 'ngcp-sync-grants' and then restart 
the rate-o-mat service and let us know if it solves the problem.

About the original reported issue, I confirm what I reported in my last 
email: in the subscribers' call list you get all the calls received or 
done by that user.
So in your case you should get on one user an entry as outgoing call and 
on the other user an entry as incoming call.
This is the expected behavior.

About the call costs calculation you need to rely on the CDRs (so one 
for each call) and not on the call-list of the subscribers.

Regards
Marco

On 18/10/22 12:05, Henk wrote:
>
> Hi Marco,
>
> I started with the 9.5.5 VMWare image. Just added two subscribers to 
> the first customer (#7 customer.test at spce.test). I registered two 
> devices and made a call without succes. It seems the kamailio proxy 
> crashed on INVITE with a memory dump:
>
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: DEFAULT_ROUTE <script>: New 
> request on proxy - M=INVITE 
> R=«sip:1121234567 at test1654835032.example.org» 
> F=«sip:c2 at test1654835032.example.org» 
> T=«sip:1121234567 at test1654835032.example.org» IP=«10.0.1.212»:«6062» 
> («127.0.0.1»:«5060») ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream 
> DP750 1.0.17.8' DESTIP=«127.0.0.1»:«5062»
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: DEFAULT_ROUTE <script>: 
> Sending reply S=100 Trying M=INVITE fs='«127.0.0.1»:«5062»' 
> du='«127.0.0.1»:«5060»' - 
> R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_AUTH <script>: 
> Authentication failed, no credentials - 
> R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8' 
> Auth=«<null>»
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_AUTH <script>: 
> Sending reply S=407 fs='«127.0.0.1»:«5062»' du='«127.0.0.1»:«5060»' - 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: sl:filtered-ack <script>: 
> New request on proxy - M=ACK 
> R=«sip:1121234567 at test1654835032.example.org» 
> F=«sip:c2 at test1654835032.example.org» 
> T=«sip:1121234567 at test1654835032.example.org» IP=«<null>»:«<null>» 
> («127.0.0.1»:«5060») ID=«1991747540-6062-9 at BA.A.B.CBC» UA='<null>' 
> DESTIP=«127.0.0.1»:«5062»
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: DEFAULT_ROUTE <script>: New 
> request on proxy - M=INVITE 
> R=«sip:1121234567 at test1654835032.example.org» 
> F=«sip:c2 at test1654835032.example.org» 
> T=«sip:1121234567 at test1654835032.example.org» IP=«10.0.1.212»:«6062» 
> («127.0.0.1»:«5060») ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream 
> DP750 1.0.17.8' DESTIP=«127.0.0.1»:«5062»
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: DEFAULT_ROUTE <script>: 
> Sending reply S=100 Trying M=INVITE fs='«127.0.0.1»:«5062»' 
> du='«127.0.0.1»:«5060»' - 
> R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_FIND_CALLER <script>: 
> Sending reply S=101 Connecting fs='«127.0.0.1»:«5062»' 
> du='«127.0.0.1»:«5060»' - 
> R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_DLG_MANAGE <script>: 
> Dialog managed, lua_dlg_callid:[«1991747540-6062-9 at BA.A.B.CBC»] - 
> R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_GET_CALLER_CLI 
> <script>: User-Provided CLI '«c2»' taken from From-User - 
> R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_CHECK_CLI_ALLOWED 
> <script>: User-provided CLI '«c2»' rejected, using network-provided 
> CLI '«1127654321»' - R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_INVITE <script>: 
> Setting '«1127654321»@«test1654835032.example.org»' as initiating 
> user-provided CLI - R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_INVITE <script>: 
> Setting '«1127654321»@«test1654835032.example.org»' as initiating 
> network-provided CLI - R=«sip:1121234567 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_FIND_CALLEE <script>: 
> Callee was aliased with base '«1121234567»' - 
> R=«sip:c1 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_FIND_CALLEE <script>: 
> Callee is local, uuid='«e5eb8a53-d91a-4460-83b0-eb84cbc9240a»' - 
> R=«sip:c1 at test1654835032.example.org» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_ACC_CALLER <script>: 
> Setting acc source-leg for uuid 
> '«a889b68d-9999-42a4-b897-e5c4bdb102f5»': 
> '«{"gpp":[null,null,null,null,null,null,null,null,null,null],"clir":0,"uuid":"a889b68d-9999-42a4-b897-e5c4bdb102f5","u":"c2","d":"test1654835032.example.org","cli":"1127654321","s_id":"","c_id":"","a_id":7,"pau":"","par":"","s":"call","ip":"10.0.1.212","t":1666085103.2204731,"lnp_p":"","cli_out":"1127654321","lnp_t":"","pai":"","div":"","last_hih":"","cid":"","u2u":"","lcr":0,"cc_quota":"","cc_sub":"1","cc_cust":"2"}»' 
> - 
> R=«sip:c1 at 77.160.100.40:61022;rinstance=38ecd83d4d88e500;transport=TCP» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_ACC_CALLEE <script>: 
> Setting acc destination-leg for uuid 
> '«e5eb8a53-d91a-4460-83b0-eb84cbc9240a»': 
> '«{"gpp":[null,null,null,null,null,null,null,null,null,null],"plu":0,"s_id":"","c_id":"","a_id":7,"dialed":"1121234567","uuid":"e5eb8a53-d91a-4460-83b0-eb84cbc9240a","u":"c1","d":"test1654835032.example.org","u_in":"1121234567","d_in":"test1654835032.example.org","lcr":0,"lnp_p":"","u_out":"c1","lnp_t":"","fci":"","cc_quota":"","cc_sub":"1","cc_cust":"2"}»' 
> - 
> R=«sip:c1 at 77.160.100.40:61022;rinstance=38ecd83d4d88e500;transport=TCP» 
> ID=«1991747540-6062-9 at BA.A.B.CBC» UA='Grandstream DP750 1.0.17.8'
> Oct 18 11:25:03 spce proxy[27230]: CRITICAL: 
> ROUTE_REMOVE_TIMER_SUPP_REQ <core> [core/mem/q_malloc.c:133]: 
> qm_debug_check_frag(): BUG: qm: fragm. 0x7f63d68230c0 (address 
> 0x7f63d68230f8) end overwritten (c0c0c000, abcdefed)! Memory allocator 
> was called from pv_headers: pvh_func.c:444. Fragment marked by 
> pv_headers: pvh_func.c:391. Exec from core/mem/q_malloc.c:511.
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_REMOVE_TIMER_SUPP_REQ 
> qm_status: qm_status(): (0x7f63d5980010):
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_REMOVE_TIMER_SUPP_REQ 
> qm_status: qm_status(): heap size= 134217728
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_REMOVE_TIMER_SUPP_REQ 
> qm_status: qm_status(): used= 26496208, used+overhead=33382264, 
> free=100835464
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_REMOVE_TIMER_SUPP_REQ 
> qm_status: qm_status(): max used (+overhead)= 33687296
> Oct 18 11:25:03 spce proxy[27230]: NOTICE: ROUTE_REMOVE_TIMER_SUPP_REQ 
> qm_status: qm_status(): dumping all alloc'ed. fragments:
>
> .....
>
> So I ran ngcp-update which fixed the issue, only now rate-o-mat crashes:
> Oct 18 11:33:48 spce (info) ngcp-rate-o-mat[65715]: DBD::mysql::db do 
> failed: Access denied; you need (at least one of) the SUPER, BINLOG 
> ADMIN privilege(s) for this operation at /usr/sbin/ngcp-rate-o-mat 
> line 288.
> Oct 18 11:33:48 spce (info) ngcp-rate-o-mat[65715]: FATAL: error 
> setting session binlog_format
> Oct 18 11:33:48 spce (info) ngcp-rate-o-mat[65715]: INFO: Trying to 
> connect to billing db...
> Oct 18 11:34:09 spce (info) ngcp-rate-o-mat[66252]: DBD::mysql::db do 
> failed: Access denied; you need (at least one of) the SUPER, BINLOG 
> ADMIN privilege(s) for this operation at /usr/sbin/ngcp-rate-o-mat 
> line 288.
> Oct 18 11:34:09 spce (info) ngcp-rate-o-mat[66252]: FATAL: error 
> setting session binlog_format
> Oct 18 11:34:09 spce (info) ngcp-rate-o-mat[66252]: INFO: Trying to 
> connect to billing db...
> Oct 18 11:34:42 spce (info) ngcp-rate-o-mat[67355]: DBD::mysql::db do 
> failed: Access denied; you need (at least one of) the SUPER, BINLOG 
> ADMIN privilege(s) for this operation at /usr/sbin/ngcp-rate-o-mat 
> line 288.
> Oct 18 11:34:42 spce (info) ngcp-rate-o-mat[67355]: FATAL: error 
> setting session binlog_format
> Oct 18 11:34:42 spce (info) ngcp-rate-o-mat[67355]: INFO: Trying to 
> connect to billing db...
>
> So, the image seems not very stable, but I was able to finish my test.
> The call list for subscriber 1:
>
> Call List for c1 at test1654835032.example.org (1 12 1234567)
> 115 1127654321    1121234567    0        cancel    2022-10-18 
> 11:36:39.586    0:00:00 568301286-6062-11 at BA.A.B.CBC 0.00
> 116    1121234567    1127654321    0        ok    2022-10-18 
> 11:37:39.065    0:00:05.501    0.0    0.0    0.0    0.0 
> DgOp_xBrhhPSWa5Df2TovQ..    0.00
>
> and for subscriber 2:
>
> Call List for c2 at test1654835032.example.org (1 12 7654321)
> 115 1127654321    1121234567    0        cancel    2022-10-18 
> 11:36:39.586    0:00:00 568301286-6062-11 at BA.A.B.CBC 0.00
> 116    1121234567    1127654321    0        ok    2022-10-18 
> 11:37:39.065    0:00:05.501    0.0    0.0    0.0    0.0 
> DgOp_xBrhhPSWa5Df2TovQ..    0.00
>
> The relevant parts of the CDR record:
> MariaDB [accounting]> select * from cdr where id=116\G;
> *************************** 1. row ***************************
>                                   id: 116
>                          update_time: 2022-10-18 11:37:51
>                       source_user_id: e5eb8a53-d91a-4460-83b0-eb84cbc9240a
>                   source_provider_id: 1
>        source_external_subscriber_id:
>          source_external_contract_id:
>                    source_account_id: 7
>                          source_user: c1
>                        source_domain: test1654835032.example.org
>                           source_cli: 1121234567
>                          source_clir: 0
>                            source_ip: 10.0.1.10
>
>                      source_user_out: 1121234567
>                  destination_user_id: a889b68d-9999-42a4-b897-e5c4bdb102f5
>              destination_provider_id: 1
>   destination_external_subscriber_id:
>     destination_external_contract_id:
>               destination_account_id: 7
>                     destination_user: c2
>                   destination_domain: test1654835032.example.org
>              destination_user_dialed: 1127654321
>                  destination_user_in: 1127654321
>                destination_domain_in: test1654835032.example.org
>
>                 destination_user_out: c2
>                       peer_auth_user:
>                      peer_auth_realm:
>                            call_type: call
>                          call_status: ok
>                            call_code: 200
>                            init_time: 1666085853.906
>                           start_time: 1666085859.065
>                             duration: 5.501
>                              call_id: DgOp_xBrhhPSWa5Df2TovQ..
>
> I hope this is enough to investigate, if you need any more logs just 
> let me know.
>
> Regards,
>
> Henk Plessius
>
> On 17-Oct-22 17:23, Marco Capetta via Spce-user wrote:
>> Hi Henk,
>>
>> Can you please detail a bit more?
>> In the subscribers' call list you should get on one user an entry as 
>> outgoing call and on the other user an entry as incoming call.
>> If you check in the DB or in the exported records, how many CDRs do 
>> you get in total for a single call?
>>
>> Thank you
>> Regards
>> Marco
>>
>>
>> On 17/10/22 12:52, Henk wrote:
>>> Hi all,
>>>
>>> I'm on mr9.5.4 and found that calls between subscribers from the 
>>> same customer are appearing in both call lists, in my test the 
>>> callee gets to see the record of the caller.
>>>
>>> The total cost for the callee in the CDR list will also not be 
>>> correct, as the amount from the caller is added.
>>>
>>> Regards,
>>>
>>> Henk Plessius
>>>
>>>
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sipwise.com/pipermail/spce-user_lists.sipwise.com/attachments/20221019/a9f745c9/attachment-0001.html>