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/04410aef38f5ed40c8f4a6796d956584...
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@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:
- Call gets setup
- Callee's internet connection drops
- Call gets terminated (nicely) due to ka_timer/ka_interval
- 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.