[kamailio/kamailio] kamailio 5.7.1 as a webrtc server experiences random crashes (Issue #3563)
### Description Crashed after about 30 minutes of uptime. I probably have several bug reports to post on similar lines, they may all be related or they may all be completely different but I will raise a separate bug report for each.
### Troubleshooting Tried varying SHM_MEMORY from 256 to 512 and PKG_MEMORY from 8 to 64 in various increments. None seemed to help.
#### Reproduction Open kamailio on tcp port 7443 and set up webrtc to point to it for traffic. `` #### Debugging Data
coredumpctl debug PID: 1186 (kamailio) UID: 990 (kamailio) GID: 988 (kamailio) Signal: 11 (SEGV) Timestamp: Wed 2023-09-13 22:39:40 UTC (8min ago) Command Line: /usr/sbin/kamailio -DD -P /run/kamailio/kamailio.pid -f /etc/kamailio/kamailio.cfg -m 256 -M 8 --atexit=no Executable: /usr/sbin/kamailio Control Group: /system.slice/kamailio.service Unit: kamailio.service Slice: system.slice Boot ID: 3fc4251c606f4c6183610573f44c46ba Machine ID: 16e913e686424f13b970f9b1044cc6b3 Hostname: kamrtc01.voiceflex.com Storage: /var/lib/systemd/coredump/core.kamailio.990.3fc4251c606f4c6183610573f44c46ba.1186.1694644780000000.zst (present) Size on Disk: 4.6M Message: Process 1186 (kamailio) of user 990 dumped core.
Stack trace of thread 1186: #0 0x00007f156ae338aa __strlen_sse2 (libc.so.6 + 0x338aa) #1 0x00007f156ae84278 __vfprintf_internal (libc.so.6 + 0x84278) #2 0x00007f156af4775a __vsyslog_internal (libc.so.6 + 0x14775a) #3 0x00007f156af47c3a syslog (libc.so.6 + 0x147c3a) #4 0x00000000007164b4 qm_debug_check_frag (kamailio + 0x3164b4) #5 0x000000000071a703 qm_free (kamailio + 0x31a703) #6 0x0000000000725209 qm_shm_free (kamailio + 0x325209) #7 0x00007f15690843d6 ser_free (tls.so + 0x313d6) #8 0x00007f156996d737 ERR_pop_to_mark (libcrypto.so.3 + 0x16d737) #9 0x00007f15699b3e42 ossl_namemap_doall_names (libcrypto.so.3 + 0x1b3e42) #10 0x00007f156999f225 EVP_PKEY_set_type_by_keymgmt (libcrypto.so.3 + 0x19f225) #11 0x00007f156999859a evp_keymgmt_util_assign_pkey (libcrypto.so.3 + 0x19859a) #12 0x00007f15699a21c3 EVP_PKEY_generate (libcrypto.so.3 + 0x1a21c3) #13 0x00007f1569d8082d ssl_generate_param_group (libssl.so.3 + 0x2682d) #14 0x00007f1569db52ea tls_parse_ctos_key_share (libssl.so.3 + 0x5b2ea) #15 0x00007f1569da7f79 tls_parse_all_extensions (libssl.so.3 + 0x4df79) #16 0x00007f1569dd1cde ossl_statem_server_post_process_message (libssl.so.3 + 0x77cde) #17 0x00007f1569dbc2cb state_machine.part.0 (libssl.so.3 + 0x622cb) #18 0x00007f15690ac584 tls_accept (tls.so + 0x59584) #19 0x00007f15690b78be tls_h_read_f (tls.so + 0x648be) #20 0x00000000006c79bc tcp_read_headers (kamailio + 0x2c79bc) #21 0x00000000006cfb94 tcp_read_req (kamailio + 0x2cfb94) #22 0x00000000006d4cc3 handle_io (kamailio + 0x2d4cc3) #23 0x00000000006c271d io_wait_loop_epoll (kamailio + 0x2c271d) #24 0x00000000006d7a47 tcp_receive_loop (kamailio + 0x2d7a47) #25 0x00000000006b7689 tcp_init_children (kamailio + 0x2b7689) #26 0x000000000042fae9 main_loop (kamailio + 0x2fae9) #27 0x0000000000439969 main (kamailio + 0x39969) #28 0x00007f156ae3feb0 __libc_start_call_main (libc.so.6 + 0x3feb0) #29 0x00007f156ae3ff60 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x3ff60) #30 0x000000000041dc65 _start (kamailio + 0x1dc65) ELF object binary architecture: AMD x86-64 ``
`` (gdb) bt full #0 0x00007f156ae338aa in __strlen_sse2 () from /lib64/libc.so.6 No symbol table info available. #1 0x00007f156ae84278 in __vfprintf_internal () from /lib64/libc.so.6 No symbol table info available. #2 0x00007f156af4775a in __vsyslog_internal () from /lib64/libc.so.6 No symbol table info available. #3 0x00007f156af47c3a in syslog () from /lib64/libc.so.6 No symbol table info available. #4 0x00000000007164b4 in qm_debug_check_frag (qm=0x7f1559053000, f=0x7f155a04cea0, file=0x7f15690cafe1 "tls: tls_init.c", line=405, efile=0x8a1659 "core/mem/q_malloc.c", eline=511) at core/mem/q_malloc.c:123 __llevel = -3 p = 0x10 __func__ = "qm_debug_check_frag" #5 0x000000000071a703 in qm_free (qmp=0x7f1559053000, p=0x7f155a04ced8, file=0x7f15690cafe1 "tls: tls_init.c", func=0x7f15690ccae0 <__func__.0> "ser_free", line=405, mname=0x7f15690caf52 "tls") at core/mem/q_malloc.c:511 qm = 0x7f1559053000 f = 0x7f155a04cea0 size = 140730841078464 next = 0x1 prev = 0x7f155908c6c8 __func__ = "qm_free" #6 0x0000000000725209 in qm_shm_free (qmp=0x7f1559053000, p=0x7f155a04ced8, file=0x7f15690cafe1 "tls: tls_init.c", func=0x7f15690ccae0 <__func__.0> "ser_free", line=405, mname=0x7f15690caf52 "tls") at core/mem/q_malloc.c:1350 No locals. #7 0x00007f15690843d6 in ser_free (ptr=0x7f155a04ced8, fname=0x7f1569b2d829 "crypto/err/err_local.h", fline=88) at tls_init.c:405 __func__ = "ser_free" #8 0x00007f156996d737 in err_clear (deall=0, i=<optimized out>, es=0x7f15590f6770) at crypto/err/err_local.h:88 No locals. #9 ERR_pop_to_mark () at crypto/err/err.c:902 es = 0x7f15590f6770 #10 0x00007f15699b3e42 in ossl_namemap_doall_names (namemap=<optimized out>, number=<optimized out>, fn=0x7f156999de80 <find_ameth>, data=0x7ffe73ca9bb0) at crypto/core_namemap.c:168 cbdata = {number = 107, names = 0x7f15597d9ca0, found = 2} num_names = <optimized out> i = <optimized out> #11 0x00007f156999f225 in EVP_PKEY_set_type_by_keymgmt (pkey=0x7f1559b1b918, keymgmt=0x7f15593dd430) at crypto/evp/p_lib.c:1633 str = {0x0, 0x0} __func__ = "EVP_PKEY_set_type_by_keymgmt" #12 0x00007f156999859a in evp_keymgmt_util_assign_pkey (pkey=0x7f1559b1b918, keymgmt=<optimized out>, keydata=0x7f1559cb4148) at crypto/evp/keymgmt_lib.c:64 __func__ = "evp_keymgmt_util_assign_pkey" #13 0x00007f15699a21c3 in evp_keymgmt_util_gen (cb=0x7f15699a04b0 <ossl_callback_to_pkey_gencb>, cbarg=0x7f1559b1cdf0, genctx=<optimized out>, keymgmt=<optimized out>, target=0x7f1559b1b918) at crypto/evp/keymgmt_lib.c:518 keydata = 0x7f1559cb4148 keydata = <optimized out> #14 EVP_PKEY_generate (ctx=ctx@entry=0x7f1559b1cdf0, ppkey=ppkey@entry=0x7ffe73ca9c70) at crypto/evp/pmeth_gn.c:189 ret = <optimized out> allocated_pkey = <optimized out> gentmp = {-1, -1} __func__ = "EVP_PKEY_generate" #15 0x00007f15699a23ce in EVP_PKEY_paramgen (ctx=ctx@entry=0x7f1559b1cdf0, ppkey=ppkey@entry=0x7ffe73ca9c70) at crypto/evp/pmeth_gn.c:265 __func__ = "EVP_PKEY_paramgen" #16 0x00007f1569d8082d in ssl_generate_param_group (s=0x7f1559ec7320, id=<optimized out>) at ssl/s3_lib.c:4751 --Type <RET> for more, q to quit, c to continue without paging-- pctx = 0x7f1559b1cdf0 pkey = 0x7f1559b1b918 ginf = 0x7f1559463030 __func__ = "ssl_generate_param_group" #17 0x00007f1569db52ea in tls_parse_ctos_key_share (s=0x7f1559ec7320, pkt=<optimized out>, context=<optimized out>, x=<optimized out>, chainidx=<optimized out>) at ssl/statem/extensions_srvr.c:664 group_id = <optimized out> key_share_list = {curr = 0x7f1559fef73d "", remaining = 0} encoded_pt = {curr = 0x7f1559fef71d "\\024\061\225\003+G\vz\224;\a\261\032D\212\066\304\370!\235!\304C\365\035)9", remaining = 32} clntgroups = 0x7f1559b1cd78 srvrgroups = 0x7f155945b478 clnt_num_groups = 5 srvr_num_groups = 10 found = 0 __func__ = "tls_parse_ctos_key_share" #18 0x00007f1569da7f79 in tls_parse_all_extensions (s=0x7f1559ec7320, context=128, exts=0x7f1559bc1068, x=0x0, chainidx=0, fin=1) at ssl/statem/extensions.c:753 i = 19 numexts = 26 thisexd = <optimized out> #19 0x00007f1569dd1cde in tls_early_post_process_client_hello (s=0x7f1559ec7320) at ssl/statem/statem_srvr.c:1862 j = <optimized out> loop = <optimized out> scsvs = 0x7f1559f649f8 al = 80 protverr = <optimized out> id = <optimized out> comp = 0x0 i = <optimized out> c = <optimized out> ciphers = 0x7f1559cb40c0 clienthello = 0x7f1559e950f0 dgrd = DOWNGRADE_NONE j = <optimized out> i = <optimized out> al = <optimized out> protverr = <optimized out> loop = <optimized out> id = <optimized out> comp = <optimized out> c = <optimized out> ciphers = <optimized out> scsvs = <optimized out> clienthello = <optimized out> dgrd = <optimized out> __func__ = {<optimized out> <repeats 36 times>} err = <optimized out> cipher = <optimized out> trc_out = <optimized out> pos = <optimized out> pref_cipher = <optimized out> master_key_length = <optimized out> m = <optimized out> --Type <RET> for more, q to quit, c to continue without paging-- comp_id = <optimized out> k = <optimized out> m = <optimized out> nn = <optimized out> v = <optimized out> done = <optimized out> o = <optimized out> #20 tls_post_process_client_hello (wst=<optimized out>, s=0x7f1559ec7320) at ssl/statem/statem_srvr.c:2189 rv = <optimized out> cipher = <optimized out> err = <optimized out> cipher = <optimized out> err = <optimized out> __func__ = {<optimized out> <repeats 30 times>} rv = <optimized out> rv = <optimized out> ret = <optimized out> #21 ossl_statem_server_post_process_message (s=s@entry=0x7f1559ec7320, wst=<optimized out>) at ssl/statem/statem_srvr.c:1236 st = <optimized out> __func__ = "ossl_statem_server_post_process_message" #22 0x00007f1569dbc2cb in read_state_machine (s=0x7f1559ec7320) at ssl/statem/statem.c:675 mt = <optimized out> pkt = {curr = 0x7f1559fef820 "", remaining = 0} max_message_size = <optimized out> ret = <optimized out> process_message = 0x7f1569dce720 <ossl_statem_server_process_message> post_process_message = <optimized out> st = 0x7f1559ec7368 len = <optimized out> transition = <optimized out> cb = 0x7f1569071e72 <sr_ssl_ctx_info_callback> st = <optimized out> ret = <optimized out> mt = <optimized out> len = <optimized out> transition = <optimized out> pkt = {curr = <optimized out>, remaining = <optimized out>} process_message = <optimized out> post_process_message = <optimized out> max_message_size = <optimized out> cb = <optimized out> __func__ = {<optimized out> <repeats 19 times>} #23 state_machine (s=0x7f1559ec7320, server=<optimized out>) at ssl/statem/statem.c:442 buf = 0x0 cb = <optimized out> st = <optimized out> ret = <optimized out> ssret = <optimized out> __func__ = {<optimized out> <repeats 14 times>} #24 0x00007f15690ac584 in tls_accept (c=0x7f1559af1e30, error=0x7ffe73cca124) at tls_server.c:470 ret = 0 ssl = 0x7f1559ec7320 --Type <RET> for more, q to quit, c to continue without paging-- cert = 0x1 tls_c = 0x7f1559eb7ca8 tls_log = 0 __func__ = "tls_accept" #25 0x00007f15690b78be in tls_h_read_f (c=0x7f1559af1e30, flags=0x7ffe73cca560) at tls_server.c:1175 r = 0x7f1559af1f58 bytes_free = 16383 bytes_read = 517 read_size = 16383 ssl_error = 0 ssl_read = 0 ssl = 0x7f1559ec7320 rd_buf = "\026\003\001\002\000\001\000\001\374\003\003\037~\204HD\300A\177\303\343\071\354Z\327t\203\377\334iC&\212ў\fװG*\222J\223 \027\213^8\025\212\346H\321·\332\063\060\352=\250\255\257\002\231\306{\026Cp\315\344\274\347\332#\000*\372\372\023\001\023\002\023\003\300,\300+̩\300\060\300/̨\300\n\300\t\300\024\300\023\000\235\000\234\000\065\000/\300\b\300\022\000\n\001\000\001\211\212\212\000\000\000\000\000\030\000\026\000\000\023webrtc.nebulaip.com\000\027\000\000\377\001\000\001\000\000\n\000\f\000\n\232\232\000\035\000\027\000\030\000\031\000\v\000\002\001\000\000\020\000\v\000\t\bhttp/1.1\000\005\000"... wr_buf = "@\241\313s\376\177\000\000\025\003\000\000\025\003\000\000\000\000\001\000\301X\252\275\204\313b\322\000\023\302:y}",\247\205\364R\353ؑ\372#\326\357'\354D\244\366_\336\355D\227U\360\071u\305WI\370BZ\262\303V\272j(;\363\035\363\372\062\025\365\276ݍm\207\344\373\346\355\320ť\026\235lp(v4/\b\373\276z\002\261U\005P#\230v\215\261O)\021\347\370\071\337\316r\336a\332#\357\245N,\353\024\215\267z\t\026\313u\354\023Jf(\370\227z\023 \242@hy+P\026CM\220c\r9f\374\277\213\025\t\322{\355\000\363Փ\256\v\303\375\027\201\303؇\202\316#Q\215Ds\001\021\254zSF\177\325\350\020\252|"... rd = {buf = 0x7ffe73cba120 "\026\003\001\002", pos = 517, used = 517, size = 65536} wr = {buf = 0x7ffe73caa120 "@\241\313s\376\177", pos = 0, used = 0, size = 65536} tls_c = 0x7f1559eb7ca8 enc_rd_buf = 0x0 n = 0 flush_flags = 0 err_src = 0x7f15690d45a0 "TLS read:" ip_buf = "93.95.124.6", '\000' <repeats 52 times> x = 1793780809 tls_dbg = 4095 __func__ = "tls_h_read_f" #26 0x00000000006c79bc in tcp_read_headers (c=0x7f1559af1e30, read_flags=0x7ffe73cca560) at core/tcp_read.c:441 bytes = 65535 remaining = 0 p = 0x2f759ab3eb3 <error: Cannot access memory at address 0x2f759ab3eb3> r = 0x7f1559af1f58 mc = 32533 body_len = 22955 mfline = 0x7f1559ab3c90 "\201\376\002\367\266/\375\257\344j\272\346\345{\270\375\226\\224ߌX\230\315\304[\236\201\330J\237\332\332N\224ߘL\222\302\226|\264\377\231\035ӟ\273%\253\306\327\025\335\374\377\177ҝ\230\037\322\370\345|\335\333\325\036\314ȄM\312\316\322\027\234\201\337A\213\316\332F\231\224\324]\234\301\325G\300ՏG\272\233\324dΙ\217\033ʟ\273%\260\316\316\002\273\300\304X\234\335\322\Ǐ\201\037\360\245\342@Ǐ\212\\224ߌX\230\315\304[\236\357\301J\237\335\302L\323\301\323M\210\303\327F\215\201\325@\220\221\273%\273\335\331BǏ\212\\224ߌX\230\315\304[\236\357\301J\237\335\302L\323\301\323M\210\303\327F\215\201"... mtransid = {s = 0x7f1559ab38e8 "V", len = 1504393472} __func__ = "tcp_read_headers" #27 0x00000000006cfb94 in tcp_read_req (con=0x7f1559af1e30, bytes_read=0x7ffe73cca564, read_flags=0x7ffe73cca560) at core/tcp_read.c:1469 bytes = -1 total_bytes = 0 resp = 1 size = 0 req = 0x7f1559af1f58 dst = {send_sock = 0x7f1559ab38e8, to = {s = {sa_family = 0, sa_data = "\000\020\002\000\000\000\001\000\314s\026\000\000"}, sin = {sin_family = 0, sin_port = 4096, sin_addr = {s_addr = 2}, sin_zero = "\001\000\314s\026\000\000"}, sin6 = {sin6_family = 0, sin6_port = 4096, sin6_flowinfo = 2, --Type <RET> for more, q to quit, c to continue without paging-- sin6_addr = {__in6_u = {__u6_addr8 = "\001\000\314s\026\000\000\000ಙ\000\000\000\000", __u6_addr16 = {1, 29644, 22, 0, 45792, 153, 0, 0}, __u6_addr32 = { 1942749185, 22, 10072800, 0}}}, sin6_scope_id = 1794407328}, sas = {ss_family = 0, __ss_padding = "\000\020\002\000\000\000\001\000\314s\026\000\000\000ಙ\000\000\000\000\000\240{\364j\025\177\000\000\200:\253Y\025\177\000\000\240\244\314s\250\204\257M\240\264\231\000\000\000\000\000\024\000\000\000\000\000\000\000\001\000\000\000\001\000\000\000\027\000\000\000\376\177\000\000-uQ\000\000\000\000\000X\245\314s\376\177\000\000\b", '\000' <repeats 22 times>, __ss_align = 140730841211888}}, id = 1, send_flags = {f = 0, blst_imask = 0}, proto = -48 '\320', proto_pad0 = -93 '\243', proto_pad1 = 29644} c = 0 '\000' ret = 0 __func__ = "tcp_read_req" #28 0x00000000006d4cc3 in handle_io (fm=0x7f156a799ce8, events=1, idx=-1) at core/tcp_read.c:1780 ret = 8 n = 8 read_flags = RD_CONN_SHORT_READ con = 0x7f1559af1e30 s = 23 resp = 1 t = 1303348392 ee = 0x0 __func__ = "handle_io" #29 0x00000000006c271d in io_wait_loop_epoll (h=0x99b2e0 <io_w>, t=2, repeat=0) at core/io_wait.h:1070 n = 1 r = 0 fm = 0x7f156a799ce8 revents = 1 __func__ = "io_wait_loop_epoll" #30 0x00000000006d7a47 in tcp_receive_loop (unix_sock=47) at core/tcp_read.c:1976 __func__ = "tcp_receive_loop" #31 0x00000000006b7689 in tcp_init_children (woneinit=0x7ffe73cca91c) at core/tcp_main.c:5239 r = 3 i = 3 reader_fd_1 = 47 pid = 0 si_desc = "tcp receiver (generic)\000\000\000\000\000\000\000\000\000\000\023e\204\000\000\000\000\000\033\000\000\000\000\000\000\000\240{\364j\025\177\000\000\000\000\000\020\000\000\000\000\260\250\314s\376\177\000\000\034\003e\000\000\000\000\000\260\250\314s\376\177\000\000\345\030n\000\000\000\000\000`\250\314s\376\177\000\000\252\264~\000\000\000\000\000\023e\204\000\000\000\000\000\310\311\bY \000\000" si = 0x0 __func__ = "tcp_init_children" #32 0x000000000042fae9 in main_loop () at main.c:1851 i = 4 pid = 1165 si = 0x0 si_desc = "udp receiver child=3 sock=172.16.128.55:5090\000\023\243\360\200\251\314s\376\177\000\000\000\000\000\000\000\000\000\000\340\256\314s\376\177\000\000\023e\204\000\000\000\000\000\033\000\000\000\000\000\000\000X_jj\025\177\000\000\000\000\000\020\000\000\000\000:|\364j\025\177\000\000\060\000\000\000\060\000\000\000\230\252\314s\376\177\000" nrprocs = 4 woneinit = 1 __func__ = "main_loop" #33 0x0000000000439969 in main (argc=11, argv=0x7ffe73ccaff8) at main.c:3086 cfg_stream = 0x1246380 c = -1 r = 0 tmp = 0x7ffe73ccbea5 "" --Type <RET> for more, q to quit, c to continue without paging-- tmp_len = 0 port = 0 proto = 0 ahost = 0x0 aport = 0 options = 0x8322d8 ":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 = 3223125455 rfd = 4 debug_save = 0 debug_flag = 0 dont_fork_cnt = 2 n_lst = 0x200000064 p = 0x0 st = {st_dev = 24, st_ino = 891, st_nlink = 2, st_mode = 16832, st_uid = 990, st_gid = 988, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1694643229, tv_nsec = 729000000}, st_mtim = {tv_sec = 1694643229, tv_nsec = 729000000}, st_ctim = {tv_sec = 1694643229, tv_nsec = 729000000}, __glibc_reserved = {0, 0, 0}} tbuf = "\331\f k\025\177\000\000\070\313\034k\025\177\000\000p\254\314s\376\177\000\000\a\000\000\000\000\000\000\000ظ\034k\025\177\000\000\a\000\000\000#\000\000\000\060\032 k\025\177\000\000\245\346\035k\025\177\000\000\000\000\000\000\000\000\000\000\220\371\035k\025\177\000\000\070\000\341j\025\177\000\000\000*\034k\025\177\000\000\000\000\000\000\000\000\000\000@\254\314s\376\177\000\000\360\016 k\025\177\000\000\330\312\034k\025\177\000\000\330\312\034k\025\177\000\000\000\000\000\000\000\000\000\000\330\070\034k\025\177\000\000@\254\314s\376\177\000\000\220% k\025\177\000\000\000\260\034k\025\177\000\000\022\274\034k\025\177\000\000\066\261\035k\025\177\000\000\344#\340j\025\177\000\000\272"... option_index = 12 long_options = {{name = 0x834976 "help", has_arg = 0, flag = 0x0, val = 104}, {name = 0x82f4f4 "version", has_arg = 0, flag = 0x0, val = 118}, { name = 0x83497b "alias", has_arg = 1, flag = 0x0, val = 1024}, {name = 0x834981 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name = 0x834987 "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name = 0x834990 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name = 0x83499a "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x8349a4 "loadmodule", has_arg = 1, flag = 0x0, val = 1029}, {name = 0x8349af "modparam", has_arg = 1, flag = 0x0, val = 1030}, {name = 0x8349b8 "log-engine", has_arg = 1, flag = 0x0, val = 1031}, {name = 0x8349c3 "debug", has_arg = 1, flag = 0x0, val = 1032}, { name = 0x8349c9 "cfg-print", has_arg = 0, flag = 0x0, val = 1033}, {name = 0x8349d3 "atexit", has_arg = 1, flag = 0x0, val = 1034}, { name = 0x8349da "all-errors", has_arg = 0, flag = 0x0, val = 1035}, {name = 0x0, has_arg = 0, flag = 0x0, val = 0}} __func__ = "main" ``
`` (gdb) info locals No symbol table info available. ``
#### Log Messages
``` Sep 13 22:39:41 kamrtc01 /usr/sbin/kamailio[2110]: INFO: <core> [core/cfg/cfg_ctx.c:599]: cfg_set_now(): tls.low_mem_threshold1 has been changed to 14155776 Sep 13 22:39:41 kamrtc01 /usr/sbin/kamailio[2110]: INFO: <core> [core/cfg/cfg_ctx.c:599]: cfg_set_now(): tls.low_mem_threshold2 has been changed to 7077888
Sep 13 22:39:40 kamrtc01 /usr/sbin/kamailio[1184]: INFO: <script>: START: REGISTER from sip:webrtc@webrtc.nebulaip.com (IP:90.251.178.17:52715) Sep 13 22:39:40 kamrtc01 /usr/sbin/kamailio[1185]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f155a04cde0), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring Sep 13 22:39:40 kamrtc01 kernel: kamailio[1186]: segfault at 60 ip 00007f156ae338aa sp 00007ffe73ca9118 error 4 in libc.so.6[7f156ae28000+175000] Sep 13 22:39:40 kamrtc01 kernel: Code: f3 0f 1e fa 66 0f ef c0 66 0f ef c9 66 0f ef d2 66 0f ef db 48 89 f8 48 89 f9 48 81 e1 ff 0f 00 00 48 81 f9 cf 0f 00 00 77 66 <f3> 0f 6f 20 66 0f 74 e0 66 0f d7 d4 85 d2 74 04 0f bc c2 c3 48 83 Sep 13 22:39:40 kamrtc01 systemd[1]: Started Process Core Dump (PID 2102/UID 0). Sep 13 22:39:41 kamrtc01 systemd-coredump[2103]: Process 1186 (kamailio) of user 990 dumped core.#012#012Stack trace of thread 1186:#012#0 0x00007f156ae338aa __strlen_sse2 (libc.so.6 + 0x338aa)#012#1 0x00007f156ae84278 __vfprintf_internal (libc.so.6 + 0x84278)#012#2 0x00007f156af4775a __vsyslog_internal (libc.so.6 + 0x14775a)#012#3 0x00007f156af47c3a syslog (libc.so.6 + 0x147c3a)#012#4 0x00000000007164b4 qm_debug_check_frag (kamailio + 0x3164b4)#012#5 0x000000000071a703 qm_free (kamailio + 0x31a703)#012#6 0x0000000000725209 qm_shm_free (kamailio + 0x325209)#012#7 0x00007f15690843d6 ser_free (tls.so + 0x313d6)#012#8 0x00007f156996d737 ERR_pop_to_mark (libcrypto.so.3 + 0x16d737)#012#9 0x00007f15699b3e42 ossl_namemap_doall_names (libcrypto.so.3 + 0x1b3e42)#012#10 0x00007f156999f225 EVP_PKEY_set_type_by_keymgmt (libcrypto.so.3 + 0x19f225)#012#11 0x00007f156999859a evp_keymgmt_util_assign_pkey (libcrypto.so.3 + 0x19859a)#012#12 0x00007f15699a21c3 EVP_PKEY_generate (libcrypto.so.3 + 0x1a21c3)#012#13 0x00007f1569d8082d ssl_generate_param_group (libssl.so.3 + 0x2682d)#012#14 0x00007f1569db52ea tls_parse_ctos_key_share (libssl.so.3 + 0x5b2ea)#012#15 0x00007f1569da7f79 tls_parse_all_extensions (libssl.so.3 + 0x4df79)#012#16 0x00007f1569dd1cde ossl_statem_server_post_process_message (libssl.so.3 + 0x77cde)#012#17 0x00007f1569dbc2cb state_machine.part.0 (libssl.so.3 + 0x622cb)#012#18 0x00007f15690ac584 tls_accept (tls.so + 0x59584)#012#19 0x00007f15690b78be tls_h_read_f (tls.so + 0x648be)#012#20 0x00000000006c79bc tcp_read_headers (kamailio + 0x2c79bc)#012#21 0x00000000006cfb94 tcp_read_req (kamailio + 0x2cfb94)#012#22 0x00000000006d4cc3 handle_io (kamailio + 0x2d4cc3)#012#23 0x00000000006c271d io_wait_loop_epoll (kamailio + 0x2c271d)#012#24 0x00000000006d7a47 tcp_receive_loop (kamailio + 0x2d7a47)#012#25 0x00000000006b7689 tcp_init_children (kamailio + 0x2b7689)#012#26 0x000000000042fae9 main_loop (kamailio + 0x2fae9)#012#27 0x0000000000439969 main (kamailio + 0x39969)#012#28 0x00007f156ae3feb0 __libc_start_call_main (libc.so.6 + 0x3feb0)#012#29 0x00007f156ae3ff60 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x3ff60)#012#30 0x000000000041dc65 _start (kamailio + 0x1dc65)#012ELF object binary architecture: AMD x86-64 Sep 13 22:39:41 kamrtc01 systemd[1]: systemd-coredump@0-2102-0.service: Deactivated successfully. Sep 13 22:39:41 kamrtc01 /usr/sbin/kamailio[893]: ALERT: <core> [main.c:776]: handle_sigs(): child process 1186 exited by a signal 11 Sep 13 22:39:41 kamrtc01 /usr/sbin/kamailio[1145]: INFO: <core> [main.c:856]: sig_usr(): signal 15 received
```
#### SIP Traffic
<!-- If the issue is exposed by processing specific SIP messages, grab them with ngrep or save in a pcap file, then add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site). -->
``` (paste your sip traffic here) ```
### Possible Solutions
Nope, sorry, completely out of my depth on this one.
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
``` version: kamailio 5.7.1 (x86_64/linux) 4238e4 flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, MEM_JOIN_FREE, 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_BLOCKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED 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: 4238e4 compiled on 00:00:00 May 23 2022 with gcc 11.3.1
rpm Build Date : Mon 11 Sep 2023 19:02:26 UTC
```
* **Operating System**:
``` Oracle Enterprise Linux 9 (RHEL 9 clone) Linux kamrtc01.voiceflex.com 5.14.0-284.25.1.0.1.el9_2.x86_64 #1 SMP PREEMPT_DYNAMIC Fri Aug 4 09:00:16 PDT 2023 x86_64 x86_64 x86_64 GNU/Linux openssl-3.0.7-17.0.1.el9_2.x86_64 glibc-2.34-60.0.2.el9.x86_64 libgcc-11.3.1-4.3.0.1.el9.x86_64 kamailio-5.7.1-1.el9.x86_64 kamailio-ims-5.7.1-1.el9.x86_64 kamailio-mysql-5.7.1-1.el9.x86_64 kamailio-redis-5.7.1-1.el9.x86_64 kamailio-regex-5.7.1-1.el9.x86_64 kamailio-snmpstats-5.7.1-1.el9.x86_64 kamailio-tls-5.7.1-1.el9.x86_64 kamailio-websocket-5.7.1-1.el9.x86_64 kamailio-debuginfo-5.7.1-1.el9.x86_64 kamailio-ims-debuginfo-5.7.1-1.el9.x86_64 kamailio-mysql-debuginfo-5.7.1-1.el9.x86_64 kamailio-redis-debuginfo-5.7.1-1.el9.x86_64 kamailio-regex-debuginfo-5.7.1-1.el9.x86_64 kamailio-snmpstats-debuginfo-5.7.1-1.el9.x86_64 kamailio-tls-debuginfo-5.7.1-1.el9.x86_64 kamailio-websocket-debuginfo-5.7.1-1.el9.x86_64 ```
Unfortunately Oracle do not seem to have published recent glibc libgcc libstdc++ or sssd-client debuginfo packages. I will attempt to contact them to ask them to add those.
If you are using OpenSSL 3 can you use the following config https://kamailio.org/docs/modules/devel/modules/tls.html#tls.p.init_mode:
``` modparam("tls", "init_mode", 1) ```
It was not set. Will try that now, thanks.
Crashed twice more in quick succession after restarting with that parameter included
``` PID: 8813 (kamailio) UID: 990 (kamailio) GID: 988 (kamailio) Signal: 6 (ABRT) Timestamp: Thu 2023-09-14 02:13:40 UTC (2min 18s ago) Command Line: /usr/sbin/kamailio -DD -P /run/kamailio/kamailio.pid -f /etc/kamailio/kamailio.cfg -m 256 -M 8 --atexit=no Executable: /usr/sbin/kamailio Control Group: /system.slice/kamailio.service Unit: kamailio.service Slice: system.slice Boot ID: 3fc4251c606f4c6183610573f44c46ba Machine ID: 16e913e686424f13b970f9b1044cc6b3 Hostname: kamrtc01.voiceflex.com Storage: /var/lib/systemd/coredump/core.kamailio.990.3fc4251c606f4c6183610573f44c46ba.8813.1694657620000000.zst (present) Size on Disk: 2.8M Message: Process 8813 (kamailio) of user 990 dumped core.
Stack trace of thread 8813: #0 0x00007f86152a158c __pthread_kill_implementation (libc.so.6 + 0xa158c) #1 0x00007f8615254d46 raise (libc.so.6 + 0x54d46) #2 0x00007f86152287f3 abort (libc.so.6 + 0x287f3) #3 0x00000000007164db qm_debug_check_frag (kamailio + 0x3164db) #4 0x000000000071a703 qm_free (kamailio + 0x31a703) #5 0x0000000000725209 qm_shm_free (kamailio + 0x325209) #6 0x00007f861344a3d6 ser_free (tls.so + 0x313d6) #7 0x00007f8613d6d737 ERR_pop_to_mark (libcrypto.so.3 + 0x16d737) #8 0x00007f8613db3e42 ossl_namemap_doall_names (libcrypto.so.3 + 0x1b3e42) #9 0x00007f8613d9f225 EVP_PKEY_set_type_by_keymgmt (libcrypto.so.3 + 0x19f225) #10 0x00007f8613d9859a evp_keymgmt_util_assign_pkey (libcrypto.so.3 + 0x19859a) #11 0x00007f8613da21c3 EVP_PKEY_generate (libcrypto.so.3 + 0x1a21c3) #12 0x00007f861418082d ssl_generate_param_group (libssl.so.3 + 0x2682d) #13 0x00007f86141b52ea tls_parse_ctos_key_share (libssl.so.3 + 0x5b2ea) #14 0x00007f86141a7f79 tls_parse_all_extensions (libssl.so.3 + 0x4df79) #15 0x00007f86141d1cde ossl_statem_server_post_process_message (libssl.so.3 + 0x77cde) #16 0x00007f86141bc2cb state_machine.part.0 (libssl.so.3 + 0x622cb) #17 0x00007f8613472584 tls_accept (tls.so + 0x59584) #18 0x00007f861347d8be tls_h_read_f (tls.so + 0x648be) #19 0x00000000006c79bc tcp_read_headers (kamailio + 0x2c79bc) #20 0x00000000006cfb94 tcp_read_req (kamailio + 0x2cfb94) #21 0x00000000006d4cc3 handle_io (kamailio + 0x2d4cc3) #22 0x00000000006c271d io_wait_loop_epoll (kamailio + 0x2c271d) #23 0x00000000006d7a47 tcp_receive_loop (kamailio + 0x2d7a47) #24 0x00000000006b7689 tcp_init_children (kamailio + 0x2b7689) #25 0x000000000042fae9 main_loop (kamailio + 0x2fae9) #26 0x0000000000439969 main (kamailio + 0x39969) #27 0x00007f861523feb0 __libc_start_call_main (libc.so.6 + 0x3feb0) #28 0x00007f861523ff60 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x3ff60) #29 0x000000000041dc65 _start (kamailio + 0x1dc65) ELF object binary architecture: AMD x86-64 ``` then ``` PID: 9487 (kamailio) UID: 990 (kamailio) GID: 988 (kamailio) Signal: 11 (SEGV) Timestamp: Thu 2023-09-14 02:14:53 UTC (2min 23s ago) Command Line: /usr/sbin/kamailio -DD -P /run/kamailio/kamailio.pid -f /etc/kamailio/kamailio.cfg -m 256 -M 8 --atexit=no Executable: /usr/sbin/kamailio Control Group: /system.slice/kamailio.service Unit: kamailio.service Slice: system.slice Boot ID: 3fc4251c606f4c6183610573f44c46ba Machine ID: 16e913e686424f13b970f9b1044cc6b3 Hostname: kamrtc01.voiceflex.com Storage: /var/lib/systemd/coredump/core.kamailio.990.3fc4251c606f4c6183610573f44c46ba.9487.1694657693000000.zst (present) Size on Disk: 2.3M Message: Process 9487 (kamailio) of user 990 dumped core.
Stack trace of thread 9487: #0 0x00007f932d339fa4 EC_GROUP_get_field_type (libcrypto.so.3 + 0x139fa4) #1 0x00007f932d33cb59 ossl_ec_key_public_check_quick (libcrypto.so.3 + 0x13cb59) #2 0x00007f932d46fb15 ec_validate.lto_priv.0 (libcrypto.so.3 + 0x26fb15) #3 0x00007f932d3a1ca1 try_provided_check (libcrypto.so.3 + 0x1a1ca1) #4 0x00007f932d3a1d31 evp_pkey_public_check_combined (libcrypto.so.3 + 0x1a1d31) #5 0x00007f932d397943 EVP_PKEY_derive_set_peer_ex (libcrypto.so.3 + 0x197943) #6 0x00007f932df81b6b ssl_derive (libssl.so.3 + 0x28b6b) #7 0x00007f932dfce63b ossl_statem_server_process_message (libssl.so.3 + 0x7563b) #8 0x00007f932dfbadbf state_machine.part.0 (libssl.so.3 + 0x61dbf) #9 0x00007f932cb24584 tls_accept (tls.so + 0x59584) #10 0x00007f932cb2f8be tls_h_read_f (tls.so + 0x648be) #11 0x00000000006c79bc tcp_read_headers (kamailio + 0x2c79bc) #12 0x00000000006cfb94 tcp_read_req (kamailio + 0x2cfb94) #13 0x00000000006d6097 handle_io (kamailio + 0x2d6097) #14 0x00000000006c271d io_wait_loop_epoll (kamailio + 0x2c271d) #15 0x00000000006d7a47 tcp_receive_loop (kamailio + 0x2d7a47) #16 0x00000000006b7689 tcp_init_children (kamailio + 0x2b7689) #17 0x000000000042fae9 main_loop (kamailio + 0x2fae9) #18 0x0000000000439969 main (kamailio + 0x39969) #19 0x00007f932e83feb0 __libc_start_call_main (libc.so.6 + 0x3feb0) #20 0x00007f932e83ff60 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x3ff60) #21 0x000000000041dc65 _start (kamailio + 0x1dc65) ELF object binary architecture: AMD x86-64 ```
Can you try tls_wolfssl or tlsa + OpenSSL 1.1.1?
This is a RHEL 9 clone and the only SSL packages in the repos are openssl 3.0.7 so it's that or nothing.
So the first of those crashes after setting tls init_mode 1 wrote this to the logs
``` Sep 14 02:13:40 kamrtc01 /usr/sbin/kamailio[8815]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f8603d45dc8), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring Sep 14 02:13:40 kamrtc01 /usr/sbin/kamailio[8813]: CRITICAL: <core> [core/mem/q_malloc.c:123]: qm_debug_check_frag(): BUG: qm: fragm. 0x7f8603d45e10 (address 0x7f8603d45e48) beginning overwritten (195)! Memory allocator was called from tls: tls_init.c:405. Fragment marked by :140213825900370. Exec from core/mem/q_malloc.c:511. Sep 14 02:13:40 kamrtc01 systemd[1]: Started Process Core Dump (PID 9454/UID 0). Sep 14 02:13:41 kamrtc01 systemd-coredump[9455]: Process 8813 (kamailio) of user 990 dumped core.#012#012Stack trace of thread 8813:#012#0 0x00007f86152a158c __pthread_kill_implementation (libc.so.6 + 0xa158c)#012#1 0x00007f8615254d46 raise (libc.so.6 + 0x54d46)#012#2 0x00007f86152287f3 abort (libc.so.6 + 0x287f3)#012#3 0x00000000007164db qm_debug_check_frag (kamailio + 0x3164db)#012#4 0x000000000071a703 qm_free (kamailio + 0x31a703)#012#5 0x0000000000725209 qm_shm_free (kamailio + 0x325209)#012#6 0x00007f861344a3d6 ser_free (tls.so + 0x313d6)#012#7 0x00007f8613d6d737 ERR_pop_to_mark (libcrypto.so.3 + 0x16d737)#012#8 0x00007f8613db3e42 ossl_namemap_doall_names (libcrypto.so.3 + 0x1b3e42)#012#9 0x00007f8613d9f225 EVP_PKEY_set_type_by_keymgmt (libcrypto.so.3 + 0x19f225)#012#10 0x00007f8613d9859a evp_keymgmt_util_assign_pkey (libcrypto.so.3 + 0x19859a)#012#11 0x00007f8613da21c3 EVP_PKEY_generate (libcrypto.so.3 + 0x1a21c3)#012#12 0x00007f861418082d ssl_generate_param_group (libssl.so.3 + 0x2682d)#012#13 0x00007f86141b52ea tls_parse_ctos_key_share (libssl.so.3 + 0x5b2ea)#012#14 0x00007f86141a7f79 tls_parse_all_extensions (libssl.so.3 + 0x4df79)#012#15 0x00007f86141d1cde ossl_statem_server_post_process_message (libssl.so.3 + 0x77cde)#012#16 0x00007f86141bc2cb state_machine.part.0 (libssl.so.3 + 0x622cb)#012#17 0x00007f8613472584 tls_accept (tls.so + 0x59584)#012#18 0x00007f861347d8be tls_h_read_f (tls.so + 0x648be)#012#19 0x00000000006c79bc tcp_read_headers (kamailio + 0x2c79bc)#012#20 0x00000000006cfb94 tcp_read_req (kamailio + 0x2cfb94)#012#21 0x00000000006d4cc3 handle_io (kamailio + 0x2d4cc3)#012#22 0x00000000006c271d io_wait_loop_epoll (kamailio + 0x2c271d)#012#23 0x00000000006d7a47 tcp_receive_loop (kamailio + 0x2d7a47)#012#24 0x00000000006b7689 tcp_init_children (kamailio + 0x2b7689)#012#25 0x000000000042fae9 main_loop (kamailio + 0x2fae9)#012#26 0x0000000000439969 main (kamailio + 0x39969)#012#27 0x00007f861523feb0 __libc_start_call_main (libc.so.6 + 0x3feb0)#012#28 0x00007f861523ff60 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x3ff60)#012#29 0x000000000041dc65 _start (kamailio + 0x1dc65)#012ELF object binary architecture: AMD x86-64 ```
and the second wrote
``` Sep 14 02:14:53 kamrtc01 /usr/sbin/kamailio[9487]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f931d685ac8), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring Sep 14 02:14:53 kamrtc01 kernel: kamailio[9487]: segfault at 4 ip 00007f932d339fa4 sp 00007ffd5e317f58 error 4 in libcrypto.so.3.0.7[7f932d2ad000+25b000] Sep 14 02:14:53 kamrtc01 kernel: Code: 00 00 00 0f 1f 00 f3 0f 1e fa 8b 47 20 c3 0f 1f 84 00 00 00 00 00 f3 0f 1e fa 48 8b 47 40 c3 0f 1f 80 00 00 00 00 f3 0f 1e fa <48> 8b 07 8b 40 04 c3 0f 1f 44 00 00 f3 0f 1e fa 89 77 24 c3 0f 1f
Sep 14 02:14:53 kamrtc01 systemd-coredump[9542]: Process 9487 (kamailio) of user 990 dumped core.#012#012Stack trace of thread 9487:#012#0 0x00007f932d339fa4 EC_GROUP_get_field_type (libcrypto.so.3 + 0x139fa4)#012#1 0x00007f932d33cb59 ossl_ec_key_public_check_quick (libcrypto.so.3 + 0x13cb59)#012#2 0x00007f932d46fb15 ec_validate.lto_priv.0 (libcrypto.so.3 + 0x26fb15)#012#3 0x00007f932d3a1ca1 try_provided_check (libcrypto.so.3 + 0x1a1ca1)#012#4 0x00007f932d3a1d31 evp_pkey_public_check_combined (libcrypto.so.3 + 0x1a1d31)#012#5 0x00007f932d397943 EVP_PKEY_derive_set_peer_ex (libcrypto.so.3 + 0x197943)#012#6 0x00007f932df81b6b ssl_derive (libssl.so.3 + 0x28b6b)#012#7 0x00007f932dfce63b ossl_statem_server_process_message (libssl.so.3 + 0x7563b)#012#8 0x00007f932dfbadbf state_machine.part.0 (libssl.so.3 + 0x61dbf)#012#9 0x00007f932cb24584 tls_accept (tls.so + 0x59584)#012#10 0x00007f932cb2f8be tls_h_read_f (tls.so + 0x648be)#012#11 0x00000000006c79bc tcp_read_headers (kamailio + 0x2c79bc)#012#12 0x00000000006cfb94 tcp_read_req (kamailio + 0x2cfb94)#012#13 0x00000000006d6097 handle_io (kamailio + 0x2d6097)#012#14 0x00000000006c271d io_wait_loop_epoll (kamailio + 0x2c271d)#012#15 0x00000000006d7a47 tcp_receive_loop (kamailio + 0x2d7a47)#012#16 0x00000000006b7689 tcp_init_children (kamailio + 0x2b7689)#012#17 0x000000000042fae9 main_loop (kamailio + 0x2fae9)#012#18 0x0000000000439969 main (kamailio + 0x39969)#012#19 0x00007f932e83feb0 __libc_start_call_main (libc.so.6 + 0x3feb0)#012#20 0x00007f932e83ff60 __libc_start_main@@GLIBC_2.34 (libc.so.6 + 0x3ff60)#012#21 0x000000000041dc65 _start (kamailio + 0x1dc65)#012ELF object binary architecture: AMD x86-64 Sep 14 02:14:53 kamrtc01 systemd[1]: systemd-coredump@9-9541-0.service: Deactivated successfully. Sep 14 02:14:53 kamrtc01 /usr/sbin/kamailio[9488]: CRITICAL: <core> [core/pass_fd.c:84]: recv_all(): 1st recv on 46 failed: Connection reset by peer Sep 14 02:14:53 kamrtc01 /usr/sbin/kamailio[9488]: CRITICAL: <core> [core/tcp_main.c:3635]: handle_tcp_child(): read from tcp child 3 (pid 9487, no 25) Connection reset by peer [104] Sep 14 02:14:53 kamrtc01 /usr/sbin/kamailio[9488]: CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 43 ```
I've also seen that in the current run that has not crashed I see things like this in the log
``` Sep 14 02:26:37 kamrtc01 /usr/sbin/kamailio[9593]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f8f6efd0078), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring Sep 14 02:26:37 kamrtc01 /usr/sbin/kamailio[9594]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f8f6eccf120), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring Sep 14 02:28:47 kamrtc01 /usr/sbin/kamailio[9591]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f8f6ecf01a8), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring Sep 14 02:28:47 kamrtc01 /usr/sbin/kamailio[9594]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f8f6efd72c8), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring Sep 14 02:32:09 kamrtc01 /usr/sbin/kamailio[9592]: INFO: <script>: START: REGISTER from sip:webrtc@webrtc.nebulaip.com (IP:92.239.255.130:50125) Sep 14 02:32:09 kamrtc01 /usr/sbin/kamailio[9592]: INFO: <script>: START: REGISTER from sip:webrtc@webrtc.nebulaip.com (IP:92.239.255.130:50125) Sep 14 02:32:12 kamrtc01 /usr/sbin/kamailio[9593]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f8f6ef7f298), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring Sep 14 02:32:12 kamrtc01 /usr/sbin/kamailio[9594]: CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing already freed pointer (0x7f8f6ef7f3a0), called from tls: tls_init.c: ser_free(405), first free tls: tls_init.c: ser_free(405) - ignoring ```
I think that in every case of those sets of pairs of messages they are associated with those START:REGISTER from messages that come from the same ip address and same port with the same timestamp.
@themsley-voiceflex - I am able to reproduce OpenSSL crashes now with EL9 + OpenSSL 3. I thought this had been fixed with the pthread locking work but it seems more complicated than that.
To isolate the problem I have created a build kamailio of 5.7.2/EL9 with a `tls_wolfssl` subpackage for testing here: https://copr.fedorainfracloud.org/coprs/beaveryoga/Kamailio/
Usage: replace `tls.so` in the config file with `tls_wolfssl.so`; comment out the `init_mode` param setting as this is not used by `tls_wolfssl`.
Disclaimer: this is for testing purposes *ONLY*; it's on Copr as I haven't figured out openSUSE OBS yet.
Thanks for the update, I will try to test this out of hours one night to see if it improves stability.
So it didn't actually crash but I took this out again after a few minutes due to errors in the log. There are some that look "normal" but others that definitely do not. Normal ones look like this
Oct 9 20:06:11 kamrtc01 /usr/sbin/kamailio[1171]: INFO: tls_wolfssl [tls_domain.c:742]: sr_ssl_ctx_info_callback(): SSL handshake done Oct 9 20:06:11 kamrtc01 /usr/sbin/kamailio[1171]: ERROR: <core> [core/tcp_read.c:269]: tcp_read_data(): error reading: Connection reset by peer (104) ([x.x.134.10]:60314 -> Oct 9 20:06:11 kamrtc01 /usr/sbin/kamailio[1171]: ERROR: <core> [core/tcp_read.c:273]: tcp_read_data(): -> [y.y.124.6]:7443) Oct 9 20:06:11 kamrtc01 /usr/sbin/kamailio[1171]: ERROR: <core> [core/tcp_read.c:1476]: tcp_read_req(): ERROR: tcp_read_req: error reading - c: 0x7fa39fdb8ee8 r: 0x7fa39fdb9010 (-1)
Fairly sure those are just noisy and do not affect anything but we do see quite a lot of them. The more worrying ones are
Oct 9 20:06:38 kamrtc01 /usr/sbin/kamailio[1174]: WARNING: websocket [ws_frame.c:393]: decode_and_validate_ws_frame(): WebSocket reserved fields with non-zero values
Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1174]: INFO: <script>: START: REGISTER from sip:webrtc@webrtc.nebulaip.com (IP:z.z.241.224:38116) Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1174]: BUG: tls_wolfssl [tls_server.c:861]: tls_h_encode_f(): write buffer too small (65536/65536 bytes) Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1174]: ERROR: websocket [ws_frame.c:275]: encode_and_send_ws_frame(): sending WebSocket frame Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1174]: ERROR: websocket [ws_frame.c:737]: ws_frame_transmit(): sending message Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1178]: ERROR: <core> [core/tcp_main.c:3903]: handle_ser_child(): received CON_ERROR for 0x7fa3a0517ec8 (id 346), refcnt 5, flags 0x4018 Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1174]: ERROR: registrar [reply.c:734]: reg_reply_helper(): failed to send 200 OK Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1174]: WARNING: sl [../../core/forward.h:203]: msg_send_buffer(): TCP/TLS connection for WebSocket could not be found Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1174]: ERROR: sl [sl_funcs.c:418]: sl_reply_error(): stateless error reply used: I'm terribly sorry, server error occurred (1/SL) Oct 9 20:07:20 kamrtc01 /usr/sbin/kamailio[1174]: WARNING: <core> [core/tcp_read.c:1838]: handle_io(): F_TCPCONN connection marked as bad: 0x7fa3a0517ec8 id 346 fd 18 refcnt 1 ([z.z.241.224]:38116 -> [z.z.241.224]:7443)
The duplicate mention of z.z.241.224 in that last message looks wrong. That is not our server ip but the 7443 port is the one in use on our side.
It started issuing those write buffer too small errors after about 1m10s uptime and they were then continuously issued for the next 30s before I stopped it.
This issue is stale because it has been open 6 weeks with no activity. Remove stale label or comment or this will be closed in 2 weeks.
Closed #3563 as not planned.
I reworked the init_mode=1 yesterday, with commits pushed to git master and 5.7 branches. Try again with one of these latest versions. The crash is not related to websockets, but to tls, seems to be like in #3635 (/notexpired).
Reopened #3563.
I don't think I am able to recreate this any more. We were using freeswitch as a webrtc server but it had its own issues so we tried to use kamailio as a substitute for that and that's when we saw this lot. I've subsequently chased the freeswitch bug (their bug #2283) through and they have fixed their issues and we are back using that as our webrtc server.
I guess that if you really need a guinea pig to test this I could resurrect the kamailio VM we were using and switch it in overnight when it's barely used and see how it holds up. We get hundreds if not thousands of registrations over webrtc per day but the actual server does about 50 calls a day so it's either either quite busy or not very busy at all depending on how you look at it!
If you want to test again and you are using debian packages, you have to switch to nightly apt repo for 5.7 series and wait one more day, because I pushed a bit earlier today another commit because the one from yesterday introduced another issue.
We're RHEL 9 (well actually a mix of OEL 9/Rocky and Alma 9) so I build kamailio packages from SRPM and deploy them. I presume this is only on master?
The commits are in master and 5.7 branches.
Closing with commits on current master and 5.7. Probably fixed by thread-locals rework.
Closed #3563 as completed.
-
Daniel-Constantin Mierla -
github-actions[bot]
-
space88man
-
themsley-voiceflex