Hi list, We're currently experiencing crashes on two OpenSIPS production servers, occurring several times daily. These instances are handling high call volumes (200–500 CPS).
I was able to capture a core dump, which appears to point to a double free issue within the dialog module. The servers are running OpenSIPS installed via the official YUM repositories on CentOS 9. I'd greatly appreciate any assistance in determining whether this is a bug in OpenSIPS itself or potentially a misconfiguration on my end. I've reviewed the configuration but haven't found anything that would obviously cause the dialog to be freed twice. Thanks in advance!! May 30 09:54:26 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075647]: May 30 07:54:26 [2075647] CRITICAL:core:sig_usr: segfault in process pid: 2075647, id: 13 May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 100 ms ago (now 70802550 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 190 ms ago (now 70802640 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 290 ms ago (now 70802740 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 390 ms ago (now 70802840 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 490 ms ago (now 70802940 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 590 ms ago (now 70803040 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 690 ms ago (now 70803140 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 790 ms ago (now 70803240 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 880 ms ago (now 70803330 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:timer_ticker: timer task <tm- timer> already scheduled 980 ms ago (now 70803330 ms), delaying execution May 30 09:54:27 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:27 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 980 ms ago (now 70803430 ms), delaying execution May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:28 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 1080 ms ago (now 70803530 ms), delaying execution May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:28 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 1180 ms ago (now 70803630 ms), delaying execution May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:28 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 1280 ms ago (now 70803730 ms), delaying execution May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:28 [2075638] WARNING:core:utimer_ticker: utimer task <tm- utimer> already scheduled 1380 ms ago (now 70803830 ms), delaying execution May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: May 30 07:54:28 [2075617] INFO:core:handle_sigs: child process 2075647 exited by a signal 11 May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: May 30 07:54:28 [2075617] INFO:core:handle_sigs: core was generated May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: May 30 07:54:28 [2075617] INFO:core:handle_sigs: terminating due to SIGCHLD May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075638]: May 30 07:54:28 [2075638] INFO:core:sig_usr: signal 15 received May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: May 30 07:54:28 [2075617] INFO:core:shutdown_opensips: process 1(2075635) [MI FIFO] terminated, still waiting for 11 more May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075637]: May 30 07:54:28 [2075637] INFO:core:sig_usr: signal 15 received May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: May 30 07:54:28 [2075617] INFO:core:shutdown_opensips: process 2(2075636) [HTTPD *:8888] terminated, still waiting for 10 more May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: May 30 07:54:28 [2075617] INFO:core:shutdown_opensips: process 4(2075638) [timer] terminated, still waiting for 9 more May 30 09:54:28 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: May 30 07:54:28 [2075617] INFO:core:shutdown_opensips: process 3(2075637) [time_keeper] terminated, still waiting for 8 more May 30 09:54:33 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: May 30 07:54:33 [2075617] INFO:core:cleanup: cleanup May 30 09:54:34 za-cl-jhb-avm-billing1.imcore.co.za opensips[2075617]: Thank you for running opensips May 30 09:54:34 za-cl-jhb-avm-billing1.imcore.co.za systemd[1]: opensips.service: Main process exited, code=exited, status=139/n/a May 30 09:54:34 za-cl-jhb-avm-billing1.imcore.co.za systemd[1]: opensips.service: Failed with result 'exit-code'. May 30 09:54:34 za-cl-jhb-avm-billing1.imcore.co.za systemd[1]: opensips.service: Consumed 29min 51.610s CPU time. May 30 09:54:34 za-cl-jhb-avm-billing1.imcore.co.za systemd[1]: opensips.service: Scheduled restart job, restart counter is at 4. May 30 09:54:34 za-cl-jhb-avm-billing1.imcore.co.za systemd[1]: Stopped OpenSIPS is a very fast and flexible SIP (RFC3261) server. May 30 09:54:34 za-cl-jhb-avm-billing1.imcore.co.za systemd[1]: opensips.service: Consumed 29min 51.610s CPU time. coredump backtrace (gdb) bt #0 0x00007f3300f5c9bd in __strlen_avx2 () from /lib64/libc.so.6 #1 0x00007f3300e600f8 in __vfprintf_internal () from /lib64/libc.so.6 #2 0x00007f3300e608bf in buffered_vfprintf () from /lib64/libc.so.6 #3 0x0000556064e7835c in vfprintf (__ap=<optimized out>, __fmt=<optimized out>, __stream=<optimized out>) at /usr/include/bits/stdio2.h:109 #4 stderr_dprint (log_level=<optimized out>, facility=<optimized out>, module=<optimized out>, func=<optimized out>, format=<optimized out>, ap=<optimized out>) at /usr/src/debug/opensips-3.4.12- 1.el9.x86_64/dprint.c:484 #5 0x0000556064e734e8 in dprint (log_level=-2, facility=128, module=0x55606504693c "core", func=0x556065078e98 <__FUNCTION__.1> "fm_free", stderr_fmt=0x556065075900 "%s [%d] %sCRITICAL:core:%s: freeing already freed %s pointer (%p), first free: %s: %s(%ld) - aborting!\n", syslog_fmt=0x556065075908 "%sCRITICAL:core:%s: freeing already freed %s pointer (%p), first free: %s: %s(%ld) - aborting!\n", format=0x556065075968 "freeing already freed %s pointer (%p), first free: %s: %s(%ld) - aborting!\n") at /usr/src/debug/opensips-3.4.12- 1.el9.x86_64/dprint.c:698 #6 0x0000556064f368c6 in fm_free (fm=<optimized out>, p=0x7f32c11781b8, file=<optimized out>, func=<optimized out>, line=<optimized out>) at mem/f_malloc_dyn.h:240 #7 0x00007f3277549d3d in _shm_free (line=183, function=<synthetic pointer>, file=0x7f327757e0fc "dlg_hash.c", ptr=0x7f32c11781b8) at ../../evi/../mem/shm_mem.h:550 #8 free_dlg_dlg (dlg=0x7f32beab9148) at /usr/src/debug/opensips-3.4.12- 1.el9.x86_64/modules/dialog/dlg_hash.c:183 #9 0x00007f327755133f in _unref_dlg (dlg=0x7f32beab9148, cnt=<optimized out>) at /usr/src/debug/opensips-3.4.12- 1.el9.x86_64/modules/dialog/dlg_hash.c:1040 #10 0x00007f327753cc80 in dlg_onreply (t=t@entry=0x0, type=type@entry=4096, param=param@entry=0x7ffe5c0b72e0) at /usr/src/debug/opensips-3.4.12- 1.el9.x86_64/modules/dialog/dlg_handlers.c:829 #11 0x00007f327753e94b in unreference_dialog_create (dialog=<optimized out>) at /usr/src/debug/opensips-3.4.12- 1.el9.x86_64/modules/dialog/dlg_handlers.c:1254 #12 0x00007f327877c79b in empty_tmcb_list (head=0x7f32c224bbf0) at /usr/src/debug/opensips-3.4.12-1.el9.x86_64/modules/tm/t_hooks.c:53 #13 0x00007f327876cbff in free_cell (dead_cell=0x7f32c224bb80) at /usr/src/debug/opensips-3.4.12-1.el9.x86_64/modules/tm/h_table.c:127 #14 0x00007f32787982be in wait_handler (wait_tl=0x7f32c224bc00) at /usr/src/debug/opensips-3.4.12-1.el9.x86_64/modules/tm/timer.c:478 #15 timer_routine (ticks=70802, set=<optimized out>) at /usr/src/debug/opensips-3.4.12-1.el9.x86_64/modules/tm/timer.c:1115 #16 0x0000556064f0bca9 in handle_timer_job () at /usr/src/debug/opensips-3.4.12-1.el9.x86_64/timer.c:1018 #17 0x000055606502b5d5 in handle_io.constprop.2 (fm=0x7f32f8e82d20, event_type=1, idx=<optimized out>) at /usr/src/debug/opensips-3.4.12- 1.el9.x86_64/timer.c:765 #18 0x0000556065037c08 in io_wait_loop_epoll.constprop.3.isra.0 (repeat=<optimized out>, t=<optimized out>, h=<optimized out>) at /usr/src/debug/opensips-3.4.12-1.el9.x86_64/io_wait_loop.h:305 #19 0x0000556064f0ebed in start_timer_extra_processes (chd_rank=<optimized out>) at /usr/src/debug/opensips-3.4.12- 1.el9.x86_64/timer.c:932 #20 0x0000556064e52581 in main_loop () at /usr/src/debug/opensips- 3.4.12-1.el9.x86_64/main.c:249 #21 main (argc=<optimized out>, argv=<optimized out>) at /usr/src/debug/opensips-3.4.12-1.el9.x86_64/main.c:966 (gdb) Regards Trevor Steyn
_______________________________________________ Devel mailing list Devel@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
