[kamailio/kamailio] Kamailio 5.3.0 crashed when exec module tried to execute external program (#2165)
### Description
<!-- Explain what you did, what you expected to happen, and what actually happened. -->
In some cases we need to call zabbix_sender utility to notify that some failure happens. At this time we move our configs from Kamailio 4.4.7 to Kamailio 5.3.0 and during testing we meet this issue.
We configured exec module to kill the program after 20 seconds ``` modparam("exec", "time_to_kill", 20) .... exec_avp("/usr/bin/zabbix_sender --config ZABBIX_AGENT_CONFIG_PATH --key ecsp_no_telephony --value 1");
```
zabbix_sender could not connect to server and were hanged up.
Kamailio probably tried to kill it and crashed.
### Troubleshooting
#### Reproduction
<!-- If the issue can be reproduced, describe how it can be done. -->
#### Debugging Data
<!-- If you got a core dump, use gdb to extract troubleshooting data - full backtrace, local variables and the list of the code at the issue location.
gdb /path/to/kamailio /path/to/corefile bt full
``` (gdb) bt full #0 0x00007f57a4397e4b in run_failure_handlers (t=0x7f579d31b8c8, rpl=0xffffffffffffffff, code=408, extra_flags=32) at t_reply.c:1020 faked_req = 0x7f579d31f4a0 faked_req_len = 7264 shmem_msg = 0x7f579d31cf88 on_failure = 1 keng = 0x0 __FUNCTION__ = "run_failure_handlers" #1 0x00007f57a439b6ff in t_should_relay_response (Trans=0x7f579d31b8c8, new_code=408, branch=0, should_store=0x7ffdc1d48efc, should_relay=0x7ffdc1d48f00, cancel_data=0x7ffdc1d48fb0, reply=0xffffffffffffffff) at t_reply.c:1390 branch_cnt = 1 picked_code = 408 new_branch = 0 inv_through = 0 extra_flags = 32 i = 0 replies_dropped = 0 __FUNCTION__ = "t_should_relay_response" #2 0x00007f57a43a04ae in relay_reply (t=0x7f579d31b8c8, p_msg=0xffffffffffffffff, branch=0, msg_status=408, cancel_data=0x7ffdc1d48fb0, do_put_on_wait=0) at t_reply.c:1821 relay = -1043034112 save_clone = 0 buf = 0x0 res_len = 0 relayed_code = 0 relayed_msg = 0x0 reply_bak = 0x0 bm = {to_tag_val = {s = 0x419140 <_start> "1\355I\211\321^H\211\342H\203\344\360PTI\307\300\020yw", len = -1043032080}} totag_retr = 0 reply_status = RPS_ERROR uas_rb = 0x7f579d31cc10 to_tag = 0x7f579d31ba98 reason = {s = 0x0, len = -2058737957} onsend_params = {req = 0x419140 <_start>, rpl = 0x7ffdc1d497f0, param = 0x0, code = 0, flags = 0, branch = 0, t_rbuf = 0x7ffdc1d48fd0, dst = 0x7f57a1935bb9 <db_timer_udomain+1213>, send_buf = {s = 0x50ffffffff <Address 0x50ffffffff out of bounds>, len = -1657680744}} ip = {af = 26069008, len = 0, u = {addrl = {12898834416, 0}, addr32 = {13932528, 3, 0, 0}, addr16 = {38896, 212, 3, 0, 0, 0, 0, 0}, addr = "\360\227\324\000\003\000\000\000\000\000\000\000\000\000\000"}} __FUNCTION__ = "relay_reply" #3 0x00007f57a43f0b80 in fake_reply (t=0x7f579d31b8c8, branch=0, code=408) at timer.c:294 cancel_data = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len = -1657685816}, e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = -1657685816}}}} do_cancel_branch = 0 reply_status = 12458 #4 0x00007f57a43f100d in final_response_handler (r_buf=0x7f579d31baf0, t=0x7f579d31b8c8) at timer.c:455 silent = 0 branch_ret = 0 prev_branch = 0 now = 0 #5 0x00007f57a43f10bc in retr_buf_handler (ticks=1687494363, tl=0x7f579d31bb10, p=0x1f40) at timer.c:511 rbuf = 0x7f579d31baf0 fr_remainder = 1 retr_remainder = 32599 retr_interval = 2634899704 new_retr_interval_ms = 7546900672 crt_retr_interval_ms = 140014273782008 t = 0x7f579d31b8c8 __FUNCTION__ = "retr_buf_handler" #6 0x00000000004bb4f9 in slow_timer_main () at core/timer.c:1104 n = 12 ---Type <return> to continue, or q <return> to quit--- ret = 4294967295 tl = 0x7f579d31bb10 i = 951 __FUNCTION__ = "slow_timer_main" #7 0x000000000042655f in main_loop () at main.c:1727 i = 20 pid = 0 si = 0x0 si_desc = "udp receiver child=19 sock=127.0.0.1:16060\000\066\060 (5.17.138.141:16060)\000\000\000\000\000\000\310\026\t\235W\177", '\000' <repeats 14 times>, "\001\000\000\000`\222\324\301\375\177\000\000\061\212j\000\000\000\000\000\300\352z\000\000\000\000\000Xv<\250W\177\000" nrprocs = 20 woneinit = 1 __FUNCTION__ = "main_loop" #8 0x000000000042e56a in main (argc=15, argv=0x7ffdc1d497f8) at main.c:2802 cfg_stream = 0x17e0010 c = -1 r = 0 tmp = 0x7ffdc1d49f44 "" tmp_len = 0 port = 0 proto = 0 ahost = 0x0 aport = 0 options = 0x77b510 ":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 = 4246587393 rfd = 4 debug_save = 0 debug_flag = 0 dont_fork_cnt = 0 n_lst = 0x2f2f2f2f2f2f2f2f p = 0x0 st = {st_dev = 19, st_ino = 22551, st_nlink = 2, st_mode = 16832, st_uid = 0, st_gid = 0, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = { tv_sec = 1575037545, tv_nsec = 784790655}, st_mtim = {tv_sec = 1571941656, tv_nsec = 613426287}, st_ctim = {tv_sec = 1571941656, tv_nsec = 613426287}, __unused = {0, 0, 0}} tbuf = "\000\000\000\000\000\000\000\000\240\223\324\301\375\177\000\000\210+\251\250W\177\000\000\350\363\251\250W\177\000\000\260\224\324\301\375\177\000\000\240\224\324\301\375\177\000\000.", '\000' <repeats 23 times>, "\300\365H\251W\177\000\000\000\360H\251W\177\000\000\270\366@\000\000\000\000\000\320\377\251\250W\177\000\000\230=@\000\000\000\000\000\000\000\000\000\001\000\000\000D\b\000\000\001", '\000' <repeats 11 times>, "h\225\324\301\375\177\000\000@\225\324\301\375\177\000\000\001\000\000\000\000\000\000\000\300\365H\251W\177\000\000\250\324I\251W\177\000\000P\321I\251W\177\000\000O@(\251W\177\000\000\000\000\000\000\000\000\000\000"... option_index = 0 long_options = {{name = 0x77e08a "help", has_arg = 0, flag = 0x0, val = 104}, {name = 0x777dac "version", has_arg = 0, flag = 0x0, val = 118}, {name = 0x77e08f "alias", has_arg = 1, flag = 0x0, val = 1024}, {name = 0x77e095 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name = 0x77e09b "substdef", has_arg = 1, flag = 0x0, val = 1026}, { name = 0x77e0a4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name = 0x77e0ae "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0, has_arg = 0, flag = 0x0, val = 0}} __FUNCTION__ = "main"
```
info locals
``` (gdb) info locals cfg_stream = 0x17e0010 c = -1 r = 0 tmp = 0x7ffdc1d49f44 "" tmp_len = 0 port = 0 proto = 0 ahost = 0x0 aport = 0 options = 0x77b510 ":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 = 4246587393 rfd = 4 debug_save = 0 debug_flag = 0 dont_fork_cnt = 0 n_lst = 0x2f2f2f2f2f2f2f2f p = 0x0 st = {st_dev = 19, st_ino = 22551, st_nlink = 2, st_mode = 16832, st_uid = 0, st_gid = 0, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = { tv_sec = 1575037545, tv_nsec = 784790655}, st_mtim = {tv_sec = 1571941656, tv_nsec = 613426287}, st_ctim = {tv_sec = 1571941656, tv_nsec = 613426287}, __unused = {0, 0, 0}} tbuf = "\000\000\000\000\000\000\000\000\240\223\324\301\375\177\000\000\210+\251\250W\177\000\000\350\363\251\250W\177\000\000\260\224\324\301\375\177\000\000\240\224\324\301\375\177\000\000.", '\000' <repeats 23 times>, "\300\365H\251W\177\000\000\000\360H\251W\177\000\000\270\366@\000\000\000\000\000\320\377\251\250W\177\000\000\230=@\000\000\000\000\000\000\000\000\000\001\000\000\000D\b\000\000\001", '\000' <repeats 11 times>, "h\225\324\301\375\177\000\000@\225\324\301\375\177\000\000\001\000\000\000\000\000\000\000\300\365H\251W\177\000\000\250\324I\251W\177\000\000P\321I\251W\177\000\000O@(\251W\177\000\000\000\000\000\000\000\000\000\000"... option_index = 0 long_options = {{name = 0x77e08a "help", has_arg = 0, flag = 0x0, val = 104}, {name = 0x777dac "version", has_arg = 0, flag = 0x0, val = 118}, {name = 0x77e08f "alias", has_arg = 1, flag = 0x0, val = 1024}, {name = 0x77e095 "subst", has_arg = 1, flag = 0x0, val = 1025}, {name = 0x77e09b "substdef", has_arg = 1, flag = 0x0, val = 1026}, {name = 0x77e0a4 "substdefs", has_arg = 1, flag = 0x0, val = 1027}, {name = 0x77e0ae "server-id", has_arg = 1, flag = 0x0, val = 1028}, {name = 0x0, has_arg = 0, flag = 0x0, val = 0}} __FUNCTION__ = "main"
```
list
``` (gdb) list 1015 } 1016 exec_post_script_cb(faked_req, FAILURE_CB_TYPE); 1017 } 1018 log_prefix_set(NULL); 1019 /* update message flags, if changed in failure route */ 1020 t->uas.request->flags = faked_req->flags; 1021 } 1022 1023 /* restore original environment */ 1024 faked_env( t, 0, 0);
```
#### Log Messages
<!-- Check the syslog file and if there are relevant log messages printed by Kamailio, add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site). -->
``` Dec 5 12:25:08 sip-proxy01 /usr/ecsp/sbin/kamailio[12458]: NOTICE: <script>: zabbix_sender (ecsp_no_telephony) Dec 5 12:25:09 sip-proxy01 /usr/ecsp/sbin/kamailio[12417]: ALERT: <core> [main.c:767]: handle_sigs(): child process 12458 exited by a signal 11 Dec 5 12:25:09 sip-proxy01 /usr/ecsp/sbin/kamailio[12466]: CRITICAL: <core> [core/pass_fd.c:277]: receive_fd(): EOF on 50 Dec 5 12:25:09 sip-proxy01 /usr/ecsp/sbin/kamailio[12417]: ALERT: <core> [main.c:770]: handle_sigs(): core was generated
```
#### 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
<!-- If you found a solution or workaround for the issue, describe it. Ideally, provide a pull request with a fix. -->
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
``` version: kamailio 5.3.0 (x86_64/linux) 4cc67a 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: 4cc67a compiled on 14:01:24 Nov 28 2019 with gcc 4.8.5 ```
* **Operating System**:
<!-- Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04, CentOS 7.1, ...), MacOS, xBSD, Solaris, ...; Kernel details (output of `uname -a`) -->
``` Linux sip-proxy01 3.10.0-1062.4.1.el7.x86_64 #1 SMP Fri Oct 18 17:15:30 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
CentOS Linux release 7.7.1908 (Core)
```
Thanks for the report. A core was generated, could you post the backtrace (e.g. "gdb bt") from the core file here as well?
``` (gdb) bt #0 0x00007f57a4397e4b in run_failure_handlers (t=0x7f579d31b8c8, rpl=0xffffffffffffffff, code=408, extra_flags=32) at t_reply.c:1020 #1 0x00007f57a439b6ff in t_should_relay_response (Trans=0x7f579d31b8c8, new_code=408, branch=0, should_store=0x7ffdc1d48efc, should_relay=0x7ffdc1d48f00, cancel_data=0x7ffdc1d48fb0, reply=0xffffffffffffffff) at t_reply.c:1390 #2 0x00007f57a43a04ae in relay_reply (t=0x7f579d31b8c8, p_msg=0xffffffffffffffff, branch=0, msg_status=408, cancel_data=0x7ffdc1d48fb0, do_put_on_wait=0) at t_reply.c:1821 #3 0x00007f57a43f0b80 in fake_reply (t=0x7f579d31b8c8, branch=0, code=408) at timer.c:294 #4 0x00007f57a43f100d in final_response_handler (r_buf=0x7f579d31baf0, t=0x7f579d31b8c8) at timer.c:455 #5 0x00007f57a43f10bc in retr_buf_handler (ticks=1687494363, tl=0x7f579d31bb10, p=0x1f40) at timer.c:511 #6 0x00000000004bb4f9 in slow_timer_main () at core/timer.c:1104 #7 0x000000000042655f in main_loop () at main.c:1727 #8 0x000000000042e56a in main (argc=15, argv=0x7ffdc1d497f8) at main.c:2802
```
Is the exec_avp() used in a failure_route block?
Can you get from the core file the output for the next gdb commands:
``` list info locals p t p *t p *t->uas.request p faked_req p *faked_req ```
Do you need the output of the shell command? If not, you can run it with the option to go in background, so there is no blocking waiting for the shell command to complete, like:
``` exec_avp("/usr/bin/zabbix_sender --config ZABBIX_AGENT_CONFIG_PATH --key ecsp_no_telephony --value 1 &"); ```
Hi!
Yes exec_avp() is used in failure_route block.
Originally I would like to have the output, but I always had null output. Probably that is another issue. So now I agree to skip the output.
Thank you. We have already implemented such approach - start the zabbix_sender in background. This workaround works well.
I will try to get requested info a bit later.
``` (gdb) list 2692 if (rpl.s==0) { 2693 LM_ERR("failed in doing build_res_buf_from_sip_req()\n"); 2694 goto error; 2695 } 2696 2697 LM_DBG("buffer computed\n"); 2698 // frees 'res.s' ... no panic ! 2699 ret=_reply_light( trans, rpl.s, rpl.len, code, 2700 s_to_tag.s, s_to_tag.len, 1 /* lock replies */, &bm ); 2701 /* this is ugly hack -- the function caller may wish to continue with ```
``` (gdb) info locals __llevel = -1043034928 hdr_lump = 0x7f579d31cf88 body_lump = 0x0 s_to_tag = {s = 0x0, len = 7264} rpl = {s = 0xffffffffffffffff <Address 0xffffffffffffffff out of bounds>, len = -1657685816} ret = 32599 bm = {to_tag_val = {s = 0x800000000 <Address 0x800000000 out of bounds>, len = 32}} __FUNCTION__ = "t_reply_with_body"
```
``` (gdb) p t No symbol "t" in current context. (gdb) p *t No symbol "t" in current context. (gdb) p *t->uas.request No symbol "t" in current context. (gdb) p faked_req No symbol "faked_req" in current context.
```
I cannot get requested information. I deleted that binary and built another one. As result I have different back trace. The back trace is now different in comparing with reported before.
I crashed it again on new binary.
``` [root@sip-proxy01 ecsp]# gdb ./sbin/kamailio --core=core.23544 GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-115.el7 Copyright (C) 2013 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-redhat-linux-gnu". For bug reporting instructions, please see: http://www.gnu.org/software/gdb/bugs/... Reading symbols from /usr/ecsp/sbin/kamailio...Reading symbols from /usr/lib/debug/usr/ecsp/sbin/kamailio.debug...done. done. [New LWP 23544] [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib64/libthread_db.so.1". Core was generated by `/usr/ecsp/sbin/kamailio -f /usr/ecsp/etc/kamailio/ecsp.cfg -m 64 -M 8 -u kamail'. Program terminated with signal 11, Segmentation fault. #0 0x00007fa8e71d401b in run_failure_handlers (t=0x7fa8e01650f0, rpl=0xffffffffffffffff, code=408, extra_flags=32) at t_reply.c:1020 1020 t->uas.request->flags = faked_req->flags; Missing separate debuginfos, use: debuginfo-install cyrus-sasl-lib-2.1.26-23.el7.x86_64 glibc-2.17-292.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.15.1-37.el7_7.2.x86_64 libcom_err-1.42.9-16.el7.x86_64 libdb-5.3.21-25.el7.x86_64 libselinux-2.5-14.1.el7.x86_64 mongo-c-driver-1.9.4-1.0.el7.centos.x86_64 nss-softokn-freebl-3.44.0-5.el7.x86_64 openssl-libs-1.0.2k-19.el7.x86_64 pcre-8.32-17.el7.x86_64 zlib-1.2.7-18.el7.x86_64 (gdb) bt #0 0x00007fa8e71d401b in run_failure_handlers (t=0x7fa8e01650f0, rpl=0xffffffffffffffff, code=408, extra_flags=32) at t_reply.c:1020 #1 0x00007fa8e71d78cf in t_should_relay_response (Trans=0x7fa8e01650f0, new_code=408, branch=0, should_store=0x7fffb8aee41c, should_relay=0x7fffb8aee420, cancel_data=0x7fffb8aee4d0, reply=0xffffffffffffffff) at t_reply.c:1390 #2 0x00007fa8e71dc67e in relay_reply (t=0x7fa8e01650f0, p_msg=0xffffffffffffffff, branch=0, msg_status=408, cancel_data=0x7fffb8aee4d0, do_put_on_wait=0) at t_reply.c:1821 #3 0x00007fa8e723cb80 in fake_reply (t=0x7fa8e01650f0, branch=0, code=408) at timer.c:294 #4 0x00007fa8e723d00d in final_response_handler (r_buf=0x7fa8e0165318, t=0x7fa8e01650f0) at timer.c:455 #5 0x00007fa8e723d0bc in retr_buf_handler (ticks=757073884, tl=0x7fa8e0165338, p=0x1f40) at timer.c:511 #6 0x00000000004bd284 in slow_timer_main () at core/timer.c:1104 #7 0x000000000042655f in main_loop () at main.c:1727 #8 0x000000000042e56a in main (argc=15, argv=0x7fffb8aeed18) at main.c:2802 (gdb) list 1015 } 1016 exec_post_script_cb(faked_req, FAILURE_CB_TYPE); 1017 } 1018 log_prefix_set(NULL); 1019 /* update message flags, if changed in failure route */ 1020 t->uas.request->flags = faked_req->flags; 1021 } 1022 1023 /* restore original environment */ 1024 faked_env( t, 0, 0); (gdb) info locals faked_req = 0x7fa8e01693d0 faked_req_len = 7264 shmem_msg = 0x7fa8e01667b0 on_failure = 1 keng = 0x0 __FUNCTION__ = "run_failure_handlers" (gdb) p t $1 = (struct cell *) 0x7fa8e01650f0 (gdb) p *t $2 = {next_c = 0x534e4f4954504f00, prev_c = 0x4b62344768397a00, hash_index = 926102061, label = 825045297, flags = 12333, nr_of_outgoings = 0, fcount = 0, ref_count = {val = 0}, from = {s = 0x0, len = 0}, callid = {s = 0x0, len = 0}, cseq_n = {s = 0x0, len = 0}, to = {s = 0x0, len = 0}, method = {s = 0x0, len = 0}, tmcb_hl = {first = 0x0, reg_types = 0}, wait_timer = {next = 0x0, prev = 0x0, expire = 0, initial_timeout = 0, data = 0x0, f = 0x0, flags = 0, slow_idx = 0}, wait_start = 0, uas = {request = 0x0, end_request = 0x0, response = {rbtype = 0, flags = 0, t_active = 0, branch = 0, buffer_len = 0, buffer = 0x0, my_T = 0xc0c0c0c0, timer = {next = 0xabcdefed, prev = 0x0, expire = 0, initial_timeout = 0, data = 0x100, f = 0x0, flags = 14880, slow_idx = 0}, dst = { send_sock = 0x7fa8dfed6e00, to = {s = {sa_family = 31956, sa_data = "\366\346\250\177\000\000{e\200\000\000\000\000"}, sin = {sin_family = 31956, sin_port = 59126, sin_addr = {s_addr = 32680}, sin_zero = "{e\200\000\000\000\000"}, sin6 = {sin6_family = 31956, sin6_port = 59126, sin6_flowinfo = 32680, sin6_addr = {__in6_u = { __u6_addr8 = "{e\200\000\000\000\000\000\320|\366\346\250\177\000", __u6_addr16 = {25979, 128, 0, 0, 31952, 59126, 32680, 0}, __u6_addr32 = {8414587, 0, 3874913488, 32680}}}, sin6_scope_id = 271}}, id = 0, proto = -16 '\360', send_flags = {f = 61680, blst_imask = 0}}, retr_expire = 0, fr_expire = 0}, local_totag = {s = 0x0, len = 0}, cancel_reas = 0x0, status = 0}, uac = 0x0, async_backup = {backup_route = 0, backup_branch = 0, blind_uac = 0, ruri_new = 0}, fwded_totags = 0x0, uri_avps_from = 0x0, uri_avps_to = 0x0, user_avps_from = 0x0, user_avps_to = 0x0, domain_avps_from = 0x0, domain_avps_to = 0x0, xavps_list = 0x0, reply_mutex = {val = 0}, reply_locker_pid = {val = 0}, reply_rec_lock_level = 0, fr_timeout = 0, fr_inv_timeout = 0, rt_t1_timeout_ms = 0, rt_t2_timeout_ms = 0, end_of_life = 0, relayed_reply_branch = 0, on_failure = 0, on_branch_failure = 0, on_reply = 0, on_branch = 0, on_branch_delayed = 0, md5 = 0x7fa8e01652e8 "674189e128b010d9ec725cf0ba186019\377\377\377\377\377\377\377\377"} (gdb) p *t->uas.request Cannot access memory at address 0x0 (gdb) p faked_req $3 = (struct sip_msg *) 0x7fa8e01693d0 (gdb) p *faked_req $4 = {id = 0, pid = 23514, tval = {tv_sec = 1576512772, tv_usec = 855609}, fwd_send_flags = {f = 0, blst_imask = 0}, rpl_send_flags = {f = 0, blst_imask = 0}, first_line = {type = 1, flags = 1, len = 75, u = {request = {method = { s = 0x7fa8e0169ae8 "INVITE sip:18447757711@mightyc.pr.mytcall.com:16060;transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: <sip:i.gurieva."..., len = 6}, uri = { s = 0x7fa8e0169aef "sip:18447757711@mightyc.pr.mytcall.com:16060;transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: <sip:i.gurieva.mightyc"..., len = 58}, version = { s = 0x7fa8e0169b2a "SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: sip:i.gurieva.mightycall.com@192.168.158.139:43228;transport=UDP\r\nTo: <sip:1844"..., len = 7}, method_value = 1}, reply = {version = { s = 0x7fa8e0169ae8 "INVITE sip:18447757711@mightyc.pr.mytcall.com:16060;transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: <sip:i.gurieva."..., len = 6}, status = { s = 0x7fa8e0169aef "sip:18447757711@mightyc.pr.mytcall.com:16060;transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: <sip:i.gurieva.mightyc"..., len = 58}, reason = { s = 0x7fa8e0169b2a "SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: sip:i.gurieva.mightycall.com@192.168.158.139:43228;transport=UDP\r\nTo: <sip:1844"..., len = 7}, statuscode = 1}}}, via1 = 0x7fa8e016a058, via2 = 0x0, headers = 0x7fa8e016a018, last_header = 0x7fa8e016a970, parsed_flag = 18446744073709551615, h_via1 = 0x7fa8e016a018, h_via2 = 0x0, callid = 0x7fa8e016a660, to = 0x7fa8e016a200, cseq = 0x7fa8e016a6a0, from = 0x7fa8e016a418, contact = 0x7fa8e016a1c0, maxforwards = 0x7fa8e016a180, route = 0x0, record_route = 0x0, content_type = 0x7fa8e016a750, content_length = 0x7fa8e016a970, authorization = 0x0, expires = 0x0, proxy_auth = 0x7fa8e016a790, supported = 0x7fa8e016a8b0, require = 0x0, proxy_require = 0x0, unsupported = 0x0, allow = 0x7fa8e016a710, event = 0x0, accept = 0x0, accept_language = 0x0, organization = 0x0, priority = 0x0, subject = 0x0, user_agent = 0x7fa8e016a8f0, server = 0x0, content_disposition = 0x0, diversion = 0x0, rpid = 0x0, refer_to = 0x0, session_expires = 0x0, min_se = 0x0, sipifmatch = 0x0, subscription_state = 0x0, date = 0x0, identity = 0x0, identity_info = 0x0, pai = 0x0, ppi = 0x0, path = 0x0, privacy = 0x0, min_expires = 0x0, body = 0x0, eoh = 0x7fa8e0169f1c "\r\nv=0\r\no=Z 0 0 IN IP4 192.168.158.139\r\ns=Z\r\nc=IN IP4 192.168.158.139\r\nt=0 0\r\nm=audio 8000 RTP/AVP 3 110 8 0 97 101\r\na=rtpmap:110 speex/8000\r\na=rtpmap:97 iLBC/8000\r\na=fmtp:97 mode=30\r\na=rtpmap:101 tele"..., unparsed = 0x7fa8e0169f1c "\r\nv=0\r\no=Z 0 0 IN IP4 192.168.158.139\r\ns=Z\r\nc=IN IP4 192.168.158.139\r\nt=0 0\r\nm=audio 8000 RTP/AVP 3 110 8 0 97 101\r\na=rtpmap:110 speex/8000\r\na=rtpmap:97 iLBC/8000\r\na=fmtp:97 mode=30\r\na=rtpmap:101 tele"..., rcv = {src_ip = {af = 2, len = 4, u = {addrl = {2190086405, 140736291857920}, addr32 = {2190086405, 0, 3098469888, 32767}, addr16 = {4357, 33418, 0, 0, 58880, 47278, 32767, 0}, addr = "\005\021\212\202\000\000\000\000\000殸\377\177\000"}}, dst_ip = {af = 2, len = 4, u = {addrl = {2374635781, 0}, addr32 = {2374635781, 0, 0, 0}, addr16 = { 4357, 36234, 0, 0, 0, 0, 0, 0}, addr = "\005\021\212\215", '\000' <repeats 11 times>}}, src_port = 43228, dst_port = 16060, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = { sa_family = 2, sa_data = "\250\334\005\021\212\202\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 56488, sin_addr = {s_addr = 2190086405}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 56488, sin6_flowinfo = 2190086405, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}}, bind_address = 0x7fa8eb16cb58, proto = 1 '\001'}, buf = 0x7fa8e0169ae8 "INVITE sip:18447757711@mightyc.pr.mytcall.com:16060;transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: <sip:i.gurieva."..., len = 1323, new_uri = {s = 0x0, len = 0}, dst_uri = {s = 0x7fa8eb210e58 "sip:94.72.41.53:5167", len = 20}, parsed_uri_ok = 0, parsed_uri = {user = { s = 0x7fa8e0169af3 "18447757711@mightyc.pr.mytcall.com:16060;transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: <sip:i.gurieva.mightycall."..., len = 11}, passwd = {s = 0x0, len = 0}, host = { s = 0x7fa8e0169aff "mightyc.pr.mytcall.com:16060;transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: <sip:i.gurieva.mightycall.com@192.168."..., len = 22}, port = { s = 0x7fa8e0169b16 "16060;transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: <sip:i.gurieva.mightycall.com@192.168.158.139:43228;transport"..., len = 5}, params = { s = 0x7fa8e0169b1c "transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: sip:i.gurieva.mightycall.com@192.168.158.139:43228;transport=UDP\r"..., len = 13}, sip_params = {s = 0xa826f4 <buf.6964+52> "", len = 13}, headers = {s = 0x0, len = 0}, port_no = 16060, proto = 1, type = SIP_URI_T, flags = (unknown: 0), transport = { s = 0x7fa8e0169b1c "transport=UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: sip:i.gurieva.mightycall.com@192.168.158.139:43228;transport=UDP\r"..., len = 13}, ttl = {s = 0x0, len = 0}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0, len = 0}, lr = {s = 0x0, len = 0}, r2 = { s = 0x0, len = 0}, gr = {s = 0x0, len = 0}, transport_val = { s = 0x7fa8e0169b26 "UDP SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.158.139:43228;branch=z9hG4bK-524287-1---e4184c5f8f7432bd\r\nMax-Forwards: 69\r\nContact: sip:i.gurieva.mightycall.com@192.168.158.139:43228;transport=UDP\r\nTo: <sip:"..., len = 3}, ttl_val = {s = 0x0, len = 0}, user_param_val = {s = 0x0, len = 0}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 0}, lr_val = {s = 0x0, len = 0}, r2_val = {s = 0x0, len = 0}, gr_val = {s = 0x0, len = 0}}, parsed_orig_ruri_ok = 0, parsed_orig_ruri = {user = {s = 0x0, len = 0}, passwd = {s = 0x0, len = 0}, host = {s = 0x0, len = 0}, port = {s = 0x0, len = 0}, params = {s = 0x0, len = 0}, sip_params = {s = 0x0, len = 0}, headers = {s = 0x0, len = 0}, port_no = 0, proto = 0, type = ERROR_URI_T, flags = (unknown: 0), transport = {s = 0x0, len = 0}, ttl = {s = 0x0, len = 0}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0, len = 0}, lr = {s = 0x0, len = 0}, r2 = {s = 0x0, len = 0}, gr = {s = 0x0, len = 0}, transport_val = {s = 0x0, len = 0}, ttl_val = {s = 0x0, len = 0}, user_param_val = {s = 0x0, len = 0}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 0}, lr_val = {s = 0x0, len = 0}, r2_val = {s = 0x0, len = 0}, gr_val = {s = 0x0, len = 0}}, add_rm = 0x7fa8e016a9b0, body_lumps = 0x0, reply_lump = 0x0, add_to_branch_s = '\000' <repeats 57 times>, add_to_branch_len = 0, hash_index = 43574, msg_flags = 262321, flags = 3, xflags = {0, 0}, set_global_address = {s = 0x0, len = 0}, set_global_port = {s = 0x0, len = 0}, force_send_socket = 0x0, path_vec = {s = 0x0, len = 0}, instance = {s = 0x0, len = 0}, reg_id = 0, ruid = {s = 0x0, len = 0}, location_ua = {s = 0x0, len = 0}, otcpid = 0, ldv = {flow = {decoded = 0, rcv = {src_ip = {af = 0, len = 0, u = {addrl = {0, 0}, addr32 = {0, 0, 0, 0}, addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, addr = '\000' <repeats 15 times>}}, dst_ip = {af = 0, len = 0, u = {addrl = {0, 0}, addr32 = {0, 0, 0, 0}, addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, addr = '\000' <repeats 15 times>}}, src_port = 0, dst_port = 0, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 0, sa_data = '\000' <repeats 13 times>}, sin = {sin_family = 0, sin_port = 0, sin_addr = {s_addr = 0}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 0, sin6_port = 0, sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}}, bind_address = 0x0, proto = 0 '\000'}}}} (gdb) ```
It is easy to reproduce, just call exec_avp with sh script which has sleep 1 min.
Please find below part of configuration file where the exec_avp is used:
failure_route[HANDLE_FAILURE_ON_INCOMING_REQ] { if (t_is_canceled()) { exit; }
if (t_branch_timeout()) {
if (t_branch_replied()) {
// A local timeout after some provsional reply. xlog("L_WARN", "No final response on request $rm CSeq:$cs ($ci)!\n");
} else { // A local transaction timed out w/o any reply received. // In case incoming calls that means out Telephony doesn't reply.
xlog("L_ERR", "Failover on request $rm CSeq:$cs ($ci)!\n");
// Set current Telephony to inactive probbing state ds_mark_dst("IP");
// Checking next endpoint from the destination list if (!ds_next_dst()) { t_reply("503", "Service Unavailable"); xlog("L_CRIT","Failure route: All Telephony servers are invactive!\n");
if ($shv(is_zabbix_event_sent) == 0) { $shv(is_zabbix_event_sent) = 1; exec_avp("etc/kamailio/run_zabbix_sender.sh ecsp_no_telephony"); xlog("L_NOTICE","ecsp_no_telephony event is sent to zabbix\n"); }
exit; }
xlog("L_ERR", "Try to send to $rd:$rp ($ci)\n");
route(RELAY); } }
}
Can you try with master branch? I just added some extra/safety checks to tm module trying to catch such cases.
Will do today. Thank you.
It works well. You can close the ticket. Thank you for good job. :)
OK, thanks for testing and reproting back. The changes were consistent, not sure it worth backporting in short term, I would like more testing. Meanwhile there is the option to do non-blocking shell script execution by putting it in background execution (using '&' at the end of command).
Closed #2165.
-
Daniel-Constantin Mierla -
Henning Westerholt
-
Konstantin