Hi All,
We have recently encountered a challenging issue in our environment that I
wanted to bring to your attention. A few months ago, we performed updates
to our Docker and OpenSSL installations, upgrading OpenSSL to version
1.1.1u. Since then, we have been experiencing intermittent traffic blocking
(TLS and UDP both for around 10 minutes and getting recovered) on some of
our instances.
Prior to the OpenSSL upgrade, we had not observed any such issues. However,
the situation has become more complex due to a substantial increase in
traffic, with each instance now handling 4K-5K concurrent calls and a daily
total of approximately 200,000 calls per instance.
Our initial suspicion was related to a Docker iptable issue. To investigate
further, we conducted a GDB trace using "kamctl pstrap" and discovered
specific log entries indicating potential issues within the
"pthread_rwlock_wrlock" function. This has prompted us to explore whether
the problems are linked to the OpenSSL upgrade.
We are considering upgrading Kamailio to the latest version, although this
process typically requires a significant amount of time for proper planning
and testing. Given the high volume of calls we are currently handling, we
are also exploring the possibility of a temporary solution involving a
rollback of the OpenSSL version to see if it resolves the issue.
Curiously, during a recent load test using SIPP, which simulated 10,000
concurrent calls with a rate of 100 calls per second, we did not encounter
the same problem.
any hints or insights you may have that could help us pinpoint the root
cause of the problem .
We do have a complete GDB trace available, but its size necessitates
sharing a truncated version for now.
version: kamailio 5.4.3 (x86_64/linux) 0178a5
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: 0178a5
compiled on 12:36:56 Oct 22 2023 with gcc 4.8.5
Operating System Host :
LSB Version: :core-4.1-amd64:core-4.1-noarch
Distributor ID: Rocky
Description: Rocky Linux release 8.8 (Green Obsidian)
Release: 8.8
Codename: GreenObsidian
container os (Centos7)
Kamctl pstraip output (truncated to last few lines)
---start 154 -----------------------------------------------------
kamailio: No such file or directory.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007fbf6f38a0c3 in __epoll_wait_nocancel () from /lib64/libc.so.6
$1 = 82
$2 = {pid = 154, unix_sock = 182, idx = 27, status = 1, rank = 48, desc =
"tcp receiver (tcp:xxx.xxx.xxx.xx:5060 <http://223.62.234.57:5060/>)
child=27", '\000' <repeats 81 times>}
#0 0x00007fbf6f38a0c3 in __epoll_wait_nocancel () from /lib64/libc.so.6
No symbol table info available.
#1 0x0000000000684858 in io_wait_loop_epoll (h=0xb41720 <io_w>, t=2,
repeat=0) at core/io_wait.h:1039
n = 84
r = 0
fm = 0x2
revents = 8201656
__FUNCTION__ = "io_wait_loop_epoll"
#2 0x0000000000699e7a in tcp_receive_loop (unix_sock=186) at
core/tcp_read.c:1997
__FUNCTION__ = "tcp_receive_loop"
#3 0x00000000005279e7 in tcp_init_children () at core/tcp_main.c:5134
r = 27
i = -1
reader_fd_1 = 186
pid = 0
si_desc = "tcp receiver (tcp:xxx.xx.xxx.xxx:5060
<http://223.62.234.57:5060/>
)\000\000\000\355\217c\000\000\000\000\000\240\213{\001\001\000\000\000\017\000\000\000\000\000\000\000\250\a2o\276\177\000\000\200\b\231o\000\000\000\000\260\006\346\261\376\177\000\000\230\210w\000\000\000\000\000=\000\000\000>\000\000\000\270\016z\350\274\177\000\000\060;8o\002\000\000\000P\224\346\352\001\000\000"
si = 0x0
__FUNCTION__ = "tcp_init_children"
#4 0x000000000042ae66 in main_loop () at main.c:1771
i = 16
pid = 94
si = 0x0
si_desc = "udp receiver child=15
sock=xxxx.xxx.xxx.xx:5060\000\000\000\v\235\200", '\000' <repeats 13
times>,
"P\r\346\261\376\177\000\000\270%}\000\000\000\000\000T\000\000\000\000\000\000\000\060;8o\277\177\000\000\343\207\201\000\000\000\000\000\277;8o\277\177\000\000
\271A\000\000\000\000\000@\374Ko\276\177\000"
nrprocs = 16
woneinit = 1
__FUNCTION__ = "main_loop"
#5 0x0000000000433ad6 in main (argc=9, argv=0x7ffeb1e60e38) at main.c:2856
cfg_stream = 0x16c9010
c = -1
r = 0
tmp = 0x7ffeb1e61f0c ""
tmp_len = 2496
port = 2496
proto = 1472
ahost = 0x0
aport = 0
options = 0x7d5238
":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 = 2208520674
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x7fbf6f40f3a0 <intel_02_known>
p = 0xf0b5ff <Address 0xf0b5ff out of bounds>
st = {st_dev = 76, st_ino = 120506675, st_nlink = 2, st_mode =
16877, st_uid = 0, st_gid = 0, __pad0 = 0, st_rdev = 0, st_size = 40,
st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1698340416, tv_nsec =
618631009}, st_mtim = {tv_sec = 1698340416, tv_nsec = 618631009}, st_ctim =
{tv_sec = 1698340416, tv_nsec = 618631009}, __unused = {0, 0, 0}}
tbuf = '\000' <repeats 376 times>...
option_index = 0
long_options = {{name = 0x7d742f "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x7d2a34 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x7d7434 "alias", has_arg = 1, flag = 0x0, val = 1024}, {name
= 0x7d743a "subst", has_arg = 1, flag = 0x0, val = 1025}, {name = 0x7d7440
"substdef", has_arg = 1, flag = 0x0, val = 1026}, {name = 0x7d7449
"substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name = 0x7d7453
"server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x7d745d
"loadmodule", has_arg = 1, flag = 0x0, val = 1029}, {name = 0x7d7468
"modparam", has_arg = 1, flag = 0x0, val = 1030}, {name = 0x7d7471
"log-engine", has_arg = 1, flag = 0x0, val = 1031}, {name = 0x7d747c
"debug", has_arg = 1, flag = 0x0, val = 1032}, {name = 0x0, has_arg = 0,
flag = 0x0, val = 0}}
__FUNCTION__ = "main"
[Inferior 1 (process 154) detached]
---end 154 -------------------------------------------------------
---start 155 -----------------------------------------------------
kamailio: No such file or directory.
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
0x00007fbe6e5bd39e in pthread_rwlock_wrlock () from /lib64/libpthread.so.0
$1 = 83
$2 = {pid = 155, unix_sock = -1, idx = -1, status = 1, rank = -4, desc =
"tcp main process", '\000' <repeats 111 times>}
#0 0x00007fbe6e5bd39e in pthread_rwlock_wrlock () from
/lib64/libpthread.so.0
No symbol table info available.
#1 0x00007fbe68b745c9 in CRYPTO_THREAD_write_lock () from
/lib64/libcrypto.so.1.1
No symbol table info available.
#2 0x00007fbe68afe07e in CRYPTO_free_ex_data () from
/lib64/libcrypto.so.1.1
No symbol table info available.
#3 0x00007fbe68ea52c2 in SSL_free () from /lib64/libssl.so.1.1
No symbol table info available.
#4 0x00007fbe69149480 in tls_h_tcpconn_clean_f (c=0x7fbceeae00d0) at
tls_server.c:655
extra = 0x7fbceec3b898
__FUNCTION__ = "tls_h_tcpconn_clean_f"
#5 0x00000000004fbf2d in _tcpconn_free (c=0x7fbceeae00d0) at
core/tcp_main.c:1529
__FUNCTION__ = "_tcpconn_free"
#6 0x0000000000510912 in tcpconn_put_destroy (tcpconn=0x7fbceeae00d0) at
core/tcp_main.c:3284
__FUNCTION__ = "tcpconn_put_destroy"
#7 0x00000000005156a5 in handle_tcp_child (tcp_c=0x7fbe6f813440, fd_i=-1)
at core/tcp_main.c:3723
tcpconn = 0x7fbceeae00d0
response = {140449434960080, -2}
cmd = -2
bytes = 16
n = 1865551792
t = 887186228
crt_timeout = 410
con_lifetime = 57680
__FUNCTION__ = "handle_tcp_child"
#8 0x00000000005208ed in handle_io (fm=0x7fbe6f9d7c78, ev=1, idx=-1) at
core/tcp_main.c:4542
ret = 1
__FUNCTION__ = "handle_io"
#9 0x00000000004e93ed in io_wait_loop_epoll (h=0xad5740 <io_h>, t=5,
repeat=0) at core/io_wait.h:1070
n = 1
r = 0
fm = 0x7fbe6f9d7c78
revents = 1
__FUNCTION__ = "io_wait_loop_epoll"
#10 0x0000000000523c99 in tcp_main_loop () at core/tcp_main.c:4827
si = 0x0
r = 28
__FUNCTION__ = "tcp_main_loop"
#11 0x000000000042b1be in main_loop () at main.c:1779
i = 16
pid = 0
si = 0x0
si_desc = "udp receiver child=15 sock=xxx.xx.xxx.xxx:5060
<http://223.62.234.76:5060/>\000\000\000\v\235\200", '\000' <repeats
13
times>,
"P\r\346\261\376\177\000\000\270%}\000\000\000\000\000T\000\000\000\000\000\000\000\060;8o\277\177\000\000\343\207\201\000\000\000\000\000\277;8o\277\177\000\000
\271A\000\000\000\000\000@\374Ko\276\177\000"
nrprocs = 16
woneinit = 1
__FUNCTION__ = "main_loop"
#12 0x0000000000433ad6 in main (argc=9, argv=0x7ffeb1e60e38) at main.c:2856
cfg_stream = 0x16c9010
c = -1
r = 0
tmp = 0x7ffeb1e61f0c ""
tmp_len = 2496
port = 2496
proto = 1472
ahost = 0x0
aport = 0
options = 0x7d5238
":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 = 2208520674
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x7fbf6f40f3a0 <intel_02_known>
p = 0xf0b5ff <Address 0xf0b5ff out of bounds>
st = {st_dev = 76, st_ino = 120506675, st_nlink = 2, st_mode =
16877, st_uid = 0, st_gid = 0, __pad0 = 0, st_rdev = 0, st_size = 40,
st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1698340416, tv_nsec =
618631009}, st_mtim = {tv_sec = 1698340416, tv_nsec = 618631009}, st_ctim =
{tv_sec = 1698340416, tv_nsec = 618631009}, __unused = {0, 0, 0}}
tbuf = '\000' <repeats 376 times>...
option_index = 0
long_options = {{name = 0x7d742f "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x7d2a34 "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x7d7434 "alias", has_arg = 1, flag = 0x0, val = 1024}, {name
= 0x7d743a "subst", has_arg = 1, flag = 0x0, val = 1025}, {name = 0x7d7440
"substdef", has_arg = 1, flag = 0x0, val = 1026}, {name = 0x7d7449
"substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name = 0x7d7453
"server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x7d745d
"loadmodule", has_arg = 1, flag = 0x0, val = 1029}, {name = 0x7d7468
"modparam", has_arg = 1, flag = 0x0, val = 1030}, {name = 0x7d7471
"log-engine", has_arg = 1, flag = 0x0, val = 1031}, {name = 0x7d747c
"debug", has_arg = 1, flag = 0x0, val = 1032}, {name = 0x0, has_arg = 0,
flag = 0x0, val = 0}}
__FUNCTION__ = "main"
[Inferior 1 (process 155) detached]
---end 155 -------------------------------------------------------
Thanks & Regards
Pintu Lohar