[sr-dev] [tracker] Comment added: zombie dialogs in state 5

Tue Sep 16 21:33:02 CEST 2014

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 at 192.168.2.97:5064 From:sip:1234 at 192.168.2.62,tag=as1948d268 To:sip:4165552222 at 192.168.2.62,tag=394e236c94334078o4 Call-ID:7f8b057c-5a0545a8 at 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 at 192.168.2.97:5064 From:sip:1234 at 192.168.2.62,tag=as1948d268 To:sip:4165552222 at 192.168.2.62,tag=394e236c94334078o4 Call-ID:7f8b057c-5a0545a8 at 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 at 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 '7f8b057c-5a0545a8 at 192.168.2.97' 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#comment1630

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.