THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY. The following task has a new comment added: FS#424 - zombie dialogs in state 5 User who did this - Ovidiu Sas (osas) ---------- I'm testing on master. For your reference, here are the logs from a run with a pre-created transaction. In this case, the tm calbacks are properly executed (when the BYE tm transaction is destroyed): Sep 16 15:26:37 centos k[28392]: INFO: <script>: [2] BYE sip:4165552222@192.168.2.97:5064 From:sip:1234@192.168.2.62,tag=as1948d268 To:sip:4165552222@192.168.2.62,tag=394e236c94334078o4 Call-ID:7f8b057c-5a0545a8@192.168.2.97 Contact:<null> <192.168.2.2:5060->udp:192.168.2.62:5060> Sep 16 15:26:37 centos k[28392]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=2 , global msg id=1 , T on entrance=0xffffffffffffffff Sep 16 15:26:37 centos k[28392]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=8480, isACK=0 Sep 16 15:26:37 centos k[28392]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed Sep 16 15:26:37 centos k[28392]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found Sep 16 15:26:37 centos k[28392]: DEBUG: tm [t_hooks.c:374]: run_reqin_callbacks_internal(): DBG: trans=0x7f6f5e037320, callback type 1, id 0 entered Sep 16 15:26:37 centos k[28392]: DEBUG: tm [t_hooks.c:374]: run_reqin_callbacks_internal(): DBG: trans=0x7f6f5e037320, callback type 1, id 0 entered Sep 16 15:26:37 centos k[28392]: INFO: <script>: [2] t_newtran completed Sep 16 15:26:37 centos k[28392]: DEBUG: dialog [dlg_handlers.c:1163]: dlg_onroute(): route param is '052.da31' (len=8) Sep 16 15:26:37 centos k[28392]: DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x7f6f5e037070 with 1 -> 3 Sep 16 15:26:37 centos k[28392]: DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=5037 found on entry 592 Sep 16 15:26:37 centos k[28392]: DEBUG: dialog [dlg_profile.c:511]: set_current_dialog(): setting current dialog [592:5037] Sep 16 15:26:37 centos k[28392]: DEBUG: dialog [dlg_hash.c:1066]: next_state_dlg(): dialog 0x7f6f5e037070 changed from state 4 to state 5, due event 7 (ref 3) Sep 16 15:26:37 centos k[28392]: DEBUG: dialog [dlg_hash.c:854]: dlg_ref(): ref dlg 0x7f6f5e037070 with 1 -> 4 Sep 16 15:26:37 centos k[28392]: DEBUG: dialog [dlg_handlers.c:1552]: dlg_run_event_route(): executing event_route 1 on state 5 Sep 16 15:26:37 centos k[28392]: INFO: <script>: [2] entering event_route[dialog:end] Sep 16 15:26:38 centos k[28389]: INFO: <script>: [2] BYE sip:4165552222@192.168.2.97:5064 From:sip:1234@192.168.2.62,tag=as1948d268 To:sip:4165552222@192.168.2.62,tag=394e236c94334078o4 Call-ID:7f8b057c-5a0545a8@192.168.2.97 Contact:<null> <192.168.2.2:5060->udp:192.168.2.62:5060> Sep 16 15:26:38 centos k[28389]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=2 , global msg id=1 , T on entrance=0xffffffffffffffff Sep 16 15:26:38 centos k[28389]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=8480, isACK=0 Sep 16 15:26:38 centos k[28389]: DEBUG: tm [t_lookup.c:470]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=05104abe Sep 16 15:26:38 centos k[28389]: DEBUG: tm [t_lookup.c:726]: t_lookup_request(): DEBUG: t_lookup_request: transaction found (T=0x7f6f5e037320) Sep 16 15:26:38 centos k[28389]: DEBUG: tm [t_reply.c:1603]: t_retransmit_reply(): DBG: t_retransmit_reply: nothing to retransmit Sep 16 15:26:38 centos k[28392]: INFO: <script>: [2] exiting event_route[dialog:end] Sep 16 15:26:38 centos k[28392]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7f6f5e037070 with 1 -> 3 Sep 16 15:26:38 centos k[28392]: DEBUG: dialog [dlg_hash.c:854]: dlg_ref(): ref dlg 0x7f6f5e037070 with 1 -> 4 Sep 16 15:26:38 centos k[28392]: DEBUG: dialog [dlg_handlers.c:1285]: dlg_onroute(): BYE successfully processed Sep 16 15:26:38 centos k[28392]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7f6f5e037070 with 2 -> 2 Sep 16 15:26:38 centos k[28392]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7f6f5e037070 with 1 -> 1 Sep 16 15:26:38 centos k[28392]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=2 , global msg id=2 , T on entrance=0x7f6f5e037320 Sep 16 15:26:38 centos k[28392]: DEBUG: tm [t_lookup.c:1378]: t_newtran(): DEBUG: t_newtran: transaction already in process 0x7f6f5e037320 Sep 16 15:26:38 centos k[28392]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=2 T start=(nil) Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 8480 label 0 branch 0 Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f6f5e037320)! Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f6f5e037320, callback type 2, id 0 entered Sep 16 15:26:38 centos k[28388]: DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x7f6f5e037070 with 1 -> 2 Sep 16 15:26:38 centos k[28388]: DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=5037 found on entry 592 Sep 16 15:26:38 centos k[28388]: DEBUG: dialog [dlg_profile.c:511]: set_current_dialog(): setting current dialog [592:5037] Sep 16 15:26:38 centos k[28388]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7f6f5e037070 with 1 -> 1 Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=3 T end=0x7f6f5e037320 Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_reply.c:2210]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) Sep 16 15:26:38 centos k[28388]: INFO: <script>: [3] entering onreply_route[BYE] for 200 OK Call-ID:7f8b057c-5a0545a8@192.168.2.97 Cseq:102 Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_reply.c:1304]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_reply.c:1822]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0 Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f6f5e037320, callback type 512, id 0 entered Sep 16 15:26:38 centos k[28388]: DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x7f6f5e037070 with 1 -> 2 Sep 16 15:26:38 centos k[28388]: DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=5037 found on entry 592 Sep 16 15:26:38 centos k[28388]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7f6f5e037070 with 1 -> 1 Sep 16 15:26:38 centos k[28388]: DEBUG: tm [t_reply.c:1663]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset Sep 16 15:26:43 centos k[28394]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7f6f5e037320, callback type 131072, id 0 entered Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x7f6f5e037070 with 1 -> 2 Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=5037 found on entry 592 Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7f6f5e037070 with 2 -> 0 Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): ref <=0 for dialog 0x7f6f5e037070 Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_hash.c:355]: destroy_dlg(): destroying dialog 0x7f6f5e037070 (ref 0) Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_hash.c:371]: destroy_dlg(): removed timer for dlg 0x7f6f5e037070 [592:5037] with clid &#39;7f8b057c-5a0545a8(a)192.168.2.97&#39; and tags '394e236c94334078o4' 'as1948d268' Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_handlers.c:324]: dlg_iuid_sfree(): freeing dlg iuid [592:5037] (0x7f6f5e03a948) Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_handlers.c:324]: dlg_iuid_sfree(): freeing dlg iuid [592:5037] (0x7f6f5e039d68) Sep 16 15:26:43 centos k[28394]: DEBUG: dialog [dlg_handlers.c:324]: dlg_iuid_sfree(): freeing dlg iuid [592:5037] (0x7f6f5e038938) In the previous run, when the transaction wasn't pre-created, the tm calback for BYE was not run and this lead to dialog zombification. That's why I see a fix in tm (if possible) is more suitable. We need to make sure that the tm calbacks are run in both cases. ---------- More information can be found at the following URL: http://sip-router.org/tracker/index.php?do=details&task_id=424#comment1… You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.