sr-dev September 2014

sr-dev@lists.kamailio.org

33 participants
375 discussions

[tracker] Comment added: zombie dialogs in state 5
by sip-router 16 Sep '14

16 Sep '14

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) ---------- You got all the logs before (tm and dialog in debug mode). Here are all the logs in full debug. The dialog is still there: Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:623]: parse_msg(): SIP Request: Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:625]: parse_msg(): method: <BYE> Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:627]: parse_msg(): uri: <sip:4165552222@192.168.2.97:5064> Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:629]: parse_msg(): version: <SIP/2.0> Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK72762b8e>; state=6 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 235, <rport> = <n/a>; state=17 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [receive.c:154]: receive_msg(): After parse_msg... Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [receive.c:197]: receive_msg(): preparing to run routing scripts... Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=as0f39dff6 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=d0da9d2543fc82fco4 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [54]; uri=[sip:4165552222@192.168.2.62] Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:4165552222@192.168.2.62>] Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <102> <BYE> Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header Sep 16 18:49:50 centos k[28620]: DEBUG: pv [pv_core.c:385]: pv_get_contact(): no contact header! Sep 16 18:49:50 centos k[28620]: INFO: <script>: [2] BYE sip:4165552222@192.168.2.97:5064 From:sip:1234@192.168.2.62,tag=as0f39dff6 To:sip:4165552222@192.168.2.62,tag=d0da9d2543fc82fco4 Call-ID:d0d61319-383c6598@192.168.2.97 Contact:<null> <192.168.2.2:5060->udp:192.168.2.62:5060> Sep 16 18:49:50 centos k[28620]: DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 70 Sep 16 18:49:50 centos k[28620]: DEBUG: siputils [checks.c:106]: has_totag(): totag found Sep 16 18:49:50 centos k[28620]: DEBUG: rr [loose.c:90]: is_preloaded(): is_preloaded: No Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 12==12 && [192.168.2.97] == [192.168.2.62] Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5064 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 12==12 && [192.168.2.97] == [192.168.2.62] Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 8080 (advertise 0) matches port 5064 Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [forward.c:454]: check_self(): check_self: host != me Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 12==12 && [192.168.2.62] == [192.168.2.62] Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5060 Sep 16 18:49:50 centos k[28620]: DEBUG: rr [loose.c:785]: after_loose(): Topmost route URI: 'sip:192.168.2.62;lr;ftag=d0da9d2543fc82fco4;did=10c.b9a' is me Sep 16 18:49:50 centos k[28620]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header Sep 16 18:49:50 centos k[28620]: DEBUG: rr [loose.c:181]: find_next_route(): No next Route HF found Sep 16 18:49:50 centos k[28620]: DEBUG: rr [loose.c:809]: after_loose(): No next URI found Sep 16 18:49:50 centos k[28620]: DEBUG: rr [rr_cb.c:97]: run_rr_callbacks(): callback id 0 entered with <lr;ftag=d0da9d2543fc82fco4;did=10c.b9a> Sep 16 18:49:50 centos k[28620]: DEBUG: dialog [dlg_handlers.c:1163]: dlg_onroute(): route param is '10c.b9a' (len=7) Sep 16 18:49:50 centos k[28620]: DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x7ffd35cf9070 with 1 -> 3 Sep 16 18:49:50 centos k[28620]: DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=2715 found on entry 3073 Sep 16 18:49:50 centos k[28620]: DEBUG: dialog [dlg_profile.c:511]: set_current_dialog(): setting current dialog [3073:2715] Sep 16 18:49:50 centos k[28620]: DEBUG: dialog [dlg_hash.c:1066]: next_state_dlg(): dialog 0x7ffd35cf9070 changed from state 4 to state 5, due event 7 (ref 3) Sep 16 18:49:50 centos k[28620]: DEBUG: dialog [dlg_hash.c:854]: dlg_ref(): ref dlg 0x7ffd35cf9070 with 1 -> 4 Sep 16 18:49:50 centos k[28620]: DEBUG: dialog [dlg_handlers.c:1552]: dlg_run_event_route(): executing event_route 1 on state 5 Sep 16 18:49:50 centos k[28620]: INFO: <script>: [2] entering event_route[dialog:end] Sep 16 18:49:50 centos k[28620]: DEBUG: cfgutils [cfgutils.c:675]: m_usleep(): sleep 1300000 microseconds Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:623]: parse_msg(): SIP Request: Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:625]: parse_msg(): method: <BYE> Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:627]: parse_msg(): uri: <sip:4165552222@192.168.2.97:5064> Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:629]: parse_msg(): version: <SIP/2.0> Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK72762b8e>; state=6 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 235, <rport> = <n/a>; state=17 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [receive.c:154]: receive_msg(): After parse_msg... Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [receive.c:197]: receive_msg(): preparing to run routing scripts... Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=as0f39dff6 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=d0da9d2543fc82fco4 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [54]; uri=[sip:4165552222@192.168.2.62] Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:4165552222@192.168.2.62>] Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <102> <BYE> Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header Sep 16 18:49:50 centos k[28617]: DEBUG: pv [pv_core.c:385]: pv_get_contact(): no contact header! Sep 16 18:49:50 centos k[28617]: INFO: <script>: [2] BYE sip:4165552222@192.168.2.97:5064 From:sip:1234@192.168.2.62,tag=as0f39dff6 To:sip:4165552222@192.168.2.62,tag=d0da9d2543fc82fco4 Call-ID:d0d61319-383c6598@192.168.2.97 Contact:<null> <192.168.2.2:5060->udp:192.168.2.62:5060> Sep 16 18:49:50 centos k[28617]: DEBUG: maxfwd [mf_funcs.c:85]: is_maxfwd_present(): value = 70 Sep 16 18:49:50 centos k[28617]: DEBUG: siputils [checks.c:106]: has_totag(): totag found Sep 16 18:49:50 centos k[28617]: DEBUG: rr [loose.c:90]: is_preloaded(): is_preloaded: No Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 12==12 && [192.168.2.97] == [192.168.2.62] Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5064 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 12==12 && [192.168.2.97] == [192.168.2.62] Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 8080 (advertise 0) matches port 5064 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [forward.c:454]: check_self(): check_self: host != me Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 12==12 && [192.168.2.62] == [192.168.2.62] Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5060 Sep 16 18:49:50 centos k[28617]: DEBUG: rr [loose.c:785]: after_loose(): Topmost route URI: 'sip:192.168.2.62;lr;ftag=d0da9d2543fc82fco4;did=10c.b9a' is me Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header Sep 16 18:49:50 centos k[28617]: DEBUG: rr [loose.c:181]: find_next_route(): No next Route HF found Sep 16 18:49:50 centos k[28617]: DEBUG: rr [loose.c:809]: after_loose(): No next URI found Sep 16 18:49:50 centos k[28617]: DEBUG: rr [rr_cb.c:97]: run_rr_callbacks(): callback id 0 entered with <lr;ftag=d0da9d2543fc82fco4;did=10c.b9a> Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_handlers.c:1163]: dlg_onroute(): route param is '10c.b9a' (len=7) Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x7ffd35cf9070 with 1 -> 5 Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=2715 found on entry 3073 Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_profile.c:511]: set_current_dialog(): setting current dialog [3073:2715] Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_hash.c:1066]: next_state_dlg(): dialog 0x7ffd35cf9070 changed from state 5 to state 5, due event 7 (ref 5) Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7ffd35cf9070 with 1 -> 4 Sep 16 18:49:50 centos k[28617]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=2 , global msg id=0 , T on entrance=0xffffffffffffffff Sep 16 18:49:50 centos k[28617]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=15057, isACK=0 Sep 16 18:49:50 centos k[28617]: DEBUG: tm [t_lookup.c:485]: matching_3261(): DEBUG: RFC3261 transaction matching failed Sep 16 18:49:50 centos k[28617]: DEBUG: tm [t_lookup.c:709]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found Sep 16 18:49:50 centos k[28617]: DEBUG: tm [t_hooks.c:374]: run_reqin_callbacks_internal(): DBG: trans=0x7ffd35cf9320, callback type 1, id 0 entered Sep 16 18:49:50 centos k[28617]: DEBUG: tm [t_hooks.c:374]: run_reqin_callbacks_internal(): DBG: trans=0x7ffd35cf9320, callback type 1, id 0 entered Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [md5utils.c:67]: MD5StringArray(): DEBUG: MD5 calculated: 159d78ac3eb576dff3365fffb4d172d7 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [msg_translator.c:205]: check_via_address(): check_via_address(192.168.2.2, 192.168.2.2, 0) Sep 16 18:49:50 centos k[28617]: DEBUG: tm [t_funcs.c:394]: t_relay_to(): SER: new transaction fwd'ed Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x7ffd35cf9070 with 1 -> 5 Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=2715 found on entry 3073 Sep 16 18:49:50 centos k[28617]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7ffd35cf9070 with 1 -> 4 Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil) Sep 16 18:49:50 centos k[28617]: DEBUG: <core> [receive.c:300]: receive_msg(): receive_msg: cleaning up Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:633]: parse_msg(): SIP Reply (status): Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:635]: parse_msg(): version: <SIP/2.0> Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:637]: parse_msg(): status: <200> Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:639]: parse_msg(): reason: <OK> Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=d0da9d2543fc82fco4 Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=29 Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [54]; uri=[sip:4165552222@192.168.2.62] Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:4165552222@192.168.2.62>] Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <102> <BYE> Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK1da3.159d78ac3eb576dff3365fffb4d172d7.0>; state=16 Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5 Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2 Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [receive.c:154]: receive_msg(): After parse_msg... Sep 16 18:49:50 centos k[28618]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=2 T start=0xffffffffffffffff Sep 16 18:49:50 centos k[28618]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 15057 label 0 branch 0 Sep 16 18:49:50 centos k[28618]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7ffd35cf9320)! Sep 16 18:49:50 centos k[28618]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7ffd35cf9320, callback type 2, id 0 entered Sep 16 18:49:50 centos k[28618]: DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x7ffd35cf9070 with 1 -> 5 Sep 16 18:49:50 centos k[28618]: DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=2715 found on entry 3073 Sep 16 18:49:50 centos k[28618]: DEBUG: dialog [dlg_profile.c:511]: set_current_dialog(): setting current dialog [3073:2715] Sep 16 18:49:50 centos k[28618]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7ffd35cf9070 with 1 -> 4 Sep 16 18:49:50 centos k[28618]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=3 global id=3 T end=0x7ffd35cf9320 Sep 16 18:49:50 centos k[28618]: 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 18:49:50 centos k[28618]: INFO: <script>: [3] entering onreply_route[BYE] for 200 OK Call-ID:d0d61319-383c6598@192.168.2.97 Cseq:102 Sep 16 18:49:50 centos k[28618]: INFO: <script>: [3] exiting onreply_route[BYE] for 200 OK Call-ID:d0d61319-383c6598@192.168.2.97 Cseq:102 Sep 16 18:49:50 centos k[28618]: DEBUG: tm [t_reply.c:1304]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=200 Sep 16 18:49:50 centos k[28618]: DEBUG: tm [t_reply.c:1822]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=0 icode=0 Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [msg_translator.c:2305]: generate_res_buf_from_sip_res(): old size: 468, new size: 383 Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [msg_translator.c:2323]: generate_res_buf_from_sip_res(): copied size: orig:261, new: 176, rest: 207 msg=#012SIP/2.0 200 OK#015#012To: <sip:4165552222@192.168.2.62>;tag=d0da9d2543fc82fco4#015#012From: <sip:1234@192.168.2.62>;tag=as0f39dff6#015#012Call-ID: d0d61319-383c6598(a)192.168.2.97#015#012CSeq: 102 BYE#015#012Via: SIP/2.0/UDP 192.168.2.2:5060;branch=z9hG4bK72762b8e;rport=5060#015#012Server: Linksys/SPA962-6.1.5(a)#015#012P-RTP-Stat: PS=615,OS=98400,PR=585,OR=93600,PL=0,JI=0,LA=0,DU=12,EN=G711u,DE=G711u#015#012Content-Length: 0#015#012#015#012 Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [mem/shm_mem.c:111]: _shm_resize(): WARNING:vqm_resize: resize(0) called Sep 16 18:49:50 centos k[28618]: DEBUG: tm [t_reply.c:1663]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil) Sep 16 18:49:50 centos k[28618]: DEBUG: <core> [receive.c:300]: receive_msg(): receive_msg: cleaning up Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:623]: parse_msg(): SIP Request: Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:625]: parse_msg(): method: <NOTIFY> Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:627]: parse_msg(): uri: <sip:192.168.2.62> Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:629]: parse_msg(): version: <SIP/2.0> Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-cc90acfe>; state=16 Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5 Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2 Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [receive.c:154]: receive_msg(): After parse_msg... Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [receive.c:197]: receive_msg(): preparing to run routing scripts... Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/parse_addr_spec.c:898]: parse_addr_spec(): end of header reached, state=10 Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [20]; uri=[sip:192.168.2.62] Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<sip:192.168.2.62>#015#012] Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <265193> <NOTIFY> Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:204]: get_hdr_field(): DEBUG: get_hdr_body : content_length=0 Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [parser/msg_parser.c:106]: get_hdr_field(): found end of header Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [socket_info.c:583]: grep_sock_info(): grep_sock_info - checking if host==us: 12==12 && [192.168.2.62] == [192.168.2.62] Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [socket_info.c:587]: grep_sock_info(): grep_sock_info - checking if port 5060 (advertise 0) matches port 5060 Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [msg_translator.c:205]: check_via_address(): check_via_address(192.168.2.97, 192.168.2.97, 0) Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil) Sep 16 18:49:50 centos k[28616]: DEBUG: <core> [receive.c:300]: receive_msg(): receive_msg: cleaning up Sep 16 18:49:51 centos k[28620]: INFO: <script>: [2] exiting event_route[dialog:end] Sep 16 18:49:51 centos k[28620]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7ffd35cf9070 with 1 -> 3 Sep 16 18:49:51 centos k[28620]: DEBUG: dialog [dlg_hash.c:854]: dlg_ref(): ref dlg 0x7ffd35cf9070 with 1 -> 4 Sep 16 18:49:51 centos k[28620]: DEBUG: dialog [dlg_handlers.c:1285]: dlg_onroute(): BYE successfully processed Sep 16 18:49:51 centos k[28620]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7ffd35cf9070 with 2 -> 2 Sep 16 18:49:51 centos k[28620]: DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x7ffd35cf9070 with 1 -> 1 Sep 16 18:49:51 centos k[28620]: DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=2 , global msg id=1 , T on entrance=0xffffffffffffffff Sep 16 18:49:51 centos k[28620]: DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=15057, isACK=0 Sep 16 18:49:51 centos k[28620]: DEBUG: tm [t_lookup.c:470]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=72762b8e Sep 16 18:49:51 centos k[28620]: DEBUG: tm [t_lookup.c:726]: t_lookup_request(): DEBUG: t_lookup_request: transaction found (T=0x7ffd35cf9320) Sep 16 18:49:51 centos k[28620]: DEBUG: tm [t_reply.c:1623]: t_retransmit_reply(): DEBUG: reply retransmitted. buf=0x7ffd30ab97a0: SIP/2.0 2..., shmem=0x7ffd35cfca68: SIP/2.0 2 Sep 16 18:49:51 centos k[28620]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:51 centos k[28620]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:51 centos k[28620]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:51 centos k[28620]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:51 centos k[28620]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:51 centos k[28620]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil) Sep 16 18:49:51 centos k[28620]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil) Sep 16 18:49:51 centos k[28620]: DEBUG: <core> [receive.c:300]: receive_msg(): receive_msg: cleaning up Sep 16 18:49:55 centos k[28622]: DEBUG: dialog [dlg_handlers.c:324]: dlg_iuid_sfree(): freeing dlg iuid [3073:2715] (0x7ffd35cfbd68) $ kamcmd dlg.list { h_entry: 3073 h_id: 2715 call-id: d0d61319-383c6598(a)192.168.2.97 from_uri: sip:4165552222@192.168.2.62 to_uri: sip:1234@192.168.2.62 state: 5 start_ts: 1410907778 init_ts: 1410907775 timeout: 0 lifetime: 3600 dflags: 519 sflags: 0 iflags: 1 caller: { tag: d0da9d2543fc82fco4 contact: sip:4165552222@192.168.2.97:5064 cseq: 101 route_set: socket: udp:192.168.2.62:5060 } callee: { tag: as0f39dff6 contact: sip:240@192.168.2.2:5060 cseq: 0 route_set: socket: udp:192.168.2.62:5060 } profiles: { } variables: { } } ---------- More information can be found at the following URL: http://sip-router.org/tracker/index.php?do=details&task_id=424#comment1635 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.

1 0

[tracker] Comment added: zombie dialogs in state 5
by sip-router 16 Sep '14

16 Sep '14

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 - Daniel-Constantin Mierla (miconda) ---------- You didn't provide all messages for processing that request. You can see that it stays to ref 1, then tm detects retransmission (you provided logs up to here), then is the message cleanup from core, including execution of post-script callbacks which cleans the dialog. Can you provide the logs up the messages related to destroying avps for bye request (they are the last printed for a request after config execution in this case -- I haven't provided them in the above logs, but they are printed). ---------- More information can be found at the following URL: http://sip-router.org/tracker/index.php?do=details&task_id=424#comment1634 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.

1 0

git:master: dialog: allocate buffer for new request after updating CSeq value
by Daniel-Constantin Mierla 16 Sep '14

16 Sep '14

Module: sip-router Branch: master Commit: a306ea024d1098df81ce9c68ec558e6c3a0e7086 URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=a306ea0… Author: Daniel-Constantin Mierla <miconda(a)gmail.com> Committer: Daniel-Constantin Mierla <miconda(a)gmail.com> Date: Tue Sep 16 23:43:34 2014 +0200 dialog: allocate buffer for new request after updating CSeq value - new buffer is higher than the old one -- situation only when dialog is taking care of updating cseq downstream (e.g., after authentication) --- modules/dialog/dlg_cseq.c | 5 +++++ 1 files changed, 5 insertions(+), 0 deletions(-) diff --git a/modules/dialog/dlg_cseq.c b/modules/dialog/dlg_cseq.c index 24a23f4..994975d 100644 --- a/modules/dialog/dlg_cseq.c +++ b/modules/dialog/dlg_cseq.c @@ -303,6 +303,11 @@ int dlg_cseq_msg_sent(void *data) - get_cseq(&msg)->number.len; /* replace old msg content */ + obuf->s = pkg_malloc((tbuf_len+1)*sizeof(char)); + if(obuf->s==NULL) { + LM_ERR("not enough memory for new message\n"); + goto done; + } memcpy(obuf->s, tbuf, tbuf_len); obuf->s[tbuf_len] = 0; obuf->len = tbuf_len;

1 0

git:master: core: safety check for outbound buffer
by Daniel-Constantin Mierla 16 Sep '14

16 Sep '14

Module: sip-router Branch: master Commit: c2b0be97a3ef8e4e1bff34a5c73328a63979aa61 URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=c2b0be9… Author: Daniel-Constantin Mierla <miconda(a)gmail.com> Committer: Daniel-Constantin Mierla <miconda(a)gmail.com> Date: Tue Sep 16 23:38:35 2014 +0200 core: safety check for outbound buffer - pointer can end up being NULL if replacement fails to be built (e.g., via topoh) --- forward.h | 5 +++++ 1 files changed, 5 insertions(+), 0 deletions(-) diff --git a/forward.h b/forward.h index 271e6c7..2c5d942 100644 --- a/forward.h +++ b/forward.h @@ -145,6 +145,11 @@ static inline int msg_send(struct dest_info* dst, char* buf, int len) outb.len = len; sr_event_exec(SREV_NET_DATA_OUT, (void*)&outb); + if(outb.s==NULL) { + LM_ERR("failed to update outgoing buffer\n"); + return -1; + } + #ifdef USE_TCP if (unlikely((dst->proto == PROTO_WS #ifdef USE_TLS

1 0

git:master: core: hanlde replacement buffer free for WS/WSS frame sending
by Daniel-Constantin Mierla 16 Sep '14

16 Sep '14

Module: sip-router Branch: master Commit: ec8fe1e7ea904a51ca933d0b15408ca464002cbe URL: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=ec8fe1e… Author: Daniel-Constantin Mierla <miconda(a)gmail.com> Committer: Daniel-Constantin Mierla <miconda(a)gmail.com> Date: Tue Sep 16 23:33:20 2014 +0200 core: hanlde replacement buffer free for WS/WSS frame sending - affected when using topoh for ws/wss traffic --- forward.h | 6 ++++-- 1 files changed, 4 insertions(+), 2 deletions(-) diff --git a/forward.h b/forward.h index 4187540..271e6c7 100644 --- a/forward.h +++ b/forward.h @@ -183,7 +183,7 @@ static inline int msg_send(struct dest_info* dst, char* buf, int len) wsev.id = con->id; ret = sr_event_exec(SREV_TCP_WS_FRAME_OUT, (void *) &wsev); tcpconn_put(con); - return ret; + goto done; } #endif @@ -277,9 +277,11 @@ static inline int msg_send(struct dest_info* dst, char* buf, int len) LOG(L_CRIT, "BUG: msg_send: unknown proto %d\n", dst->proto); goto error; } + ret = 0; +done: if(outb.s != buf) pkg_free(outb.s); - return 0; + return ret; error: if(outb.s != buf) pkg_free(outb.s);

1 0

[tracker] Comment added: zombie dialogs in state 5
by sip-router 16 Sep '14

16 Sep '14

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) ---------- Yes, it does remain stuck. My logs are different then yours and you can see that at the end there still one reference left. ---------- More information can be found at the following URL: http://sip-router.org/tracker/index.php?do=details&task_id=424#comment1633 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.

1 0

[tracker] Comment added: zombie dialogs in state 5
by sip-router 16 Sep '14

16 Sep '14

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 - Daniel-Constantin Mierla (miconda) ---------- I got the time to test it a bit and the dialog is cleaned up in such situation: <code> 4(28491) INFO: <script>: ============== [2] exiting event_route[dialog:end] 4(28491) DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x109d7e240 with 1 -> 3 4(28491) DEBUG: dialog [dlg_hash.c:854]: dlg_ref(): ref dlg 0x109d7e240 with 1 -> 4 4(28491) DEBUG: dialog [dlg_handlers.c:1285]: dlg_onroute(): BYE successfully processed 4(28491) DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x109d7e240 with 2 -> 2 4(28491) DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x109d7e240 with 1 -> 1 4(28491) DEBUG: dialog [dlg_hash.c:711]: internal_get_dlg(): ref dlg 0x109d7e240 with 1 -> 2 4(28491) DEBUG: dialog [dlg_hash.c:714]: internal_get_dlg(): dialog callid='2pHz2yNmDfEylHpQxnRUJDPBQBKvPtWZ' found on entry 758, dir=1 4(28491) DEBUG: dialog [dlg_profile.c:511]: set_current_dialog(): setting current dialog [758:7585] 4(28491) DEBUG: dialog [dlg_hash.c:1066]: next_state_dlg(): dialog 0x109d7e240 changed from state 5 to state 5, due event 7 (ref 2) 4(28491) DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x109d7e240 with 1 -> 1 4(28491) DEBUG: tm [t_lookup.c:1373]: t_newtran(): DEBUG: t_newtran: msg id=2 , global msg id=1 , T on entrance=0xffffffffffffffff 4(28491) DEBUG: tm [t_lookup.c:527]: t_lookup_request(): t_lookup_request: start searching: hash=22509, isACK=0 4(28491) DEBUG: tm [t_lookup.c:470]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=PjGad24LDN.vST7cXbP-hVJYEhNXB0agt. 4(28491) DEBUG: tm [t_lookup.c:726]: t_lookup_request(): DEBUG: t_lookup_request: transaction found (T=0x109d82308) 4(28491) DEBUG: tm [t_reply.c:1623]: t_retransmit_reply(): DEBUG: reply retransmitted. buf=0x1095403d0: SIP/2.0 2..., shmem=0x109d84cf8: SIP/2.0 2 4(28491) DEBUG: dialog [dlg_hash.c:654]: dlg_lookup(): ref dlg 0x109d7e240 with 1 -> 2 4(28491) DEBUG: dialog [dlg_hash.c:656]: dlg_lookup(): dialog id=7585 found on entry 758 4(28491) DEBUG: dialog [dlg_var.c:58]: dlg_cfg_cb(): dialog with no expected trasaction after config execution 4(28491) DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x109d7e240 with 1 -> 1 4(28491) DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): unref dlg 0x109d7e240 with 1 -> 0 4(28491) DEBUG: dialog [dlg_hash.c:872]: dlg_unref(): ref <=0 for dialog 0x109d7e240 4(28491) DEBUG: dialog [dlg_hash.c:355]: destroy_dlg(): destroying dialog 0x109d7e240 (ref 0) 4(28491) DEBUG: dialog [dlg_hash.c:371]: destroy_dlg(): removed timer for dlg 0x109d7e240 [758:7585] with clid '2pHz2yNmDfEylHpQxnRUJDPBQBKvPtWZ' and tags 'lEyM6a2sWu4eUMznDJpgwew7Bs6h3h4A' '6f853e802780e732afe74b37489b8ba1.6e9a' </code> Can you check with kamctl if dialog still exists? ---------- More information can be found at the following URL: http://sip-router.org/tracker/index.php?do=details&task_id=424#comment1632 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.

1 0

[tracker] Comment added: zombie dialogs in state 5
by sip-router 16 Sep '14

16 Sep '14

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 - Daniel-Constantin Mierla (miconda) ---------- It is impossible to ensure that dlg callbacks can be executed if added after the transaction was created. Think about the case when it takes more than a second to execute your event route, once it is finished, the transaction created by the other BYE could be in 'wait-for-delete' state, with the reply already sent out. What I tried to do with the patch -- if the request is not creating a transaction by itself, then unref not to get dialog in zombie state. But apparently there is a 'bug' to the patch. This mechanism is used also for initial INVITE that is stateless replied from config, after a dlg_manage() - that situation created zombies in the past as well. ---------- More information can be found at the following URL: http://sip-router.org/tracker/index.php?do=details&task_id=424#comment1631 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.

1 0

[tracker] Comment added: zombie dialogs in state 5
by sip-router 16 Sep '14

16 Sep '14

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 '7f8b057c-5a0545a8(a)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.

1 0

[tracker] Comment added: zombie dialogs in state 5
by sip-router 16 Sep '14

16 Sep '14

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 - Daniel-Constantin Mierla (miconda) ---------- The tm does the job of catching the 'retransmission'. As written in previous commits, it's hard to detect what is the retransmission and by config, all requests should get same processing with the other modules until tm discards one the same requests. The problem is dlg specific, as it skips some internal processing if there is no change in dlg state. Maybe you can give more specific example where an eventual fix in tm will benefit to other modules. Were you testing with master branch? If not, what version and patches on top? ---------- More information can be found at the following URL: http://sip-router.org/tracker/index.php?do=details&task_id=424#comment1629 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.

1 0

← Newer
1
...
10
11
12
13
14
15
16
...
38
Older →

Jump to page:

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

sr-dev September 2014