[sr-dev] [kamailio/kamailio] tls module causes too many small fragments when tls connection time out (Issue #2943)

Mon Nov 22 08:09:13 CET 2021

### Description
I made sipp 3000 calls test with tls connection in both caller side and callee side. After 3000calls are all established, the sipp will stay for 1min and then shut down all the network interfaces(iptables -I INPUT -j DROP) to let all tls connections timeout. And then repeat this test over and over again . But after some rounds of this kind of test, the calls can not reach 3000, only 2900calls will meet "out of mem" issue. The log is :+1: fm_malloc(): fm_malloc(0x7fd314a68000, 256760) called from core: tcp_main.c: tcpconn_new(1886), module: core; Free fragment not found!
Our reliminary analysis:  1. this is not memory leak issue,   2. tls module malloc too many small fragments, which causes shared memory pool's utility reduced (we can see core.shmmem show us the free >= 200MB and fragments >=600000. But there is no consecutive free frags for a new tls connections)

### Reproduction
Settings:
/opt/kamailio/sbin/kamailio -m 2048 -M 64
----------------------cfg-------------------------
enable_tls=yes
tls_port_no=SIP_LISTEN_PORT_V6
tls_max_connections=102400
tcp_connection_lifetime=3605
tcp_max_connections=102400
dns_cache_min_ttl=1800
open_files_limit=102400
tcp_no_connect=no
tcp_conn_wq_max=10240000
tcp_async=no
tcp_rd_buf_size=256000
-----------------------------------------

Topology:
sipp caller ------tls--------kamailio-----tls-------sipp callee   (3000calls = 6000 tls connections)
sipp and kamailio are running in the same PC

Step1:  start sipp 3000 call test
Step2:  after 3000 calls are all established,  execute "iptables -I INPUT -j DROP"
Step3:  wait for all connections are timeout
Step4:  go to Step1: restart sipp scripts

### Expected Behavior
3000 calls test will always be successful

#### Log Messages
------------------------------this is the log of "after 2900 calls"----------------------------
Nov 16 05:36:27 kamailio[3103]: ERROR: <core> [mem/f_malloc.c:416]: fm_search_defrag(): fm_search_defrag(0x7fd314a68000, 256760); Free fragment not found!
Nov 16 05:36:27 kamailio[3103]: ERROR: <core> [mem/f_malloc.c:499]: fm_malloc(): fm_malloc(0x7fd314a68000, 256760) called from core: tcp_main.c: tcpconn_new(1886), module: core; Free fragment not found!
Nov 16 05:36:27 kamailio[3103]: ERROR: <core> [tcp_main.c:1888]: tcpconn_new(): mem. allocation failure
-----------------------------this is corex.shm_summary of "after 2900 calls"------------------------------
corex [corex_rpc.c:176]: corex_rpc_shm_summary(): printing shared memory summary report
fm_status: summarizing all alloc'ed. fragments:
fm_status:  count=  2928 size=    113296 bytes from tls: tls_ct_q.h: tls_ct_q_add(58)
fm_status:  count=  5857 size=1504098328 bytes from core: tcp_main.c: tcpconn_new(1886)
fm_status:  count=     1 size=      8192 bytes from core: counters.c: counters_prefork_init(207)
fm_status:  count=    22 size=       688 bytes from core: cfg_parser.c: cfg_parse_str(906)
fm_status:  count=     8 size=      1024 bytes from tls: tls_domain.c: fix_domain(1004)
fm_status:  count=  5856 size=    307200 bytes from tls: tls_server.c: tls_complete_init(228)
fm_status:  count=     1 size=      3072 bytes from sl: sl_stats.c: init_sl_stats_child(125)
fm_status:  count=     1 size=       768 bytes from kex: pkg_stats.c: pkg_proc_stats_init(79)
fm_status:  count=     5 size=       152 bytes from core: cfg/cfg_struct.c: cfg_clone_str(130)
fm_status:  count=     1 size=       712 bytes from core: cfg/cfg_struct.c: cfg_shmize(217)
fm_status:  count=     1 size=      2240 bytes from core: pt.c: init_pt(104)
fm_status:  count=     1 size=         8 bytes from core: pt.c: init_pt(110)
fm_status:  count=     1 size=         8 bytes from core: pt.c: init_pt(105)
fm_status:  count=     3 size=       120 bytes from gs: gs_mod.c: _append_to_blacklist_unsafe(692)
fm_status:  count=     3 size=        48 bytes from gs: gs_mod.c: _append_to_blacklist_unsafe(684)
fm_status:  count=  1008 size=     40320 bytes from gs: gs_mod.c: _append_to_backend_server_list_unsafe(472)
fm_status:  count=  1008 size=     16128 bytes from gs: gs_mod.c: _append_to_backend_server_list_unsafe(465)
fm_status:  count=  1011 size=     32352 bytes from gs: gs_mod.c: _update_one_slot_in_gs_hash_table_by_domain_dir(892)
fm_status:  count=  1011 size=     48528 bytes from gs: gs_mod.c: _update_one_slot_in_gs_hash_table_by_domain_dir(883)
fm_status:  count= 65536 size=   3670016 bytes from gs: gs_mod.c: mod_init(267)
fm_status:  count=     1 size=   1048576 bytes from gs: gs_mod.c: mod_init(260)
fm_status:  count=     1 size=        24 bytes from outbound: ob_mod.c: mod_init(104)
fm_status:  count=     1 size=        24 bytes from utils: conf.c: conf_init(549)
fm_status:  count=     1 size=         8 bytes from utils: utils.c: init_shmlock(160)
fm_status:  count=     8 size=      1536 bytes from tls: tls_domain.c: tls_new_domain(160)
fm_status:  count=     2 size=        96 bytes from tls: tls_domain.c: tls_new_cfg(1317)
fm_status:  count=     1 size=         8 bytes from tls: tls_ct_wrq.c: tls_ct_wq_init(49)
fm_status:  count=     1 size=         8 bytes from tls: tls_mod.c: mod_init(406)
fm_status:  count=     1 size=         8 bytes from tls: tls_mod.c: mod_init(390)
fm_status:  count=     1 size=         8 bytes from sl: sl_funcs.c: sl_startup(83)
fm_status:  count=     1 size=         8 bytes from sl: sl_stats.c: init_sl_stats(110)
fm_status:  count=     2 size=        64 bytes from core: cfg/cfg_ctx.c: cfg_register_ctx(47)
fm_status:  count= 63282 size=   2975704 bytes from tls: tls_init.c: ser_realloc(292)
fm_status:  count=     1 size=      8192 bytes from core: tcp_main.c: init_tcp(5649)
fm_status:  count=     1 size=     32768 bytes from core: tcp_main.c: init_tcp(5643)
fm_status:  count=     1 size=         8 bytes from core: tcp_main.c: init_tcp(5635)
fm_status:  count=     1 size=         8 bytes from core: tcp_main.c: init_tcp(5628)
fm_status:  count=     1 size=         8 bytes from core: tcp_main.c: init_tcp(5621)
fm_status:  count=     1 size=         8 bytes from core: tcp_main.c: init_tcp(5615)
fm_status:  count=     1 size=         8 bytes from core: tcp_main.c: init_tcp(5603)
fm_status:  count=     1 size=         8 bytes from core: usr_avp.c: init_avps(90)
fm_status:  count=     1 size=         8 bytes from core: usr_avp.c: init_avps(89)
fm_status:  count=     1 size=     16384 bytes from core: dst_blacklist.c: init_dst_blacklist(437)
fm_status:  count=     1 size=         8 bytes from core: dst_blacklist.c: init_dst_blacklist(430)
fm_status:  count=     2 size=        96 bytes from core: timer.c: timer_alloc(514)
fm_status:  count=     1 size=         8 bytes from core: dns_cache.c: init_dns_cache(369)
fm_status:  count=     1 size=     16384 bytes from core: dns_cache.c: init_dns_cache(361)
fm_status:  count=     1 size=        16 bytes from core: dns_cache.c: init_dns_cache(354)
fm_status:  count=     1 size=         8 bytes from core: dns_cache.c: init_dns_cache(345)
fm_status:  count=     1 size=         8 bytes from core: timer.c: init_timer(283)
fm_status:  count=     1 size=     16384 bytes from core: timer.c: init_timer(282)
fm_status:  count=     1 size=         8 bytes from core: timer.c: init_timer(281)
fm_status:  count=     1 size=         8 bytes from core: timer.c: init_timer(280)
fm_status:  count=     1 size=         8 bytes from core: timer.c: init_timer(269)
fm_status:  count=     1 size=         8 bytes from core: timer.c: init_timer(237)
fm_status:  count=     1 size=    278544 bytes from core: timer.c: init_timer(220)
fm_status:  count=     1 size=         8 bytes from core: timer.c: init_timer(219)
fm_status:  count=     1 size=         8 bytes from core: timer.c: init_timer(206)
fm_status:  count=     1 size=        64 bytes from core: cfg/cfg_struct.c: cfg_child_cb_new(830)
fm_status:  count=     1 size=         8 bytes from core: cfg/cfg_struct.c: sr_cfg_init(361)
fm_status:  count=     1 size=         8 bytes from core: cfg/cfg_struct.c: sr_cfg_init(354)
fm_status:  count=     1 size=         8 bytes from core: cfg/cfg_struct.c: sr_cfg_init(347)
fm_status:  count=     1 size=         8 bytes from core: cfg/cfg_struct.c: sr_cfg_init(335)
fm_status:  count=     1 size=         8 bytes from core: cfg/cfg_struct.c: sr_cfg_init(323)
fm_status:  count=502731 size= 292261096 bytes from tls: tls_init.c: ser_malloc(286)
fm_status:  count=     1 size=        24 bytes from tls: ../../lock_alloc.h: lock_set_alloc(70)
fm_status:  count=     1 size=         8 bytes from core: mem/shm.c: shm_core_lock_init(153)
fm_status: -----------------------------

-- 
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/2943
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20211121/949b76e2/attachment-0001.htm>