[kamailio/kamailio] Segmentation fault in rpc_mod_print function while shutting down server. (#2433)
10 Aug
2020
10 Aug
'20
9:42 a.m.
<!--
Kamailio Project uses GitHub Issues only for bugs in the code or feature requests. Please
use this template only for bug reports.
If you have questions about using Kamailio or related to its configuration file, ask on
sr-users mailing list:
* http://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
If you have questions about developing extensions to Kamailio or its existing C code, ask
on sr-dev mailing list:
* http://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
Please try to fill this template as much as possible for any issue. It helps the
developers to troubleshoot the issue.
If there is no content to be filled in a section, the entire section can be removed.
You can delete the comments from the template sections when filling.
You can delete next line and everything above before submitting (it is a comment).
-->
### Description
We have segfault in Kamailio v5.3.1 installed on Debain 9.x 64 bit occured while kamailio
was shutting down while our script tryed to get metric using kamcmd utility at the same
time.
### Troubleshooting
No troubleshooting was done, since it happened on a production server. We simply restarted
the server.
#### Reproduction
The problem periodically happens on production servers during restart. Kamailio crashes
when one of our scripts tried getting statistics about websocket and tls modules using
kamcmd during server restart. As I see in core dump, shared memory was already freed when
rpc_mod_print called in the child process.
#### Debugging Data
<!--
If you got a core dump, use gdb to extract troubleshooting data - full backtrace,
local variables and the list of the code at the issue location.
gdb /path/to/kamailio /path/to/corefile
bt full
info locals
list
If you are familiar with gdb, feel free to attach more of what you consider to
be relevant.
-->
```
core.kamailio.17684
/var/lib/ums/sbin/kamailio
GNU gdb (Debian 7.12-6) 7.12.0.20161007-git
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /var/lib/ums/sbin/kamailio...done.
[New LWP 17684]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/var/lib/ums/sbin/kamailio -m 2048 -M 12 -P
/var/run/kamailio/kamailio.pid -f /'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 __strcmp_ssse3 () at ../sysdeps/x86_64/multiarch/../strcmp.S:1197
#0 __strcmp_ssse3 () at ../sysdeps/x86_64/multiarch/../strcmp.S:1197
#1 0x00007ff4d6ddb2f5 in rpc_mod_print (rpc=0x7ff4d66f0540 <binrpc_callbacks>,
ctx=0x7fff11cd5658, mname=0x1f140b8 "tls", stats=0x1f2f180, flag=2) at
mod_stats.c:117
#2 0x00007ff4d6ddb0eb in rpc_mod_print_one (rpc=0x7ff4d66f0540 <binrpc_callbacks>,
ctx=0x7fff11cd5658, mname=0x1f140b8 "tls", pkg_stats=0x1f2d9c0,
shm_stats=0x1f2f180, flag=2) at mod_stats.c:159
#3 0x00007ff4d6ddaee1 in rpc_mod_mem_stats_mode (rpc=0x7ff4d66f0540
<binrpc_callbacks>, ctx=0x7fff11cd5658, fmode=0) at mod_stats.c:239
#4 0x00007ff4d6dda84f in rpc_mod_mem_stats (rpc=0x7ff4d66f0540 <binrpc_callbacks>,
ctx=0x7fff11cd5658) at mod_stats.c:251
#5 0x00007ff4d64bfc80 in process_rpc_req (buf=0x1f140a4
"\241\003\026t\256\214=\221\nmod.stats", size=29, bytes_needed=0x7fff11cd5aa0,
sh=0x7fff11cd5a10, saved_state=0x1f240a8) at binrpc_run.c:678
#6 0x00007ff4d64ad72f in handle_stream_read (s_c=0x1f14070, idx=-1) at io_listener.c:511
#7 0x00007ff4d64a9121 in handle_io (fm=0x7ff55a4e4ae0, events=1, idx=-1) at
io_listener.c:706
#8 0x00007ff4d64a793a in io_wait_loop_epoll (h=0x7ff4d66f0348 <io_h>, t=10,
repeat=0) at ./../../core/io_wait.h:1062
#9 0x00007ff4d649b62c in io_listen_loop (fd_no=2, cs_lst=0x1e28940) at io_listener.c:281
#10 0x00007ff4d64d172c in mod_child (rank=0) at ctl.c:338
#11 0x0000000000638c14 in init_mod_child (m=0x7ff55a3634b0, rank=0) at
core/sr_module.c:780
#12 0x000000000063862d in init_mod_child (m=0x7ff55a363b78, rank=0) at
core/sr_module.c:776
#13 0x000000000063862d in init_mod_child (m=0x7ff55a364018, rank=0) at
core/sr_module.c:776
#14 0x000000000063862d in init_mod_child (m=0x7ff55a364528, rank=0) at
core/sr_module.c:776
#15 0x000000000063862d in init_mod_child (m=0x7ff55a3649c8, rank=0) at
core/sr_module.c:776
#16 0x000000000063862d in init_mod_child (m=0x7ff55a365140, rank=0) at
core/sr_module.c:776
#17 0x000000000063862d in init_mod_child (m=0x7ff55a3657b0, rank=0) at
core/sr_module.c:776
#18 0x000000000063862d in init_mod_child (m=0x7ff55a365c38, rank=0) at
core/sr_module.c:776
#19 0x00000000006385b2 in init_child (rank=0) at core/sr_module.c:825
#20 0x000000000043140c in main_loop () at main.c:1753
#21 0x000000000043df6f in main (argc=9, argv=0x7fff11cd9dd8) at main.c:2802
```
#### Log Messages
No any useful logs available.
#### SIP Traffic
No SIP traffic available.
### Possible Solutions
<!--
If you found a solution or workaround for the issue, describe it. Ideally, provide a pull
request with a fix.
-->
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
```
version: kamailio 5.3.1 (x86_64/linux) 283e46
flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST,
DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY,
USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR,
USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535,
DEFAULT PKG_SIZE 8MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: 283e46
compiled on 14:23:37 Jul 28 2020 with clang 9.0
```
* **Operating System**:
<!--
Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04,
CentOS 7.1, ...), MacOS, xBSD, Solaris, ...;
Kernel details (output of `uname -a`)
-->
```
Linux devhpbx005-1.vx 4.9.0-12-amd64 #1 SMP Debian 4.9.210-1 (2020-01-20) x86_64
GNU/Linux
```
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433
10 Aug
10 Aug
2:40 p.m.
This is a race that can show up in a multi-process application and is hard to avoid it
completely if you do not "cool down" the server (stop/reduce other interactions
with kamailio) -- you run RPC commands as the same time with triggering shut down.
I pushed the commit referenced above (which depends on another commit to the core) to
narrow down the window of this specific case, but it is not completely avoidable, as the
rpc command can be in the middle of iterating some internal lists when kill is performed
and some structures can be destroyed by other processes.
If someone wants to propose other solutions, make PRs and can be discussed there.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-671396222
2:40 p.m.
Closed #2433.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#event-3639085929
11 Aug
11 Aug
9:35 a.m.
Thanks Daniel. I'll add this fix as a patch to our kamailio build.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-671840917
20 Aug
20 Aug
1:30 p.m.
**Updates:**
A few days ago we've got the same segfault on production server, but in this case it
happened without shut down. I think there is a race when calling process_rpc_req function
and it does not relate to server cooldown.
**Core dump:**
GNU gdb (Debian 7.12-6) 7.12.0.20161007-git
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /var/lib/ums/sbin/kamailio...done.
[New LWP 6226]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/var/lib/ums/sbin/kamailio -m 2048 -M 12 -P
/var/run/kamailio/kamailio.pid -f /'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 __strcmp_sse2_unaligned ()
at ../sysdeps/x86_64/multiarch/strcmp-sse2-unaligned.S:32
#0 __strcmp_sse2_unaligned () at ../sysdeps/x86_64/multiarch/strcmp-sse2-unaligned.S:32
#1 0x00007f327f55c2f5 in rpc_mod_print (rpc=0x7f327ee71540 <binrpc_callbacks>,
ctx=0x7ffe1418a9b8, mname=0x1dca0c8 "tls", stats=0x1de5310, flag=2) at
mod_stats.c:117
#2 0x00007f327f55c0eb in rpc_mod_print_one (rpc=0x7f327ee71540 <binrpc_callbacks>,
ctx=0x7ffe1418a9b8, mname=0x1dca0c8 "tls", pkg_stats=0x1de39d0,
shm_stats=0x1de5310, flag=2) at mod_stats.c:159
#3 0x00007f327f55bee1 in rpc_mod_mem_stats_mode (rpc=0x7f327ee71540
<binrpc_callbacks>, ctx=0x7ffe1418a9b8, fmode=0) at mod_stats.c:239
#4 0x00007f327f55b84f in rpc_mod_mem_stats (rpc=0x7f327ee71540 <binrpc_callbacks>,
ctx=0x7ffe1418a9b8) at mod_stats.c:251
#5 0x00007f327ec40c80 in process_rpc_req (buf=0x1dca0b4
"\241\003\026F\270\067\r\221\nmod.stats", size=29, bytes_needed=0x7ffe1418ae00,
sh=0x7ffe1418ad70, saved_state=0x1dda0b8) at binrpc_run.c:678
#6 0x00007f327ec2e72f in handle_stream_read (s_c=0x1dca080, idx=-1) at io_listener.c:511
#7 0x00007f327ec2a121 in handle_io (fm=0x7f3302c66cc0, events=1, idx=-1) at
io_listener.c:706
#8 0x00007f327ec2893a in io_wait_loop_epoll (h=0x7f327ee71348 <io_h>, t=10,
repeat=0) at ./../../core/io_wait.h:1062
#9 0x00007f327ec1c62c in io_listen_loop (fd_no=2, cs_lst=0x1cde940) at io_listener.c:281
#10 0x00007f327ec5272c in mod_child (rank=0) at ctl.c:338
#11 0x0000000000638c14 in init_mod_child (m=0x7f3302ae54b0, rank=0) at
core/sr_module.c:780
#12 0x000000000063862d in init_mod_child (m=0x7f3302ae5b78, rank=0) at
core/sr_module.c:776
#13 0x000000000063862d in init_mod_child (m=0x7f3302ae6018, rank=0) at
core/sr_module.c:776
#14 0x000000000063862d in init_mod_child (m=0x7f3302ae6528, rank=0) at
core/sr_module.c:776
#15 0x000000000063862d in init_mod_child (m=0x7f3302ae69c8, rank=0) at
core/sr_module.c:776
#16 0x000000000063862d in init_mod_child (m=0x7f3302ae7140, rank=0) at
core/sr_module.c:776
#17 0x000000000063862d in init_mod_child (m=0x7f3302ae77b0, rank=0) at
core/sr_module.c:776
#18 0x000000000063862d in init_mod_child (m=0x7f3302ae7c38, rank=0) at
core/sr_module.c:776
#19 0x00000000006385b2 in init_child (rank=0) at core/sr_module.c:825
#20 0x000000000043140c in main_loop () at main.c:1753
#21 0x000000000043df6f in main (argc=9, argv=0x7ffe1418f138) at main.c:2802
**Logs:**
2020-08-18T12:36:03.755718-07:00 hpbx031-1.va /var/lib/ums/sbin/kamailio[6204]: INFO:
<script>: sip_call_id=9bf05e23-bdab-4c7e-93fd-975f1d27d3a9(a)hpbx031-1.va; Received
ACK in a dialog
2020-08-18T12:36:03.755756-07:00 hpbx031-1.va /var/lib/ums/sbin/kamailio[6204]: INFO:
<script>: sip_call_id=9bf05e23-bdab-4c7e-93fd-975f1d27d3a9(a)hpbx031-1.va; Relaying
ACK from b2bua to sip:54171324@127.0.0.1:5060
2020-08-18T12:36:03.757855-07:00 hpbx031-1.va /var/lib/ums/sbin/kamailio[6197]: INFO:
<script>: [75229096,R,0_1478685494]: Received, method: REGISTER, R-URI:
sip:hpbx031.telecomsvc.com:5060, ct: <sip:75229096@192.168.10.116:5100>, cseq:
14166, s-ip: 74.89.64.126, s-port: 5100
2020-08-18T12:37:29.073600-07:00 hpbx031-1.va /var/lib/ums/sbin/kamailio[6193]: INFO:
<core> [core/sctp_core.c:53]: sctp_core_destroy(): SCTP API not initialized
2020-08-18T12:37:39.583593-07:00 hpbx031-1.va kamailio: INFO: <core>
[core/sctp_core.c:75]: sctp_core_check_support(): SCTP API not enabled - if you want to
use it, load sctp module
2020-08-18T12:37:39.780830-07:00 hpbx031-1.va kamailio: INFO: <core>
[core/tcp_main.c:5043]: init_tcp(): using epoll_lt as the io watch method (auto detected)
2020-08-18T12:37:39.781363-07:00 hpbx031-1.va kamailio[23718]: loading modules under
config path: /var/lib/ums/lib64/kamailio/modules/
2020-08-18T12:37:39.781546-07:00 hpbx031-1.va kamailio[23718]: Listening on
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-677665752
2:04 p.m.
Was this a case of running the rpc command many times at the same time?
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-677686078
6:32 p.m.
Was this a case of running the rpc command many times
at the same time?
I'll ask our LSA about it tomorow. Do you think it could be a problem? I thought that
RPC handlers have thread safe (interprocess, in this case) access to shared memory, is
it?
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-677828367
21 Aug
21 Aug
11:03 a.m.
This is a sequence of commands that python script runs every 10 seconds:
/var/lib/ums/sbin/kamcmd -s tcp:localhost:2048 stats.get_statistics websocket:
/var/lib/ums/sbin/kamcmd -s tcp:localhost:2048 stats.get_statistics tcp:
/var/lib/ums/sbin/kamcmd -s tcp:localhost:2048 stats.get_statistics shmem:
/var/lib/ums/sbin/kamcmd -s tcp:localhost:2048 mod.stats tls pkg
/var/lib/ums/sbin/kamcmd -s tcp:localhost:2048 mod.stats tls shm
/var/lib/ums/sbin/kamcmd -s tcp:localhost:2048 mod.stats websocket pkg
/var/lib/ums/sbin/kamcmd -s tcp:localhost:2048 mod.stats websocket shm
/var/lib/ums/sbin/kamcmd -s tcp:localhost:2048 mod.stats core shm
This script parses output of every command and gets needed metrics. I see at least one
problem here - the script should use udp instead of tcp.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-678234199
1 Sep
1 Sep
10:40 a.m.
Bump! Any updates?
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-684758225
10:51 a.m.
Access to shared memory is unlocked if shutdown is triggered, otherwise some worker
processes can be killed while it acquired the lock, leaving kamailio shutdown worker in
deadlock. So there are potential races if you run the rpc commands when you trigger the
shut down. Probably you can make your stats fetch script to execute only if shutdown is
not triggered, by using a state file created on shutdown command.
Shut down multiprocess races with shared memory access are hard to avoid completely, being
a trade between complexity and being able to do a fast restart. If anyone wants to work on
this, he/she is more than welcome to propose a pull request.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-684764647
12:48 p.m.
I understand, but we've got a lot of such crashes during normal kamailio operation,
NOT during shutdown. This is the issue I'm concerned about.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-684827111
12:55 p.m.
The problem is not reproducible on the hosts where we disabled metrics gathering on
kamailio.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-684831361
2:24 p.m.
Somehow I failed to notice it happens at runtime as well, I thought it was only during
shut down.
Open a new issue adding the output of `bt full` from a recent core file for a runtime
crash, to start fresh on troubleshooting.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-684892786
5:30 p.m.
Created issue #2460
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-685018354
9 Sep
9 Sep
4:51 p.m.
I pushed a few commits in master branch trying to address this issue. I haven't
implemented the memory mod stats, but as I could see in the code, it didn't seem to be
protected for races on accessing the shm fragments.
You would need to test with master branch or by using patches from the next commits:
* aa458a62f034c2cb57639bdc713ed3c51b0292c7
* 761eb0616fea2a859a2c0abb652b22feb6f59859
* 9645be245f899fa8ae11a6be045d2ef83fd66bf5
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2433#issuecomment-689687081
1344
days inactive
1374
days old
14 comments
2 participants
participants (2)
-
Andrey Deykunov -
Daniel-Constantin Mierla