[Spce-user] Calls between subscribers are duplicated in the call list
Henk
henkpls at hotmail.com
Tue Oct 18 06:05:54 EDT 2022
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/20221018/67a4ec62/attachment-0001.html>
More information about the Spce-user
mailing list