sip-router

SIP Router Project

Tasklist

FS#173 - Double Free -- Crash/Coredump and possible security vulnerability

Attached to Project: sip-router
Opened by Bayan Towfiq (btowfiq) - Monday, 07 November 2011, 07:56 GMT
Last edited by Daniel-Constantin Mierla (miconda) - Wednesday, 30 November 2011, 18:08 GMT
Task Type Bug Report
Category Module → dialog
Status Closed
Assigned To Timo Reimann (tr)
Operating System Linux
Severity Low
Priority Normal
Reported Version Development
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 0
Private No

Details

version: kamailio 3.2.0 (x86_64/linux) 639f0a
flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC, 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_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: 639f0a
compiled on 07:18:31 Oct 29 2011 with gcc 4.4.3

Dialog module crashed in kamailio 3.2.0 with the following log error (double free) and below backtrace. This is a potential remote security vulnerability in addition to the crash which is why severity is set to Critical. Please let me know if further information is needed to debug.

Nov 6 18:04:33 guru /usr/local/sbin/kamailio[8282]: CRITICAL: dialog [dlg_hash.c:597]: bogus ref -1 with cnt 1 for dlg 0x7f47dbd0eee8 [16086:1982422345] with clid ‘1124787051_76787956@4.55.17.35’ and tags ‘gK0a13fca4’ ‘’ Nov 6 18:04:33 guru /usr/local/sbin/kamailio[8282]: : <core> [mem/q_malloc.c:457]: BUG: qm_free: freeing already freed pointer, first free: dialog: dlg_hash.c: destroy_dlg(217) - aborting Nov 6 18:04:33 guru /usr/local/sbin/kamailio[8294]: : <core> [pass_fd.c:293]: ERROR: receive_fd: EOF on 18 Nov 6 18:04:33 guru /usr/local/sbin/kamailio[8272]: ALERT: <core> [main.c:751]: child process 8282 exited by a signal 6 Nov 6 18:04:33 guru /usr/local/sbin/kamailio[8272]: ALERT: <core> [main.c:754]: core was generated Nov 6 18:05:33 guru /usr/local/sbin/kamailio[8272]: : <core> [main.c:660]: BUG: shutdown timeout triggered, dying... Nov 6 18:05:34 guru init: kamailio main process (8272) killed by ABRT signal Nov 6 18:05:34 guru init: kamailio main process ended, respawning Nov 6 18:05:34 guru kamailio: WARNING: <core> [daemonize.c:352]: pid file contains old pid, replacing pid

Full backtrace below:

(gdb) bt full
#0 0x00007f47f38b3a75 in raise () from /lib/libc.so.6
No symbol table info available.
#1 0x00007f47f38b75c0 in abort () from /lib/libc.so.6
No symbol table info available.
#2 0×0000000000534708 in qm_free (qm=0x7f47db9be000, p=0x7f47dbe5d3a8, file=0x7f47ec231bef “dialog: dlg_hash.c”, func=0x7f47ec231f52 “destroy_dlg”, line=217) at mem/q_malloc.c:458

      f = 0x7f47dbe5d378
      size = <value optimized out>

#3 0x00007f47ec218161 in destroy_dlg (dlg=0x7f47dbd0eee8) at dlg_hash.c:217

      ret = <value optimized out>
      __FUNCTION__ = "destroy_dlg"

#4 0x00007f47ec21a545 in unref_dlg (dlg=0x7f47dbd0eee8, cnt=0) at dlg_hash.c:597

      d_entry = 0x7f47dbcb1c80

#5 0x00007f47f193d5bd in free_cell (dead_cell=0x7f47dbe48920) at h_table.c:175

      b = <value optimized out>
      i = <value optimized out>
      rpl = <value optimized out>
      tt = <value optimized out>
      foo = <value optimized out>
      cbs = 0x7f47dbcc5970
      __FUNCTION__ = "free_cell"

#6 0x00007f47f195991b in wait_handler (ti=<value optimized out>, wait_tl=<value optimized out>, data=<value optimized out>) at timer.c:676

      p_cell = 0x7f47dbe48920

#7 0x000000000051f4fd in timer_list_expire () at timer.c:894

      tl = 0x7f47dbe489a0
      ret = <value optimized out>

#8 timer_handler () at timer.c:959

      saved_ticks = 444520143
      run_slow_timer = <value optimized out>

#9 timer_main () at timer.c:998
No locals.
#10 0x000000000046454f in main_loop () at main.c:1655

      i = 8
      pid = <value optimized out>
      si = 0x0
      si_desc = "udp receiver child=7 sock=70.167.153.130:5060\000\000\000\000\000@\020", '\000' <repeats 12 times>, "\016\b\000\000\000\000\000\000\000\200\271،*\306v&\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\300\v\215\000\000\000\000\000\"\000\000\000\000\000\000\000\000\000@\020", '\000' <repeats 11 times>

#11 0x0000000000465dd2 in main (argc=11, argv=0x7fff47fcb288) at main.c:2475

      cfg_stream = <value optimized out>
      c = <value optimized out>
      r = <value optimized out>
      tmp = 0x7fff47fcbe83 ""
      tmp_len = 0
      port = <value optimized out>
      proto = <value optimized out>
      ret = <value optimized out>
      seed = 1033789824
      rfd = <value optimized out>
      debug_save = 272629760
      debug_flag = 34
      dont_fork_cnt = 0
      n_lst = 0x10400000
      p = <value optimized out>

(gdb)

This task depends upon

Closed by  Daniel-Constantin Mierla (miconda)
Wednesday, 30 November 2011, 18:08 GMT
Reason for closing:  Fixed
Comment by Timo Reimann (tr) - Monday, 07 November 2011, 22:53 GMT

I applied patches to master (commit 8ca6de5) and 3.2 (commit baed41) branches that fix a problem with the usage of dialog variables.

Details: The flag to indicate that a dialog variable was changed (DLG_FLAG_CHANGED_VARS) was set with the wrong operator (&= as opposed to |=). This caused all other dialog flags to reset, including DLG_FLAG_TM introduced to master/3.2 in order to improve dialog handling of stateless responses. With DLG_FLAG_TM effectively rendered useless, the reference counter would be decremented too many times, thereby causing a double-free.

Have you been using dialog variables (possibly indirectly by means of CDR generation in the acc module)? If so, could you try to verify that the bug is fixed in the latest 3.2 branch?

Comment by Bayan Towfiq (btowfiq) - Tuesday, 08 November 2011, 02:48 GMT

Thanks Timo,
I will let you know in a few days if crashes have stopped on this test installation.

Bayan

Comment by Bayan Towfiq (btowfiq) - Tuesday, 08 November 2011, 03:52 GMT

It is still crashing with a similar backtrace: Here is a new backtrace:

(gdb) bt full
#0 0x00007f43d474aa75 in raise () from /lib/libc.so.6
No symbol table info available.
#1 0x00007f43d474e5c0 in abort () from /lib/libc.so.6
No symbol table info available.
#2 0×0000000000534708 in qm_free (qm=0x7f43bc853000, p=0x7f43bcb4be30, file=0x7f43cd0c6dff “dialog: dlg_hash.c”, func=0x7f43cd0c7162 “destroy_dlg”, line=217) at mem/q_malloc.c:458

      f = 0x7f43bcb4be00
      size = <value optimized out>

#3 0x00007f43cd0ad351 in destroy_dlg (dlg=0x7f43bcb4bbe8) at dlg_hash.c:217

      ret = <value optimized out>
      __FUNCTION__ = "destroy_dlg"

#4 0x00007f43cd0af735 in unref_dlg (dlg=0x7f43bcb4bbe8, cnt=0) at dlg_hash.c:597

      d_entry = 0x7f43bcafb380

#5 0x00007f43d27d45bd in free_cell (dead_cell=0x7f43bcb91f08) at h_table.c:175

      b = <value optimized out>
      i = <value optimized out>
      rpl = <value optimized out>
      tt = <value optimized out>
      foo = <value optimized out>
      cbs = 0x7f43bcb6fba8
      __FUNCTION__ = "free_cell"

#6 0x00007f43d27f091b in wait_handler (ti=<value optimized out>, wait_tl=<value optimized out>, data=<value optimized out>) at timer.c:676

      p_cell = 0x7f43bcb91f08

#7 0x000000000051f4fd in timer_list_expire () at timer.c:894

      tl = 0x7f43bcb91f88
      ret = <value optimized out>

#8 timer_handler () at timer.c:959

      saved_ticks = 790137305
      run_slow_timer = <value optimized out>

#9 timer_main () at timer.c:998
No locals.
#10 0x000000000046454f in main_loop () at main.c:1655

      i = 8
      pid = <value optimized out>
      si = 0x0
      si_desc = "udp receiver child=7 sock=70.167.153.130:5160\000\000\000\000\000@\020", '\000' <repeats 12 times>, "\016\b\000\000\000\000\000\000\000\270\337\364\352\351\304!&\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\300\v\215\000\000\000\000\000\"\000\000\000\000\000\000\000\000\000@\020", '\000' <repeats 11 times>

#11 0x0000000000465dd2 in main (argc=11, argv=0x7fff3e203ff8) at main.c:2475

      cfg_stream = <value optimized out>
      c = <value optimized out>
      r = <value optimized out>
      tmp = 0x7fff3e205e83 ""
      tmp_len = 0
      port = <value optimized out>
      proto = <value optimized out>
      ret = <value optimized out>
      seed = 1312519318
      rfd = <value optimized out>
      debug_save = 272629760
      debug_flag = 34
      dont_fork_cnt = 0
      n_lst = 0x10400000
      p = <value optimized out>

(gdb)

Comment by Timo Reimann (tr) - Tuesday, 08 November 2011, 16:24 GMT

Just to be sure: You did check out the latest 3.2 or master branch and re-compiled Kamailio, right?

If so, could you please let me know what features of the dialog module (e.g., profiling, dialog variables, etc.) you are using (and whether you are using CDR generation from the acc module)?

Comment by Bayan Towfiq (btowfiq) - Tuesday, 08 November 2011, 20:13 GMT

Yes I’m running the latest 3.2 branch with recompiled kamailio. it includes your commits to the dialog module:

version: kamailio 3.2.0 (x86_64/linux) baed41-dirty
flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC, 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_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: baed41 -dirty
compiled on 02:47:08 Nov 8 2011 with gcc 4.4.3

I’m not using CDR generation or ACC module in this config.

I am using the dialog module to terminate calls (Inject BYEs) with RPC commands using dialog hashes.

In the script I use dialog variables for h_entry and h_id and for setting dlg_ctx(timeout_bye):

       $avp(hash_entry) = $dlg(h_entry);
       $avp(hash_id) = $dlg(h_id);
       $dlg_ctx(timeout_bye) = 1;

I also use the dlg_manage() function from the config.

For the dlg_match_mode I use modparam(”dialog”, “dlg_match_mode”, 2)

Comment by Timo Reimann (tr) - Tuesday, 08 November 2011, 23:10 GMT

I’m still investigating the issue but will need some more time.

In the meantime, is it possible for you to change dlg_match_mode to 1? That could help in ruling out match mode as a possible error source.

Comment by Bayan Towfiq (btowfiq) - Wednesday, 09 November 2011, 00:40 GMT

I set dlg_match_mode to 1 and it is still crashing the same way. One other thing I noticed is that I am getting two separate coredumps from two processes. After the first coredump (same as above), there is a second coredump about 1 minute later, before all the processes end. Here is the short and long backtrace for the second coredump from the other process 1 min after the first crash:

(gdb) bt
#0 0x00007f1cb918ea75 in raise () from /lib/libc.so.6
#1 0x00007f1cb91925c0 in abort () from /lib/libc.so.6
#2 0x000000000045ff41 in sig_alarm_abort (signo=<value optimized out>) at main.c:661
#3 <signal handler called>
#4 0x00007f1cb923d877 in syscall () from /lib/libc.so.6
#5 0x00007f1cb1ae5f05 in futex_get (ticks=<value optimized out>, param=<value optimized out>) at ../../mem/../futexlock.h:123
#6 dialog_update_db (ticks=<value optimized out>, param=<value optimized out>) at dlg_db_handler.c:828
#7 0x00007f1cb1adbd21 in mod_destroy () at dialog.c:692
#8 0x00000000004e23f4 in destroy_modules () at sr_module.c:782
#9 0x000000000046154f in cleanup (show_status=1) at main.c:536
#10 0x00000000004621bb in shutdown_children (show_status=1, sig=<value optimized out>) at main.c:678
#11 0x00000000004631d2 in handle_sigs () at main.c:769
#12 0x000000000046436e in main_loop () at main.c:1713
#13 0x0000000000465dd2 in main (argc=11, argv=0x7fffc752dbc8) at main.c:2475

(gdb) bt
#0 0x00007f1cb918ea75 in raise () from /lib/libc.so.6
#1 0x00007f1cb91925c0 in abort () from /lib/libc.so.6
#2 0x000000000045ff41 in sig_alarm_abort (signo=<value optimized out>) at main.c:661
#3 <signal handler called>
#4 0x00007f1cb923d877 in syscall () from /lib/libc.so.6
#5 0x00007f1cb1ae5f05 in futex_get (ticks=<value optimized out>, param=<value optimized out>) at ../../mem/../futexlock.h:123
#6 dialog_update_db (ticks=<value optimized out>, param=<value optimized out>) at dlg_db_handler.c:828
#7 0x00007f1cb1adbd21 in mod_destroy () at dialog.c:692
#8 0x00000000004e23f4 in destroy_modules () at sr_module.c:782
#9 0x000000000046154f in cleanup (show_status=1) at main.c:536
#10 0x00000000004621bb in shutdown_children (show_status=1, sig=<value optimized out>) at main.c:678
#11 0x00000000004631d2 in handle_sigs () at main.c:769
#12 0x000000000046436e in main_loop () at main.c:1713
#13 0x0000000000465dd2 in main (argc=11, argv=0x7fffc752dbc8) at main.c:2475
(gdb) bt full
#0 0x00007f1cb918ea75 in raise () from /lib/libc.so.6
No symbol table info available.
#1 0x00007f1cb91925c0 in abort () from /lib/libc.so.6
No symbol table info available.
#2 0x000000000045ff41 in sig_alarm_abort (signo=<value optimized out>) at main.c:661
No locals.
#3 <signal handler called>
No symbol table info available.
#4 0x00007f1cb923d877 in syscall () from /lib/libc.so.6
No symbol table info available.
#5 0x00007f1cb1ae5f05 in futex_get (ticks=<value optimized out>, param=<value optimized out>) at ../../mem/../futexlock.h:123

      v = <value optimized out>

#6 dialog_update_db (ticks=<value optimized out>, param=<value optimized out>) at dlg_db_handler.c:828

      index = <value optimized out>
      cell = <value optimized out>

#7 0x00007f1cb1adbd21 in mod_destroy () at dialog.c:692
No locals.
#8 0x00000000004e23f4 in destroy_modules () at sr_module.c:782

      t = 0x7f1cb8da6578
      foo = 0x7f1cb8da6108
      __FUNCTION__ = "destroy_modules"

#9 0x000000000046154f in cleanup (show_status=1) at main.c:536

      memlog = <value optimized out>
      __FUNCTION__ = "cleanup"

#10 0x00000000004621bb in shutdown_children (show_status=1, sig=<value optimized out>) at main.c:678
No locals.
#11 0x00000000004631d2 in handle_sigs () at main.c:769

      chld = 0
      chld_status = 134
      memlog = <value optimized out>

#12 0x000000000046436e in main_loop () at main.c:1713

      i = 8
      pid = <value optimized out>
      si = 0x0
      si_desc = "udp receiver child=7 sock=70.167.153.130:5160\000\000\000\000\000@\020", '\000' <repeats 12 times>, "\016\b\000\000\000\000\000\000\000h\244@N\225\342\362&\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\300\v\215\000\000\000\000\000\"\000\000\000\000\000\000\000\000\000@\020", '\000' <repeats 11 times>

#13 0x0000000000465dd2 in main (argc=11, argv=0x7fffc752dbc8) at main.c:2475

      cfg_stream = <value optimized out>
      c = <value optimized out>
      r = <value optimized out>
      tmp = 0x7fffc752ee83 ""
      tmp_len = 0
      port = <value optimized out>
      proto = <value optimized out>
      ret = <value optimized out>

—Type <return> to continue, or q <return> to quit—

      seed = 48325081
      rfd = <value optimized out>
      debug_save = 272629760
      debug_flag = 34
      dont_fork_cnt = 0
      n_lst = 0x10400000
      p = <value optimized out>
Comment by Timo Reimann (tr) - Wednesday, 09 November 2011, 21:59 GMT

I think Kamailio automatically tries to shut down if a segfault occurs; this is what you see in the second core dump and should be unrelated to the cause of the problem.

You also seem to be storing dialogs in the database. What DB mode are you using? Could you try disabling DB usage (i.e., set db_mode to 0) for a while and see if it helps?

Comment by Bayan Towfiq (btowfiq) - Thursday, 10 November 2011, 07:34 GMT

There have not been any segfaults since I set db_mode to 0, but the crashes are sporadic so it is hard to tell if this fixed the issue.

In production I need to use db_mode to 3. I will let you know the status over the next few days.

Bayan

Comment by Bayan Towfiq (btowfiq) - Thursday, 10 November 2011, 20:10 GMT

Hi Timo, it is still crashing. I am emailing you a full backtrace instead of posting it due to certain information contained in the bt.

Comment by Timo Reimann (tr) - Friday, 11 November 2011, 00:07 GMT

OK thanks. Will take a look at it as soon as time permits.

Comment by Bayan Towfiq (btowfiq) - Monday, 14 November 2011, 21:56 GMT

Hi Timo,
Kamailio is still crashing frequently. Have you had a chance to look into it? Would you like any other tests?

Comment by Timo Reimann (tr) - Monday, 14 November 2011, 23:11 GMT

Hey Bayan,

sorry for not replying any sooner. I was quite busy in the last couple of days and couldn’t dedicate too much time to the project. Your issue is quite on the top of my priority list, however, and I’ll try to get to it as soon as I can.

The dump you gave me looks different this time – will scrutinze it further.

What would prove really helpful as well (if your resources permit to do so) is a SIP trace (using ngrep for example) together with another dump and more debug-level logging. That way, I could possibly correlate the dump content to the failing dialog and figure out what lead to the faulty situation. If setting log verbosity to DEBUG is too heavy for you, what you can do alternatively is change all “LM_DBG” strings in modules_k/dialog/*.{h,c} to LM_<whatever level you usually log>.

Comment by Daniel-Constantin Mierla (miconda) - Friday, 18 November 2011, 10:48 GMT

IMO, the fundamental issue here is the relation between dialog and tm module. Dialog stores own pointers in tm, expecting tm to clean up them in various cases. But tm has many exit cases and special handlings right now and any tm change in the future, based on the current dependencies, are just keeping dialog exposed to many issue. I plan to refactor this dialog-tm dependency, to avoid storing dialog pointers inside tm. Long term is safe bet, rather than just tracking and troubleshooting for corner cases (existing now or added in the future) of tm processing.

Comment by Bayan Towfiq (btowfiq) - Friday, 18 November 2011, 12:47 GMT

I agree. It seems to have been a regression from 3.1 as this issue didn’t exist in 3.1 with the same config.

Although long term this dependency needs to be refactored for the time being it’s preventing a migration from 3.1 to 3.2 for production use.

Please let me know if you want any specific details on how the config is using TM module.

Comment by Bayan Towfiq (btowfiq) - Sunday, 20 November 2011, 07:40 GMT

Sorry, this issue may also exist in 3.1 – I have a friend who is having a very similar problem on 3.1.5 and the crashes are very frequent

Comment by Brandon Armstead (CRYY2010) - Sunday, 20 November 2011, 08:07 GMT

Syslog of crash:

Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:310]: the database has information about 18 dialogs
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 55
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd145e0 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd14630 for 149474413
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd145e0 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149474413
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 3913
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd14aa8 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd14af8 for 149478945
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd14aa8 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149478945
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 120
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd14ee0 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd14f30 for 149478647
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd14ee0 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149478647
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 829
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd15360 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd153b0 for 149479077
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd15360 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149479077
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 4066
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd15790 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd157e0 for 149479115
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd15790 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149479115
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 2879
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd15c48 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd15c98 for 149479196
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd15c48 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149479196
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 3768
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd16078 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd160c8 for 149479321
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd16078 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149479321
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 3177
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd16530 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd16580 for 149479625
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd16530 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149479625
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 2487
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd16a20 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd16a70 for 149479820
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd16a20 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149479820
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 1815
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd16e98 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd16ee8 for 149479829
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd16e98 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149479829
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 111
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd17380 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd173d0 for 149479836
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd17380 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149479836
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 3346
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd17820 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd17870 for 149480885
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd17820 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149480885
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 0
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd17cf8 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd17d48 for 149480891
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd17cf8 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149480891
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 2662
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd181d0 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd18220 for 149480910
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd181d0 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149480910
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 80
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd186c8 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd18718 for 149480942
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd186c8 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149480942
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 851
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd18bc0 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd18c10 for 149480994
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd18bc0 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 149480994
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 660
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd190b8 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd19108 for 74738800
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd190b8 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 74738800
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 815
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd19558 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_timer.c:115]: inserting 0x7f12fbd195a8 for 74738800
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd19558 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:417]: current dialog timeout is 74738800
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_db_handler.c:502]: the database has information about 27 dialog variables
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_handlers.c:1029]: route param is ‘05.b90956b6’ (len=11)
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:454]: ref dlg 0x7f12fbd186c8 with 1 → 3
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:456]: dialog id=1801818267 found on entry 80
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:770]: dialog 0x7f12fbd186c8 changed from state 4 to state 5, due event 7
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd186c8 with 1 → 4
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_handlers.c:1132]: BYE successfully processed
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd186c8 with 2 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd186c8 with 1 → 3
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd186c8 with 2 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:500]: no dialog callid=’1dBfQRAoyLT464fISVZ9dhaephqd82tP@chat.server.com’ found
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:500]: no dialog callid=’1dBfQRAoyLT464fISVZ9dhaephqd82tP@chat.server.com’ found
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:530]: no dialog callid=’1dBfQRAoyLT464fISVZ9dhaephqd82tP@chat.server.com’ found
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 815
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_handlers.c:271]: route_set <sip:REGISTRAR;lr=on;ftag=7b2add35>, contact sip:phone@IP, cseq 2 and bind_addr udp:kamailio:5060
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbd4b540 with 1 → 1
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_handlers.c:555]: invalid AVP value, using default timeout
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd4b540 with 1 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd4b540 with 1 → 3
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd4b540 with 1 → 4
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd4b540 with 1 → 3
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21597]: INFO: dialog [dlg_hash.c:770]: dialog 0x7f12fbd4b540 changed from state 1 to state 2, due event 2
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_timer.c:240]: start with tl=0x7f12fbd19108 tl→prev=0x7f12fbcfa408 tl→next=0x7f12fbd195a8 (74738800) at 74738801 and end with end=0x7f12fbcfa408 end→prev=0x7f12fbd18c10 end→next=0x7f12fbd19108
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_timer.c:243]: getting tl=0x7f12fbd19108 tl→prev=0x7f12fbcfa408 tl→next=0x7f12fbd195a8 with 74738800
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_timer.c:243]: getting tl=0x7f12fbd195a8 tl→prev=0x7f12fbd19108 tl→next=0x7f12fbd14630 with 74738800
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_timer.c:249]: end with tl=0x7f12fbd14630 tl→prev=0x7f12fbd195a8 tl→next=0x7f12fbd14f30 and d_timer→first.next→prev=(nil)
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_timer.c:282]: tl=0x7f12fbd19108 next=0x7f12fbd195a8
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:770]: dialog 0x7f12fbd190b8 changed from state 3 to state 5, due event 7
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: WARNING: dialog [dlg_handlers.c:1261]: timeout for dlg with CallID ‘1454228328-5078-8@69.247.46.172’ and tags ‘418753786’ ‘cf27ebe79162c9cd74b4c1640ab50ac0’ Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd190b8 with 2 → 0
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:597]: ref ⇐0 for dialog 0x7f12fbd190b8
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd190b8 (ref 0)
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:197]: removed timer for dlg 0x7f12fbd190b8 [660:1579719972] with clid ‘1454228328-5078-8@69.247.46.172’ and tags ‘418753786’ ‘cf27ebe79162c9cd74b4c1640ab50ac0’ Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_db_handler.c:584]: trying to remove dialog [1454228328-5078-8@69.247.46.172], update_flag is 4
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_db_handler.c:610]: callid was 1454228328-5078-8@69.247.46.172
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_timer.c:282]: tl=0x7f12fbd195a8 next=(nil)
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:770]: dialog 0x7f12fbd19558 changed from state 3 to state 5, due event 7
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: WARNING: dialog [dlg_handlers.c:1261]: timeout for dlg with CallID ‘1dBfQRAoyLT464fISVZ9dhaephqd82tP@chat.server.com’ and tags ‘7b2add35’ ‘394024340’ Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd19558 with 2 → 0
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:597]: ref ⇐0 for dialog 0x7f12fbd19558
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd19558 (ref 0)
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_hash.c:197]: removed timer for dlg 0x7f12fbd19558 [815:299849786] with clid ‘1dBfQRAoyLT464fISVZ9dhaephqd82tP@chat.server.com’ and tags ‘7b2add35’ ‘394024340’ Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_db_handler.c:584]: trying to remove dialog [1dBfQRAoyLT464fISVZ9dhaephqd82tP@chat.server.com], update_flag is 4
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21604]: INFO: dialog [dlg_db_handler.c:610]: callid was 1dBfQRAoyLT464fISVZ9dhaephqd82tP@chat.server.com
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:500]: no dialog callid=’K8JKSrpkjMl5dNl3KXEoEP4p72XCNwv7@chat.server.com’ found
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:500]: no dialog callid=’K8JKSrpkjMl5dNl3KXEoEP4p72XCNwv7@chat.server.com’ found
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:530]: no dialog callid=’K8JKSrpkjMl5dNl3KXEoEP4p72XCNwv7@chat.server.com’ found
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:307]: new dialog on hash 3598
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_handlers.c:271]: route_set <sip:REGISTRAR;lr=on;ftag=7b2add35>, contact sip:phone@IP, cseq 2 and bind_addr udp:kamailio:5060
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:559]: ref dlg 0x7f12fbdd29d0 with 1 → 1
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_handlers.c:555]: invalid AVP value, using default timeout
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbdd29d0 with 1 → 2
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbdd29d0 with 1 → 3
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbdd29d0 with 1 → 4
Nov 17 09:40:05 kamailio /usr/local/sbin/kamailio[21596]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbdd29d0 with 1 → 3
Nov 17 09:40:06 kamailio /usr/local/sbin/kamailio[21601]: INFO: dialog [dlg_hash.c:770]: dialog 0x7f12fbdd29d0 changed from state 1 to state 2, due event 2
Nov 17 09:40:09 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd186c8 with 1 → 0
Nov 17 09:40:09 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_hash.c:597]: ref ⇐0 for dialog 0x7f12fbd186c8
Nov 17 09:40:09 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd186c8 (ref 0)
Nov 17 09:40:09 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_hash.c:197]: removed timer for dlg 0x7f12fbd186c8 [80:1801818267] with clid ‘600081265-5078-16@BJC.BGI.B.GJ’ and tags ‘858402541’ ‘SDb2h8199-14c02ea8+1+29820001+3d78f6d6’ Nov 17 09:40:09 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_db_handler.c:584]: trying to remove dialog [600081265-5078-16@BJC.BGI.B.GJ], update_flag is 4
Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_db_handler.c:610]: callid was 600081265-5078-16@BJC.BGI.B.GJ
Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd186c8 with 1 → -1
Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: CRITICAL: dialog [dlg_hash.c:597]: bogus ref -1 with cnt 1 for dlg 0x7f12fbd186c8 [80:1801818267] with clid ‘600081265-5078-16@BJC.BGI.B.GJ’ and tags ‘858402541’ ‘SDb2h8199-14c02ea8+1+29820001+3d78f6d6’ Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_hash.c:597]: ref ⇐0 for dialog 0x7f12fbd186c8
Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd186c8 (ref -1)
Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_hash.c:197]: removed timer for dlg 0x7f12fbd186c8 [80:1801818267] with clid ‘600081265-5078-16@BJC.BGI.B.GJ’ and tags ‘858402541’ ‘SDb2h8199-14c02ea8+1+29820001+3d78f6d6’ Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_db_handler.c:584]: trying to remove dialog [600081265-5078-16@BJC.BGI.B.GJ], update_flag is 4
Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: INFO: dialog [dlg_db_handler.c:610]: callid was 600081265-5078-16@BJC.BGI.B.GJ
Nov 17 09:40:11 kamailio /usr/local/sbin/kamailio[21605]: : <core> [mem/q_malloc.c:457]: BUG: qm_free: freeing already freed pointer, first free: dialog: dlg_hash.c: destroy_dlg(217) - aborting
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd17cf8 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd145e0 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd17380 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd14ee0 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd4b540 (ref 3)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:197]: removed timer for dlg 0x7f12fbd4b540 [815:1061505763] with clid ‘1dBfQRAoyLT464fISVZ9dhaephqd82tP@chat.server.com’ and tags ‘7b2add35’ Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd15360 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd18bc0 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd16e98 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd16a20 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd181d0 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd15c48 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd16530 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd17820 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbdd29d0 (ref 3)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:197]: removed timer for dlg 0x7f12fbdd29d0 [3598:1332925286] with clid ‘K8JKSrpkjMl5dNl3KXEoEP4p72XCNwv7@chat.server.com’ and tags ‘7b2add35’
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd16078 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd14aa8 (ref 2)
Nov 17 09:40:12 kamailio /usr/local/sbin/kamailio[21595]: INFO: dialog [dlg_hash.c:181]: destroying dialog 0x7f12fbd15790 (ref 2)

Comment by Brandon Armstead (CRYY2010) - Sunday, 20 November 2011, 08:11 GMT

SEPARATE CRASH (full backtrace)

#0 0x00007f1eb16fbed5 in raise () from /lib/libc.so.6
#1 0x00007f1eb16fd3f3 in abort () from /lib/libc.so.6
#2 0×0000000000528739 in qm_free (qm=0x7f1e9a864000, p=0x7f1e9c2b28a0, file=0x7f1eaf8c26bb “dialog: dlg_hash.c”, func=0x7f1eaf8c3022 “destroy_dlg”, line=215) at mem/q_malloc.c:447
#3 0x00007f1eaf8aa224 in destroy_dlg (dlg=0x7f1e9cae87f8) at dlg_hash.c:215
#4 0x00007f1eaf8ac69b in unref_dlg (dlg=0x7f1e9cae87f8, cnt=518) at dlg_hash.c:584
#5 0x00007f1eaf8b1a94 in profile_cleanup (msg=<value optimized out>, flags=<value optimized out>, param=0×6) at dlg_profile.c:317
#6 0x00000000004bca91 in exec_post_script_cb (msg=0xaa93c8, type=<value optimized out>) at script_cb.c:195
#7 0x0000000000495a4d in receive_msg (

  buf=0x8a4300 "ACK sip:URI@IP:5060;user=phone;transport=udp SIP/2.0\r\nRecord-Route: <sip:PROXY:5078;lr=on;ftag=7a0b74aea87281deo0>\r\nVia: SIP/2.0/UDP PROXY:5078;branch=z9hG4bK-4ab37cdb"..., len=<value optimized out>, rcv_info=0x7fffba04e9a0) at receive.c:221

#8 0x000000000051ca91 in udp_rcv_loop () at udp_server.c:532
#9 0x0000000000464bf5 in main_loop () at main.c:1560
#10 0×0000000000468063 in main (argc=<value optimized out>, argv=0x7fffba04ec68) at main.c:2410
#0 0x00007f1eb16fbed5 in raise () from /lib/libc.so.6
No symbol table info available.
#1 0x00007f1eb16fd3f3 in abort () from /lib/libc.so.6
No symbol table info available.
#2 0×0000000000528739 in qm_free (qm=0x7f1e9a864000, p=0x7f1e9c2b28a0, file=0x7f1eaf8c26bb “dialog: dlg_hash.c”, func=0x7f1eaf8c3022 “destroy_dlg”, line=215) at mem/q_malloc.c:447

f = <value optimized out>
size = <value optimized out>

#3 0x00007f1eaf8aa224 in destroy_dlg (dlg=0x7f1e9cae87f8) at dlg_hash.c:215

ret = <value optimized out>
__FUNCTION__ = "destroy_dlg"

#4 0x00007f1eaf8ac69b in unref_dlg (dlg=0x7f1e9cae87f8, cnt=518) at dlg_hash.c:584

d_entry = <value optimized out>

#5 0x00007f1eaf8b1a94 in profile_cleanup (msg=<value optimized out>, flags=<value optimized out>, param=0×6) at dlg_profile.c:317
No locals.
#6 0x00000000004bca91 in exec_post_script_cb (msg=0xaa93c8, type=<value optimized out>) at script_cb.c:195

cb = (struct script_cb *) 0xe0e410
flags = 2147483649

#7 0x0000000000495a4d in receive_msg (

  buf=0x8a4300 "ACK sip:URI@IP:5060;user=phone;transport=udp SIP/2.0\r\nRecord-Route: <sip:PROXY:5078;lr=on;ftag=7a0b74aea87281deo0>\r\nVia: SIP/2.0/UDP PROXY:5078;branch=z9hG4bK-4ab37cdb"..., len=<value optimized out>, rcv_info=0x7fffba04e9a0) at receive.c:221
msg = (struct sip_msg *) 0xaa93c8
ctx = {rec_lev = 6, run_flags = 0, last_retcode = 0, jmp_env = {{__jmpbuf = {9420032, 5082739, 140736314272479, 0, 139769802477104, 139769812373504, 6, 4294967295}, __mask_was_saved = 9420904, 
    __saved_mask = {__val = {8357392, 140736314272168, 14652072, 4294967245, 139769812371096, 0, 139769810264522, 1, 0, 139771120713727, 4250091, 139769802477104, 14728624, 14652064, 139769810288658, 16}}}}}
ret = <value optimized out>
inb = {
s = 0x8a4300 "ACK sip:URI@IP:5060;user=phone;transport=udp SIP/2.0\r\nRecord-Route: <sip:PROXY:5078;lr=on;ftag=7a0b74aea87281deo0>\r\nVia: SIP/2.0/UDP PROXY:5078;branch=z9hG4bK-4ab37cdb"..., len = 729}
__FUNCTION__ = "receive_msg"

#8 0x000000000051ca91 in udp_rcv_loop () at udp_server.c:532

len = 729
from = (union sockaddr_union *) 0xdf92a0
fromlen = 16
ri = {src_ip = {af = 2, len = 4, u = {addrl = {2083402568, 6}, addr32 = {2083402568, 0, 6, 0}, addr16 = {13128, 31790, 0, 0, 6, 0, 0, 0}, addr = "H3.|\000\000\000\000\006\000\000\000\000\000\000"}}, 
dst_ip = {af = 2, len = 4, u = {addrl = {162653251, 0}, addr32 = {162653251, 0, 0, 0}, addr16 = {58435, 2481, 0, 0, 0, 0, 0, 0}, addr = "Cä±\t", '\0' <repeats 11 times>}}, src_port = 5078, dst_port = 5060, 
proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "\023ÖH3.|\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 54803, sin_addr = {s_addr = 2083402568}, 
    sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 54803, sin6_flowinfo = 2083402568, sin6_addr = {in6_u = {u6_addr8 = '\0' <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 = 0xe0bdb0, proto = 1 '\001'}
buf = "ACK sip:URI@IP:5060;user=phone;transport=udp SIP/2.0\r\nRecord-Route: <sip:PROXY:5078;lr=on;ftag=7a0b74aea87281deo0>\r\nVia: SIP/2.0/UDP PROXY:5078;branch=z9hG4bK-4ab37cdb"...
__FUNCTION__ = "udp_rcv_loop"

#9 0x0000000000464bf5 in main_loop () at main.c:1560

i = 5
pid = <value optimized out>
si = (struct socket_info *) 0xe0bdb0
si_desc = "udp receiver child=5 sock=67.228.177.9:5060\000\000\000\000\000°·à\000\000\000\000\000\001\000\000\000\036\177", '\0' <repeats 18 times>, "t\000\000\000\000\000\000\000\030\225\211\232\001\000\000\000\001\000\000\000\000\000\000\000\003", '\0' <repeats 22 times>

#10 0×0000000000468063 in main (argc=<value optimized out>, argv=0x7fffba04ec68) at main.c:2410

cfg_stream = (FILE *) 0x1a00010
c = <value optimized out>
r = <value optimized out>
tmp = 0x7fffba050e5f ""

Quit

Comment by Brandon Armstead (CRYY2010) - Sunday, 20 November 2011, 08:16 GMT

version: kamailio 3.1.5 (x86_64/linux) 2bb8bb-dirty
flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC, 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_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, PKG_SIZE 16MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: 2bb8bb -dirty
compiled on 18:55:59 Nov 19 2011 with gcc 4.3.2

This crash was produced on the above build

Also the syslog output I provided is with LM_DBG → LM_INFO (LM_INFO SYSLOG)

Let me know if I can provide any additional information, thanks!

Comment by Timo Reimann (tr) - Sunday, 20 November 2011, 10:57 GMT

Brandon,

I took a closer look at the information you gave: The problem seems to be related to reference counting (again).

I can see that the reference counter is decremented one time too often after the BYE message is received. In your scenario, things look like this:

Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_handlers.c:1132]: BYE successfully processed
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd186c8 with 2 → 2
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:579]: ref dlg 0x7f12fbd186c8 with 1 → 3
Nov 17 09:40:04 kamailio /usr/local/sbin/kamailio[21598]: INFO: dialog [dlg_hash.c:597]: unref dlg 0x7f12fbd186c8 with 2 → 1

In a reference call I did on my machine, you can see that the last unref operation is one less:

0(43729) NOTICE: dialog [dlg_handlers.c:1132]: BYE successfully processed
0(43729) NOTICE: dialog [dlg_hash.c:597]: unref dlg 0x101bb2080 with 2 → 2
0(43729) NOTICE: dialog [dlg_hash.c:579]: ref dlg 0x101bb2080 with 1 → 3
0(43729) NOTICE: dialog [dlg_hash.c:597]: unref dlg 0x101bb2080 with 1 → 2

This leads to the situation where the dialog is erroneously removed prematurely. When the “canonical” dialog termination occurs later, removal is conducted for a second time, leading to a double free.

So the question is: What is happening in your scenario? Are you using any dialog module-related functions or touch the dialog in any way within the configuration script during processing of the BYE request? If so, which one(s)?

Also, could you please post your dialog modparams?

I assume you’re using a latest build of 3.2 (that is, not the official release but a recently compiled build from the 3.2 branch). Is that correct?

Comment by Brandon Armstead (CRYY2010) - Sunday, 20 November 2011, 22:32 GMT

Timo,

 To be honest - after the crash occurred I've tried like 10 different builds from the top of the origin/3.1 origin/3.2 branch downwards - trying to see if one of them would not reproduce the crash.  So I can not say without a doubt that this log info is from a 3.1 or a 3.2 branch.

However the crash has happened with latest git 3.1 and 3.2 and several commits downwards from these branches.

* MOD PARAM *

# dialog
modparam(”dialog”, “enable_stats”, 1)
modparam(”dialog”, “dlg_flag”, 4)
modparam(”dialog”, “timeout_avp”, “$avp(s:dialog-timeout)”)
modparam(”dialog”, “default_timeout”, 3600)
modparam(”dialog”, “dlg_match_mode”, 1)
modparam(”dialog”, “db_mode”, 1)
modparam(”dialog”, “detect_spirals”, 1)

* SCENARIO *

The only thing that I am doing in configuration with dialog is three things.

1) I call dlg_manage right before t_relay()

2) I have the following code ABOVE loose_route:

if(dlg_get(”$ci”, “$ft”, “$tt”)){

          xlog("L_INFO", "[$ci] forceful call hangup");
          dlg_bye("all");

}

3) I am using various dialog pseudo variables through out the config, typically to insert information into the database via avp_db_query.

That is the extent of my dialog scripting.

Here is another interesting .... thought this issue seems specific to the following call scenario:

UAC → outbound call → REGISTRAR → (CORE PROXY / LCR *CRASHING*) → PSTN

PSTN responds with 503 “Service Unavailable”

CORE / PROXY advance routes → SECOND PSTN

*CRASH*

Also - another interesting note is that it seems it only happens in this scenario when sending the call to the explicit “SECOND PSTN”.

If I trade out SECOND PSTN for THIRD PSTN (an alternate carrier) then the crash does not happen.

I hope this provides some more light on the situation, let me know if I can provide any additional information, thanks!

Comment by Bayan Towfiq (btowfiq) - Monday, 21 November 2011, 06:59 GMT

Just as a note both Brandon Armstead and I are using dlg_manage() in the script. Could this have something to do with it?

Bayan

Comment by Timo Reimann (tr) - Monday, 21 November 2011, 20:18 GMT

I know of quite a few people who use dlg_manage() regularly and repeatedly for subsequent requests, so I wouldn’t consider it to be the #1 suspect. I’ll take a closer look at it though, just to be sure.

Thanks!

Comment by Brandon Armstead (CRYY2010) - Monday, 21 November 2011, 21:54 GMT

Timo,

  This bug is turning into a nightmare! :(.  It is totally weird since it seems to be present in 3.1 and 3.2 --- we've been running the 3.1 build since you worked out the last dialog issue.  However it appears to be present in all recent builds (origin/3.1, origin/3.2, and several dialog commits downwards from HEAD of 3.1 & 3.2).

I really really really appreciate any time and effort you can put into resolving this matter.

Thanks for your help as always!

Comment by Daniel-Constantin Mierla (miconda) - Monday, 21 November 2011, 22:46 GMT

Try with attached patch – an workaround solution for now discussed with Timo, but I guess he had no time to check and commit it yet.

Comment by Daniel-Constantin Mierla (miconda) - Monday, 21 November 2011, 23:07 GMT

Also, I just pushed in a tmp branch (tmp/dlgnewref) a patch refactoring the dlg structure reference counting, mainly in relation with TM module. The commit link is:

This approach should be safer for any future development of tm, as there is no more storage of a dialog module specific pointer inside TM structures. Also, dialog structures destroyed for various reasons, will be no longer found by tm callbacks or timer functions, thus no more risk of segmentation fault.

Testing of this new version will appreciated. Based on results and feedback, it will be merged into master branch and backported – there is no change in config functionality or exported API of dialog module – just internal refactoring.

Comment by Timo Reimann (tr) - Tuesday, 22 November 2011, 20:33 GMT

Daniel, great you pushed the patch. I couldn’t manage to do it myself yesterday so thanks for taking care of things.

Comment by Bayan Towfiq (btowfiq) - Wednesday, 23 November 2011, 02:46 GMT

Timo, just a note:
on the unpatched 3.2 (not including the new patches/branch/ or workaround solution) changing the config file stopped it from crashing. Here is the diff. Do you think it may have something to do with the dlg variables in branch_route or the dlg_manage changing to setflag(4)?

1 — natproxy.cfg.old 2011-11-22 09:17:31.888043699 +0000
2 +++ natproxy.cfg 2011-11-22 08:30:52.182372274 +0000
3 @@ -94,11 +95,13 @@
4
5 modparam(”ctl”, “binrpc”, “/tmp/ser_ctl”)
6
7 modparam(”sanity”, “autodrop”, 0)
8
9 include_file “/usr/local/etc/kamailio/natproxy-modulesconfig.cfg” 10
11 -flags inbound_call, hash_id, hash_entry;
12 +flags inbound_call;
13
14
15 route{
16 @@ -172,10 +175,7 @@
17 }
18
19 if(allow_trusted() && is_method(”INVITE”)) {
20 - dlg_manage();
21 - $avp(hash_entry) = $dlg(h_entry);
22 - $avp(hash_id) = $dlg(h_id);
23 + setflag(4);
24 $dlg_ctx(timeout_bye) = 1;
25 setflag(inbound_call);
26 if(is_present_hf(”X-Reject”)) {
27 @@ -690,8 +687,7 @@
28
29 onreply_route[1] {
30 if($rm == “INVITE” && isflagset(inbound_call)) {
31 - append_hf(”X-Hash: $avp(hash_entry):$avp(hash_id)\r\n”); #Appending hash in onreply_route here
32 append_hf(”X-XMLRPC: $sel(cfg_get.xmlrpc.hostport)\r\n”);
33 };
34 }
35 @@ -765,12 +761,7 @@
36 }
37
38 branch_route[1] {
39 - if($avp(s:dlghash1) == $null) {
40 - $avp(s:dlghash1) = $dlg(h_entry);
41 - $avp(s:dlghash2) = $dlg(h_id);
42 - };
43 - append_hf(”X-Hash: $avp(s:dlghash1):$avp(s:dlghash2)\r\n”); #Appending hash in branch_route here
44 append_hf(”X-XMLRPC: $sel(cfg_get.xmlrpc.hostport)\r\n”);
45 }
46

Comment by Brandon Armstead (CRYY2010) - Wednesday, 23 November 2011, 03:17 GMT

Wow - please look into this - very bad :(.

Comment by Daniel-Constantin Mierla (miconda) - Wednesday, 23 November 2011, 07:38 GMT

There are two options of fixing provided above, that means we looked into it. Have you tried any of them and it is still a problem?

Comment by Brandon Armstead (CRYY2010) - Wednesday, 23 November 2011, 20:46 GMT

Daniel - Thanks! I've tried the patch for the time being and it appears that it is working so far. I will be sure to try the new dlg reference counting branch soon as well. Thanks!

Comment by Bayan Towfiq (btowfiq) - Thursday, 24 November 2011, 00:25 GMT

I am running dlgnewref and I will keep you updated. Bayan

Comment by Daniel-Constantin Mierla (miconda) - Thursday, 24 November 2011, 11:39 GMT

OK, thanks! I will reduce the severity of the item for now (there is a fix) and close it later when we have more feedback.

Comment by Brandon Armstead (CRYY2010) - Friday, 25 November 2011, 13:22 GMT

I just experienced a crash with the work-around. I'm going to try the dlg new reference.

Comment by Brandon Armstead (CRYY2010) - Friday, 25 November 2011, 13:58 GMT

Dialog New Ref *** CRASH *** [New process 22271] #0 0x00007f6d164e8ad2 in dlg_lookup (h_entry=2849, h_id=1192025086) at dlg_hash.c:442 442 if (h_entry>=d_table->size) (gdb) bt #0 0x00007f6d164e8ad2 in dlg_lookup (h_entry=2849, h_id=1192025086) at dlg_hash.c:442 #1 0x00007f6d164e0725 in unref_dlg_from_cb (t=<value optimized out>, type=1192025086, param=0x7fff21c7a460) at dlg_handlers.c:964 #2 0x00007f6d1673db19 in run_trans_callbacks_internal (cb_lst=0x7f6d017c9b20, type=32768, trans=0x7f6d017c9ab0, params=0x7fff21c7a460) at t_hooks.c:290 #3 0x00007f6d1673dd86 in run_trans_callbacks (type=32768, trans=<value optimized out>, req=0x0, rpl=0x7f6d1670cc68, code=0) at t_hooks.c:317 #4 0x00007f6d167238c6 in free_cell (dead_cell=0x7f6d017c9ab0) at h_table.c:152 #5 0x00007f6d16723af0 in free_hash_table () at h_table.c:443 #6 0x00007f6d16734875 in tm_shutdown () at t_funcs.c:126 #7 0x00000000004e068f in destroy_modules () at sr_module.c:783 #8 0x00000000004655d0 in cleanup (show_status=1) at main.c:564 #9 0x00000000004662a4 in shutdown_children (sig=<value optimized out>, show_status=1) at main.c:706 #10 0x0000000000466c7b in handle_sigs () at main.c:797 #11 0x0000000000467bb6 in main_loop () at main.c:1741 #12 0x000000000046b22c in main (argc=<value optimized out>, argv=0x7fff21c7a888) at main.c:2508 (gdb) bt full #0 0x00007f6d164e8ad2 in dlg_lookup (h_entry=2849, h_id=1192025086) at dlg_hash.c:442 dlg = <value optimized out> d_entry = <value optimized out> #1 0x00007f6d164e0725 in unref_dlg_from_cb (t=<value optimized out>, type=1192025086, param=0x7fff21c7a460) at dlg_handlers.c:964 dlg = <value optimized out> iuid = (dlg_iuid_t *) 0xb21 #2 0x00007f6d1673db19 in run_trans_callbacks_internal (cb_lst=0x7f6d017c9b20, type=32768, trans=0x7f6d017c9ab0, params=0x7fff21c7a460) at t_hooks.c:290 cbp = (struct tm_callback *) 0x7f6d018fe5e8 backup_from = (avp_list_t *) 0x8d0310 backup_to = (avp_list_t *) 0x8d0318 backup_dom_from = (avp_list_t *) 0x8d0320 backup_dom_to = (avp_list_t *) 0x8d0328 backup_uri_from = (avp_list_t *) 0x8d0300 backup_uri_to = (avp_list_t *) 0x8d0308 backup_xavps = (sr_xavp_t **) 0x8d0410 #3 0x00007f6d1673dd86 in run_trans_callbacks (type=32768, trans=<value optimized out>, req=0x0, rpl=0x7f6d1670cc68, code=0) at t_hooks.c:317 params = {req = 0x0, rpl = 0x0, param = 0x7f6d018fe5f8, code = 0, flags = 0, branch = 0, t_rbuf = 0x0, dst = 0x0, send_buf = {s = 0x0, len = 0}} #4 0x00007f6d167238c6 in free_cell (dead_cell=0x7f6d017c9ab0) at h_table.c:152 b = <value optimized out> i = <value optimized out> rpl = <value optimized out> tt = <value optimized out> foo = <value optimized out> cbs = <value optimized out> __FUNCTION__ = "free_cell" #5 0x00007f6d16723af0 in free_hash_table () at h_table.c:443 p_cell = (struct cell *) 0xb21 tmp_cell = (struct cell *) 0x7f6d0164cd18 __FUNCTION__ = "free_hash_table" #6 0x00007f6d16734875 in tm_shutdown () at t_funcs.c:126 No locals. #7 0x00000000004e068f in destroy_modules () at sr_module.c:783 t = <value optimized out> foo = (struct sr_module *) 0x7f6d1832f810 __FUNCTION__ = "destroy_modules" #8 0x00000000004655d0 in cleanup (show_status=1) at main.c:564 memlog = <value optimized out> __FUNCTION__ = "cleanup" #9 0x00000000004662a4 in shutdown_children (sig=<value optimized out>, show_status=1) at main.c:706 No locals. #10 0x0000000000466c7b in handle_sigs () at main.c:797 chld = 0 chld_status = 139 memlog = <value optimized out> #11 0x0000000000467bb6 in main_loop () at main.c:1741 i = 8 pid = <value optimized out> si = (struct socket_info *) 0x0 si_desc = "udp receiver child=7 sock=67.228.177.9:5060\000\000\000\000\000`+\205\030m\177\000\000\001\000\000\000m\177\000\000\016\b", '\0' <repeats 22 times>, "\001\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\003\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\b\000\000\000\000\000\000" #12 0x000000000046b22c in main (argc=<value optimized out>, argv=0x7fff21c7a888) at main.c:2508 ---Type <return> to continue, or q <return> to quit---q

Comment by Daniel-Constantin Mierla (miconda) - Friday, 25 November 2011, 17:09 GMT

Do you have the backtrace for the case with the patch (workaround)?

Comment by Daniel-Constantin Mierla (miconda) - Friday, 25 November 2011, 17:10 GMT

The crash for the new version of dlg ref is at shut down. Did you stop the sip server?

Comment by Brandon Armstead (CRYY2010) - Friday, 25 November 2011, 18:27 GMT

Daniel, I believe the following backtrace I'm going to post is from the "work around" crash. As for restarting the SIP server --- this is possible but ONLY after a crash - so not sure if somehow the core file was still being generated and kamailio hadn't completely shutdown... **** BACK TRACE **** #0 0x00007fd59be0fed5 in raise () from /lib/libc.so.6 #1 0x00007fd59be113f3 in abort () from /lib/libc.so.6 #2 0x0000000000528679 in qm_free (qm=0x7fd584f78000, p=0x7fd585269fe8, file=0x7fd599fd66bb "dialog: dlg_hash.c", func=0x7fd599fd7022 "destroy_dlg", line=215) at mem/q_malloc.c:447 #3 0x00007fd599fbe224 in destroy_dlg (dlg=0x7fd58526c828) at dlg_hash.c:215 #4 0x00007fd599fc069b in unref_dlg (dlg=0x7fd58526c828, cnt=514) at dlg_hash.c:584 #5 0x00007fd599fc5a94 in profile_cleanup (msg=<value optimized out>, flags=<value optimized out>, param=0x6) at dlg_profile.c:317 #6 0x00000000004bc9d1 in exec_post_script_cb (msg=0xe04b18, type=<value optimized out>) at script_cb.c:195 #7 0x000000000049598d in receive_msg ( buf=0x8a4300 "INVITE sip:RURI@KAMAILIO SIP/2.0\r\nRecord-Route: <sip:KAMAILIO_REGISTRAR;lr=on;ftag=658fa5a34456db0do0>\r\nVia: SIP/2.0/UDP KAMAILIO_REGISTRAR;branch=z9hG4bK8177.1bcb9436.0\r\nVia: SIP/2."..., len=<value optimized out>, rcv_info=0x7fffa4763210) at receive.c:221 #8 0x000000000051c9d1 in udp_rcv_loop () at udp_server.c:532 #9 0x0000000000464b35 in main_loop () at main.c:1560 #10 0x0000000000467fa3 in main (argc=<value optimized out>, argv=0x7fffa47634d8) at main.c:2410 #0 0x00007fd59be0fed5 in raise () from /lib/libc.so.6 No symbol table info available. #1 0x00007fd59be113f3 in abort () from /lib/libc.so.6 No symbol table info available. #2 0x0000000000528679 in qm_free (qm=0x7fd584f78000, p=0x7fd585269fe8, file=0x7fd599fd66bb "dialog: dlg_hash.c", func=0x7fd599fd7022 "destroy_dlg", line=215) at mem/q_malloc.c:447 f = <value optimized out> size = <value optimized out> #3 0x00007fd599fbe224 in destroy_dlg (dlg=0x7fd58526c828) at dlg_hash.c:215 ret = <value optimized out> __FUNCTION__ = "destroy_dlg" #4 0x00007fd599fc069b in unref_dlg (dlg=0x7fd58526c828, cnt=514) at dlg_hash.c:584 d_entry = <value optimized out> #5 0x00007fd599fc5a94 in profile_cleanup (msg=<value optimized out>, flags=<value optimized out>, param=0x6) at dlg_profile.c:317 No locals. #6 0x00000000004bc9d1 in exec_post_script_cb (msg=0xe04b18, type=<value optimized out>) at script_cb.c:195 cb = (struct script_cb *) 0xe19c08 flags = 2147483649 #7 0x000000000049598d in receive_msg ( buf=0x8a4300 "INVITE sip:RURI@KAMAILIO SIP/2.0\r\nRecord-Route: <sip:KAMAILIO_REGISTRAR;lr=on;ftag=658fa5a34456db0do0>\r\nVia: SIP/2.0/UDP KAMAILIO_REGISTRAR;branch=z9hG4bK8177.1bcb9436.0\r\nVia: SIP/2."..., len=<value optimized out>, rcv_info=0x7fffa4763210) at receive.c:221 msg = (struct sip_msg *) 0xe04b18 ctx = {rec_lev = 8, run_flags = 0, last_retcode = 0, jmp_env = {{__jmpbuf = {9420032, 5082547, 140735952597839, 0, 140555419815472, 140555429711872, 8, 4294967295}, __mask_was_saved = 9420904, __saved_mask = {__val = {8357392, 140735952597528, 14699168, 4294967245, 140555429709464, 0, 140555427602890, 1, 0, 140557099728895, 4250091, 140555419815472, 14775720, 14699160, 140555427627026, 16}}}}} ret = <value optimized out> inb = { s = 0x8a4300 "INVITE sip:RURI@KAMAILIO SIP/2.0\r\nRecord-Route: <sip:KAMAILIO_REGISTRAR;lr=on;ftag=658fa5a34456db0do0>\r\nVia: SIP/2.0/UDP KAMAILIO_REGISTRAR;branch=z9hG4bK8177.1bcb9436.0\r\nVia: SIP/2."..., len = 1077} __FUNCTION__ = "receive_msg" #8 0x000000000051c9d1 in udp_rcv_loop () at udp_server.c:532 len = 1077 from = (union sockaddr_union *) 0xe04a98 fromlen = 16 ri = {src_ip = {af = 2, len = 4, u = {addrl = {2512315459, 8}, addr32 = {2512315459, 0, 8, 0}, addr16 = {58435, 38334, 0, 0, 8, 0, 0, 0}, addr = "C��\225\000\000\000\000\b\000\000\000\000\000\000"}}, dst_ip = {af = 2, len = 4, u = {addrl = {162653251, 0}, addr32 = {162653251, 0, 0, 0}, addr16 = {58435, 2481, 0, 0, 0, 0, 0, 0}, addr = "C��\t", '\0' <repeats 11 times>}}, src_port = 5060, dst_port = 5060, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "\023�C��\225\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 50195, sin_addr = {s_addr = 2512315459}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, sin6_flowinfo = 2512315459, sin6_addr = {in6_u = {u6_addr8 = '\0' <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 = 0xe175a8, proto = 1 '\001'} buf = "INVITE sip:RURI@KAMAILIO SIP/2.0\r\nRecord-Route: <sip:KAMAILIO_REGISTRAR;lr=on;ftag=658fa5a34456db0do0>\r\nVia: SIP/2.0/UDP KAMAILIO_REGISTRAR;branch=z9hG4bK8177.1bcb9436.0\r\nVia: SIP/2."... __FUNCTION__ = "udp_rcv_loop" #9 0x0000000000464b35 in main_loop () at main.c:1560 i = 7 pid = <value optimized out> si = (struct socket_info *) 0xe175a8 si_desc = "udp receiver child=7 sock=KAMAILIO:5060\000\000\000\000\000�o�\000\000\000\000\000\001\000\000\000�\177", '\0' <repeats 18 times>, "t\000\000\000\000\000\000\000\030��\204\001\000\000\000\001\000\000\000\000\000\000\000\003", '\0' <repeats 22 times> #10 0x0000000000467fa3 in main (argc=<value optimized out>, argv=0x7fffa47634d8) at main.c:2410 cfg_stream = (FILE *) 0x2316010 c = <value optimized out> r = <value optimized out> tmp = 0x7fffa4764f76 "" tmp_len = 32725 port = <value optimized out> proto = <value optimized out> ret = <value optimized out> seed = 427627096 rfd = 4 debug_save = <value optimized out> debug_flag = 0 dont_fork_cnt = 0 n_lst = <value optimized out> p = <value optimized out>

Comment by Bayan Towfiq (btowfiq) - Friday, 25 November 2011, 18:44 GMT

I also had a crash with dlgnewref -- it was not during shutdown: Program terminated with signal 11, Segmentation fault. #0 0x00007f11fb8bbe61 in dlg_lookup (h_entry=9097, h_id=1731333290) at dlg_hash.c:442 442 if (h_entry>=d_table->size) (gdb) bt #0 0x00007f11fb8bbe61 in dlg_lookup (h_entry=9097, h_id=1731333290) at dlg_hash.c:442 #1 0x00007f11fb8b2bf5 in unref_dlg_from_cb (t=<value optimized out>, type=1731333290, param=0x7fffb1193a40) at dlg_handlers.c:964 #2 0x00007f1200dea164 in run_trans_callbacks_internal (cb_lst=<value optimized out>, type=32768, trans=0x7f11eb1e1750, params=0x7fffb1193a40) at t_hooks.c:290 #3 0x00007f1200dea503 in run_trans_callbacks (type=32768, trans=<value optimized out>, req=<value optimized out>, rpl=0x0, code=0) at t_hooks.c:317 #4 0x00007f1200dcfc9a in free_cell (dead_cell=0x7f11eb1e1750) at h_table.c:152 #5 0x00007f1200dcfe68 in free_hash_table () at h_table.c:443 #6 0x00007f1200ddff15 in tm_shutdown () at t_funcs.c:126 #7 0x00000000004e25af in destroy_modules () at sr_module.c:783 #8 0x00000000004616ff in cleanup (show_status=1) at main.c:564 #9 0x000000000046236b in shutdown_children (show_status=1, sig=<value optimized out>) at main.c:706 #10 0x0000000000463382 in handle_sigs () at main.c:797 #11 0x000000000046451e in main_loop () at main.c:1741 #12 0x0000000000465f98 in main (argc=11, argv=0x7fffb1193ef8) at main.c:2508 (gdb) bt full #0 0x00007f11fb8bbe61 in dlg_lookup (h_entry=9097, h_id=1731333290) at dlg_hash.c:442 dlg = <value optimized out> d_entry = <value optimized out> #1 0x00007f11fb8b2bf5 in unref_dlg_from_cb (t=<value optimized out>, type=1731333290, param=0x7fffb1193a40) at dlg_handlers.c:964 dlg = <value optimized out> iuid = 0x2389 #2 0x00007f1200dea164 in run_trans_callbacks_internal (cb_lst=<value optimized out>, type=32768, trans=0x7f11eb1e1750, params=0x7fffb1193a40) at t_hooks.c:290 cbp = 0x7f11eb1b8620 backup_from = 0x8cb110 backup_to = 0x8cb118 backup_dom_from = 0x8cb120 backup_dom_to = 0x8cb128 backup_uri_from = 0x8cb100 backup_uri_to = 0x8cb108 backup_xavps = 0x8cb210 #3 0x00007f1200dea503 in run_trans_callbacks (type=32768, trans=<value optimized out>, req=<value optimized out>, rpl=0x0, code=0) at t_hooks.c:317 params = {req = 0x0, rpl = 0x0, param = 0x7f11eb1b8630, code = 0, flags = 0, branch = 0, t_rbuf = 0x0, dst = 0x0, send_buf = {s = 0x0, len = 0}} #4 0x00007f1200dcfc9a in free_cell (dead_cell=0x7f11eb1e1750) at h_table.c:152 b = <value optimized out> i = <value optimized out> rpl = <value optimized out> tt = <value optimized out> foo = <value optimized out> cbs = <value optimized out> __FUNCTION__ = "free_cell" #5 0x00007f1200dcfe68 in free_hash_table () at h_table.c:443 p_cell = 0x2389 tmp_cell = 0x7f11eaee5dc8 i = 598 __FUNCTION__ = "free_hash_table" #6 0x00007f1200ddff15 in tm_shutdown () at t_funcs.c:126 No locals. #7 0x00000000004e25af in destroy_modules () at sr_module.c:783 t = <value optimized out> foo = 0x7f12028fe0f0 __FUNCTION__ = "destroy_modules" #8 0x00000000004616ff in cleanup (show_status=1) at main.c:564 memlog = <value optimized out> __FUNCTION__ = "cleanup" #9 0x000000000046236b in shutdown_children (show_status=1, sig=<value optimized out>) at main.c:706 No locals. #10 0x0000000000463382 in handle_sigs () at main.c:797 chld = 0 chld_status = 134 memlog = <value optimized out> #11 0x000000000046451e in main_loop () at main.c:1741 i = 8 pid = <value optimized out> si = 0x0 si_desc = "udp receiver child=7 sock=70.167.xxx.xxx:5160\000\000\000\000\000@\020", '\000' <repeats 12 times>, "\016\b\000\000\000\000\000\000\000=\206=\220]֛&\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\300\v\215\000\000\000\000\000\"\000\000\000\000\000\000\000\000\000@\020", '\000' <repeats 11 times> #12 0x0000000000465f98 in main (argc=11, argv=0x7fffb1193ef8) at main.c:2508 cfg_stream = <value optimized out> c = <value optimized out> r = <value optimized out> tmp = 0x7fffb1195e83 "" ---Type <return> to continue, or q <return> to quit--- tmp_len = 0 port = <value optimized out> proto = <value optimized out> ret = <value optimized out> seed = 3986280357 rfd = <value optimized out> debug_save = 272629760 debug_flag = 34 dont_fork_cnt = 0 n_lst = 0x10400000 p = <value optimized out>

Comment by Bayan Towfiq (btowfiq) - Friday, 25 November 2011, 18:45 GMT

this crash was even with the simplified config snippet i posted above

Comment by Bayan Towfiq (btowfiq) - Friday, 25 November 2011, 19:01 GMT

Sorry, this is a crash during shutdown only: I just tested it.

Comment by Daniel-Constantin Mierla (miconda) - Friday, 25 November 2011, 19:43 GMT

I will have a fix shortly for shutdown case -- the problem is that dialog module is destroyed before tm module, there has to be an extra check for this case.

Comment by Daniel-Constantin Mierla (miconda) - Friday, 25 November 2011, 23:37 GMT

I just pushed the patch for shutdown case to GIT branch tmp/dlgnewref

Comment by Bayan Towfiq (btowfiq) - Monday, 28 November 2011, 22:24 GMT

The dlgnewref has been working well. Please commit/backport the fixes to 3.2 .

Comment by Bayan Towfiq (btowfiq) - Tuesday, 29 November 2011, 11:22 GMT

will the dlgnewref also be merged?

Comment by Daniel-Constantin Mierla (miconda) - Wednesday, 30 November 2011, 18:08 GMT

Merged branch branch tmp/dlgnewref to master and backported to 3.2

Comment by Anonymous Submitter - Wednesday, 25 April 2012, 00:48 GMT

specifically created for every single with the 4 pillars on which our item providing is now primarily based http://www.askweddingdress.net halter beach dress http://www.askweddingdress.net wholesale bridesmaid dresses ,; Corum;s Common Supervisor Antonio Calce mentioned within a media launch. ;Every single pillar may have a provider whose profile corresponds towards the precise complexion from the specific assortment. http://www.askweddingdress.net cheap short prom dresses ; To coincide using this new method, Corum is together with rebuilding its distribution labyrinth by lowering the factors of sale globally, appointing regional professionals and strengthening its associations with distributors. http://www.askweddingdress.net cheap dresses wholesale Corum lately exhibited its Admiral;s Cup Problem forty four chronograph from your new Admiral;s Cup selection http://www.askweddingdress.net discount wedding gowns , that has currently been developed using this steady strategy in thoughts, from Dec. 79 in Paris http://www.askweddingdress.net cheap wedding dresses http://www.askweddingdress.net/bridesmaid-dresses.html bridesmaid prom dresses http://www.askweddingdress.net cute summer dresses . The situation was the initial version of ;Belles Montres; in the Salon Worldwide de l;Horlogerie de celeb inside the Carrousel du Louvre http://www.askweddingdress.net pregnant brides dresses , plus the

Comment by bayram (forza198419) - Monday, 30 April 2012, 06:25 GMT

Hi Daniel, Is this fix solved in 3.2.3 version? we face this problem in 3.2.0 and updated to 3.2.3 # kamailio -V version: kamailio 3.2.3 (x86_64/linux) flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC, 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_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 14:19:25 Apr 19 2012 with gcc 4.4.5

Loading...