[SR-Users] Keep-Alive in dialog "freeing a free fragment"

[Daniel-Constantin Mierla]

Hello,

I couldn't correlate the log message for double free with the code for
bye_reply_cb and dlg_ka_cb. The logs from pid 24493 shows only dialog
lookups and that double free message.

Do you have the instance still running? Can you send the output of:

kamctl ps

Also, would be helpful to see some other logs messages printed just
before by pid 24493.

By analyzing the code I found an improvement to be done, already
committed in master via:

-
https://github.com/kamailio/kamailio/commit/04410aef38f5ed40c8f4a6796d95658407e1597c

It is about being sure the dialog is still in confirmed state when the
keepalive callback is handled.

But I can't be sure yet if that was the case resulting in double free.

Cheers,
Daniel

On 07/05/15 09:34, Dirk Teurlings - SIGNET B.V. wrote:
> Hi again,
>
> File dlg_req_within.c
>     function bye_reply_cb line: 166-236
>     functino dlg_ka_cb line: 240-275
>
> To help you out a bit more, this is important part of the log.
>
>
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: DEBUG: dialog
> [dlg_hash.c:1066]: next_state_dlg(): dialog 0x7f812f2585e8 changed
> from state 4 to state 5, due event 7 (ref 5)
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: DEBUG: dialog
> [dlg_req_within.c:195]: bye_reply_cb(): removing dialog with h_entry
> 1231 and h_id 1142
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: WARNING: dialog
> [dlg_req_within.c:212]: bye_reply_cb(): inconsitent dlg timer data on
> dlg 0x7f812f2585e8 [1231:1142] with clid
> '6fcb9a946131aad41e1deda730c6b76a at 192.168.10.245:5060' and tags
> 'as57b6a153' 'c42610a13600fe22i0'
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: DEBUG: dialog
> [dlg_cb.c:256]: run_dlg_callbacks(): dialog=0x7f812f2585e8, type=64
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: DEBUG: dialog
> [dlg_req_within.c:219]: bye_reply_cb(): first final reply
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: DEBUG: dialog
> [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7f812f2585e8 with 2 -> 3
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: DEBUG: dialog
> [dlg_handlers.c:324]: dlg_iuid_sfree(): freeing dlg iuid [1231:1142]
> (0x7f812f2529f0)
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: DEBUG: tm
> [t_reply.c:1653]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers:
> RETR/FR timers reset
> May  4 18:09:42 vps-host /usr/sbin/kamailio[24484]: DEBUG: dialog
> [dlg_var.c:81]: cb_dlg_locals_reset(): resetting the local dialog
> shortcuts on script callback: 2147483652
>
> ...
>
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24484]: DEBUG: <core>
> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24484]: DEBUG: <core>
> [receive.c:298]: receive_msg(): receive_msg: cleaning up
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24488]: DEBUG: tm
> [t_reply.c:1294]: t_should_relay_response(): ->>>>>>>>> T_code=0,
> new_code=408
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24488]: DEBUG: tm
> [t_reply.c:2080]: local_reply(): DEBUG: local_reply: branch=0, save=0,
> winner=0
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24488]: DEBUG: tm
> [t_reply.c:2117]: local_reply(): DEBUG: local transaction completed
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24488]: DEBUG: tm
> [t_hooks.c:288]: run_trans_callbacks_internal(): DBG:
> trans=0x7f812f256fd0, callback type 1024, id 0 entered
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24488]: DEBUG: dialog
> [dlg_req_within.c:255]: dlg_ka_cb(): receiving a final reply 408
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24488]: DEBUG: dialog
> [dlg_hash.c:663]: dlg_lookup(): no dialog id=1142 found on entry 1231
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24488]: DEBUG: dialog
> [dlg_handlers.c:324]: dlg_iuid_sfree(): freeing dlg iuid [1231:1142]
> (0x7f812f252ba0)
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24493]: DEBUG: dialog
> [dlg_hash.c:663]: dlg_lookup(): no dialog id=1142 found on entry 1231
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24493]: DEBUG: dialog
> [dlg_hash.c:663]: dlg_lookup(): no dialog id=11917 found on entry 68
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24493]: DEBUG: dialog
> [dlg_hash.c:663]: dlg_lookup(): no dialog id=1142 found on entry 1231
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24493]: INFO: <core>
> [mem/f_malloc.c:599]: fm_free(): freeing a free fragment
> (0x7f812f252ad0/0x7f812f252b08) - ignore
> May  4 18:10:02 vps-host /usr/sbin/kamailio[24493]: DEBUG: dialog
> [dlg_hash.c:663]: dlg_lookup(): no dialog id=11917 found on entry 68
> etc...
>
>
> Cheers,
> Dirk Teurlings
>
>
> On 07-05-15 09:03, Daniel-Constantin Mierla wrote:
>> Hello,
>>
>> thanks for reporting and troubleshooting.
>>
>> Can you refer to the code (file+lines) for step 3 and 4? It will save me
>> some time to look into the code and fix the issue.
>>
>> Cheers,
>> Daniel
>>
>> On 07/05/15 08:46, Dirk Teurlings - SIGNET B.V. wrote:
>>> Hi,
>>>
>>> (Kamailio 4.2.3)
>>>
>>> Working to get dialogs closed and cleaned up nicely I'm looking into
>>> the ka_interval and ka_timer parameter of the dialog module. The
>>> following is now happening.
>>>
>>> Scenario:
>>> 1. Call gets setup
>>> 2. Callee's internet connection drops
>>> 3. Call gets terminated (nicely) due to ka_timer/ka_interval
>>> 4. Log fills with "freeing a free fragment" after about 10 seconds
>>>
>>> Digging into this I saw that the dialog is being closed and cleaned
>>> properly in step 3. But it fails to remove/clean the timers used for
>>> the keep-alive. That's what triggers step 4, which in turn tries to
>>> clean the (or some of the) dialog space again. Is this expected
>>> behaviour when using the keep-alive options, or am I running into
>>> somekind of (known) bug?
>>>
>>> Thanks in advance for any help.
>>>
>>

-- 
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio World Conference, May 27-29, 2015
Berlin, Germany - http://www.kamailioworld.com