Description

Intermittent CRITICAL memory use after free at startup.

Troubleshooting

Reproduction

This happens intermittently on startup. Because our container restarts automatically and the issue is not seen other than at startup it is ultimately innocuous. But the restarts are a false alarm for sys admin.

Debugging Data

(paste your debugging data here)

Log Messages

Sep 10 15:29:22 product-name process-name[1764]: new user 'admin@172.51.1.1' added
Sep 10 15:29:22 product-name process-name[1764]: Starting xxxx 1.5.8-0+gxxxxxxxx
Sep 10 15:29:22 product-name process-name[1764]: Setting core dump pattern
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_init.c:503]: init_tls_compression(): disabling compression...
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [core/sctp_core.c:74]: sctp_core_check_support(): SCTP API not enabled - if you want to use it, load sctp module
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [core/tcp_main.c:5042]: init_tcp(): using epoll_lt as the io watch method (auto detected)
Sep 10 15:29:22 product-name process-name[1764]: Listening on
Sep 10 15:29:22 product-name process-name[1764]:             udp: 172.51.1.1:5060 advertise 172.51.1.1:5060
Sep 10 15:29:22 product-name process-name[1764]:             tcp: 172.51.1.1:5060 advertise 172.51.1.1:5060
Sep 10 15:29:22 product-name process-name[1764]:             tls: 172.51.1.1:5061 advertise 172.51.1.1:5060
Sep 10 15:29:22 product-name process-name[1764]: Aliases:
Sep 10 15:29:22 product-name process-name[1764]:             tls: bb48d50a0892:5061
Sep 10 15:29:22 product-name process-name[1764]:             tcp: bb48d50a0892:5060
Sep 10 15:29:22 product-name process-name[1764]:             udp: bb48d50a0892:5060
Sep 10 15:29:22 product-name process-name[1764]:             *: 172.51.1.1:*
Sep 10 15:29:22 product-name process-name[1764]: 
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: db_sqlite [db_sqlite.c:218]: mod_init(): SQlite library version 3.16.2 (compiled using 3.16.2)
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: rr [../outbound/api.h:52]: ob_load_api(): unable to import bind_ob - maybe module is not loaded
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: rr [rr_mod.c:177]: mod_init(): outbound module not available
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: http_async_client [http_async_client_mod.c:222]: mod_init(): Initializing Http Async module
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: [App] xxxx init
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: [---] Location reporting format: custom-1
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: [---] Logging of location reporting: DISABLED
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_mod.c:377]: mod_init(): With ECDH-Support!
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_mod.c:380]: mod_init(): With Diffie Hellman
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: auth [auth_mod.c:345]: mod_init(): qop set, but nonce-count (nonce_count) support disabled
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_init.c:719]: init_tls_h(): compiled  with  openssl  version "OpenSSL 1.0.2u  20 Dec 2019" (0x1000215f), kerberos support: off, compression: on
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_init.c:723]: init_tls_h(): installed openssl library version "OpenSSL 1.0.2u  20 Dec 2019" (0x1000215f), kerberos support: off,  zlib compression: off
Sep 10 15:29:22 product-name process-name[1764]: compiler: gcc -I. -I.. -I../include  -fPIC -DOPENSSL_PIC -DOPENSSL_THREADS -D_REENTRANT -DDSO_DLFCN -DHAVE_DLFCN_H -m64 -DL_ENDIAN -g -O2 -fdebug-prefix-map=/build/openssl1.0-NNAFzi/openssl1.0-1.0.2u=. -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -Wl,-z,relro -Wa,--noexecstack -Wall -DMD32_REG_T=int -DOPENSSL_IA32_SSE2 -DOPENSSL_BN_ASM_MONT -DOPENSSL_BN_ASM_MONT5 -DOPENSSL_BN_ASM_GF2m -DRC4_ASM -DSHA1_ASM -DSHA256_ASM -DSHA512_ASM -DMD5_ASM -DAES_ASM -DVPAES_ASM -DBSAES_ASM -DWHIRLPOOL_ASM -DGHASH_ASM -DECP_NISTZ256_ASM
Sep 10 15:29:22 product-name process-name[1764]: 0(1) WARNING: tls [tls_init.c:784]: init_tls_h(): openssl bug #1491 (crash/mem leaks on low memory) workaround enabled (on low memory tls operations will fail preemptively) with free memory thresholds 7864320 and 3932160 bytes
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [core/cfg/cfg_ctx.c:595]: cfg_set_now(): tls.low_mem_threshold1 has been changed to 7864320
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [core/cfg/cfg_ctx.c:595]: cfg_set_now(): tls.low_mem_threshold2 has been changed to 3932160
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [main.c:2779]: main(): processes (at least): 15 - shm size: 67108864 - pkg size: 8388608
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [core/udp_server.c:154]: probe_max_receive_buffer(): SO_RCVBUF is initially 212992
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [core/udp_server.c:206]: probe_max_receive_buffer(): SO_RCVBUF is finally 425984
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: http_async_client [async_http.c:101]: async_http_init_sockets(): inter-process event notification sockets initialized
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: http_async_client [async_http.c:101]: async_http_init_sockets(): inter-process event notification sockets initialized
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:303]: ksr_tls_fill_missing(): TLSs<default>: tls_method=18
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:315]: ksr_tls_fill_missing(): TLSs<default>: certificate='/etc/kamailio/publickey.pem'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:322]: ksr_tls_fill_missing(): TLSs<default>: ca_list='(null)'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:329]: ksr_tls_fill_missing(): TLSs<default>: crl='(null)'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:333]: ksr_tls_fill_missing(): TLSs<default>: require_certificate=0
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:340]: ksr_tls_fill_missing(): TLSs<default>: cipher_list='(null)'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:347]: ksr_tls_fill_missing(): TLSs<default>: private_key='/etc/kamailio/privatekey.pem'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:351]: ksr_tls_fill_missing(): TLSs<default>: verify_certificate=0
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:354]: ksr_tls_fill_missing(): TLSs<default>: verify_depth=9
Sep 10 15:29:22 product-name process-name[1764]: 0(1) NOTICE: tls [tls_domain.c:1087]: ksr_tls_fix_domain(): registered server_name callback handler for socket [:0], server_name='<default>' ...
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:707]: set_verification(): TLSs<default>: No client certificate required and no checks performed
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:303]: ksr_tls_fill_missing(): TLSc<default>: tls_method=18
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:315]: ksr_tls_fill_missing(): TLSc<default>: certificate='(null)'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:322]: ksr_tls_fill_missing(): TLSc<default>: ca_list='/etc/kamailio/sipcacert.pem'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:329]: ksr_tls_fill_missing(): TLSc<default>: crl='(null)'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:333]: ksr_tls_fill_missing(): TLSc<default>: require_certificate=1
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:340]: ksr_tls_fill_missing(): TLSc<default>: cipher_list='(null)'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:347]: ksr_tls_fill_missing(): TLSc<default>: private_key='(null)'
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:351]: ksr_tls_fill_missing(): TLSc<default>: verify_certificate=1
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:354]: ksr_tls_fill_missing(): TLSc<default>: verify_depth=9
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: tls [tls_domain.c:692]: set_verification(): TLSc<default>: Server MUST present valid certificate
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: http_async_client [async_http.c:84]: async_http_init_worker(): started worker process: 1
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: http_async_client [async_http.c:84]: async_http_init_worker(): started worker process: 2
Sep 10 15:29:22 product-name process-name[1764]: 8(160) INFO: ctl [io_listener.c:214]: io_listen_loop(): io_listen_loop:  using epoll_lt io watch method (config)
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [main.c:783]: handle_sigs(): SIGCHLD received, but no child has stopped, ignoring it
Sep 10 15:29:22 product-name process-name[1764]: 6(158) CRITICAL: <core> [core/mem/q_malloc.c:646]: qm_realloc(): BUG: trying to realloc an already freed pointer 0x7f7d3413f928 , fragment 0x7f7d3413f8f0 -- aborting
Sep 10 15:29:22 product-name process-name[1764]: 14(166) CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 23
Sep 10 15:29:22 product-name process-name[1764]: 0(1) ALERT: <core> [main.c:766]: handle_sigs(): child process 158 exited by a signal 6
Sep 10 15:29:22 product-name process-name[1764]: 0(1) ALERT: <core> [main.c:769]: handle_sigs(): core was not generated
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [main.c:792]: handle_sigs(): terminating due to SIGCHLD
Sep 10 15:29:22 product-name process-name[1764]: 1(153) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 2(154) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 4(156) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 14(166) CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 15
Sep 10 15:29:22 product-name process-name[1764]: 3(155) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 14(166) CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 18
Sep 10 15:29:22 product-name process-name[1764]: 7(159) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 5(157) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 9(161) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 10(162) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 8(160) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 11(163) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 14(166) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 13(165) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 12(164) INFO: <core> [main.c:847]: sig_usr(): signal 15 received
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: db_sqlite [db_sqlite.c:227]: mod_destroy(): SQlite terminate
Sep 10 15:29:22 product-name process-name[1764]: 0(1) INFO: <core> [core/sctp_core.c:53]: sctp_core_destroy(): SCTP API not initialized

SIP Traffic

Occurs at startup before SIP traffic relevant.

Possible Solutions

Additional Information

• Kamailio Version - output of kamailio -v

version: kamailio 5.3.4 (x86_64/linux) f7690e-dirty
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: f7690e -dirty
compiled with gcc 6.3.0

• Operating System:

Running under docker on Centos 7
Linux bb48d50a0892 3.10.0-1062.el7.x86_64 #1 SMP Wed Aug 7 18:08:02 UTC 2019 x86_64 GNU/Linux

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or unsubscribe.