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

sip-router bugtracker at sip-router.org
Wed Sep 17 00:52:39 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)

----------
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 at 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 at 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 at 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 at 192.168.2.97:5064 From:sip:1234 at 192.168.2.62,tag=as0f39dff6 To:sip:4165552222 at 192.168.2.62,tag=d0da9d2543fc82fco4 Call-ID:d0d61319-383c6598 at 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 at 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 at 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 at 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 at 192.168.2.97:5064 From:sip:1234 at 192.168.2.62,tag=as0f39dff6 To:sip:4165552222 at 192.168.2.62,tag=d0da9d2543fc82fco4 Call-ID:d0d61319-383c6598 at 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 at 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 at 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 at 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 at 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 at 192.168.2.62>;tag=d0da9d2543fc82fco4#015#012From: <sip:1234 at 192.168.2.62>;tag=as0f39dff6#015#012Call-ID: d0d61319-383c6598 at 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 at 192.168.2.97
        from_uri: sip:4165552222 at 192.168.2.62
        to_uri: sip:1234 at 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 at 192.168.2.97:5064
                cseq: 101
                route_set:
                socket: udp:192.168.2.62:5060
        }
        callee: {
                tag: as0f39dff6
                contact: sip:240 at 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.

More information about the sr-dev mailing list