zenichev created an issue (kamailio/kamailio#4642)
### Description
Crash of kamailio (5.7.5) after introducing
cefd6f97659cb7572ecb32279e1f57d3b68e0f4c for TCP reads (checks for MSRP first
line).
I've added this important security related fix to all versions of Kamailio that
we maintain, including those long terms supported, as well as those older like
5.7.5.
So far the crash happened only in 5.7.5
Keep you posted about other versions (especially those supported).
### Troubleshooting
Scope:
src/core/tcp_read.c
`tcp_init_children()`
`tcp_read_headers()`
---
`enable_tls=yes`
>From what we can see it is a simple origination of new call with INVITE
>request over TLS.
Shortly before the crash, we see these log lines:
```
Mar 12 15:41:16.873907 sp1 lb[416237]: CRITICAL: <core> [core/pass_fd.c:85]:
recv_all(): 1st recv on 50 failed: Connection reset by peer
Mar 12 15:41:16.873924 sp1 lb[416237]: CRITICAL: <core> [core/tcp_main.c:3738]:
handle_tcp_child(): read from tcp child 6 (pid 416233, no 31) Connection reset
by peer [104]
Mar 12 15:41:16.873930 sp1 lb[416237]: CRITICAL: <core> [core/pass_fd.c:281]:
receive_fd(): EOF on 47
Mar 12 15:41:16.874074 sp1 lb[416200]: ALERT: <core> [main.c:792]:
handle_sigs(): child process 416233 exited by a signal 11
Mar 12 15:41:16.874087 sp1 lb[416200]: ALERT: <core> [main.c:796]:
handle_sigs(): core was generated
Mar 12 15:41:16.888319 sp1 lb[416200]: CRITICAL: <core>
[core/mem/q_malloc.c:535]: qm_free(): BUG: freeing already freed pointer
(0x7f78c1b0ad70), called from tls: tls_init.c: ser_free(399), first free tls:
tls_init.c: ser_free(399) - ignoring
```
#### Reproduction
Enable TLS with:
`enable_tls=yes`
Originate a normal call A to B, with the INVITE coming to the TLS socket.
Kamailio sends the request further to the registrar via UDP.
The registrar server makes the authorization with 407.
Kamailio attempts to send 407 to the remote side via TLS socket.
(the onreply_route is used for processing of 407).
What exactly has triggered this misbehavior (crash) is not known.
>From what I can see, the actions in TLS were so far:
- TLS connection is in this init state (see logs)
- TLS connection is reset by remote peer
- while being in `tls_init` processing we try to do the double free
#### Debugging Data
BT trace with excluded sensible data:
```
#0 mem_ctrl (b=0x7f78c198cea0, cmd=3, num=0, ptr=0x7ffce623f970) at
../crypto/bio/bss_mem.c:257
257 ../crypto/bio/bss_mem.c: No such file or directory.
(gdb) bt full
#0 mem_ctrl (b=0x7f78c198cea0, cmd=3, num=0, ptr=0x7ffce623f970) at
../crypto/bio/bss_mem.c:257
ret = 1
pptr = <optimized out>
bbm = <optimized out>
bm = 0x63696666
bo = 0x6172742073682073
off = <optimized out>
remain = <optimized out>
#1 0x00007f78c5308e1d in BIO_ctrl (b=0x7f78c198cea0, cmd=cmd@entry=3,
larg=larg@entry=0, parg=parg@entry=0x7ffce623f970) at
../crypto/bio/bio_lib.c:580
ret = <optimized out>
__func__ = "BIO_ctrl"
#2 0x00007f78c56b104e in ssl3_digest_cached_records (s=s@entry=0x7f78c197c3a8,
keep=keep@entry=0) at ../ssl/s3_enc.c:378
md = <optimized out>
hdatalen = <optimized out>
hdata = 0x7ffce623fa00
__func__ = "ssl3_digest_cached_records"
#3 0x00007f78c56fec9b in tls_construct_server_hello (s=0x7f78c197c3a8,
pkt=0x7ffce623fa00) at ../ssl/statem/statem_srvr.c:2401
compm = 0
sl = <optimized out>
len = 2
version = <optimized out>
session_id = <optimized out>
usetls13 = <optimized out>
__func__ = "tls_construct_server_hello"
#4 0x00007f78c56f08ff in write_state_machine (s=0x7f78c197c3a8) at
../ssl/statem/statem.c:855
tmpret = <optimized out>
post_work = 0x7f78c5701af0 <ossl_statem_server_post_work>
mt = 2
pkt = {buf = 0x7f78c1b0adf0, staticbuf = 0x0, curr = 122, written =
122, maxsize = 18446744073709551615, subs = 0x7f78c1990dd8, endfirst = 0}
ret = <optimized out>
pre_work = 0x7f78c57018d0 <ossl_statem_server_pre_work>
get_construct_message_f = 0x7f78c5701ed0
<ossl_statem_server_construct_message>
confunc = 0x7f78c56fea10 <tls_construct_server_hello>
st = 0x7f78c197c3f0
transition = 0x7f78c5701480 <ossl_statem_server_write_transition>
cb = 0x7f78c5747550 <sr_ssl_ctx_info_callback>
st = <optimized out>
ret = <optimized out>
transition = <optimized out>
pre_work = <optimized out>
post_work = <optimized out>
get_construct_message_f = <optimized out>
cb = <optimized out>
confunc = <optimized out>
mt = <optimized out>
pkt = <optimized out>
__func__ = "write_state_machine"
tmpret = <optimized out>
#5 state_machine (s=0x7f78c197c3a8, server=1) at ../ssl/statem/statem.c:451
buf = 0x0
cb = 0x7f78c5747550 <sr_ssl_ctx_info_callback>
st = 0x7f78c197c3f0
ret = -1
ssret = <optimized out>
__func__ = "state_machine"
#6 0x00007f78c5774dd6 in tls_accept (c=c@entry=0x7f78c1a32fb0,
error=error@entry=0x7ffce623fc08) at ./src/modules/tls/tls_server.c:457
--Type <RET> for more, q to quit, c to continue without paging--c
ret = <optimized out>
ssl = 0x7f78c197c3a8
cert = <optimized out>
tls_c = 0x7f78c1b2aed0
tls_log = <optimized out>
__func__ = "tls_accept"
#7 0x00007f78c5780eb0 in tls_h_read_f (c=c@entry=0x7f78c1a32fb0,
flags=flags@entry=0x7ffce6260030) at ./src/modules/tls/tls_server.c:1153
r = <optimized out>
bytes_free = 65535
bytes_read = <optimized out>
read_size = <optimized out>
ssl_error = 0
ssl_read = 0
ssl = 0x7f78c197c3a8
rd_buf =
"\026\003\001\002\000\001\000\001\374\003\003K^\006\353Kyp\277wb\202UJ3\372/\276\230\017\243\334\317\333;\302b\230\254\232~y\325
\342\357?\350&\3266\247\217\201\212\3026\367\334\b\b\323<\311N\257|\311\035\207\316L\327\300[F\000>\023\002\023\003\023\001\300,\3000\000\237̨̩̪\300+\300/\000\236\300$\300(\000k\300#\300'\000g\300\n\300\024\0009\300\t\300\023\0003\000\235\000\234\000=\000<\0005\000/\000\377\001\000\001u\000\000\000\031\000\027\000\000\024sip01-acit.techit.be\000\v\000\004\003\000\001\002\000\n\000\026\000\024\000\035\000\027\000\036\000\031\000\030\001\000\001\001\001\002"...
wr_buf =
"\027\003\003\001\032\204\240b)*L\252\246b\2753\v\002\345}\363s֬M\f\372\203\220\261\203\246^3\300}\273O\331\t|\223\017\323\332Y\025\035\245\232\315a\363\035&\3274\227\025\366n\331{\372d\264OY\262v\0013\277k\300\207ki\020\201\031\370\"\213xQ\253po\204\3377rK\375~\\\033\307\021\205\264ۘX\265\361\235\256>[\\ꬣ\223Pk$[\371+<<\021\031\351\006\257\372\247\365\024>*S@f\262\341\375\320fr\214l\216Et\025\343\036bPd\312\322w\362d!\210\261v\225\353\366rjV{=%\323(\024A\021\372g\347\375\354\306t\222\245\255*\026\251\351J\262\020\032~\027\2520Fe\206W"...
rd = {buf = 0x7ffce623fcd0 "\026\003\001\002", pos = 517, used = 517,
size = 65536}
wr = {
buf = 0x7ffce624fcd0
"\027\003\003\001\032\204\240b)*L\252\246b\2753\v\002\345}\363s֬M\f\372\203\220\261\203\246^3\300}\273O\331\t|\223\017\323\332Y\025\035\245\232\315a\363\035&\3274\227\025\366n\331{\372d\264OY\262v\0013\277k\300\207ki\020\201\031\370\"\213xQ\253po\204\3377rK\375~\\\033\307\021\205\264ۘX\265\361\235\256>[\\ꬣ\223Pk$[\371+<<\021\031\351\006\257\372\247\365\024>*S@f\262\341\375\320fr\214l\216Et\025\343\036bPd\312\322w\362d!\210\261v\225\353\366rjV{=%\323(\024A\021\372g\347\375\354\306t\222\245\255*\026\251\351J\262\020\032~\027\2520"...,
pos = 0, used = 0, size = 65536}
tls_c = 0x7f78c1b2aed0
enc_rd_buf = <optimized out>
n = <optimized out>
flush_flags = 0
err_src = <optimized out>
ip_buf = '\000' <repeats 63 times>
x = <optimized out>
tls_dbg = <optimized out>
__func__ = "tls_h_read_f"
redo_read = <optimized out>
__llevel = <optimized out>
__kld = <optimized out>
__llevel = <optimized out>
__kld = <optimized out>
#8 0x0000555ced7b05a1 in tcp_read_headers (c=c@entry=0x7f78c1a32fb0,
read_flags=read_flags@entry=0x7ffce6260030) at core/tcp_read.c:445
bytes = <optimized out>
remaining = <optimized out>
p = <optimized out>
r = 0x7f78c1a330d8
mc = <optimized out>
body_len = <optimized out>
tvnow = {tv_sec = 8295706741926415945, tv_usec = 93857609625105}
tvdiff = <optimized out>
mfline = <optimized out>
mtransid = <optimized out>
__func__ = "tcp_read_headers"
#9 0x0000555ced7b3214 in tcp_read_req (con=0x7f78c1a32fb0,
bytes_read=bytes_read@entry=0x7ffce626002c,
read_flags=read_flags@entry=0x7ffce6260030) at core/tcp_read.c:1528
bytes = <optimized out>
total_bytes = 0
resp = 1
size = <optimized out>
req = 0x7f78c1a330d8
dst = {send_sock = 0x7ffce625ff40, to = {s = {sa_family = 1, sa_data =
"\000\000\000\000\000\000P\377%\346\374\177\000"}, sin = {sin_family = 1,
sin_port = 0, sin_addr = {s_addr = 0}, sin_zero = "P\377%\346\374\177\000"},
sin6 = {sin6_family = 1,
sin6_port = 0, sin6_flowinfo = 0, sin6_addr = {__in6_u =
{__u6_addr8 = "P\377%\346\374\177\000\000\030\000\000\000\000\000\000",
__u6_addr16 = {65360, 58917, 32764, 0, 24, 0, 0, 0}, __u6_addr32 = {3861249872,
32764, 24, 0}}},
sin6_scope_id = 0}, sas = {ss_family = 1,
__ss_padding =
"\000\000\000\000\000\000P\377%\346\374\177\000\000\030", '\000' <repeats 15
times>,
"\3607\245\301x\177\000\000\004P\216\355\\U\000\000\001\000\000\000\000\000\000\0003\000\000\000\000\000\000\000&A\205\001\000\000\000\000`]\246\355\\U\000\000\003t{\355\\U\000\000\004P\216\355\\U\000\000\000ؒ\355\\U\000\0008\000&\346\374\177\000\000\b\000\000\000\000\000\000",
__ss_align = 20}}, id = 1, send_flags = {f = 1, blst_imask = 0}, proto = 11
'\v', proto_pad0 = 0 '\000',
proto_pad1 = 0}
c = <optimized out>
ret = <optimized out>
again = <optimized out>
__func__ = "tcp_read_req"
#10 0x0000555ced7b8280 in handle_io (fm=fm@entry=0x7f78c5b06e30,
events=events@entry=1, idx=idx@entry=-1) at core/tcp_read.c:1852
ret = 8
n = 8
read_flags = RD_CONN_SHORT_READ
con = 0x7f78c1a32fb0
s = 11
resp = <optimized out>
t = <optimized out>
ee = 0x0
__func__ = "handle_io"
error = <optimized out>
#11 0x0000555ced7bde1b in io_wait_loop_epoll (repeat=<optimized out>,
t=<optimized out>, h=<optimized out>) at core/io_wait.h:1073
n = 1
r = 0
fm = 0x7f78c5b06e30
revents = 1
__func__ = "io_wait_loop_epoll"
#12 0x0000555ced7be677 in tcp_receive_loop (unix_sock=<optimized out>) at
core/tcp_read.c:2052
__func__ = "tcp_receive_loop"
#13 0x0000555ced7a722c in tcp_init_children
(woneinit=woneinit@entry=0x7ffce626055c) at core/tcp_main.c:5377
r = 6
i = <optimized out>
reader_fd_1 = 51
pid = <optimized out>
si_desc = "tcp receiver
(generic)\000\000\000\000\000\000\000\000\000\000\017\000\000\000\000\000\000\000\355Su\355\\U\000\000\004P\216\355\\U\000\0000\352\222\355\\U\000\000\360\236\205\305x\177\000\000\f",
'\000' <repeats 15 times>,
"\tP\216\355\\U\000\000Ȑ\216\355\\U\000\000X\005\000\000\000\000\000\000\004P\216\355\\U\000\000o>\200\355\\U\000"
si = <optimized out>
__func__ = "tcp_init_children"
error = <optimized out>
#14 0x0000555ced5c87ae in main_loop () at ./src/main.c:1937
i = <optimized out>
pid = <optimized out>
si = <optimized out>
si_desc = "udp receiver child=7
sock=127.0.0.1:5060\00060\000\\U\000\000:\254x\305x\177\000\000\022\000\000\000\377\377\377\377DyH\000\000\000\000\000\214\025\205\306x\177\000\000\001\000\000\000\000\000\000\000\t\000\000\000\000\000\000\000Thu
Mar \000\245\271\037n8\335\026:20 2026\002\000\000\000\000\000\000"
nrprocs = <optimized out>
woneinit = 1
__func__ = "main_loop"
error = <optimized out>
#15 0x0000555ced5bcb39 in main (argc=<optimized out>, argv=<optimized out>) at
./src/main.c:3213
cfg_stream = <optimized out>
c = <optimized out>
r = <optimized out>
tmp = 0x7ffce6260e4d ""
tmp_len = 0
port = 0
proto = -961943936
ahost = 0x0
aport = 0
options = 0x555ced8e7b78
":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 = 2434881523
rfd = <optimized out>
debug_save = <optimized out>
debug_flag = <optimized out>
dont_fork_cnt = <optimized out>
n_lst = <optimized out>
p = <optimized out>
st = {st_dev = 22, st_ino = 879, st_nlink = 2, st_mode = 16872, st_uid
= 111, st_gid = 118, __pad0 = 0, st_rdev = 0, st_size = 200, st_blksize = 4096,
st_blocks = 0, st_atim = {tv_sec = 1771508381, tv_nsec = 869502865}, st_mtim = {
tv_sec = 1773323059, tv_nsec = 437452591}, st_ctim = {tv_sec =
1773323059, tv_nsec = 437452591}, __glibc_reserved = {0, 0, 0}}
tbuf =
"\000\000\000\000\000\000\000\000\200\346\251\306x\177\000\000\r\000\000\000\000\000\000\000\2301\232\306x\177\000\000\220\v&\346\374\177\000\000x,\236\355\\U\000\000
0\255\306x\177\000\000\276\376\252\306x\177\000\000\001", '\000' <repeats 15
times>,
"x\b\252\306x\177\000\000\020j\253\306x\177\000\000\000\000\000\000\000\000\000\000\260\n&\346\374\177\000\000\n",
'\000' <repeats 15 times>,
"\220\v&\346\374\177\000\0003!\253\306x\177\000\000\000\000\000\000\000\000\000\000x,\236\355\\U\000\000\220\v&\346\374\177\000\000\000\000\000\000\000\000\000\000\340B\255\306x\177\000\000\000\000\000\000\000\000\000\000\200F\252\306x\177\000\000"...
option_index = 0
long_options = {{name = 0x555ced8e622a "help", has_arg = 0, flag = 0x0,
val = 104}, {name = 0x555ced8ef7ee "version", has_arg = 0, flag = 0x0, val =
118}, {name = 0x555ced8ff0d2 "alias", has_arg = 1, flag = 0x0, val = 1024}, {
name = 0x555ced8e622f "subst", has_arg = 1, flag = 0x0, val =
1025}, {name = 0x555ced8e6235 "substdef", has_arg = 1, flag = 0x0, val = 1026},
{name = 0x555ced8e623e "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {
name = 0x555ced8e6248 "server-id", has_arg = 1, flag = 0x0, val =
1028}, {name = 0x555ced8e6252 "loadmodule", has_arg = 1, flag = 0x0, val =
1029}, {name = 0x555ced8e625d "modparam", has_arg = 1, flag = 0x0, val = 1030},
{
name = 0x555ced8e6266 "log-engine", has_arg = 1, flag = 0x0, val =
1031}, {name = 0x555ced8ef90b "debug", has_arg = 1, flag = 0x0, val = 1032},
{name = 0x555ced8e6271 "cfg-print", has_arg = 0, flag = 0x0, val = 1033}, {
name = 0x555ced8e627b "atexit", has_arg = 1, flag = 0x0, val =
1034}, {name = 0x555ced8e6282 "all-errors", has_arg = 0, flag = 0x0, val =
1035}, {name = 0x0, has_arg = 0, flag = 0x0, val = 0}}
__func__
```
#### Log Messages
Was posted already above, but still adding also to this section:
```
Mar 12 15:41:16.873907 sp1 lb[416237]: CRITICAL: <core> [core/pass_fd.c:85]:
recv_all(): 1st recv on 50 failed: Connection reset by peer
Mar 12 15:41:16.873924 sp1 lb[416237]: CRITICAL: <core> [core/tcp_main.c:3738]:
handle_tcp_child(): read from tcp child 6 (pid 416233, no 31) Connection reset
by peer [104]
Mar 12 15:41:16.873930 sp1 lb[416237]: CRITICAL: <core> [core/pass_fd.c:281]:
receive_fd(): EOF on 47
Mar 12 15:41:16.874074 sp1 lb[416200]: ALERT: <core> [main.c:792]:
handle_sigs(): child process 416233 exited by a signal 11
Mar 12 15:41:16.874087 sp1 lb[416200]: ALERT: <core> [main.c:796]:
handle_sigs(): core was generated
Mar 12 15:41:16.888319 sp1 lb[416200]: CRITICAL: <core>
[core/mem/q_malloc.c:535]: qm_free(): BUG: freeing already freed pointer
(0x7f78c1b0ad70), called from tls: tls_init.c: ser_free(399), first free tls:
tls_init.c: ser_free(399) - ignoring
```
### Possible Solutions
No workaround found so far.
### Additional Information
Kamailio 5.7.5
OS: Debian Bookworm
--
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/4642
You are receiving this because you are subscribed to this thread.
Message ID: <kamailio/kamailio/issues/[email protected]>_______________________________________________
Kamailio - Development Mailing List -- [email protected]
To unsubscribe send an email to [email protected]
Important: keep the mailing list in the recipients, do not reply only to the
sender!
