Description

Started from the minimal proxy config, we tried to run more than 1 process using TLS, and, unforntunately it crashed.

Everything is working fine using TLS with 1 child.
Everything is working fine with more than 1 child process without TLS.

To ease the reproduction, we set an env var called TARGET at container instanciation, its value is set to a reachable SIP address using TLS (without DNS resolution).

To reproduce issue you will need pjsip/pjsua with SSL/TLS enabled:

We've seen on some issues that a low memory allocation could be an issue using TLS, so we are running kamailio using more memory kamailio -DD -E -M 256 -m 1024 (still crashing).

Troubleshooting

Reproduction

Here are the steps to reproduce the issue:

@@ -1,4 +1,5 @@
 #!KAMAILIO
+#!define WITH_TLS
 #
 # Kamailio (OpenSER) SIP Server v5.2 - default configuration script
 #     - web: https://www.kamailio.org
@@ -28,7 +29,7 @@
 ####### Global Parameters #########

 ### LOG Levels: 3=DBG, 2=INFO, 1=NOTICE, 0=WARN, -1=ERR
-debug=2
+debug=3
 log_stderror=no

 memdbg=5
@@ -38,10 +39,13 @@ log_facility=LOG_LOCAL0
 log_prefix="{$mt $hdr(CSeq) $ci} "

 /* number of SIP routing processes */
-children=2
+children=1

 /* uncomment the next line to disable TCP (default on) */
 # disable_tcp=yes
+#!ifdef WITH_TLS
+enable_tls=yes
+#!endif

 /* uncomment the next line to disable the auto discovery of local aliases
  * based on reverse DNS on IPs (default on) */
@@ -65,6 +69,9 @@ children=2
 ####### Modules Section ########

 /* set paths to location of modules */
+#!ifdef WITH_TLS
+loadmodule "tls.so"
+#!endif
 loadmodule "jsonrpcs.so"
 loadmodule "kex.so"
 loadmodule "corex.so"
@@ -85,6 +92,9 @@ loadmodule "counters.so"

 # ----------------- setting module-specific parameters ---------------

+#!ifdef WITH_TLS
+modparam("tls", "config", "/etc/kamailio/tls.cfg")
+#!endif

 # ----- jsonrpcs params -----
 modparam("jsonrpcs", "pretty_format", 1)
@@ -180,7 +190,7 @@ request_route {
        }

        # update $du to set the destination address for proxying
-       $du = "sip:" + $rd + ":9";
+       $du = $env(TARGET);
        route(RELAY);
        exit;
 }
[server:default]
method = TLSv1
verify_certificate = no
require_certificate = no
private_key = /etc/kamailio/privkey.pem
certificate = /etc/kamailio/server-cert.pem

[client:default]
#method = TLSv1
verify_certificate = no
require_certificate = no
FROM kamailio/kamailio-ci:master-alpine

# Override default kamailio configuration
COPY kamailio.cfg /etc/kamailio/kamailio.cfg
COPY tls.cfg /etc/kamailio/tls.cfg
COPY privkey.pem /etc/kamailio/privkey.pem
COPY server-cert.pem /etc/kamailio/server-cert.pem

docker run -it -p 5061:5061/tcp -e "TARGET=sip:AA.BB.CC.DD;transport=tls" kamailio-tls-issue
pjsua --stun-srv=stun.l.google.com:19302 --use-tls --no-tcp --no-udp --use-srtp=2 --local-port=5062 --id=sip:alice@localhost "sip:bob@localhost;transport=tls"

Everything should work fine because we only used 1 child process

Log Messages

Log messages from kamailio proxy:

11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <script>: new branch [0] to sip:bob@localhost;transport=tls
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/msg_translator.c:2933]: create_via_hf(): id added: <;i=1>, rcv proto=3
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/tcp_main.c:1747]: tcp_send(): no open tcp connection found, opening new one
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection: 34.240.160.168
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/tcp_main.c:999]: tcpconn_new(): on port 5061, type 3
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/tcp_main.c:1305]: tcpconn_add(): hashes: 1752:0:0, 2
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} tls [tls_server.c:199]: tls_complete_init(): completing tls connection initialization
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} tls [tls_server.c:162]: tls_get_connect_server_name(): xavp with outbound server name not found
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} tls [tls_server.c:142]: tls_get_connect_server_id(): xavp with outbound server id not found
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} tls [tls_server.c:228]: tls_complete_init(): Using initial TLS domain TLSc<default> (dom 0x7fe7740bdaf0 ctx 0x55d98553ca40 sn [])
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} tls [tls_domain.c:1155]: tls_lookup_private_key(): Private key lookup for SSL_CTX-0x55d98553ca40: 0
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} tls [tls_domain.c:737]: sr_ssl_ctx_info_callback(): SSL handshake started
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/tcp_main.c:2641]: tcpconn_1st_send(): pending write on new connection 0x7fe7742cd200 (-1/122 bytes written) (err: 11 - Resource temporarily unavailable)
13(18) DEBUG: <core> [core/tcp_main.c:3540]: handle_ser_child(): read response= 7fe7742cd200, 5, fd 29 from 11 (16)
13(18) DEBUG: <core> [core/io_wait.h:380]: io_watch_add(): DBG: io_watch_add(0x55d984d52f20, 29, 2, 0x7fe7742cd200), fd_no=18
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} tm [t_funcs.c:372]: t_relay_to(): new transaction forwarded
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/receive.c:353]: receive_msg(): request-route executed in: 10827 usec
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list 0
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list 0
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list 0
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list 0
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list 0
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/usr_avp.c:636]: destroy_avp_list(): destroying list 0
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/xavp.c:495]: xavp_destroy_list(): destroying xavp list 0
11(16) DEBUG: {1 32554 INVITE 1k3Hcf7IVCnjmhjZIJXU5S0x-LRhyB2x} <core> [core/receive.c:457]: receive_msg(): cleaning up
13(18) DEBUG: <core> [core/io_wait.h:777]: io_watch_chg(): DBG: io_watch_chg (0x55d984d52f20, 29, 0x1, 0xffffffff) fd_no=19 called
13(18) DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x55d984d52f20, 29, -1, 0x0) fd_no=19 called
13(18) DEBUG: <core> [core/tcp_main.c:4196]: handle_tcpconn_ev(): sending to child, events 1
13(18) DEBUG: <core> [core/tcp_main.c:3875]: send2child(): selected tcp worker 1 12(17) for activity on [tls:172.17.0.2:5061], 0x7fe7742cd200
12(17) DEBUG: <core> [core/tcp_read.c:1767]: handle_io(): received n=8 con=0x7fe7742cd200, fd=7
13(18) DEBUG: <core> [core/tcp_main.c:3279]: handle_tcp_child(): dead tcp child 1 (pid 17, no 12) (shutting down?)
13(18) DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x55d984d52f20, 27, -1, 0x0) fd_no=18 called
13(18) CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 24
13(18) DEBUG: <core> [core/tcp_main.c:3512]: handle_ser_child(): dead child 12, pid 17 (shutting down?)
13(18) DEBUG: <core> [core/io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x55d984d52f20, 24, -1, 0x0) fd_no=17 called
0(1) ALERT: <core> [main.c:740]: handle_sigs(): child process 17 exited by a signal 11
0(1) ALERT: <core> [main.c:743]: handle_sigs(): core was generated
0(1) INFO: <core> [main.c:766]: handle_sigs(): terminating due to SIGCHLD
0(1) DEBUG: <core> [main.c:768]: handle_sigs(): terminating due to SIGCHLD
10(15) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
1(6) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
8(13) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
7(12) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
6(11) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
5(10) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
4(9) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
3(8) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
13(18) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
9(14) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
11(16) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
2(7) INFO: <core> [main.c:821]: sig_usr(): signal 15 received
0(1) DEBUG: tm [t_funcs.c:85]: tm_shutdown(): start
0(1) DEBUG: tm [t_funcs.c:88]: tm_shutdown(): emptying hash table
0(1) DEBUG: tm [h_table.c:133]: free_cell_helper(): freeing transaction 0x7fe7742c9580 from h_table.c:465
0(1) DEBUG: tm [t_funcs.c:90]: tm_shutdown(): removing semaphores
0(1) DEBUG: tm [t_funcs.c:92]: tm_shutdown(): destroying tmcb lists
0(1) DEBUG: tm [t_funcs.c:95]: tm_shutdown(): done

Additional Information

Kamailio was running on Linux Alpine from kamailio/kamailio-ci:master-alpine docker image.

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