28 Feb
2020
28 Feb
'20
9:07 p.m.
K reported during about 90 sec period that it is out of shared memory:
Feb 28 09:47:28 rox1 /usr/bin/sip-proxy[19725]: ERROR: tm
[t_hooks.c:136]: insert_tmcb(): out of shm. mem
Feb 28 09:47:28 rox1 /usr/bin/sip-proxy[19725]: ERROR: acc
[acc_logic.c:394]: acc_onreq(): cannot register additional callbacks
Feb 28 09:47:28 rox1 /usr/bin/sip-proxy[19725]: ERROR: <core>
[core/sip_msg_clone.c:499]: sip_msg_shm_clone(): could not allocate
shared memory from shm pool
Feb 28 09:47:28 rox1 /usr/bin/sip-proxy[19725]: ERROR: tm
[t_lookup.c:1293]: new_t(): out of mem:
Feb 28 09:47:28 rox1 /usr/bin/sip-proxy[19725]: ERROR: tm
[t_lookup.c:1439]: t_newtran(): new_t failed
...
Feb 28 09:47:29 rox1 /usr/bin/sip-proxy[19725]: ERROR: <core>
[core/mem/q_malloc.c:297]: qm_find_free(): qm_find_free(0x7f1f2a506000,
1232); Free fragment not found!
Feb 28 09:47:29 rox1 /usr/bin/sip-proxy[19725]: ERROR: <core>
[core/mem/q_malloc.c:434]: qm_malloc(): qm_malloc(0x7f1f2a506000, 1232);
Free fragment not found!
Feb 28 09:47:29 rox1 /usr/bin/sip-proxy[19725]: ERROR: tm
[t_reply.c:1957]: relay_reply(): cannot alloc reply shmem
Feb 28 09:47:29 rox1 /usr/bin/sip-proxy[19725]: ERROR: <core>
[core/sip_msg_clone.c:499]: sip_msg_shm_clone(): could not allocate
shared memory from shm pool
Feb 28 09:47:29 rox1 /usr/bin/sip-proxy[19725]: ERROR: acc
[acc_logic.c:562]: acc_onreply(): failed to clone the request - acc aborted
...
Feb 28 09:48:51 rox1 /usr/bin/sip-proxy[19724]: ERROR: <core>
[core/mem/q_malloc.c:297]: qm_find_free(): qm_find_free(0x7f1f2a506000,
5728); Free fragment not found!
Feb 28 09:48:51 rox1 /usr/bin/sip-proxy[19724]: ERROR: <core>
[core/mem/q_malloc.c:434]: qm_malloc(): qm_malloc(0x7f1f2a506000, 5728);
Free fragment not found!
Feb 28 09:48:51 rox1 /usr/bin/sip-proxy[19724]: ERROR: tm
[t_lookup.c:1293]: new_t(): out of mem:
Feb 28 09:48:51 rox1 /usr/bin/sip-proxy[19724]: ERROR: tm
[t_lookup.c:1439]: t_newtran(): new_t failed
And after that period it started working normally again and
core.shmmem showed:
{
total: 134217728
free: 124173808
used: 9530960
real_used: 10043920
max_used: 134217728
fragments: 349
}
As can be seen, shm had been full, but normally only about 10% of it
is in use.
Syslog does not show any traffic spikes or other unusual activity before
the memory got full.
Any ideas what could cause such a high memory usage or could there be
a bug in shm management?
-- Juha
28 Feb
28 Feb
9:21 p.m.
The times we've seen this is when transactions are waiting on something so
they pile up consuming shared memory. Do you have any database lookups or
calls out to external services or scripts?
Long timeouts can also contribute if something stops responding because
transactions are waiting for a long timeout to expire.
It's typically a balance between setting reasonable timeouts and allocating
enough shm. In addition we implemented some watcher scripts that monitor
shm and will set gflags to disable non-critical external calls beyond a
certain threshold as well as send us an alert.
1 Mar
1 Mar
9:53 p.m.
John Petrini writes:
The times we've seen this is when transactions are
waiting on something so
they pile up consuming shared memory. Do you have any database lookups or
calls out to external services or scripts?
John,
Thanks for your reply. Yes, there are MySQL operations both during
request/reply processing and also accounting to db. I would assume that
any problems with those should show up in /var/log/mysql/error.log.
Long timeouts can also contribute if something stops
responding because
transactions are waiting for a long timeout to expire.
There is quite long "fr_inv_timer" value, that could cause problems is
lots of INVITEs are ringing at the same time.
It's typically a balance between setting
reasonable timeouts and allocating
enough shm. In addition we implemented some watcher scripts that monitor
shm and will set gflags to disable non-critical external calls beyond a
certain threshold as well as send us an alert.
I also created an external script to watch shm memory usage. I would
have liked K to watch itself, but could not find pseudo variables
corresponding to core.shmmem entries. Do they exist?
-- Juha
2 Mar
2 Mar
5:41 a.m.
Maybe not the nicest solution, but you can use (from inside the routing
script) the jsonrpc_exec() to get stats and grab the shmem usage, and build
your logic there... if this do that...
On Sun, Mar 1, 2020 at 12:54 Juha Heinanen <jh(a)tutpro.com> wrote:
John Petrini writes:
The times we've seen this is when
transactions are waiting on something
so
they pile up consuming shared memory. Do you have
any database lookups or
calls out to external services or scripts?
John,
Thanks for your reply. Yes, there are MySQL operations both during
request/reply processing and also accounting to db. I would assume that
any problems with those should show up in /var/log/mysql/error.log.
Long timeouts can also contribute if something
stops responding because
transactions are waiting for a long timeout to expire.
There is quite long "fr_inv_timer" value, that could cause problems is
lots of INVITEs are ringing at the same time.
It's typically a balance between setting
reasonable timeouts and
allocating
enough shm. In addition we implemented some
watcher scripts that monitor
shm and will set gflags to disable non-critical external calls beyond a
certain threshold as well as send us an alert.
I also created an external script to watch shm memory usage. I would
have liked K to watch itself, but could not find pseudo variables
corresponding to core.shmmem entries. Do they exist?
-- Juha
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
10:13 a.m.
On 01.03.20 21:53, Juha Heinanen wrote:
The $stat(name) can be used for any internal statistic. I think it takes
only the name of statistic, not the group, so something like
$stat(free_size).
Check also statsc module, maybe it is is useful to have the evolution of
some stats values in the recent past.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
John Petrini writes:
Failed queries should be reported to error log by kamailio as well.
On the other hand, Kamailio has some global parameters that enable
logging messages for slow db queries. Maybe you can enable them to see
if any query takes very long.
The times we've seen this is when
transactions are waiting on something so
they pile up consuming shared memory. Do you have any database lookups or
calls out to external services or scripts?
John,
Thanks for your reply. Yes, there are MySQL operations both during
request/reply processing and also accounting to db. I would assume that
any problems with those should show up in /var/log/mysql/error.log. Long timeouts can also contribute if something
stops responding because
transactions are waiting for a long timeout to expire.
There is quite long
"fr_inv_timer" value, that could cause problems is
lots of INVITEs are ringing at the same time.
It's typically a balance between setting
reasonable timeouts and allocating
enough shm. In addition we implemented some watcher scripts that monitor
shm and will set gflags to disable non-critical external calls beyond a
certain threshold as well as send us an alert.
I also created an external script
to watch shm memory usage. I would
have liked K to watch itself, but could not find pseudo variables
corresponding to core.shmmem entries. Do they exist?
3 Mar
3 Mar
2 a.m.
What kind of delay there is on cleaning of an expired transaction? I'm
asking, since tm.clean released lots of shm.
-- Juha
9:41 a.m.
Looks like something odd happened there. Is the timer process somehow
stuck? Any jump of the system clock? Virtual machine frozen somehow? Or
the transactions remained hooked in some callback, not releasing the
reference counter.
The rpc command tm.clean is like a last resort option when dealing with
an unexpected situation that messed up the timer process, otherwise the
transactions should be cleaned as they are expired or terminated because
of final response sent upstream, with a delay of 5 seconds (default value).
Cheers,
Daniel
On 03.03.20 02:00, Juha Heinanen wrote:
What kind of delay there is on cleaning of an expired
transaction? I'm
asking, since tm.clean released lots of shm.
-- Juha
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
9:16 p.m.
Daniel-Constantin Mierla writes:
The rpc command tm.clean is like a last resort option
when dealing with
an unexpected situation that messed up the timer process, otherwise the
transactions should be cleaned as they are expired or terminated because
of final response sent upstream, with a delay of 5 seconds (default value).
Before we find out why the transactions are not freed on time, I would
like to run a test every minute that checks if the shm usage is too
high and, if so, executes tm.clean. Something like this:
route [every_minute] {
$var(shm_usage) = ($stat(real_used_size) * 100) / $stat(total_size);
if ($var(shm_usage) > 90) t_clean();
}
Otherwise OK, but there is no t_clean() function. Could that be added?
-- Juha
4 Mar
4 Mar
8:51 a.m.
On 03.03.20 21:16, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
The function can be added, should be easy to extract the code from the
rpc command function. However even now you can execute rpc commands from
kamailio.cfg using jsonrpcs module:
*
https://www.kamailio.org/docs/modules/stable/modules/jsonrpcs.html#jsonrpcs…
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
The rpc command tm.clean is like a last resort
option when dealing with
an unexpected situation that messed up the timer process, otherwise the
transactions should be cleaned as they are expired or terminated because
of final response sent upstream, with a delay of 5 seconds (default value).
Before
we find out why the transactions are not freed on time, I would
like to run a test every minute that checks if the shm usage is too
high and, if so, executes tm.clean. Something like this:
route [every_minute] {
$var(shm_usage) = ($stat(real_used_size) * 100) / $stat(total_size);
if ($var(shm_usage) > 90) t_clean();
}
Otherwise OK, but there is no t_clean() function. Could that be added?
5 Mar
5 Mar
11:48 p.m.
Daniel-Constantin Mierla writes:
The function can be added, should be easy to extract
the code from the
rpc command function.
How about the tm.c patch below? Or should the function be placed in
some other tm/.c file and if so, which one?
-- Juha
-----------------------------------
*** /usr/src/orig/kamailio/src/modules/tm/tm.c 2020-03-06 00:13:15.534078140 +0200
--- tm.c 2020-03-06 00:45:26.405625701 +0200
***************
*** 208,213 ****
--- 207,213 ----
char* pnexthop, char* psock, char *phdrs, char* pbody);
static int w_t_get_status_code(sip_msg_t* msg, char *p1, char *p2);
+ static int t_clean(struct sip_msg* msg, char* key, char* value);
/* by default the fr timers avps are not set, so that the avps won't be
* searched for nothing each time a new transaction is created */
***************
*** 411,416 ****
--- 411,417 ----
REQUEST_ROUTE | FAILURE_ROUTE},
{"t_next_contact_flow", t_next_contact_flow, 0, 0, 0,
REQUEST_ROUTE },
+ {"t_clean", t_clean, 0, 0, 0, ANY_ROUTE },
/* not applicable from the script */
{"load_tm", (cmd_function)load_tm, NO_SCRIPT, 0, 0,
0},
***************
*** 2952,2957 ****
--- 2909,2921 ----
return ki_t_relay_to_proxy_flags(msg, NULL, rflags);
}
+ /* script function to clean active but very old transactions */
+ static int t_clean(struct sip_msg* msg, char* key, char* value)
+ {
+ tm_clean_lifetime();
+ return 1;
+ }
+
/**
*
*/
6 Mar
6 Mar
7:08 a.m.
It is ok, just add the documentation for the new function as well.
Cheers,
Daniel
On 05.03.20 23:48, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
The function can be added, should be easy to
extract the code from the
rpc command function.
How about the tm.c patch below? Or should the function be
placed in
some other tm/.c file and if so, which one?
-- Juha
-----------------------------------
*** /usr/src/orig/kamailio/src/modules/tm/tm.c 2020-03-06 00:13:15.534078140 +0200
--- tm.c 2020-03-06 00:45:26.405625701 +0200
***************
*** 208,213 ****
--- 207,213 ----
char* pnexthop, char* psock, char *phdrs, char* pbody);
static int w_t_get_status_code(sip_msg_t* msg, char *p1, char *p2);
+ static int t_clean(struct sip_msg* msg, char* key, char* value);
/* by default the fr timers avps are not set, so that the avps won't be
* searched for nothing each time a new transaction is created */
***************
*** 411,416 ****
--- 411,417 ----
REQUEST_ROUTE | FAILURE_ROUTE},
{"t_next_contact_flow", t_next_contact_flow, 0, 0, 0,
REQUEST_ROUTE },
+ {"t_clean", t_clean, 0, 0, 0, ANY_ROUTE },
/* not applicable from the script */
{"load_tm", (cmd_function)load_tm, NO_SCRIPT, 0, 0,
0},
***************
*** 2952,2957 ****
--- 2909,2921 ----
return ki_t_relay_to_proxy_flags(msg, NULL, rflags);
}
+ /* script function to clean active but very old transactions */
+ static int t_clean(struct sip_msg* msg, char* key, char* value)
+ {
+ tm_clean_lifetime();
+ return 1;
+ }
+
/**
*
*/
3 Mar
3 Mar
2:24 a.m.
Daniel-Constantin Mierla writes:
The $stat(name) can be used for any internal
statistic. I think it takes
only the name of statistic, not the group, so something like
$stat(free_size).
Thanks, free_size and the others in
core.shmmem
{
total: 67108864
free: 58274976
used: 7403616
real_used: 8833888
max_used: 8851696
fragments: 10
}
were found. For some reason, "_size" suffix needs to be appended to the
attribute names.
-- Juha
9:44 a.m.
On 03.03.20 02:24, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
I think you used a different rpc command, the one only for shared memory
info, which is not giving the exact statistic names.
To see the name of statistics, use the stats command with kamctl:
kamctl stats
It returns:
group.name = value
like:
shmem.fragments: '41'
shmem.free_size: '128218840'
shmem.max_used_size: '8643872'
shmem.real_used_size: '5998888'
shmem.total_size: '134217728'
shmem.used_size: '4309712'
Cheers,
Daniel
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
The $stat(name) can be used for any internal
statistic. I think it takes
only the name of statistic, not the group, so something like
$stat(free_size).
Thanks, free_size and the others in
core.shmmem
{
total: 67108864
free: 58274976
used: 7403616
real_used: 8833888
max_used: 8851696
fragments: 10
}
were found. For some reason, "_size" suffix needs to be appended to the
attribute names.
5:39 a.m.
Here is some more details about the shm usage. Usage was steady at
about 10 MB until time 17:05. Then it usage started to steadily grow
during 15 min period and 17:21 hit 80 MB at which point tm.clean was
executed. After that usage dropped straight back to 10 MB level.
How is that possible, i.e,, why the expired transactions were not
automatically cleared?
According to tm README:
An INVITE transaction will be kept in memory for maximum:
max_inv_lifetime+fr_timer(from the ACK to the final reply
wait)+wt_timer.
In this case the max memory time was 180 + 5 + 5 = 190 sec, which is
much less than 16 minutes.
-- Juha
9:48 a.m.
If you can reproduce it, watch what the timer processes do during that
time frame. Get the list of processes with 'kamctl ps', then when the
issue is exposed, grab the backtraces of all processes with:
kamctl trap
A file is created with the backtraces taken with gdb. Sent it over here
to analyze, if you cannot spot an issue there.
Cheers,
Daniel
On 03.03.20 05:39, Juha Heinanen wrote:
Here is some more details about the shm usage. Usage
was steady at
about 10 MB until time 17:05. Then it usage started to steadily grow
during 15 min period and 17:21 hit 80 MB at which point tm.clean was
executed. After that usage dropped straight back to 10 MB level.
How is that possible, i.e,, why the expired transactions were not
automatically cleared?
According to tm README:
An INVITE transaction will be kept in memory for maximum:
max_inv_lifetime+fr_timer(from the ACK to the final reply
wait)+wt_timer.
In this case the max memory time was 180 + 5 + 5 = 190 sec, which is
much less than 16 minutes.
-- Juha
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
4 Mar
4 Mar
10:18 p.m.
Daniel-Constantin Mierla writes:
If you can reproduce it, watch what the timer
processes do during that
time frame. Get the list of processes with 'kamctl ps', then when the
issue is exposed, grab the backtraces of all processes with:
kamctl trap
A file is created with the backtraces taken with gdb. Sent it over here
to analyze, if you cannot spot an issue there.
Will do that. Now it happened that K crashed when tm.clean was given at
the time when the number transactions was growing. Below is backtrace of
that crash.
-- Juha
-------------------------------
(gdb) bt full
#0 0x00007f5151fa3cf8 in tm_clean_lifetime () at h_table.c:617
r = 53487
tcell = 0x0
texp = 1117017528
#1 0x00007f5151fe1afd in tm_rpc_clean (rpc=0x7f51513b0a00 <func_param>,
c=0x7f51513b0920 <_jsonrpc_ctx_global>) at t_stats.c:299
No locals.
#2 0x00007f515138fc9f in jsonrpc_dispatch (msg=0x7fff3d1dc210, s1=0x0, s2=0x0) at
jsonrpcs_mod.c:1294
rpce = 0x7f5152dcf360
ctx = 0x7f51513b0920 <_jsonrpc_ctx_global>
ret = 0
nj = 0x0
val = {s = 0x557bb08fe9d0 "tm.clean", len = 8}
__func__ = "jsonrpc_dispatch"
#3 0x0000557bae5c28b5 in do_action (h=0x7fff3d1dc130, a=0x7f51537ebd30,
msg=0x7fff3d1dc210) at core/action.c:1073
ret = -5
v = 1390957541
dst = {send_sock = 0xc00000, to = {s = {sa_family = 6, sa_data =
"\000\000\000\000\000\000\220\270\035=\377\177\000"}, sin = {sin_family = 6,
sin_port = 0, sin_addr = {s_addr = 0}, sin_zero = "\220\270\035=\377\177\000"},
sin6 = {sin6_family = 6, sin6_port = 0,
sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 =
"\220\270\035=\377\177\000\000\000\b\302\tv\223\062\213", __u6_addr16 = {47248,
15645, 32767, 0, 2048, 2498, 37750, 35634}, __u6_addr32 = {1025357968, 32767, 163710976,
2335347574}}},
sin6_scope_id = 1025358088}}, id = 32767, send_flags = {f = 50272,
blst_imask = 21212}, proto = 81 'Q', proto_pad0 = 127 '\177', proto_pad1 =
0}
tmp = 0x7f5152ab3c1e "H\205\300\177\345ƃ\224"
new_uri = 0x7f51537e9da8 ""
end = 0x7fff3d1dc210 "\255\004"
crt = 0x557bb08fc931 "ip_proxy_cache"
cmd = 0x7f5152dd27c0
len = 4
user = 0
uri = {user = {s = 0x7fff3d1db580 "\340\265\035=\377\177", len =
1390199904}, passwd = {s = 0x557bae7f69e3 "INFO", len = -1368709420}, host = {s
= 0x7fff3d1db5a0 "", len = 1389801488}, port = {s = 0x7fff3d1db640
"\320\006", len = 1389801488}, params = {
s = 0x7fff3d1db5e0 "\020\266\035=\377\177", len = 1356175867},
sip_params = {s = 0x7fff3d1db7f0 "", len = 0}, headers = {s = 0xc00000
<error: Cannot access memory at address 0xc00000>, len = 1260448}, port_no = 56128,
proto = 159, type = ERROR_URI_T,
flags = (unknown: 11322464), transport = {s = 0xb7fab0 <error: Cannot access
memory at address 0xb7fab0>, len = 16}, ttl = {s = 0x11e <error: Cannot access
memory at address 0x11e>, len = 163710976}, user_param = {s = 0x7fff3d1db610
"\220\266\035=\377\177",
len = -1370752186}, maddr = {s = 0x0, len = 0}, method = {s = 0x7f5153158560
"\320\006", len = 0}, lr = {s = 0x7fff3d1db690
"\360\266\035=\377\177", len = -1368723422}, r2 = {s = 0x7f51531531f0
"\002", len = 1389801488}, gr = {s = 0x7f51537ea518 "\002",
len = 1393897952}, transport_val = {s = 0x6d0 <error: Cannot access memory
at address 0x6d0>, len = 1389801488}, ttl_val = {s = 0x7f51531530d0 <incomplete
sequence \360>, len = 1393899728}, user_param_val = {s = 0x7f51531531f8
">5\025SQ\177", len = 1390199904},
maddr_val = {s = 0x557bae7f69e3 "INFO", len = 536870912}, method_val =
{s = 0xc00000 <error: Cannot access memory at address 0xc00000>, len = 6}, lr_val =
{s = 0x7fff3d1db6f0 "P\267\035=\377\177", len = -1371351967}, r2_val = {s =
0x7fff3d1dc210 "\255\004",
len = 1400808728}, gr_val = {s = 0x7fff3d1db730
"\220\267\035=\377\177", len = 163710976}}
next_hop = {user = {s = 0x0, len = 1390199904}, passwd = {s = 0x557bae7f69e3
"INFO", len = 536870912}, host = {s = 0xc00000 <error: Cannot access memory
at address 0xc00000>, len = 6}, port = {s = 0x7fff3d1db750 "", len =
-1371324103}, params = {
s = 0x7fff3d1db7f0 "", len = 1400806792}, sip_params = {s =
0x19000017ac <error: Cannot access memory at address 0x19000017ac>, len =
1400808728}, headers = {s = 0x7fff3d1dc210 "\255\004", len = -1369366375},
port_no = 46992, proto = 15645, type = 32767,
flags = (unknown: 1390199904), transport = {s = 0x557bae7f69e3 "INFO",
len = 536870912}, ttl = {s = 0xc00000 <error: Cannot access memory at address
0xc00000>, len = 6}, user_param = {s = 0x7fff3d1db8a0
"\340\271\035=\377\177", len = -1371320250}, maddr = {
s = 0x557bae7f69e3 "INFO", len = 536870912}, method = {s = 0xc00000
<error: Cannot access memory at address 0xc00000>, len = 6}, lr = {s =
0x7fff3d1db7f0 "", len = 1387308127}, r2 = {s = 0x7f51537eac00 "\031",
len = 1025358088}, gr = {
s = 0x7fff3d1dc210 "\255\004", len = 1025360176}, transport_val = {s
= 0x17ac3d1db7f0 <error: Cannot access memory at address 0x17ac3d1db7f0>, len =
6060}, ttl_val = {s = 0x557bae7f69e3 "INFO", len = 536870912}, user_param_val =
{s = 0x7f51537e9d88 "\a",
len = 1400808728}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len
= 0}, lr_val = {s = 0x557bae95a842 <ut_buf_int2str+18> "976", len =
1398451376}, r2_val = {s = 0x7fff3d1db900 "\360\275\331R\001", len =
1390350000}, gr_val = {s = 0x0,
len = 1390199904}}
u = 0x7f5152abbc8d
port = 21269
dst_host = 0x7fff3d1db7f8
i = 0
flags = 32593
avp = 0x7fff3d1db4f8
st = {flags = 1400806800, id = 32593, name = {n = 1025360400, s = {s =
0x7fff3d1dc210 "\255\004", len = 1025357344}, re = 0x7fff3d1dc210}, avp =
0x557b00000000}
sct = 0x7f51511a819b <pv_get_huri+69>
sjt = 0x7f5153164bb0
rve = 0x7fff3d1dc248
mct = 0x7fff3d1db7f8
rv = 0x7fff3d1db4d0
rv1 = 0x7f5152dcc4a0
c1 = {cache_type = 2927585763, val_type = 21883, c = {avp_val = {n = 536870912, s
= {s = 0x20000000 <error: Cannot access memory at address 0x20000000>, len =
12582912}, re = 0x20000000}, pval = {rs = {
s = 0x20000000 <error: Cannot access memory at address 0x20000000>,
len = 12582912}, ri = 6, flags = 0}}, i2s =
"\340\271\035=\377\177\000\000\242KC\256{U\000\000\000\000\300\000\000"}
s = {s = 0x7f51537e9da8 "", len = 1025360400}
srevp = {0x557bae7f69e3, 0x20000000}
evp = {data = 0x0, rcv = 0x0, dst = 0x0}
mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0,
len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0,
string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {
type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0},
data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0,
str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u =
{
number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0,
select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len =
0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string =
0x0,
str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type =
NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr =
0x0, select = 0x0}}}
__func__ = "do_action"
#4 0x0000557bae5d0626 in run_actions (h=0x7fff3d1dc130, a=0x7f51537eba80,
msg=0x7fff3d1dc210) at core/action.c:1578
t = 0x7f51537ebd30
ret = 1
tvb = {tv_sec = 0, tv_usec = 0}
tve = {tv_sec = 0, tv_usec = 0}
tz = {tz_minuteswest = 21, tz_dsttime = 0}
tdiff = 2962221528
__func__ = "run_actions"
#5 0x0000557bae5c2821 in do_action (h=0x7fff3d1dc130, a=0x7f51537ebf50,
msg=0x7fff3d1dc210) at core/action.c:1064
--Type <RET> for more, q to quit, c to continue without paging--
ret = 1
v = 1
dst = {send_sock = 0x7f5153027c10, to = {s = {sa_family = 2048, sa_data =
"\302\tv\223\062\213y\237\037QQ\177\000"}, sin = {sin_family = 2048, sin_port =
2498, sin_addr = {s_addr = 2335347574}, sin_zero = "y\237\037QQ\177\000"}, sin6
= {sin6_family = 2048,
sin6_port = 2498, sin6_flowinfo = 2335347574, sin6_addr = {__in6_u =
{__u6_addr8 = "y\237\037QQ\177\000\000\017\000\000\000Q\177\000", __u6_addr16 =
{40825, 20767, 32593, 0, 15, 0, 32593, 0}, __u6_addr32 = {1361026937, 32593, 15, 32593}}},
sin6_scope_id = 2927585763}}, id = 4, send_flags = {f = 39616, blst_imask =
44675}, proto = 123 '{', proto_pad0 = 85 'U', proto_pad1 = 0}
tmp = 0x500000000 <error: Cannot access memory at address 0x500000000>
new_uri = 0x7fff3d1dc2b0 ""
end = 0x7f5152d38eda ""
crt = 0x0
cmd = 0x7f5153b25fa0 <_IO_strn_jumps>
len = 21
user = 32593
uri = {user = {s = 0x4009e6720 <error: Cannot access memory at address
0x4009e6720>, len = -1367595136}, passwd = {s = 0x7fff3d1dbcc8
"\"\027q\256{U", len = 163710976}, host = {s = 0x557bae95a830
<ut_buf_int2str> "", len = 0}, port = {
s = 0xd68 <error: Cannot access memory at address 0xd68>, len = 17},
params = {s = 0x0, len = 1390199904}, sip_params = {s = 0x557bae7f69e3 "INFO",
len = 536870912}, headers = {s = 0xc00000 <error: Cannot access memory at address
0xc00000>, len = 1025359116},
port_no = 48352, proto = 15645, type = URN_URI_T, flags = (URI_USER_NORMALIZE |
URI_SIP_USER_PHONE | unknown: 1390957584), transport = {s = 0x43d1dbd3c <error: Cannot
access memory at address 0x43d1dbd3c>, len = -1412931264}, ttl = {
s = 0x7f5152e85418 "\r\nHost: x.x.x.x:6060\r\nAccept:
*/*\r\nContent-type: application/json\r\nContent-length:
38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 1390957592}, user_param = {s =
0x7fff3d1dbe50 "p\277\035=\377\177",
len = -1368320222}, maddr = {s = 0x557bae95a842 <ut_buf_int2str+18>
"976", len = 163710976}, method = {s = 0x7fff3d1dbd00
"P\275\035=\377\177", len = 1393988016}, lr = {s = 0x7f5152e8549d "",
len = 1390957561}, r2 = {s = 0x7fff3d1dbd50 "\260\275\035=\377\177",
len = 84243696}, gr = {s = 0x37500000000 <error: Cannot access memory at
address 0x37500000000>, len = 1025359520}, transport_val = {s = 0x7f51537eccf8
"", len = -1368709420}, ttl_val = {s = 0x7fff3d1dbd70 "", len =
1389801488}, user_param_val = {
s = 0x557bae95a842 <ut_buf_int2str+18> "976", len =
1389801488}, maddr_val = {s = 0x7fff3d1dbdb0 "\340\275\035=\377\177", len =
1356175867}, method_val = {s = 0x4ae7f69e3 <error: Cannot access memory at address
0x4ae7f69e3>, len = 0}, lr_val = {
s = 0xc00000 <error: Cannot access memory at address 0xc00000>, len =
1260448}, r2_val = {s = 0x9fdb40 <error: Cannot access memory at address 0x9fdb40>,
len = 11322464}, gr_val = {s = 0xb7fab0 <error: Cannot access memory at address
0xb7fab0>, len = 16}}
next_hop = {user = {s = 0x11e <error: Cannot access memory at address
0x11e>, len = 163710976}, passwd = {s = 0x7fff3d1dbde0 "P\276\035=\377\177",
len = -1370752186}, host = {s = 0x0, len = 384}, port = {s = 0x7f51531692a0 <incomplete
sequence \360>, len = 0},
params = {s = 0x7fff3d1dbe50 "p\277\035=\377\177", len = -1368726502},
sip_params = {s = 0xf0 <error: Cannot access memory at address 0xf0>, len =
1390957594}, headers = {s = 0x0, len = 1393988016}, port_no = 37280, proto = 21270, type =
32593,
flags = (unknown: 163710976), transport = {s = 0xb7fab0 <error: Cannot access
memory at address 0xb7fab0>, len = 1390199904}, ttl = {s = 0x557bae7f69e3
"INFO", len = 536870912}, user_param = {s = 0xc00000 <error: Cannot access
memory at address 0xc00000>,
len = 6}, maddr = {s = 0x7fff3d1dbf70 "\020\300\035=\377\177", len =
-1368302309}, method = {s = 0x7f51531d2600 "\006", len = 1389801488}, lr = {s =
0x7fff3d1dbed0 "", len = 1356175867}, r2 = {s = 0x10 <error: Cannot access
memory at address 0x10>, len = 0},
gr = {s = 0xc00000 <error: Cannot access memory at address 0xc00000>, len
= 1392671776}, transport_val = {s = 0x7f5152e8549d "", len = 1390957556},
ttl_val = {s = 0xb7fab0 <error: Cannot access memory at address 0xb7fab0>, len =
16}, user_param_val = {
s = 0x11e <error: Cannot access memory at address 0x11e>, len =
163710976}, maddr_val = {s = 0x7fff3d1dbf00 "p\277\035=\001", len =
-1370752186}, method_val = {s = 0x0, len = 0}, lr_val = {s = 0x7f5152d6b0f0 "",
len = 0}, r2_val = {
s = 0x400000013d1dbf70 <error: Cannot access memory at address
0x400000013d1dbf70>, len = 1025360400}, gr_val = {
s = 0x7f5152e8541a "Host: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 1393988016}}
u = 0x7f512ecf128c
port = 21250
dst_host = 0xe
i = 1
flags = 0
avp = 0x557bae7f69e3
st = {flags = 0, id = 0, name = {n = 4, s = {s = 0x4 <error: Cannot access
memory at address 0x4>, len = 0}, re = 0x4}, avp = 0x10}
sct = 0x7f51539be112 <_IO_vfprintf_internal+1826>
sjt = 0x557bae7f69e3
rve = 0x7f51537eb2f0
mct = 0x7f5152de7980
rv = 0x0
rv1 = 0x7fff3d1dc140
c1 = {cache_type = 12582912, val_type = RV_NONE, c = {avp_val = {n = 163710976, s
= {s = 0x8b32937609c20800 <error: Cannot access memory at address
0x8b32937609c20800>, len = 1025359888}, re = 0x8b32937609c20800}, pval = {rs = {
s = 0x8b32937609c20800 <error: Cannot access memory at address
0x8b32937609c20800>, len = 1025359888}, ri = -1368282998, flags = 21883}}, i2s =
"\022\000\000\000\000\000\000\000\020\000\000\000\000\000\000\000\002\000\000\000\000"}
s = {s = 0x1352 <error: Cannot access memory at address 0x1352>, len = 0}
srevp = {0xab00000004, 0x0}
evp = {data = 0x0, rcv = 0x0, dst = 0x0}
mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0,
len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0,
string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {
type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0},
data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0,
str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u =
{
number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0,
select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len =
0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string =
0x0,
str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type =
NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr =
0x0, select = 0x0}}}
__func__ = "do_action"
#6 0x0000557bae5d0626 in run_actions (h=0x7fff3d1dc130, a=0x7f51537e7400,
msg=0x7fff3d1dc210) at core/action.c:1578
t = 0x7f51537ebf50
ret = 1
tvb = {tv_sec = 0, tv_usec = 0}
tve = {tv_sec = 0, tv_usec = 0}
tz = {tz_minuteswest = 1025360400, tz_dsttime = 32767}
tdiff = 0
__func__ = "run_actions"
#7 0x00007f51511a943e in xhttp_process_request (orig_msg=0x7f5153876780,
new_buf=0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", new_len=189) at xhttp_mod.c:296
ret = 0
backup_rt = 1
tmp_msg = {id = 1197, pid = 0, tval = {tv_sec = 0, tv_usec = 0}, fwd_send_flags =
{f = 0, blst_imask = 0}, rpl_send_flags = {f = 3, blst_imask = 0}, first_line = {type = 1,
flags = 2, len = 20, u = {request = {method = {
s = 0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 4}, uri = {
s = 0x7f5152e853e5 "/RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 4}, version = {
s = 0x7f5152e853ea "HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 8},
method_value = 65536}, reply = {version = {
s = 0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 4}, status = {
s = 0x7f5152e853e5 "/RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 4}, reason = {
s = 0x7f5152e853ea "HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 8},
statuscode = 65536}}}, via1 = 0x7f51531691b0, via2 = 0x0, headers =
0x7f5153027c20, last_header = 0x7f51531ae720, parsed_flag = 18446744073709551615, h_via1 =
0x7f5153027c20, h_via2 = 0x0, callid = 0x0, to = 0x0, cseq = 0x0, from = 0x0, contact =
0x0,
--Type <RET> for more, q to quit, c to continue without paging--
maxforwards = 0x0, route = 0x0, record_route = 0x0, content_type =
0x7f51531ae6c0, content_length = 0x7f51531ae720, authorization = 0x0, expires = 0x0,
proxy_auth = 0x0, supported = 0x0, require = 0x0, proxy_require = 0x0, unsupported = 0x0,
allow = 0x0,
event = 0x0, accept = 0x7f51531bb9f0, accept_language = 0x0, organization = 0x0,
priority = 0x0, subject = 0x0, user_agent = 0x0, server = 0x0, content_disposition = 0x0,
diversion = 0x0, rpid = 0x0, refer_to = 0x0, session_expires = 0x0, min_se = 0x0,
sipifmatch = 0x0, subscription_state = 0x0, date = 0x0, identity = 0x0,
identity_info = 0x0, pai = 0x0, ppi = 0x0, path = 0x0, privacy = 0x0, min_expires = 0x0,
body = 0x0, eoh = 0x7f5152e85475 "\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}",
unparsed = 0x7f5152e85475 "\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", rcv = {src_ip = {af = 2, len = 4, u =
{addrl = {362853934, 0}, addr32 = {362853934, 0, 0, 0}, addr16 = {46638, 5536, 0, 0, 0, 0,
0, 0},
addr = ".\266\240\025", '\000' <repeats 11
times>}}, dst_ip = {af = 2, len = 4, u = {addrl = {346076718, 0}, addr32 = {346076718,
0, 0, 0}, addr16 = {46638, 5280, 0, 0, 0, 0, 0, 0}, addr = ".\266\240\024",
'\000' <repeats 11 times>}}, src_port = 43976,
dst_port = 6060, proto_reserved1 = 1262, proto_reserved2 = 0, src_su = {s =
{sa_family = 2, sa_data = "\253\310.\266\240\025\000\000\000\000\000\000\000"},
sin = {sin_family = 2, sin_port = 51371, sin_addr = {s_addr = 362853934},
sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family
= 2, sin6_port = 51371, sin6_flowinfo = 362853934, sin6_addr = {__in6_u = {__u6_addr8 =
"\000\000\000\000\000\000\000\000\060\317\035=\377\177\000", __u6_addr16 = {0,
0, 0, 0, 53040, 15645,
32767, 0}, __u6_addr32 = {0, 0, 1025363760, 32767}}}, sin6_scope_id
= 0}}, bind_address = 0x7f5152dcc460, proto = 2 '\002', proto_pad0 = 0
'\000', proto_pad1 = 0},
buf = 0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 189, new_uri = {
s = 0x0, len = 0}, dst_uri = {s = 0x0, len = 0}, parsed_uri_ok = 0, parsed_uri
= {user = {s = 0x0, len = 0}, passwd = {s = 0x0, len = 0}, host = {s = 0x0, len = 0}, port
= {s = 0x0, len = 0}, params = {s = 0x0, len = 0}, sip_params = {s = 0x0, len = 0},
headers = {s = 0x0, len = 0}, port_no = 0, proto = 0, type = ERROR_URI_T,
flags = (unknown: 0), transport = {s = 0x0, len = 0}, ttl = {s = 0x0, len = 0}, user_param
= {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0, len = 0}, lr = {s =
0x0,
len = 0}, r2 = {s = 0x0, len = 0}, gr = {s = 0x0, len = 0}, transport_val =
{s = 0x0, len = 0}, ttl_val = {s = 0x0, len = 0}, user_param_val = {s = 0x0, len = 0},
maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 0}, lr_val = {s = 0x0, len =
0},
r2_val = {s = 0x0, len = 0}, gr_val = {s = 0x0, len = 0}}, parsed_orig_ruri_ok
= 0, parsed_orig_ruri = {user = {s = 0x0, len = 0}, passwd = {s = 0x0, len = 0}, host = {s
= 0x0, len = 0}, port = {s = 0x0, len = 0}, params = {s = 0x0, len = 0}, sip_params = {
s = 0x0, len = 0}, headers = {s = 0x0, len = 0}, port_no = 0, proto = 0,
type = ERROR_URI_T, flags = (unknown: 0), transport = {s = 0x0, len = 0}, ttl = {s = 0x0,
len = 0}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0,
len = 0}, lr = {s = 0x0, len = 0}, r2 = {s = 0x0, len = 0}, gr = {s = 0x0,
len = 0}, transport_val = {s = 0x0, len = 0}, ttl_val = {s = 0x0, len = 0}, user_param_val
= {s = 0x0, len = 0}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 0},
lr_val = {s = 0x0, len = 0}, r2_val = {s = 0x0, len = 0}, gr_val = {s = 0x0,
len = 0}}, add_rm = 0x0, body_lumps = 0x0, reply_lump = 0x0, add_to_branch_s =
'\000' <repeats 57 times>, add_to_branch_len = 0, hash_index = 0, msg_flags
= 0, flags = 0, xflags = {0,
0}, set_global_address = {s = 0x0, len = 0}, set_global_port = {s = 0x0, len =
0}, force_send_socket = 0x0, path_vec = {s = 0x0, len = 0}, instance = {s = 0x0, len = 0},
reg_id = 0, ruid = {s = 0x0, len = 0}, location_ua = {s = 0x0, len = 0}, otcpid = 0, ldv =
{
flow = {decoded = 0, rcv = {src_ip = {af = 0, len = 0, u = {addrl = {0, 0},
addr32 = {0, 0, 0, 0}, addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, addr = '\000'
<repeats 15 times>}}, dst_ip = {af = 0, len = 0, u = {addrl = {0, 0}, addr32 = {0,
0, 0, 0}, addr16 = {0, 0, 0,
0, 0, 0, 0, 0}, addr = '\000' <repeats 15 times>}},
src_port = 0, dst_port = 0, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s =
{sa_family = 0, sa_data = '\000' <repeats 13 times>}, sin = {sin_family = 0,
sin_port = 0, sin_addr = {s_addr = 0},
sin_zero = "\000\000\000\000\000\000\000"}, sin6 =
{sin6_family = 0, sin6_port = 0, sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 =
'\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0},
__u6_addr32 = {0, 0, 0, 0}}},
sin6_scope_id = 0}}, bind_address = 0x0, proto = 0 '\000',
proto_pad0 = 0 '\000', proto_pad1 = 0}}}}
msg = 0x7fff3d1dc210
ra_ctx = {rec_lev = 2, run_flags = 0, last_retcode = 1, jmp_env = {{__jmpbuf =
{139987259278432, -6960915947526443003, 93989696924131, 536870912, 12582912, 6,
-6960915947698409467, -3860432251912212475}, __mask_was_saved = 0, __saved_mask = {__val =
{
18446744073709551615, 0, 4, 93986769338368, 16, 12582944,
140734218749576, 3617854161208475648, 0, 0, 139987273275232, 139987269897424,
139987258674898, 11, 139987258674898, 139987227742213}}}}}
keng = 0x0
evrtname = {s = 0x7f51511b1598 "xhttp:request", len = 13}
__func__ = "xhttp_process_request"
#8 0x00007f51511aac55 in xhttp_handler (msg=0x7f5153876780) at xhttp_mod.c:383
ret = 0
fake_msg = 0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: X.X.X.X:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}"
fake_msg_len = 189
pmatch = {rm_so = 1025362464, rm_eo = 32767}
c = 83 'S'
__func__ = "xhttp_handler"
#9 0x0000557bae559a24 in nonsip_msg_run_hooks (msg=0x7f5153876780) at
core/nonsip_hooks.c:112
r = 0
ret = 0
#10 0x0000557bae5d6720 in receive_msg (buf=0x557bb08fee80 "POST /RPC
HTTP/1.1\r\nHost: X.X.X.X:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len=151, rcv_info=0x7f512fe42828)
at core/receive.c:348
msg = 0x7f5153876780
ctx = {rec_lev = 4, run_flags = 0, last_retcode = 803482386, jmp_env = {{__jmpbuf
= {8, 65536, 27, 0, 140734218751644, 139986672560144, 7, 70364449210396}, __mask_was_saved
= 121, __saved_mask = {__val = {10030241455286650880, 65535, 139986672560144,
93989696924131, 536870912, 12582912, 6, 140734218751232, 93989695295308,
519691042940, 2, 0, 65535, 140734218751644, 139986672560144, 18446744073709551536}}}}}
bctx = 0x7fff3d1dcc10
ret = 0
tvb = {tv_sec = 140734218751644, tv_usec = 139986672560904}
tve = {tv_sec = 139986672560144, tv_usec = 139986672560144}
tz = {tz_minuteswest = -1369026089, tz_dsttime = 21883}
diff = 0
inb = {s = 0x557bb08fee80 "POST /RPC HTTP/1.1\r\nHost:
X.X.X.X:6060\r\nAccept: */*\r\nContent-type: application/json\r\nContent-length:
38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 151}
netinfo = {data = {s = 0x1400020001 <error: Cannot access memory at address
0x1400020001>, len = 803482376}, rcv = 0x4, dst = 0x7f512fe42b0d}
keng = 0x0
evp = {data = 0x7fff3d1dcb30, rcv = 0x7f512fe42828, dst = 0x0}
cidlockidx = 0
cidlockset = 0
errsipmsg = 0
exectime = 0
__func__ = "receive_msg"
#11 0x0000557bae670357 in receive_tcp_msg (tcpbuf=0x7f512fe42b08 "POST /RPC
HTTP/1.1\r\nHost: X.X.X.X:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len=151, rcv_info=0x7f512fe42828,
con=0x7f512fe42810) at core/tcp_read.c:1448
buf = 0x557bb08fee80 "POST /RPC HTTP/1.1\r\nHost: X.X.X.X:6060\r\nAccept:
*/*\r\nContent-type: application/json\r\nContent-length:
38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}"
bsize = 65535
blen = 65535
__func__ = "receive_tcp_msg"
#12 0x0000557bae6725f3 in tcp_read_req (con=0x7f512fe42810, bytes_read=0x7fff3d1dce98,
read_flags=0x7fff3d1dce9c) at core/tcp_read.c:1631
bytes = 151
total_bytes = 151
resp = 1
size = 24
req = 0x7f512fe42890
dst = {send_sock = 0x0, to = {s = {sa_family = 61136, sa_data =
"\342/Q\177\000\000\330\316\035=\377\177\000"}, sin = {sin_family = 61136,
sin_port = 12258, sin_addr = {s_addr = 32593}, sin_zero =
"\330\316\035=\377\177\000"}, sin6 = {sin6_family = 61136,
sin6_port = 12258, sin6_flowinfo = 32593, sin6_addr = {__in6_u = {__u6_addr8
= "\330\316\035=\377\177\000\000\b\000\000\000\000\000\000", __u6_addr16 =
{52952, 15645, 32767, 0, 8, 0, 0, 0}, __u6_addr32 = {1025363672, 32767, 8, 0}}},
sin6_scope_id = 20}},
id = 0, send_flags = {f = 1, blst_imask = 0}, proto = 1 '\001',
proto_pad0 = 0 '\000', proto_pad1 = 0}
--Type <RET> for more, q to quit, c to continue without paging--
c = 49 '1'
ret = 1025363424
__func__ = "tcp_read_req"
#13 0x0000557bae6755a2 in handle_io (fm=0x7f5152db1498, events=1, idx=-1) at
core/tcp_read.c:1804
ret = 8
n = 8
read_flags = 1
con = 0x7f512fe42810
s = 28
resp = -2
t = 1117018954
__func__ = "handle_io"
#14 0x0000557bae662ba9 in io_wait_loop_epoll (h=0x557bae90ad00 <io_w>, t=2,
repeat=0) at core/io_wait.h:1062
n = 1
r = 0
fm = 0x7f5152db1498
revents = 1
__func__ = "io_wait_loop_epoll"
#15 0x0000557bae6775f5 in tcp_receive_loop (unix_sock=59) at core/tcp_read.c:1974
__func__ = "tcp_receive_loop"
#16 0x0000557bae51044a in tcp_init_children () at core/tcp_main.c:5174
r = 8
i = 7
reader_fd_1 = 59
pid = 0
si_desc = "tcp receiver
(tcp:X.X.X.X:6060)\000\000\000\062\023\000\000\001", '\000' <repeats 11
times>, "\260\034\246SQ\177\000\000\343i\177\256{U\000\000\000\000\000
\000\000\000\000\000\000\300\000\000\000\000\000\006\000\000\000\000\000\000\000
\321\035=\377\177\000\000\\8V\256{U\000\000
\321\035=\377\177\000\000\254\204a\256\000\000\000"
si = 0x0
__func__ = "tcp_init_children"
#17 0x0000557bae4228ce in main_loop () at main.c:1761
i = 8
pid = 4910
si = 0x0
si_desc = "udp receiver child=7
sock=127.0.0.1:5070\000\060\066\060\000\000\000\000\020\322\035=\377\177\000\000\000\b\302\tv\223\062\213\004\000\000\000\000\000\000\000\260\034\246SQ\177\000\000\343i\177\256{U\000\000\000\000\000
\000\000\000\000\000\000\300\000\000\000\000\000\006\000\000\000\000\000\000\000P\322\035=\377\177\000\000>0d\256{U\000"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#18 0x0000557bae42abb9 in main (argc=17, argv=0x7fff3d1dd738) at main.c:2802
cfg_stream = 0x557bb0796260
c = -1
r = 0
tmp = 0x7fff3d1def3f ""
tmp_len = 17
port = 0
proto = 1025365816
ahost = 0x0
aport = 0
options = 0x557bae7a0618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1972091384
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583307292,
tv_nsec = 782512911}, st_ctim = {tv_sec = 1583307633, tv_nsec = 722908545},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060G\272SQ\177\000\000\000\000\000\000\000\000\000\000\240q\037=\377\177\000\000\364J\270SQ\177\000\000\b\000\000\000\000\000\000\000\230r\037=\377\177\000\000\060G\272SQ\177\000\000\330\324\035=\377\177\000\000\324\324\035=\377\177",
'\000' <repeats 18 times>,
"\230r\037=\377\177\000\000\250q\037=\377\177\000\000'\356\256SQ\177\000\000&\260be\000\000\000\000@\326\035=\377\177\000\000\300\212\225\001\000\000\000\000\240\325\035=\377\177\000\000\220\325\035=\377\177\000\000\330\324\035=\377\177\000\000XG\272SQ\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x557bae7a2fca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x557bae79d438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x557bae7a2fcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x557bae7a2fd5 "subst",
has_arg = 1, flag = 0x0, val = 1025}, {name = 0x557bae7a2fdb
"substdef", has_arg = 1, flag = 0x0, val = 1026}, {name = 0x557bae7a2fe4
"substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name = 0x557bae7a2fee
"server-id", has_arg = 1, flag = 0x0, val = 1028}, {
name = 0x0, has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
10:31 p.m.
There was an unsafe list iteration - can you try with:
-
https://github.com/kamailio/kamailio/commit/325a45e846faae3e5dfa333727d5fab…
If all ok, you can backport.
Cheers,
Daniel
On 04.03.20 22:18, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
If you can reproduce it, watch what the timer
processes do during that
time frame. Get the list of processes with 'kamctl ps', then when the
issue is exposed, grab the backtraces of all processes with:
kamctl trap
A file is created with the backtraces taken with gdb. Sent it over here
to analyze, if you cannot spot an issue there.
Will do that. Now it happened that
K crashed when tm.clean was given at
the time when the number transactions was growing. Below is backtrace of
that crash.
-- Juha
-------------------------------
(gdb) bt full
#0 0x00007f5151fa3cf8 in tm_clean_lifetime () at h_table.c:617
r = 53487
tcell = 0x0
texp = 1117017528
#1 0x00007f5151fe1afd in tm_rpc_clean (rpc=0x7f51513b0a00 <func_param>,
c=0x7f51513b0920 <_jsonrpc_ctx_global>) at t_stats.c:299
No locals.
#2 0x00007f515138fc9f in jsonrpc_dispatch (msg=0x7fff3d1dc210, s1=0x0, s2=0x0) at
jsonrpcs_mod.c:1294
rpce = 0x7f5152dcf360
ctx = 0x7f51513b0920 <_jsonrpc_ctx_global>
ret = 0
nj = 0x0
val = {s = 0x557bb08fe9d0 "tm.clean", len = 8}
__func__ = "jsonrpc_dispatch"
#3 0x0000557bae5c28b5 in do_action (h=0x7fff3d1dc130, a=0x7f51537ebd30,
msg=0x7fff3d1dc210) at core/action.c:1073
ret = -5
v = 1390957541
dst = {send_sock = 0xc00000, to = {s = {sa_family = 6, sa_data =
"\000\000\000\000\000\000\220\270\035=\377\177\000"}, sin = {sin_family = 6,
sin_port = 0, sin_addr = {s_addr = 0}, sin_zero = "\220\270\035=\377\177\000"},
sin6 = {sin6_family = 6, sin6_port = 0,
sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 =
"\220\270\035=\377\177\000\000\000\b\302\tv\223\062\213", __u6_addr16 = {47248,
15645, 32767, 0, 2048, 2498, 37750, 35634}, __u6_addr32 = {1025357968, 32767, 163710976,
2335347574}}},
sin6_scope_id = 1025358088}}, id = 32767, send_flags = {f = 50272,
blst_imask = 21212}, proto = 81 'Q', proto_pad0 = 127 '\177', proto_pad1 =
0}
tmp = 0x7f5152ab3c1e "H\205\300\177\345ƃ\224"
new_uri = 0x7f51537e9da8 ""
end = 0x7fff3d1dc210 "\255\004"
crt = 0x557bb08fc931 "ip_proxy_cache"
cmd = 0x7f5152dd27c0
len = 4
user = 0
uri = {user = {s = 0x7fff3d1db580 "\340\265\035=\377\177", len =
1390199904}, passwd = {s = 0x557bae7f69e3 "INFO", len = -1368709420}, host = {s
= 0x7fff3d1db5a0 "", len = 1389801488}, port = {s = 0x7fff3d1db640
"\320\006", len = 1389801488}, params = {
s = 0x7fff3d1db5e0 "\020\266\035=\377\177", len = 1356175867},
sip_params = {s = 0x7fff3d1db7f0 "", len = 0}, headers = {s = 0xc00000
<error: Cannot access memory at address 0xc00000>, len = 1260448}, port_no = 56128,
proto = 159, type = ERROR_URI_T,
flags = (unknown: 11322464), transport = {s = 0xb7fab0 <error: Cannot access
memory at address 0xb7fab0>, len = 16}, ttl = {s = 0x11e <error: Cannot access
memory at address 0x11e>, len = 163710976}, user_param = {s = 0x7fff3d1db610
"\220\266\035=\377\177",
len = -1370752186}, maddr = {s = 0x0, len = 0}, method = {s = 0x7f5153158560
"\320\006", len = 0}, lr = {s = 0x7fff3d1db690
"\360\266\035=\377\177", len = -1368723422}, r2 = {s = 0x7f51531531f0
"\002", len = 1389801488}, gr = {s = 0x7f51537ea518 "\002",
len = 1393897952}, transport_val = {s = 0x6d0 <error: Cannot access memory
at address 0x6d0>, len = 1389801488}, ttl_val = {s = 0x7f51531530d0 <incomplete
sequence \360>, len = 1393899728}, user_param_val = {s = 0x7f51531531f8
">5\025SQ\177", len = 1390199904},
maddr_val = {s = 0x557bae7f69e3 "INFO", len = 536870912}, method_val
= {s = 0xc00000 <error: Cannot access memory at address 0xc00000>, len = 6}, lr_val
= {s = 0x7fff3d1db6f0 "P\267\035=\377\177", len = -1371351967}, r2_val = {s =
0x7fff3d1dc210 "\255\004",
len = 1400808728}, gr_val = {s = 0x7fff3d1db730
"\220\267\035=\377\177", len = 163710976}}
next_hop = {user = {s = 0x0, len = 1390199904}, passwd = {s = 0x557bae7f69e3
"INFO", len = 536870912}, host = {s = 0xc00000 <error: Cannot access memory
at address 0xc00000>, len = 6}, port = {s = 0x7fff3d1db750 "", len =
-1371324103}, params = {
s = 0x7fff3d1db7f0 "", len = 1400806792}, sip_params = {s =
0x19000017ac <error: Cannot access memory at address 0x19000017ac>, len =
1400808728}, headers = {s = 0x7fff3d1dc210 "\255\004", len = -1369366375},
port_no = 46992, proto = 15645, type = 32767,
flags = (unknown: 1390199904), transport = {s = 0x557bae7f69e3
"INFO", len = 536870912}, ttl = {s = 0xc00000 <error: Cannot access memory at
address 0xc00000>, len = 6}, user_param = {s = 0x7fff3d1db8a0
"\340\271\035=\377\177", len = -1371320250}, maddr = {
s = 0x557bae7f69e3 "INFO", len = 536870912}, method = {s = 0xc00000
<error: Cannot access memory at address 0xc00000>, len = 6}, lr = {s =
0x7fff3d1db7f0 "", len = 1387308127}, r2 = {s = 0x7f51537eac00 "\031",
len = 1025358088}, gr = {
s = 0x7fff3d1dc210 "\255\004", len = 1025360176}, transport_val =
{s = 0x17ac3d1db7f0 <error: Cannot access memory at address 0x17ac3d1db7f0>, len =
6060}, ttl_val = {s = 0x557bae7f69e3 "INFO", len = 536870912}, user_param_val =
{s = 0x7f51537e9d88 "\a",
len = 1400808728}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len
= 0}, lr_val = {s = 0x557bae95a842 <ut_buf_int2str+18> "976", len =
1398451376}, r2_val = {s = 0x7fff3d1db900 "\360\275\331R\001", len =
1390350000}, gr_val = {s = 0x0,
len = 1390199904}}
u = 0x7f5152abbc8d
port = 21269
dst_host = 0x7fff3d1db7f8
i = 0
flags = 32593
avp = 0x7fff3d1db4f8
st = {flags = 1400806800, id = 32593, name = {n = 1025360400, s = {s =
0x7fff3d1dc210 "\255\004", len = 1025357344}, re = 0x7fff3d1dc210}, avp =
0x557b00000000}
sct = 0x7f51511a819b <pv_get_huri+69>
sjt = 0x7f5153164bb0
rve = 0x7fff3d1dc248
mct = 0x7fff3d1db7f8
rv = 0x7fff3d1db4d0
rv1 = 0x7f5152dcc4a0
c1 = {cache_type = 2927585763, val_type = 21883, c = {avp_val = {n = 536870912, s
= {s = 0x20000000 <error: Cannot access memory at address 0x20000000>, len =
12582912}, re = 0x20000000}, pval = {rs = {
s = 0x20000000 <error: Cannot access memory at address 0x20000000>,
len = 12582912}, ri = 6, flags = 0}}, i2s =
"\340\271\035=\377\177\000\000\242KC\256{U\000\000\000\000\300\000\000"}
s = {s = 0x7f51537e9da8 "", len = 1025360400}
srevp = {0x557bae7f69e3, 0x20000000}
evp = {data = 0x0, rcv = 0x0, dst = 0x0}
mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0,
len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0,
string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {
type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0},
data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0,
str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u =
{
number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0,
select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len =
0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string =
0x0,
str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type =
NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr =
0x0, select = 0x0}}}
__func__ = "do_action"
#4 0x0000557bae5d0626 in run_actions (h=0x7fff3d1dc130, a=0x7f51537eba80,
msg=0x7fff3d1dc210) at core/action.c:1578
t = 0x7f51537ebd30
ret = 1
tvb = {tv_sec = 0, tv_usec = 0}
tve = {tv_sec = 0, tv_usec = 0}
tz = {tz_minuteswest = 21, tz_dsttime = 0}
tdiff = 2962221528
__func__ = "run_actions"
#5 0x0000557bae5c2821 in do_action (h=0x7fff3d1dc130, a=0x7f51537ebf50,
msg=0x7fff3d1dc210) at core/action.c:1064
--Type <RET> for more, q to quit, c to continue without paging--
ret = 1
v = 1
dst = {send_sock = 0x7f5153027c10, to = {s = {sa_family = 2048, sa_data =
"\302\tv\223\062\213y\237\037QQ\177\000"}, sin = {sin_family = 2048, sin_port =
2498, sin_addr = {s_addr = 2335347574}, sin_zero = "y\237\037QQ\177\000"}, sin6
= {sin6_family = 2048,
sin6_port = 2498, sin6_flowinfo = 2335347574, sin6_addr = {__in6_u =
{__u6_addr8 = "y\237\037QQ\177\000\000\017\000\000\000Q\177\000", __u6_addr16 =
{40825, 20767, 32593, 0, 15, 0, 32593, 0}, __u6_addr32 = {1361026937, 32593, 15, 32593}}},
sin6_scope_id = 2927585763}}, id = 4, send_flags = {f = 39616, blst_imask =
44675}, proto = 123 '{', proto_pad0 = 85 'U', proto_pad1 = 0}
tmp = 0x500000000 <error: Cannot access memory at address 0x500000000>
new_uri = 0x7fff3d1dc2b0 ""
end = 0x7f5152d38eda ""
crt = 0x0
cmd = 0x7f5153b25fa0 <_IO_strn_jumps>
len = 21
user = 32593
uri = {user = {s = 0x4009e6720 <error: Cannot access memory at address
0x4009e6720>, len = -1367595136}, passwd = {s = 0x7fff3d1dbcc8
"\"\027q\256{U", len = 163710976}, host = {s = 0x557bae95a830
<ut_buf_int2str> "", len = 0}, port = {
s = 0xd68 <error: Cannot access memory at address 0xd68>, len = 17},
params = {s = 0x0, len = 1390199904}, sip_params = {s = 0x557bae7f69e3 "INFO",
len = 536870912}, headers = {s = 0xc00000 <error: Cannot access memory at address
0xc00000>, len = 1025359116},
port_no = 48352, proto = 15645, type = URN_URI_T, flags = (URI_USER_NORMALIZE |
URI_SIP_USER_PHONE | unknown: 1390957584), transport = {s = 0x43d1dbd3c <error: Cannot
access memory at address 0x43d1dbd3c>, len = -1412931264}, ttl = {
s = 0x7f5152e85418 "\r\nHost: x.x.x.x:6060\r\nAccept:
*/*\r\nContent-type: application/json\r\nContent-length:
38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 1390957592}, user_param = {s =
0x7fff3d1dbe50 "p\277\035=\377\177",
len = -1368320222}, maddr = {s = 0x557bae95a842 <ut_buf_int2str+18>
"976", len = 163710976}, method = {s = 0x7fff3d1dbd00
"P\275\035=\377\177", len = 1393988016}, lr = {s = 0x7f5152e8549d "",
len = 1390957561}, r2 = {s = 0x7fff3d1dbd50 "\260\275\035=\377\177",
len = 84243696}, gr = {s = 0x37500000000 <error: Cannot access memory at
address 0x37500000000>, len = 1025359520}, transport_val = {s = 0x7f51537eccf8
"", len = -1368709420}, ttl_val = {s = 0x7fff3d1dbd70 "", len =
1389801488}, user_param_val = {
s = 0x557bae95a842 <ut_buf_int2str+18> "976", len =
1389801488}, maddr_val = {s = 0x7fff3d1dbdb0 "\340\275\035=\377\177", len =
1356175867}, method_val = {s = 0x4ae7f69e3 <error: Cannot access memory at address
0x4ae7f69e3>, len = 0}, lr_val = {
s = 0xc00000 <error: Cannot access memory at address 0xc00000>, len =
1260448}, r2_val = {s = 0x9fdb40 <error: Cannot access memory at address 0x9fdb40>,
len = 11322464}, gr_val = {s = 0xb7fab0 <error: Cannot access memory at address
0xb7fab0>, len = 16}}
next_hop = {user = {s = 0x11e <error: Cannot access memory at address
0x11e>, len = 163710976}, passwd = {s = 0x7fff3d1dbde0 "P\276\035=\377\177",
len = -1370752186}, host = {s = 0x0, len = 384}, port = {s = 0x7f51531692a0 <incomplete
sequence \360>, len = 0},
params = {s = 0x7fff3d1dbe50 "p\277\035=\377\177", len =
-1368726502}, sip_params = {s = 0xf0 <error: Cannot access memory at address 0xf0>,
len = 1390957594}, headers = {s = 0x0, len = 1393988016}, port_no = 37280, proto = 21270,
type = 32593,
flags = (unknown: 163710976), transport = {s = 0xb7fab0 <error: Cannot
access memory at address 0xb7fab0>, len = 1390199904}, ttl = {s = 0x557bae7f69e3
"INFO", len = 536870912}, user_param = {s = 0xc00000 <error: Cannot access
memory at address 0xc00000>,
len = 6}, maddr = {s = 0x7fff3d1dbf70 "\020\300\035=\377\177", len
= -1368302309}, method = {s = 0x7f51531d2600 "\006", len = 1389801488}, lr = {s
= 0x7fff3d1dbed0 "", len = 1356175867}, r2 = {s = 0x10 <error: Cannot access
memory at address 0x10>, len = 0},
gr = {s = 0xc00000 <error: Cannot access memory at address 0xc00000>, len
= 1392671776}, transport_val = {s = 0x7f5152e8549d "", len = 1390957556},
ttl_val = {s = 0xb7fab0 <error: Cannot access memory at address 0xb7fab0>, len =
16}, user_param_val = {
s = 0x11e <error: Cannot access memory at address 0x11e>, len =
163710976}, maddr_val = {s = 0x7fff3d1dbf00 "p\277\035=\001", len =
-1370752186}, method_val = {s = 0x0, len = 0}, lr_val = {s = 0x7f5152d6b0f0 "",
len = 0}, r2_val = {
s = 0x400000013d1dbf70 <error: Cannot access memory at address
0x400000013d1dbf70>, len = 1025360400}, gr_val = {
s = 0x7f5152e8541a "Host: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 1393988016}}
u = 0x7f512ecf128c
port = 21250
dst_host = 0xe
i = 1
flags = 0
avp = 0x557bae7f69e3
st = {flags = 0, id = 0, name = {n = 4, s = {s = 0x4 <error: Cannot access
memory at address 0x4>, len = 0}, re = 0x4}, avp = 0x10}
sct = 0x7f51539be112 <_IO_vfprintf_internal+1826>
sjt = 0x557bae7f69e3
rve = 0x7f51537eb2f0
mct = 0x7f5152de7980
rv = 0x0
rv1 = 0x7fff3d1dc140
c1 = {cache_type = 12582912, val_type = RV_NONE, c = {avp_val = {n = 163710976, s
= {s = 0x8b32937609c20800 <error: Cannot access memory at address
0x8b32937609c20800>, len = 1025359888}, re = 0x8b32937609c20800}, pval = {rs = {
s = 0x8b32937609c20800 <error: Cannot access memory at address
0x8b32937609c20800>, len = 1025359888}, ri = -1368282998, flags = 21883}}, i2s =
"\022\000\000\000\000\000\000\000\020\000\000\000\000\000\000\000\002\000\000\000\000"}
s = {s = 0x1352 <error: Cannot access memory at address 0x1352>, len = 0}
srevp = {0xab00000004, 0x0}
evp = {data = 0x0, rcv = 0x0, dst = 0x0}
mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0,
len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0,
string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {
type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0},
data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0,
str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u =
{
number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0,
select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len =
0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string =
0x0,
str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type =
NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr =
0x0, select = 0x0}}}
__func__ = "do_action"
#6 0x0000557bae5d0626 in run_actions (h=0x7fff3d1dc130, a=0x7f51537e7400,
msg=0x7fff3d1dc210) at core/action.c:1578
t = 0x7f51537ebf50
ret = 1
tvb = {tv_sec = 0, tv_usec = 0}
tve = {tv_sec = 0, tv_usec = 0}
tz = {tz_minuteswest = 1025360400, tz_dsttime = 32767}
tdiff = 0
__func__ = "run_actions"
#7 0x00007f51511a943e in xhttp_process_request (orig_msg=0x7f5153876780,
new_buf=0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", new_len=189) at xhttp_mod.c:296
ret = 0
backup_rt = 1
tmp_msg = {id = 1197, pid = 0, tval = {tv_sec = 0, tv_usec = 0}, fwd_send_flags =
{f = 0, blst_imask = 0}, rpl_send_flags = {f = 3, blst_imask = 0}, first_line = {type = 1,
flags = 2, len = 20, u = {request = {method = {
s = 0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 4}, uri = {
s = 0x7f5152e853e5 "/RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 4}, version = {
s = 0x7f5152e853ea "HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 8},
method_value = 65536}, reply = {version = {
s = 0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 4}, status = {
s = 0x7f5152e853e5 "/RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 4}, reason = {
s = 0x7f5152e853ea "HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 8},
statuscode = 65536}}}, via1 = 0x7f51531691b0, via2 = 0x0, headers =
0x7f5153027c20, last_header = 0x7f51531ae720, parsed_flag = 18446744073709551615, h_via1 =
0x7f5153027c20, h_via2 = 0x0, callid = 0x0, to = 0x0, cseq = 0x0, from = 0x0, contact =
0x0,
--Type <RET> for more, q to quit, c to continue without paging--
maxforwards = 0x0, route = 0x0, record_route = 0x0, content_type =
0x7f51531ae6c0, content_length = 0x7f51531ae720, authorization = 0x0, expires = 0x0,
proxy_auth = 0x0, supported = 0x0, require = 0x0, proxy_require = 0x0, unsupported = 0x0,
allow = 0x0,
event = 0x0, accept = 0x7f51531bb9f0, accept_language = 0x0, organization =
0x0, priority = 0x0, subject = 0x0, user_agent = 0x0, server = 0x0, content_disposition =
0x0, diversion = 0x0, rpid = 0x0, refer_to = 0x0, session_expires = 0x0, min_se = 0x0,
sipifmatch = 0x0, subscription_state = 0x0, date = 0x0, identity = 0x0,
identity_info = 0x0, pai = 0x0, ppi = 0x0, path = 0x0, privacy = 0x0, min_expires = 0x0,
body = 0x0, eoh = 0x7f5152e85475 "\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}",
unparsed = 0x7f5152e85475 "\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", rcv = {src_ip = {af = 2, len = 4, u =
{addrl = {362853934, 0}, addr32 = {362853934, 0, 0, 0}, addr16 = {46638, 5536, 0, 0, 0, 0,
0, 0},
addr = ".\266\240\025", '\000' <repeats 11
times>}}, dst_ip = {af = 2, len = 4, u = {addrl = {346076718, 0}, addr32 = {346076718,
0, 0, 0}, addr16 = {46638, 5280, 0, 0, 0, 0, 0, 0}, addr = ".\266\240\024",
'\000' <repeats 11 times>}}, src_port = 43976,
dst_port = 6060, proto_reserved1 = 1262, proto_reserved2 = 0, src_su = {s =
{sa_family = 2, sa_data = "\253\310.\266\240\025\000\000\000\000\000\000\000"},
sin = {sin_family = 2, sin_port = 51371, sin_addr = {s_addr = 362853934},
sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family
= 2, sin6_port = 51371, sin6_flowinfo = 362853934, sin6_addr = {__in6_u = {__u6_addr8 =
"\000\000\000\000\000\000\000\000\060\317\035=\377\177\000", __u6_addr16 = {0,
0, 0, 0, 53040, 15645,
32767, 0}, __u6_addr32 = {0, 0, 1025363760, 32767}}}, sin6_scope_id
= 0}}, bind_address = 0x7f5152dcc460, proto = 2 '\002', proto_pad0 = 0
'\000', proto_pad1 = 0},
buf = 0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: x.x.x.x:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 189, new_uri = {
s = 0x0, len = 0}, dst_uri = {s = 0x0, len = 0}, parsed_uri_ok = 0,
parsed_uri = {user = {s = 0x0, len = 0}, passwd = {s = 0x0, len = 0}, host = {s = 0x0, len
= 0}, port = {s = 0x0, len = 0}, params = {s = 0x0, len = 0}, sip_params = {s = 0x0, len =
0},
headers = {s = 0x0, len = 0}, port_no = 0, proto = 0, type = ERROR_URI_T,
flags = (unknown: 0), transport = {s = 0x0, len = 0}, ttl = {s = 0x0, len = 0}, user_param
= {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0, len = 0}, lr = {s =
0x0,
len = 0}, r2 = {s = 0x0, len = 0}, gr = {s = 0x0, len = 0}, transport_val =
{s = 0x0, len = 0}, ttl_val = {s = 0x0, len = 0}, user_param_val = {s = 0x0, len = 0},
maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 0}, lr_val = {s = 0x0, len =
0},
r2_val = {s = 0x0, len = 0}, gr_val = {s = 0x0, len = 0}},
parsed_orig_ruri_ok = 0, parsed_orig_ruri = {user = {s = 0x0, len = 0}, passwd = {s = 0x0,
len = 0}, host = {s = 0x0, len = 0}, port = {s = 0x0, len = 0}, params = {s = 0x0, len =
0}, sip_params = {
s = 0x0, len = 0}, headers = {s = 0x0, len = 0}, port_no = 0, proto = 0,
type = ERROR_URI_T, flags = (unknown: 0), transport = {s = 0x0, len = 0}, ttl = {s = 0x0,
len = 0}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0,
len = 0}, lr = {s = 0x0, len = 0}, r2 = {s = 0x0, len = 0}, gr = {s = 0x0,
len = 0}, transport_val = {s = 0x0, len = 0}, ttl_val = {s = 0x0, len = 0}, user_param_val
= {s = 0x0, len = 0}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 0},
lr_val = {s = 0x0, len = 0}, r2_val = {s = 0x0, len = 0}, gr_val = {s = 0x0,
len = 0}}, add_rm = 0x0, body_lumps = 0x0, reply_lump = 0x0, add_to_branch_s =
'\000' <repeats 57 times>, add_to_branch_len = 0, hash_index = 0, msg_flags
= 0, flags = 0, xflags = {0,
0}, set_global_address = {s = 0x0, len = 0}, set_global_port = {s = 0x0, len
= 0}, force_send_socket = 0x0, path_vec = {s = 0x0, len = 0}, instance = {s = 0x0, len =
0}, reg_id = 0, ruid = {s = 0x0, len = 0}, location_ua = {s = 0x0, len = 0}, otcpid = 0,
ldv = {
flow = {decoded = 0, rcv = {src_ip = {af = 0, len = 0, u = {addrl = {0, 0},
addr32 = {0, 0, 0, 0}, addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, addr = '\000'
<repeats 15 times>}}, dst_ip = {af = 0, len = 0, u = {addrl = {0, 0}, addr32 = {0,
0, 0, 0}, addr16 = {0, 0, 0,
0, 0, 0, 0, 0}, addr = '\000' <repeats 15 times>}},
src_port = 0, dst_port = 0, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s =
{sa_family = 0, sa_data = '\000' <repeats 13 times>}, sin = {sin_family = 0,
sin_port = 0, sin_addr = {s_addr = 0},
sin_zero = "\000\000\000\000\000\000\000"}, sin6 =
{sin6_family = 0, sin6_port = 0, sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 =
'\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0},
__u6_addr32 = {0, 0, 0, 0}}},
sin6_scope_id = 0}}, bind_address = 0x0, proto = 0 '\000',
proto_pad0 = 0 '\000', proto_pad1 = 0}}}}
msg = 0x7fff3d1dc210
ra_ctx = {rec_lev = 2, run_flags = 0, last_retcode = 1, jmp_env = {{__jmpbuf =
{139987259278432, -6960915947526443003, 93989696924131, 536870912, 12582912, 6,
-6960915947698409467, -3860432251912212475}, __mask_was_saved = 0, __saved_mask = {__val =
{
18446744073709551615, 0, 4, 93986769338368, 16, 12582944,
140734218749576, 3617854161208475648, 0, 0, 139987273275232, 139987269897424,
139987258674898, 11, 139987258674898, 139987227742213}}}}}
keng = 0x0
evrtname = {s = 0x7f51511b1598 "xhttp:request", len = 13}
__func__ = "xhttp_process_request"
#8 0x00007f51511aac55 in xhttp_handler (msg=0x7f5153876780) at xhttp_mod.c:383
ret = 0
fake_msg = 0x7f5152e853e0 "POST /RPC HTTP/1.1\r\nVia: SIP/2.0/TCP
X.X.X.X:43976\r\nHost: X.X.X.X:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}"
fake_msg_len = 189
pmatch = {rm_so = 1025362464, rm_eo = 32767}
c = 83 'S'
__func__ = "xhttp_handler"
#9 0x0000557bae559a24 in nonsip_msg_run_hooks (msg=0x7f5153876780) at
core/nonsip_hooks.c:112
r = 0
ret = 0
#10 0x0000557bae5d6720 in receive_msg (buf=0x557bb08fee80 "POST /RPC
HTTP/1.1\r\nHost: X.X.X.X:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len=151, rcv_info=0x7f512fe42828)
at core/receive.c:348
msg = 0x7f5153876780
ctx = {rec_lev = 4, run_flags = 0, last_retcode = 803482386, jmp_env = {{__jmpbuf
= {8, 65536, 27, 0, 140734218751644, 139986672560144, 7, 70364449210396}, __mask_was_saved
= 121, __saved_mask = {__val = {10030241455286650880, 65535, 139986672560144,
93989696924131, 536870912, 12582912, 6, 140734218751232,
93989695295308, 519691042940, 2, 0, 65535, 140734218751644, 139986672560144,
18446744073709551536}}}}}
bctx = 0x7fff3d1dcc10
ret = 0
tvb = {tv_sec = 140734218751644, tv_usec = 139986672560904}
tve = {tv_sec = 139986672560144, tv_usec = 139986672560144}
tz = {tz_minuteswest = -1369026089, tz_dsttime = 21883}
diff = 0
inb = {s = 0x557bb08fee80 "POST /RPC HTTP/1.1\r\nHost:
X.X.X.X:6060\r\nAccept: */*\r\nContent-type: application/json\r\nContent-length:
38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len = 151}
netinfo = {data = {s = 0x1400020001 <error: Cannot access memory at address
0x1400020001>, len = 803482376}, rcv = 0x4, dst = 0x7f512fe42b0d}
keng = 0x0
evp = {data = 0x7fff3d1dcb30, rcv = 0x7f512fe42828, dst = 0x0}
cidlockidx = 0
cidlockset = 0
errsipmsg = 0
exectime = 0
__func__ = "receive_msg"
#11 0x0000557bae670357 in receive_tcp_msg (tcpbuf=0x7f512fe42b08 "POST /RPC
HTTP/1.1\r\nHost: X.X.X.X:6060\r\nAccept: */*\r\nContent-type:
application/json\r\nContent-length: 38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}", len=151, rcv_info=0x7f512fe42828,
con=0x7f512fe42810) at core/tcp_read.c:1448
buf = 0x557bb08fee80 "POST /RPC HTTP/1.1\r\nHost: X.X.X.X:6060\r\nAccept:
*/*\r\nContent-type: application/json\r\nContent-length:
38\r\n\r\n{\"jsonrpc\":\"2.0\",
\"method\":\"tm.clean\"}"
bsize = 65535
blen = 65535
__func__ = "receive_tcp_msg"
#12 0x0000557bae6725f3 in tcp_read_req (con=0x7f512fe42810, bytes_read=0x7fff3d1dce98,
read_flags=0x7fff3d1dce9c) at core/tcp_read.c:1631
bytes = 151
total_bytes = 151
resp = 1
size = 24
req = 0x7f512fe42890
dst = {send_sock = 0x0, to = {s = {sa_family = 61136, sa_data =
"\342/Q\177\000\000\330\316\035=\377\177\000"}, sin = {sin_family = 61136,
sin_port = 12258, sin_addr = {s_addr = 32593}, sin_zero =
"\330\316\035=\377\177\000"}, sin6 = {sin6_family = 61136,
sin6_port = 12258, sin6_flowinfo = 32593, sin6_addr = {__in6_u =
{__u6_addr8 = "\330\316\035=\377\177\000\000\b\000\000\000\000\000\000",
__u6_addr16 = {52952, 15645, 32767, 0, 8, 0, 0, 0}, __u6_addr32 = {1025363672, 32767, 8,
0}}}, sin6_scope_id = 20}},
id = 0, send_flags = {f = 1, blst_imask = 0}, proto = 1 '\001',
proto_pad0 = 0 '\000', proto_pad1 = 0}
--Type <RET> for more, q to quit, c to continue without paging--
c = 49 '1'
ret = 1025363424
__func__ = "tcp_read_req"
#13 0x0000557bae6755a2 in handle_io (fm=0x7f5152db1498, events=1, idx=-1) at
core/tcp_read.c:1804
ret = 8
n = 8
read_flags = 1
con = 0x7f512fe42810
s = 28
resp = -2
t = 1117018954
__func__ = "handle_io"
#14 0x0000557bae662ba9 in io_wait_loop_epoll (h=0x557bae90ad00 <io_w>, t=2,
repeat=0) at core/io_wait.h:1062
n = 1
r = 0
fm = 0x7f5152db1498
revents = 1
__func__ = "io_wait_loop_epoll"
#15 0x0000557bae6775f5 in tcp_receive_loop (unix_sock=59) at core/tcp_read.c:1974
__func__ = "tcp_receive_loop"
#16 0x0000557bae51044a in tcp_init_children () at core/tcp_main.c:5174
r = 8
i = 7
reader_fd_1 = 59
pid = 0
si_desc = "tcp receiver
(tcp:X.X.X.X:6060)\000\000\000\062\023\000\000\001", '\000' <repeats 11
times>, "\260\034\246SQ\177\000\000\343i\177\256{U\000\000\000\000\000
\000\000\000\000\000\000\300\000\000\000\000\000\006\000\000\000\000\000\000\000
\321\035=\377\177\000\000\\8V\256{U\000\000
\321\035=\377\177\000\000\254\204a\256\000\000\000"
si = 0x0
__func__ = "tcp_init_children"
#17 0x0000557bae4228ce in main_loop () at main.c:1761
i = 8
pid = 4910
si = 0x0
si_desc = "udp receiver child=7
sock=127.0.0.1:5070\000\060\066\060\000\000\000\000\020\322\035=\377\177\000\000\000\b\302\tv\223\062\213\004\000\000\000\000\000\000\000\260\034\246SQ\177\000\000\343i\177\256{U\000\000\000\000\000
\000\000\000\000\000\000\300\000\000\000\000\000\006\000\000\000\000\000\000\000P\322\035=\377\177\000\000>0d\256{U\000"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#18 0x0000557bae42abb9 in main (argc=17, argv=0x7fff3d1dd738) at main.c:2802
cfg_stream = 0x557bb0796260
c = -1
r = 0
tmp = 0x7fff3d1def3f ""
tmp_len = 17
port = 0
proto = 1025365816
ahost = 0x0
aport = 0
options = 0x557bae7a0618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1972091384
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583307292,
tv_nsec = 782512911}, st_ctim = {tv_sec = 1583307633, tv_nsec = 722908545},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060G\272SQ\177\000\000\000\000\000\000\000\000\000\000\240q\037=\377\177\000\000\364J\270SQ\177\000\000\b\000\000\000\000\000\000\000\230r\037=\377\177\000\000\060G\272SQ\177\000\000\330\324\035=\377\177\000\000\324\324\035=\377\177",
'\000' <repeats 18 times>,
"\230r\037=\377\177\000\000\250q\037=\377\177\000\000'\356\256SQ\177\000\000&\260be\000\000\000\000@\326\035=\377\177\000\000\300\212\225\001\000\000\000\000\240\325\035=\377\177\000\000\220\325\035=\377\177\000\000\330\324\035=\377\177\000\000XG\272SQ\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x557bae7a2fca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x557bae79d438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x557bae7a2fcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x557bae7a2fd5 "subst",
has_arg = 1, flag = 0x0, val = 1025}, {name = 0x557bae7a2fdb
"substdef", has_arg = 1, flag = 0x0, val = 1026}, {name = 0x557bae7a2fe4
"substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name = 0x557bae7a2fee
"server-id", has_arg = 1, flag = 0x0, val = 1028}, {
name = 0x0, has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
5 Mar
5 Mar
6:18 a.m.
Daniel-Constantin Mierla writes:
There was an unsafe list iteration - can you try
with:
-
https://github.com/kamailio/kamailio/commit/325a45e846faae3e5dfa333727d5fab…
If all ok, you can backport.
Thanks for the patch. The crash has only happened once, so it is not
easy to reproduce, and it is production a sip proxy running 5.3.
I'll backport to my own 5.3 copy.
-- Juha
10 Mar
10 Mar
4:41 a.m.
Daniel-Constantin Mierla writes:
If you can reproduce it, watch what the timer
processes do during that
time frame. Get the list of processes with 'kamctl ps', then when the
issue is exposed, grab the backtraces of all processes with:
kamctl trap
A file is created with the backtraces taken with gdb. Sent it over here
to analyze, if you cannot spot an issue there.
Two traps were taken more than 10 sec apart when the number of
transactions and shared memory usage started to grow. In both traps,
process PID: 6049 DSC: timer was in the exactly same state (below).
Looks like it is stuck in an acc to db operation. How long is such an
operation allowed to last before an error is generated and the timer
process becomes free to do something else?
acc module db_insert_mode has value 2 and there is 2 async_workers
(process numbers 6056 and 5057 below). db_mysql README does not mention
if it supports async insert.
-- Juha
---start 6049 -----------------------------------------------------
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30107e4 in __GI___poll (fds=0x7fff233831e8, nfds=1, timeout=2000) at
../sysdeps/unix/sysv/linux/poll.c:29
29 ../sysdeps/unix/sysv/linux/poll.c: No such file or directory.
#0 0x00007f7dc30107e4 in __GI___poll (fds=0x7fff233831e8, nfds=1, timeout=2000) at
../sysdeps/unix/sysv/linux/poll.c:29
resultvar = 18446744073709551100
sc_ret = <optimized out>
#1 0x00007f7dc2064efa in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#2 0x00007f7dc20652da in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#3 0x00007f7dc2071425 in mysql_get_parameters () from
/usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#4 0x00007f7dc2071626 in mysql_get_parameters () from
/usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#5 0x00007f7dc2067c1e in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#6 0x00007f7dc2068654 in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#7 0x00007f7dc206d4ed in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#8 0x00007f7dc2070513 in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#9 0x00007f7dc206f230 in mysql_ping () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#10 0x00007f7dc20bbaba in db_mysql_submit_query (_h=0x7f7dc237f3a0, _s=0x7f7dc210e1e0
<sql_str>) at km_dbase.c:83
t = 1583739979
i = 0
code = 21923
__func__ = "db_mysql_submit_query"
#11 0x00007f7dc20fb35e in db_do_submit_query (_h=0x7f7dc237f3a0, _query=0x7f7dc210e1e0
<sql_str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>) at
db_query.c:58
ret = -1039426148
tvb = {tv_sec = 94160937318932, tv_usec = 140178106086304}
tve = {tv_sec = 200798118576, tv_usec = 1782411427864}
tz = {tz_minuteswest = 24, tz_dsttime = 65147}
tdiff = 32637
__func__ = "db_do_submit_query"
#12 0x00007f7dc20fdd29 in db_do_insert_cmd (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24, val2str=0x7f7dc20b9d9c
<db_mysql_val2str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>,
mode=0) at db_query.c:243
off = 804
ret = 415
__func__ = "db_do_insert_cmd"
#13 0x00007f7dc20fe396 in db_do_insert (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24, val2str=0x7f7dc20b9d9c
<db_mysql_val2str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>) at
db_query.c:258
No locals.
#14 0x00007f7dc20c08a4 in db_mysql_insert (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24) at km_dbase.c:493
No locals.
#15 0x00007f7dc07342a0 in db_cluster_insert (_h=0x7f7dc29bb650, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24) at dbcl_api.c:379
ret = -1
i = 5
k = 32637
sec = 36091306
rc = 0
rok = 0
j = 0
dbh = 0x7f7dc237f3a0
cls = 0x7f7dc239b980
__func__ = "db_cluster_insert"
#16 0x00007f7dc04c18a0 in acc_db_request (rq=0x7f7d9e36d540) at acc.c:476
m = 24
n = -1640573632
i = 24
o = 17
t = 0x7f7d9e36e668
dtime = -4.6749039984044258e+154
__func__ = "acc_db_request"
#17 0x00007f7dc04d4aca in acc_onreply (t=0x7f7d9e3b0650, req=0x7f7d9e357650,
reply=0xffffffffffffffff, code=408) at acc_logic.c:604
new_uri_bk = {s = 0x7f7d9e36dc40
"sip:xxx@x.x.x.x:5060;transport=udp203.29INVITE sip:xxx@xxx.xxx
SIP/2.0\r\nRecord-Route: <sip:x.x.x.x;lr;did=851.8452>\r\nVia: SIP/2.0/UDP
x.x.x.x;branch"..., len = 50}
br = 0
hdr = 0x7f7dc15f3c0f <msg_send_buffer+17006>
cmsg = 0x7f7d9e36d540
cmsg_len = 6968
preq = 0x7f7d9e36d540
mstart = 0x7f7d9e36d540
mend = 0x7f7d9e36f078
__func__ = "acc_onreply"
#18 0x00007f7dc04d5783 in tmcb_func (t=0x7f7d9e3b0650, type=512, ps=0x7fff23383a50) at
acc_logic.c:684
__func__ = "tmcb_func"
#19 0x00007f7dc15fff4d in run_trans_callbacks_internal (cb_lst=0x7f7d9e3b06c8, type=512,
trans=0x7f7d9e3b0650, params=0x7fff23383a50) at t_hooks.c:254
cbp = 0x7f7d9e339720
backup_from = 0x55a38cc8dc90 <def_list+16>
backup_to = 0x55a38cc8dc98 <def_list+24>
backup_dom_from = 0x55a38cc8dca0 <def_list+32>
backup_dom_to = 0x55a38cc8dca8 <def_list+40>
backup_uri_from = 0x55a38cc8dc80 <def_list>
backup_uri_to = 0x55a38cc8dc88 <def_list+8>
backup_xavps = 0x55a38cce95c0 <_xavp_list_head>
__func__ = "run_trans_callbacks_internal"
#20 0x00007f7dc1600180 in run_trans_callbacks_with_buf (type=512, rbuf=0x7f7d9e3b0720,
req=0x7f7d9e357650, repl=0xffffffffffffffff, flags=0) at t_hooks.c:297
params = {req = 0x7f7d9e357650, rpl = 0xffffffffffffffff, param = 0x7f7d9e339730,
code = 408, flags = 0, branch = 0, t_rbuf = 0x7f7d9e3b0720, dst = 0x7f7d9e3b0770, send_buf
= {s = 0x7f7d9e3cf530 "SIP/2.0 408 Request Timeout\r\nVia: SIP/2.0/UDP
x.x.x.x;branch=z9hG4bKf819.22eaf74987b5f436d71e6e7ac8c4d607.0\r\nVia: SIP/2.0/UDP
x.x.x.x:5060;rport=5060;branch=z9hG4bKac410218704\r\nFrom: \"xxx"..., len =
489}}
trans = 0x7f7d9e3b0650
#21 0x00007f7dc15b04f5 in relay_reply (t=0x7f7d9e3b0650, p_msg=0xffffffffffffffff,
branch=0, msg_status=408, cancel_data=0x7fff23383c30, do_put_on_wait=0) at t_reply.c:2021
relay = 0
save_clone = 0
buf = 0x7f7dc271d010 "SIP/2.0 408 Request Timeout\r\nVia: SIP/2.0/UDP
x.x.x.x;branch=z9hG4bKf819.22eaf74987b5f436d71e6e7ac8c4d607.0\r\nVia: SIP/2.0/UDP
x.x.x.x:5060;rport=5060;branch=z9hG4bKac410218704\r\nFrom: \"xxx"...
res_len = 489
relayed_code = 408
relayed_msg = 0xffffffffffffffff
reply_bak = 0x0
bm = {to_tag_val = {s = 0x7f7dc271d146
"f148edd50b878efc51a72f445b390303-e1110000\r\nCall-ID:
173781355593202084446(a)x.x.x.x\r\nCSeq: 1 INVITE\r\nServer: OpenSIPg SIP Proxy (5.3.2-6
(x86_64/linux))\r\nContent-Length: 0\r\n\r\n", len = 41}}
totag_retr = 0
reply_status = RPS_COMPLETED
uas_rb = 0x7f7d9e3b0720
to_tag = 0x7f7dc1677750 <tm_tag>
reason = {s = 0x55a38cb96cc4 "Request Timeout", len = 15}
onsend_params = {req = 0x0, rpl = 0x0, param = 0x0, code = 0, flags = 0, branch =
0, t_rbuf = 0x0, dst = 0x0, send_buf = {s = 0x7fff23383bc0 "\220<8#\377\177",
len = -1}}
ip = {af = 0, len = 0, u = {addrl = {xxx, xxx}, addr32 = {xxx, xxx, xxx, xxx},
addr16 = {xxx, xxx, xxx, xxx, xxx, xxx, xxx, 0}, addr = "xxx"}}
__func__ = "relay_reply"
#22 0x00007f7dc15ec23d in fake_reply (t=0x7f7d9e3b0650, branch=0, code=408) at
timer.c:295
cancel_data = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len =
-1640298928}, e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = -1640298928}}}}
do_cancel_branch = 1
reply_status = 32637
#23 0x00007f7dc15ec6dd in final_response_handler (r_buf=0x7f7d9e3b0878, t=0x7f7d9e3b0650)
at timer.c:455
silent = 0
branch_ret = 12582912
prev_branch = 0
now = 0
#24 0x00007f7dc15ec78f in retr_buf_handler (ticks=577460907, tl=0x7f7d9e3b0898, p=0x3e8)
at timer.c:511
rbuf = 0x7f7d9e3b0878
fr_remainder = 0
retr_remainder = 0
retr_interval = 0
new_retr_interval_ms = 0
crt_retr_interval_ms = 140177493637904
t = 0x7f7d9e3b0650
__func__ = "retr_buf_handler"
#25 0x000055a38c85794f in timer_list_expire (t=577460907, h=0x7f7d9dbafb70,
slow_l=0x7f7d9dbb0330, slow_mark=48237) at core/timer.c:857
tl = 0x7f7d9e3b0898
ret = 0
#26 0x000055a38c857df7 in timer_handler () at core/timer.c:922
saved_ticks = 577460907
run_slow_timer = 0
i = 109
__func__ = "timer_handler"
#27 0x000055a38c8582c0 in timer_main () at core/timer.c:961
No locals.
#28 0x000055a38c7bc306 in main_loop () at main.c:1743
i = 8
pid = 0
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#29 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6049) detached]
---end 6049 -------------------------------------------------------
---start 6056 -----------------------------------------------------
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
27 ../sysdeps/unix/sysv/linux/recvfrom.c: No such file or directory.
#0 0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
resultvar = 18446744073709551104
sc_ret = <optimized out>
#1 0x000055a38c986b74 in async_task_run (idx=1) at core/async_task.c:269
ptask = 0x2200000021
received = 1060615238
__func__ = "async_task_run"
#2 0x000055a38c9859a8 in async_task_child_init (rank=0) at core/async_task.c:185
pid = 0
i = 0
__func__ = "async_task_child_init"
#3 0x000055a38c8fd83d in init_child (rank=0) at core/sr_module.c:822
ret = 32
type = 0x55a38cb7d6cb "PROC_MAIN"
__func__ = "init_child"
#4 0x000055a38c7bc5e8 in main_loop () at main.c:1753
i = 8
pid = 6049
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#5 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6056) detached]
---end 6056 -------------------------------------------------------
---start 6057 -----------------------------------------------------
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
27 ../sysdeps/unix/sysv/linux/recvfrom.c: No such file or directory.
#0 0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
resultvar = 18446744073709551104
sc_ret = <optimized out>
#1 0x000055a38c986b74 in async_task_run (idx=2) at core/async_task.c:269
ptask = 0x2300000022
received = 1497148970
__func__ = "async_task_run"
#2 0x000055a38c9859a8 in async_task_child_init (rank=0) at core/async_task.c:185
pid = 0
i = 1
__func__ = "async_task_child_init"
#3 0x000055a38c8fd83d in init_child (rank=0) at core/sr_module.c:822
ret = 32
type = 0x55a38cb7d6cb "PROC_MAIN"
__func__ = "init_child"
#4 0x000055a38c7bc5e8 in main_loop () at main.c:1753
i = 8
pid = 6049
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#5 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6057) detached]
---end 6057 -------------------------------------------------------
8:33 a.m.
The process is stuck in mysql client library.
The async insert is not implemented in the db_cluster module, so at this
moment, if you want it, you have to use acc directly with db_mysql module.
Cheers,
Daniel
On 10.03.20 04:41, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio Advanced Training - March 9-11, 2020, Berlin - www.asipto.com
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
If you can reproduce it, watch what the timer
processes do during that
time frame. Get the list of processes with 'kamctl ps', then when the
issue is exposed, grab the backtraces of all processes with:
kamctl trap
A file is created with the backtraces taken with gdb. Sent it over here
to analyze, if you cannot spot an issue there.
Two traps were taken more than 10
sec apart when the number of
transactions and shared memory usage started to grow. In both traps,
process PID: 6049 DSC: timer was in the exactly same state (below).
Looks like it is stuck in an acc to db operation. How long is such an
operation allowed to last before an error is generated and the timer
process becomes free to do something else?
acc module db_insert_mode has value 2 and there is 2 async_workers
(process numbers 6056 and 5057 below). db_mysql README does not mention
if it supports async insert.
-- Juha
---start 6049 -----------------------------------------------------
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30107e4 in __GI___poll (fds=0x7fff233831e8, nfds=1, timeout=2000) at
../sysdeps/unix/sysv/linux/poll.c:29
29 ../sysdeps/unix/sysv/linux/poll.c: No such file or directory.
#0 0x00007f7dc30107e4 in __GI___poll (fds=0x7fff233831e8, nfds=1, timeout=2000) at
../sysdeps/unix/sysv/linux/poll.c:29
resultvar = 18446744073709551100
sc_ret = <optimized out>
#1 0x00007f7dc2064efa in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#2 0x00007f7dc20652da in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#3 0x00007f7dc2071425 in mysql_get_parameters () from
/usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#4 0x00007f7dc2071626 in mysql_get_parameters () from
/usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#5 0x00007f7dc2067c1e in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#6 0x00007f7dc2068654 in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#7 0x00007f7dc206d4ed in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#8 0x00007f7dc2070513 in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#9 0x00007f7dc206f230 in mysql_ping () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#10 0x00007f7dc20bbaba in db_mysql_submit_query (_h=0x7f7dc237f3a0, _s=0x7f7dc210e1e0
<sql_str>) at km_dbase.c:83
t = 1583739979
i = 0
code = 21923
__func__ = "db_mysql_submit_query"
#11 0x00007f7dc20fb35e in db_do_submit_query (_h=0x7f7dc237f3a0, _query=0x7f7dc210e1e0
<sql_str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>) at
db_query.c:58
ret = -1039426148
tvb = {tv_sec = 94160937318932, tv_usec = 140178106086304}
tve = {tv_sec = 200798118576, tv_usec = 1782411427864}
tz = {tz_minuteswest = 24, tz_dsttime = 65147}
tdiff = 32637
__func__ = "db_do_submit_query"
#12 0x00007f7dc20fdd29 in db_do_insert_cmd (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24, val2str=0x7f7dc20b9d9c
<db_mysql_val2str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>,
mode=0) at db_query.c:243
off = 804
ret = 415
__func__ = "db_do_insert_cmd"
#13 0x00007f7dc20fe396 in db_do_insert (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24, val2str=0x7f7dc20b9d9c
<db_mysql_val2str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>) at
db_query.c:258
No locals.
#14 0x00007f7dc20c08a4 in db_mysql_insert (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24) at km_dbase.c:493
No locals.
#15 0x00007f7dc07342a0 in db_cluster_insert (_h=0x7f7dc29bb650, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24) at dbcl_api.c:379
ret = -1
i = 5
k = 32637
sec = 36091306
rc = 0
rok = 0
j = 0
dbh = 0x7f7dc237f3a0
cls = 0x7f7dc239b980
__func__ = "db_cluster_insert"
#16 0x00007f7dc04c18a0 in acc_db_request (rq=0x7f7d9e36d540) at acc.c:476
m = 24
n = -1640573632
i = 24
o = 17
t = 0x7f7d9e36e668
dtime = -4.6749039984044258e+154
__func__ = "acc_db_request"
#17 0x00007f7dc04d4aca in acc_onreply (t=0x7f7d9e3b0650, req=0x7f7d9e357650,
reply=0xffffffffffffffff, code=408) at acc_logic.c:604
new_uri_bk = {s = 0x7f7d9e36dc40
"sip:xxx@x.x.x.x:5060;transport=udp203.29INVITE sip:xxx@xxx.xxx
SIP/2.0\r\nRecord-Route: <sip:x.x.x.x;lr;did=851.8452>\r\nVia: SIP/2.0/UDP
x.x.x.x;branch"..., len = 50}
br = 0
hdr = 0x7f7dc15f3c0f <msg_send_buffer+17006>
cmsg = 0x7f7d9e36d540
cmsg_len = 6968
preq = 0x7f7d9e36d540
mstart = 0x7f7d9e36d540
mend = 0x7f7d9e36f078
__func__ = "acc_onreply"
#18 0x00007f7dc04d5783 in tmcb_func (t=0x7f7d9e3b0650, type=512, ps=0x7fff23383a50) at
acc_logic.c:684
__func__ = "tmcb_func"
#19 0x00007f7dc15fff4d in run_trans_callbacks_internal (cb_lst=0x7f7d9e3b06c8, type=512,
trans=0x7f7d9e3b0650, params=0x7fff23383a50) at t_hooks.c:254
cbp = 0x7f7d9e339720
backup_from = 0x55a38cc8dc90 <def_list+16>
backup_to = 0x55a38cc8dc98 <def_list+24>
backup_dom_from = 0x55a38cc8dca0 <def_list+32>
backup_dom_to = 0x55a38cc8dca8 <def_list+40>
backup_uri_from = 0x55a38cc8dc80 <def_list>
backup_uri_to = 0x55a38cc8dc88 <def_list+8>
backup_xavps = 0x55a38cce95c0 <_xavp_list_head>
__func__ = "run_trans_callbacks_internal"
#20 0x00007f7dc1600180 in run_trans_callbacks_with_buf (type=512, rbuf=0x7f7d9e3b0720,
req=0x7f7d9e357650, repl=0xffffffffffffffff, flags=0) at t_hooks.c:297
params = {req = 0x7f7d9e357650, rpl = 0xffffffffffffffff, param = 0x7f7d9e339730,
code = 408, flags = 0, branch = 0, t_rbuf = 0x7f7d9e3b0720, dst = 0x7f7d9e3b0770, send_buf
= {s = 0x7f7d9e3cf530 "SIP/2.0 408 Request Timeout\r\nVia: SIP/2.0/UDP
x.x.x.x;branch=z9hG4bKf819.22eaf74987b5f436d71e6e7ac8c4d607.0\r\nVia: SIP/2.0/UDP
x.x.x.x:5060;rport=5060;branch=z9hG4bKac410218704\r\nFrom: \"xxx"..., len =
489}}
trans = 0x7f7d9e3b0650
#21 0x00007f7dc15b04f5 in relay_reply (t=0x7f7d9e3b0650, p_msg=0xffffffffffffffff,
branch=0, msg_status=408, cancel_data=0x7fff23383c30, do_put_on_wait=0) at t_reply.c:2021
relay = 0
save_clone = 0
buf = 0x7f7dc271d010 "SIP/2.0 408 Request Timeout\r\nVia: SIP/2.0/UDP
x.x.x.x;branch=z9hG4bKf819.22eaf74987b5f436d71e6e7ac8c4d607.0\r\nVia: SIP/2.0/UDP
x.x.x.x:5060;rport=5060;branch=z9hG4bKac410218704\r\nFrom: \"xxx"...
res_len = 489
relayed_code = 408
relayed_msg = 0xffffffffffffffff
reply_bak = 0x0
bm = {to_tag_val = {s = 0x7f7dc271d146
"f148edd50b878efc51a72f445b390303-e1110000\r\nCall-ID:
173781355593202084446(a)x.x.x.x\r\nCSeq: 1 INVITE\r\nServer: OpenSIPg SIP Proxy (5.3.2-6
(x86_64/linux))\r\nContent-Length: 0\r\n\r\n", len = 41}}
totag_retr = 0
reply_status = RPS_COMPLETED
uas_rb = 0x7f7d9e3b0720
to_tag = 0x7f7dc1677750 <tm_tag>
reason = {s = 0x55a38cb96cc4 "Request Timeout", len = 15}
onsend_params = {req = 0x0, rpl = 0x0, param = 0x0, code = 0, flags = 0, branch =
0, t_rbuf = 0x0, dst = 0x0, send_buf = {s = 0x7fff23383bc0 "\220<8#\377\177",
len = -1}}
ip = {af = 0, len = 0, u = {addrl = {xxx, xxx}, addr32 = {xxx, xxx, xxx, xxx},
addr16 = {xxx, xxx, xxx, xxx, xxx, xxx, xxx, 0}, addr = "xxx"}}
__func__ = "relay_reply"
#22 0x00007f7dc15ec23d in fake_reply (t=0x7f7d9e3b0650, branch=0, code=408) at
timer.c:295
cancel_data = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len
= -1640298928}, e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = -1640298928}}}}
do_cancel_branch = 1
reply_status = 32637
#23 0x00007f7dc15ec6dd in final_response_handler (r_buf=0x7f7d9e3b0878, t=0x7f7d9e3b0650)
at timer.c:455
silent = 0
branch_ret = 12582912
prev_branch = 0
now = 0
#24 0x00007f7dc15ec78f in retr_buf_handler (ticks=577460907, tl=0x7f7d9e3b0898, p=0x3e8)
at timer.c:511
rbuf = 0x7f7d9e3b0878
fr_remainder = 0
retr_remainder = 0
retr_interval = 0
new_retr_interval_ms = 0
crt_retr_interval_ms = 140177493637904
t = 0x7f7d9e3b0650
__func__ = "retr_buf_handler"
#25 0x000055a38c85794f in timer_list_expire (t=577460907, h=0x7f7d9dbafb70,
slow_l=0x7f7d9dbb0330, slow_mark=48237) at core/timer.c:857
tl = 0x7f7d9e3b0898
ret = 0
#26 0x000055a38c857df7 in timer_handler () at core/timer.c:922
saved_ticks = 577460907
run_slow_timer = 0
i = 109
__func__ = "timer_handler"
#27 0x000055a38c8582c0 in timer_main () at core/timer.c:961
No locals.
#28 0x000055a38c7bc306 in main_loop () at main.c:1743
i = 8
pid = 0
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#29 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6049) detached]
---end 6049 -------------------------------------------------------
---start 6056 -----------------------------------------------------
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
27 ../sysdeps/unix/sysv/linux/recvfrom.c: No such file or directory.
#0 0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
resultvar = 18446744073709551104
sc_ret = <optimized out>
#1 0x000055a38c986b74 in async_task_run (idx=1) at core/async_task.c:269
ptask = 0x2200000021
received = 1060615238
__func__ = "async_task_run"
#2 0x000055a38c9859a8 in async_task_child_init (rank=0) at core/async_task.c:185
pid = 0
i = 0
__func__ = "async_task_child_init"
#3 0x000055a38c8fd83d in init_child (rank=0) at core/sr_module.c:822
ret = 32
type = 0x55a38cb7d6cb "PROC_MAIN"
__func__ = "init_child"
#4 0x000055a38c7bc5e8 in main_loop () at main.c:1753
i = 8
pid = 6049
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#5 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6056) detached]
---end 6056 -------------------------------------------------------
---start 6057 -----------------------------------------------------
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
27 ../sysdeps/unix/sysv/linux/recvfrom.c: No such file or directory.
#0 0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
resultvar = 18446744073709551104
sc_ret = <optimized out>
#1 0x000055a38c986b74 in async_task_run (idx=2) at core/async_task.c:269
ptask = 0x2300000022
received = 1497148970
__func__ = "async_task_run"
#2 0x000055a38c9859a8 in async_task_child_init (rank=0) at core/async_task.c:185
pid = 0
i = 1
__func__ = "async_task_child_init"
#3 0x000055a38c8fd83d in init_child (rank=0) at core/sr_module.c:822
ret = 32
type = 0x55a38cb7d6cb "PROC_MAIN"
__func__ = "init_child"
#4 0x000055a38c7bc5e8 in main_loop () at main.c:1753
i = 8
pid = 6049
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#5 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6057) detached]
---end 6057 -------------------------------------------------------
8:07 p.m.
Daniel-Constantin Mierla writes:
The process is stuck in mysql client library.
The async insert is not implemented in the db_cluster module, so at this
moment, if you want it, you have to use acc directly with db_mysql
module.
Then how is it possible that most of the time accounting using async
inserts works and get stuck only once in awhile?
And would it be possible to detect that async inserts are trying to be
used when K is started and make the start to fail?
Maybe also some text about that in db_cluster module README would be
useful.
-- Juha
8:23 p.m.
On 10.03.20 20:07, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
There is no async-insert done by acc with db_cluster, it is always
standard (sync) insert. You would have to track why the mysql server (or
the client library) is blocking from time to time, I don't think it is
something that kamailio can do.
The process is stuck in mysql client library.
The async insert is not implemented in the db_cluster module, so at this
moment, if you want it, you have to use acc directly with db_mysql
module.
Then how is it possible that most of the time accounting using async
inserts works and get stuck only once in awhile?
And would it be possible to detect that async inserts are trying to be
used when K is started and make the start to fail?
The fallback from async-insert to standard-insert is an acc option:
*
https://www.kamailio.org/docs/modules/stable/modules/acc.html#acc.p.db_inse…
You can add a new option to db_insert_mode to fail if async-insert is
not supported by the db connector.
Maybe also some text about that in db_cluster module README would be
useful.
The db_cluster readme is listing the operations it can do for write-to
and read-from database:
*
https://www.kamailio.org/docs/modules/stable/modules/db_cluster.html#idm20
You can enhance the docs as you can consider more useful and clear.
Otherwise, I just pushed to master branch a commit implementing
async-insert for db_cluster module, with fallback to standard insert.
Testing and reporting back the results would be appreciated if you plan
to use it in the near future. Also, if you need, you can add a mod param
to have an option not to fallback to standard insert/check async-insert
option at start up.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
8:30 p.m.
Daniel-Constantin Mierla writes:
There is no async-insert done by acc with db_cluster,
it is always
standard (sync) insert. You would have to track why the mysql server (or
the client library) is blocking from time to time, I don't think it is
something that kamailio can do.
OK, thanks for the explanation.
One more question: why is the timer process involved with this acc
insert? Isn't accounting done by the normal worker processes that
handle requests/responses?
-- Juha
10:54 p.m.
Regarding db_mysql timeout_interval, it has its default value 2, which
means 6 seconds. The insert was hanging in the timer process much
longer and no error messages related to abort appear in syslog. How is
that possible?
-- Juha
11 Mar
11 Mar
8:30 a.m.
On 10.03.20 22:54, Juha Heinanen wrote:
Regarding db_mysql timeout_interval, it has its
default value 2, which
means 6 seconds. The insert was hanging in the timer process much
longer and no error messages related to abort appear in syslog. How is
that possible?
I can't say why it happens, but, iirc, in some versions of mysql client
library docs is written that the timeout may fail in various cases.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
8:44 a.m.
Hello,
this could be one cause, and another - the timeout is in the end for every request. So, if
you have a loaded sever with several requests waiting to be written to the server it will
wait for each of of them, I think. (It has been some time that I personally tested this
functionality.)
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/
Kamailio services – https://gilawa.com
-----Original Message-----
From: sr-users <sr-users-bounces(a)lists.kamailio.org> On Behalf Of Daniel-Constantin
Mierla
Sent: Wednesday, March 11, 2020 8:30 AM
To: Juha Heinanen <jh(a)tutpro.com>om>; Kamailio (SER) - Users Mailing List
<sr-users(a)lists.kamailio.org>
Subject: Re: [SR-Users] out of shm without any visible reason
On 10.03.20 22:54, Juha Heinanen wrote:
Regarding db_mysql timeout_interval, it has its
default value 2, which
means 6 seconds. The insert was hanging in the timer process much
longer and no error messages related to abort appear in syslog. How
is that possible?
I can't say why it happens, but, iirc, in some versions of mysql client library docs
is written that the timeout may fail in various cases.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com www.twitter.com/miconda --
www.linkedin.com/in/miconda Kamailio World Conference - April 27-29, 2020, in Berlin --
www.kamailioworld.com
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
8:27 a.m.
On 10.03.20 20:30, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
It seems to be the case of a retransmission timeout:
#17 0x00007f7dc04d4aca in acc_onreply (t=0x7f7d9e3b0650, req=0x7f7d9e357650,
reply=0xffffffffffffffff, code=408) at acc_logic.c:604
Code is 408 and the reply is faked value. This case is happening in
timer process.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
There is no async-insert done by acc with
db_cluster, it is always
standard (sync) insert. You would have to track why the mysql server (or
the client library) is blocking from time to time, I don't think it is
something that kamailio can do.
OK, thanks for the explanation.
One more question: why is the timer process involved with this acc
insert? Isn't accounting done by the normal worker processes that
handle requests/responses?
9:04 a.m.
Daniel-Constantin Mierla writes:
It seems to be the case of a retransmission timeout:
#17 0x00007f7dc04d4aca in acc_onreply (t=0x7f7d9e3b0650, req=0x7f7d9e357650,
reply=0xffffffffffffffff, code=408) at acc_logic.c:604
Code is 408 and the reply is faked value. This case is happening in
timer process.
That explains it. But isn't it risky that in this kind of situation
the timer process (the only one) handles the reply and accounting?
The problem is related to db_cluster/mariadb/debian. If db_cluster is
not used, everything works fine. With db_cluster, accounting hangs the
timer process at regular (about 2 hour) intervals.
-- Juha
12:16 p.m.
On 11.03.20 09:04, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
There are many
cases when delays can increase the risk of
malfunctioning, no matter is in timer module or a sip routing worker. If
that a process is blocked, slots on internal hash tables (e.g., user
location) can be locked and no other process can continue processing
until that process unlocks. Interaction with external systems such as
database, api servers, dns service ... are the typical candidates for
adding significant delay. For specific deployments, there are some
solutions to do as less as possible blocking operations, but it would be
probably impossible to do it everywhere when dealing with external
systems. Such example is even the async-insert added to db_mysql quite
some time ago, or mqueue+rtimer or async modules.
It seems to be the case of a retransmission
timeout:
#17 0x00007f7dc04d4aca in acc_onreply (t=0x7f7d9e3b0650, req=0x7f7d9e357650,
reply=0xffffffffffffffff, code=408) at acc_logic.c:604
Code is 408 and the reply is faked value. This case is happening in
timer process.
That explains it. But isn't it risky that in this kind of
situation
the timer process (the only one) handles the reply and accounting?
The problem is related to db_cluster/mariadb/debian. If db_cluster is
not used, everything works fine. With db_cluster, accounting hangs the
timer process at regular (about 2 hour) intervals.
If it happens periodically, maybe you can track why: try to identify
apps accessing the database for back up, cdr generation, etc ... as well
as infrastructure maintenance operations (vm backup snapshot).
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
8:12 p.m.
Daniel-Constantin Mierla writes:
If it happens periodically, maybe you can track why:
try to identify
apps accessing the database for back up, cdr generation, etc ... as well
as infrastructure maintenance operations (vm backup snapshot).
DB access works fine from K worker processes during the time when
insert is stuck in timer process.
-- Juha
12 Mar
12 Mar
8:38 a.m.
On 11.03.20 20:12, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
Are new records inserted in acc table? I think there are some
tools/commands for mysql to inspect the state a database table, check
acc table and missed_calls, if you also use this one.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
If it happens periodically, maybe you can track
why: try to identify
apps accessing the database for back up, cdr generation, etc ... as well
as infrastructure maintenance operations (vm backup snapshot).
DB access works
fine from K worker processes during the time when
insert is stuck in timer process.
9:09 a.m.
Daniel-Constantin Mierla writes:
Accounting records are inserted without problems from other calls to the
same accounting table where the timer process tries to insert its
record but hangs.
-- Juha
DB access
works fine from K worker processes during the time when
insert is stuck in timer process.
Are new records inserted in acc table? I think there are some
tools/commands for mysql to inspect the state a database table, check
acc table and missed_calls, if you also use this one.
10:53 a.m.
On 12.03.20 09:09, Juha Heinanen wrote:
Daniel-Constantin Mierla writes:
Accounting records are
inserted without problems from other calls to the
same accounting table where the timer process tries to insert its
record but hangs.
Try to install debugging symbols for libmariadb and maybe there will be
more hints in the backtace of what it does internally, which can improve
troubleshooting by searching on the web for similar cases.
And, as I said in previous email, try to investigate the status of mysql
server with specific commands and tools, if you can find any out there.
DB access
works fine from K worker processes during the time when
insert is stuck in timer process.
Are new records inserted in acc table? I think
there are some
tools/commands for mysql to inspect the state a database table, check
acc table and missed_calls, if you also use this one. From mysql client API, we set the query timeout
options.
Otherwise, I haven't encountered such a situation yet to have any other
hint to share specific for it.
Maybe you can try to use IP sockets for connecting to mysql server, if
the connection is done over unixsocket file. In some older versions, it
was mentioned that timeout options may not work if not on an IP connection.
What you can also try, is to change the database table type. What do you
have now, MyISAM, InnoDB or something else?
To know better the ecosystem, what is the operation system and
mysq/mariadb versions?
Cheers,
Daniel
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
9:05 p.m.
Daniel-Constantin Mierla writes:
Try to install debugging symbols for libmariadb and
maybe there will be
more hints in the backtace of what it does internally, which can improve
troubleshooting by searching on the web for similar cases.
I did that already earlier when I reported about similar issue, which
made K totally unresponsive for a long period of time. Nothing was
found from the backtrace.
What you can also try, is to change the database table
type. What do you
have now, MyISAM, InnoDB or something else?
DB type is InnoDB.
To know better the ecosystem, what is the operation
system and
mysq/mariadb versions?
Latest stable Debian 10 that comes with mariadb 10.3.
On the positive side, so far the issue has not appeared after I
backported your db_cluster async insert patch to 5.3. Perhaps there was
some issue in falling back to normal insert.
-- Juha
10 Mar
10 Mar
9:12 a.m.
Hi Juha,
about the timeout question regarding DB Operation - in case of MySQL it can be configured
(but still not that much helpful on loaded systems due to the seconds granularity)
https://kamailio.org/docs/modules/devel/modules/db_mysql.html#idm61
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/
Kamailio services – https://gilawa.com
-----Original Message-----
From: sr-users <sr-users-bounces(a)lists.kamailio.org> On Behalf Of Juha Heinanen
Sent: Tuesday, March 10, 2020 4:41 AM
To: miconda(a)gmail.com
Cc: Kamailio (SER) - Users Mailing List <sr-users(a)lists.kamailio.org>
Subject: Re: [SR-Users] out of shm without any visible reason
Daniel-Constantin Mierla writes:
If you can reproduce it, watch what the timer
processes do during that
time frame. Get the list of processes with 'kamctl ps', then when the
issue is exposed, grab the backtraces of all processes with:
kamctl trap
A file is created with the backtraces taken with gdb. Sent it over
here to analyze, if you cannot spot an issue there.
Two traps were taken more than 10 sec apart when the number of transactions and shared
memory usage started to grow. In both traps, process PID: 6049 DSC: timer was in the
exactly same state (below).
Looks like it is stuck in an acc to db operation. How long is such an operation allowed
to last before an error is generated and the timer process becomes free to do something
else?
acc module db_insert_mode has value 2 and there is 2 async_workers (process numbers 6056
and 5057 below). db_mysql README does not mention if it supports async insert.
-- Juha
---start 6049 -----------------------------------------------------
[Thread debugging using libthread_db enabled] Using host libthread_db library
"/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30107e4 in __GI___poll (fds=0x7fff233831e8, nfds=1, timeout=2000) at
../sysdeps/unix/sysv/linux/poll.c:29
29 ../sysdeps/unix/sysv/linux/poll.c: No such file or directory.
#0 0x00007f7dc30107e4 in __GI___poll (fds=0x7fff233831e8, nfds=1, timeout=2000) at
../sysdeps/unix/sysv/linux/poll.c:29
resultvar = 18446744073709551100
sc_ret = <optimized out>
#1 0x00007f7dc2064efa in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#2 0x00007f7dc20652da in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#3 0x00007f7dc2071425 in mysql_get_parameters () from
/usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#4 0x00007f7dc2071626 in mysql_get_parameters () from
/usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#5 0x00007f7dc2067c1e in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#6 0x00007f7dc2068654 in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#7 0x00007f7dc206d4ed in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#8 0x00007f7dc2070513 in ?? () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#9 0x00007f7dc206f230 in mysql_ping () from /usr/lib/x86_64-linux-gnu/libmariadb.so.3
No symbol table info available.
#10 0x00007f7dc20bbaba in db_mysql_submit_query (_h=0x7f7dc237f3a0, _s=0x7f7dc210e1e0
<sql_str>) at km_dbase.c:83
t = 1583739979
i = 0
code = 21923
__func__ = "db_mysql_submit_query"
#11 0x00007f7dc20fb35e in db_do_submit_query (_h=0x7f7dc237f3a0, _query=0x7f7dc210e1e0
<sql_str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>) at
db_query.c:58
ret = -1039426148
tvb = {tv_sec = 94160937318932, tv_usec = 140178106086304}
tve = {tv_sec = 200798118576, tv_usec = 1782411427864}
tz = {tz_minuteswest = 24, tz_dsttime = 65147}
tdiff = 32637
__func__ = "db_do_submit_query"
#12 0x00007f7dc20fdd29 in db_do_insert_cmd (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24, val2str=0x7f7dc20b9d9c
<db_mysql_val2str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>,
mode=0) at db_query.c:243
off = 804
ret = 415
__func__ = "db_do_insert_cmd"
#13 0x00007f7dc20fe396 in db_do_insert (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24, val2str=0x7f7dc20b9d9c
<db_mysql_val2str>, submit_query=0x7f7dc20bb71d <db_mysql_submit_query>) at
db_query.c:258 No locals.
#14 0x00007f7dc20c08a4 in db_mysql_insert (_h=0x7f7dc237f3a0, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24) at km_dbase.c:493 No locals.
#15 0x00007f7dc07342a0 in db_cluster_insert (_h=0x7f7dc29bb650, _k=0x7f7dc04f88a0
<db_keys>, _v=0x7f7dc04f8b80 <db_vals>, _n=24) at dbcl_api.c:379
ret = -1
i = 5
k = 32637
sec = 36091306
rc = 0
rok = 0
j = 0
dbh = 0x7f7dc237f3a0
cls = 0x7f7dc239b980
__func__ = "db_cluster_insert"
#16 0x00007f7dc04c18a0 in acc_db_request (rq=0x7f7d9e36d540) at acc.c:476
m = 24
n = -1640573632
i = 24
o = 17
t = 0x7f7d9e36e668
dtime = -4.6749039984044258e+154
__func__ = "acc_db_request"
#17 0x00007f7dc04d4aca in acc_onreply (t=0x7f7d9e3b0650, req=0x7f7d9e357650,
reply=0xffffffffffffffff, code=408) at acc_logic.c:604
new_uri_bk = {s = 0x7f7d9e36dc40
"sip:xxx@x.x.x.x:5060;transport=udp203.29INVITE sip:xxx@xxx.xxx
SIP/2.0\r\nRecord-Route: <sip:x.x.x.x;lr;did=851.8452>\r\nVia: SIP/2.0/UDP
x.x.x.x;branch"..., len = 50}
br = 0
hdr = 0x7f7dc15f3c0f <msg_send_buffer+17006>
cmsg = 0x7f7d9e36d540
cmsg_len = 6968
preq = 0x7f7d9e36d540
mstart = 0x7f7d9e36d540
mend = 0x7f7d9e36f078
__func__ = "acc_onreply"
#18 0x00007f7dc04d5783 in tmcb_func (t=0x7f7d9e3b0650, type=512, ps=0x7fff23383a50) at
acc_logic.c:684
__func__ = "tmcb_func"
#19 0x00007f7dc15fff4d in run_trans_callbacks_internal (cb_lst=0x7f7d9e3b06c8, type=512,
trans=0x7f7d9e3b0650, params=0x7fff23383a50) at t_hooks.c:254
cbp = 0x7f7d9e339720
backup_from = 0x55a38cc8dc90 <def_list+16>
backup_to = 0x55a38cc8dc98 <def_list+24>
backup_dom_from = 0x55a38cc8dca0 <def_list+32>
backup_dom_to = 0x55a38cc8dca8 <def_list+40>
backup_uri_from = 0x55a38cc8dc80 <def_list>
backup_uri_to = 0x55a38cc8dc88 <def_list+8>
backup_xavps = 0x55a38cce95c0 <_xavp_list_head>
__func__ = "run_trans_callbacks_internal"
#20 0x00007f7dc1600180 in run_trans_callbacks_with_buf (type=512, rbuf=0x7f7d9e3b0720,
req=0x7f7d9e357650, repl=0xffffffffffffffff, flags=0) at t_hooks.c:297
params = {req = 0x7f7d9e357650, rpl = 0xffffffffffffffff, param = 0x7f7d9e339730,
code = 408, flags = 0, branch = 0, t_rbuf = 0x7f7d9e3b0720, dst = 0x7f7d9e3b0770, send_buf
= {s = 0x7f7d9e3cf530 "SIP/2.0 408 Request Timeout\r\nVia: SIP/2.0/UDP
x.x.x.x;branch=z9hG4bKf819.22eaf74987b5f436d71e6e7ac8c4d607.0\r\nVia: SIP/2.0/UDP
x.x.x.x:5060;rport=5060;branch=z9hG4bKac410218704\r\nFrom: \"xxx"..., len =
489}}
trans = 0x7f7d9e3b0650
#21 0x00007f7dc15b04f5 in relay_reply (t=0x7f7d9e3b0650, p_msg=0xffffffffffffffff,
branch=0, msg_status=408, cancel_data=0x7fff23383c30, do_put_on_wait=0) at
t_reply.c:2021
relay = 0
save_clone = 0
buf = 0x7f7dc271d010 "SIP/2.0 408 Request Timeout\r\nVia: SIP/2.0/UDP
x.x.x.x;branch=z9hG4bKf819.22eaf74987b5f436d71e6e7ac8c4d607.0\r\nVia: SIP/2.0/UDP
x.x.x.x:5060;rport=5060;branch=z9hG4bKac410218704\r\nFrom: \"xxx"...
res_len = 489
relayed_code = 408
relayed_msg = 0xffffffffffffffff
reply_bak = 0x0
bm = {to_tag_val = {s = 0x7f7dc271d146
"f148edd50b878efc51a72f445b390303-e1110000\r\nCall-ID:
173781355593202084446(a)x.x.x.x\r\nCSeq: 1 INVITE\r\nServer: OpenSIPg SIP Proxy (5.3.2-6
(x86_64/linux))\r\nContent-Length: 0\r\n\r\n", len = 41}}
totag_retr = 0
reply_status = RPS_COMPLETED
uas_rb = 0x7f7d9e3b0720
to_tag = 0x7f7dc1677750 <tm_tag>
reason = {s = 0x55a38cb96cc4 "Request Timeout", len = 15}
onsend_params = {req = 0x0, rpl = 0x0, param = 0x0, code = 0, flags = 0, branch =
0, t_rbuf = 0x0, dst = 0x0, send_buf = {s = 0x7fff23383bc0 "\220<8#\377\177",
len = -1}}
ip = {af = 0, len = 0, u = {addrl = {xxx, xxx}, addr32 = {xxx, xxx, xxx, xxx},
addr16 = {xxx, xxx, xxx, xxx, xxx, xxx, xxx, 0}, addr = "xxx"}}
__func__ = "relay_reply"
#22 0x00007f7dc15ec23d in fake_reply (t=0x7f7d9e3b0650, branch=0, code=408) at
timer.c:295
cancel_data = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len =
-1640298928}, e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = -1640298928}}}}
do_cancel_branch = 1
reply_status = 32637
#23 0x00007f7dc15ec6dd in final_response_handler (r_buf=0x7f7d9e3b0878, t=0x7f7d9e3b0650)
at timer.c:455
silent = 0
branch_ret = 12582912
prev_branch = 0
now = 0
#24 0x00007f7dc15ec78f in retr_buf_handler (ticks=577460907, tl=0x7f7d9e3b0898, p=0x3e8)
at timer.c:511
rbuf = 0x7f7d9e3b0878
fr_remainder = 0
retr_remainder = 0
retr_interval = 0
new_retr_interval_ms = 0
crt_retr_interval_ms = 140177493637904
t = 0x7f7d9e3b0650
__func__ = "retr_buf_handler"
#25 0x000055a38c85794f in timer_list_expire (t=577460907, h=0x7f7d9dbafb70,
slow_l=0x7f7d9dbb0330, slow_mark=48237) at core/timer.c:857
tl = 0x7f7d9e3b0898
ret = 0
#26 0x000055a38c857df7 in timer_handler () at core/timer.c:922
saved_ticks = 577460907
run_slow_timer = 0
i = 109
__func__ = "timer_handler"
#27 0x000055a38c8582c0 in timer_main () at core/timer.c:961 No locals.
#28 0x000055a38c7bc306 in main_loop () at main.c:1743
i = 8
pid = 0
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#29 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6049) detached]
---end 6049 -------------------------------------------------------
---start 6056 -----------------------------------------------------
[Thread debugging using libthread_db enabled] Using host libthread_db library
"/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
27 ../sysdeps/unix/sysv/linux/recvfrom.c: No such file or directory.
#0 0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
resultvar = 18446744073709551104
sc_ret = <optimized out>
#1 0x000055a38c986b74 in async_task_run (idx=1) at core/async_task.c:269
ptask = 0x2200000021
received = 1060615238
__func__ = "async_task_run"
#2 0x000055a38c9859a8 in async_task_child_init (rank=0) at core/async_task.c:185
pid = 0
i = 0
__func__ = "async_task_child_init"
#3 0x000055a38c8fd83d in init_child (rank=0) at core/sr_module.c:822
ret = 32
type = 0x55a38cb7d6cb "PROC_MAIN"
__func__ = "init_child"
#4 0x000055a38c7bc5e8 in main_loop () at main.c:1753
i = 8
pid = 6049
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#5 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6056) detached]
---end 6056 -------------------------------------------------------
---start 6057 -----------------------------------------------------
[Thread debugging using libthread_db enabled] Using host libthread_db library
"/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
27 ../sysdeps/unix/sysv/linux/recvfrom.c: No such file or directory.
#0 0x00007f7dc30f4834 in __libc_recvfrom (fd=12, buf=0x7fff23383cd0, len=8, flags=0,
addr=..., addrlen=0x0) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
resultvar = 18446744073709551104
sc_ret = <optimized out>
#1 0x000055a38c986b74 in async_task_run (idx=2) at core/async_task.c:269
ptask = 0x2300000022
received = 1497148970
__func__ = "async_task_run"
#2 0x000055a38c9859a8 in async_task_child_init (rank=0) at core/async_task.c:185
pid = 0
i = 1
__func__ = "async_task_child_init"
#3 0x000055a38c8fd83d in init_child (rank=0) at core/sr_module.c:822
ret = 32
type = 0x55a38cb7d6cb "PROC_MAIN"
__func__ = "init_child"
#4 0x000055a38c7bc5e8 in main_loop () at main.c:1753
i = 8
pid = 6049
si = 0x0
si_desc = "udp receiver child=7 sock=xxx"
nrprocs = 8
woneinit = 1
__func__ = "main_loop"
#5 0x000055a38c7c4bb9 in main (argc=17, argv=0x7fff233843f8) at main.c:2802
cfg_stream = 0x55a38d35f260
c = -1
r = 0
tmp = 0x7fff23384f3f ""
tmp_len = 17
port = 0
proto = 590889976
ahost = 0x0
aport = 0
options = 0x55a38cb3a618
":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 1148589326
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x0
p = 0x0
st = {st_dev = 21, st_ino = 1930, st_nlink = 2, st_mode = 16832, st_uid = 109,
st_gid = 115, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0,
st_atim = {tv_sec = 1572122046, tv_nsec = 75984014}, st_mtim = {tv_sec = 1583490964,
tv_nsec = 420466802}, st_ctim = {tv_sec = 1583492513, tv_nsec = 260094288},
__glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\b\000\000\000\000\000\000\000\060\207\025\303}\177\000\000\000\000\000\000\000\000\000\000\240\221\070#\377\177\000\000\364\212\023\303}\177\000\000\b\000\000\000\000\000\000\000\230\222\070#\377\177\000\000\060\207\025\303}\177\000\000\230A8#\377\177\000\000\224A8#\377\177",
'\000' <repeats 18 times>,
"\230\222\070#\377\177\000\000\250\221\070#\377\177\000\000'.\n\303}\177\000\000&\260be\000\000\000\000\000C8#\377\177\000\000\300\212\225\001\000\000\000\000`B8#\377\177\000\000PB8#\377\177\000\000\230A8#\377\177\000\000X\207\025\303}\177\000\000\001",
'\000' <repeats 31 times>...
option_index = 0
long_options = {{name = 0x55a38cb3cfca "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x55a38cb37438 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x55a38cb3cfcf "alias", has_arg = 1, flag = 0x0, val = 1024},
{name = 0x55a38cb3cfd5 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name =
0x55a38cb3cfdb "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name =
0x55a38cb3cfe4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name =
0x55a38cb3cfee "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0,
has_arg = 0, flag = 0x0, val = 0}}
__func__ = "main"
[Inferior 1 (process 6057) detached]
---end 6057 -------------------------------------------------------
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
1514
days inactive
1527
days old
35 comments
5 participants
participants (5)
-
Daniel-Constantin Mierla -
Henning Westerholt -
Joel Serrano -
John Petrini -
Juha Heinanen