this is a debug view with debug=5
2(14161) INFO: no fifo_db_url given - fifo DB commands disabled! 0(14154) SIP Request: 0(14154) method: <INVITE> 0(14154) uri: sip:500@192.168.39.54 0(14154) version: <SIP/2.0> 0(14154) parse_headers: flags=2 0(14154) DEBUG:parse_to:end of header reached, state=10 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) DEBUG: get_hdr_field: <To> [25]; uri=[sip:500@192.168.39.54] 0(14154) DEBUG: to body [sip:500@192.168.39.54 ] 0(14154) get_hdr_field: cseq <CSeq>: <1> <INVITE> 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c5c-b38bc-452a>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) preparing to run routing scripts... 0(14154) parse_headers: flags=100 0(14154) DEBUG:maxfwd:is_maxfwd_present: value = 70 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) parse_headers: flags=80 0(14154) parse_headers: flags=80 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b38bc-7e15 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:anonymous@anonymous.com} 0(14154) parse_headers: flags=200 0(14154) DEBUG: get_hdr_body : content_length=230 0(14154) found end of header 0(14154) find_first_route: No Route headers found 0(14154) loose_route: There is no Route HF 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.54] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.54] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) rewrite_uri: Rewriting Request-URI with 'sip:500@192.168.39.50' 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) subst_run: running. r=1 0(14154) subst_str: no match 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) DEBUG:check_content_type: type <application/sdp> found valid 0(14154) parse_headers: flags=40 0(14154) force_rtp_proxy2: proxy reply: 35026 192.168.39.54
0(14154) DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffffffffffff 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) parse_headers: flags=78 0(14154) t_lookup_request: start searching: hash=34382, isACK=0 0(14154) DEBUG: RFC3261 transaction matching failed 0(14154) DEBUG: t_lookup_request: no transaction found 0(14154) DEBUG:tm:t_relay: new INVITE 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) WARNING:vqm_resize: resize(0) called 0(14154) DEBUG:tm:_reply_light: reply sent out. buf=0x615de0: SIP/2.0 1..., shmem=0x2ba62f3c3c50: SIP/2.0 1 0(14154) DEBUG:tm:_reply_light: finished 0(14154) DEBUG: mk_proxy: doing DNS lookup... 0(14154) parse_headers: flags=2000 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) clen_builder: content-length: 248 (248) 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) DEBUG: add_to_tail_of_timer[4]: 0x2ba62f3c16a8 0(14154) DEBUG: add_to_tail_of_timer[0]: 0x2ba62f3c16c8 0(14154) SER: new transaction fwd'ed 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 0(14154) SIP Reply (status): 0(14154) version: <SIP/2.0> 0(14154) status: <100> 0(14154) reason: <Trying> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500@192.168.39.54] 0(14154) DEBUG: to body [sip:500@192.168.39.54] 0(14154) get_hdr_field: cseq <CSeq>: <1> <INVITE> 0(14154) Found param type 232, <branch> = <z9hG4bKe468.e73bf65.0>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) forward_reply: found module nathelper, passing reply to it 0(14154) forward_reply: found module tm, passing reply to it 0(14154) DEBUG: t_check: msg id=2 global id=1 T start=0xffffffffffffffff 0(14154) parse_headers: flags=22 0(14154) parse_headers: flags=8 0(14154) DEBUG: t_reply_matching: hash 34382 label 91206526 branch 0 0(14154) DEBUG:tm:REF_UNSAFE: after is 1 0(14154) DEBUG: t_reply_matching: reply matched (T=0x2ba62f3c14c8)! 0(14154) DEBUG: t_check: msg id=2 global id=2 T end=0x2ba62f3c14c8 0(14154) DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) 0(14154) parse_headers: flags=80 0(14154) Found param type 235, <rport> = <5060>; state=6 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c5c-b38bc-452a>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=80 0(14154) parse_headers: this is the second via 0(14154) DEBUG:tm:t_should_relay_response: T_code=100, new_code=100 0(14154) DEBUG:tm:relay_reply: branch=0, save=0, relay=-1 0(14154) DEBUG: add_to_tail_of_timer[1]: 0x2ba62f3c16c8 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 0(14154) SIP Reply (status): 0(14154) version: <SIP/2.0> 0(14154) status: <180> 0(14154) reason: <Ringing> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500@192.168.39.54] 0(14154) DEBUG: to body [sip:500@192.168.39.54] 0(14154) get_hdr_field: cseq <CSeq>: <1> <INVITE> 0(14154) Found param type 232, <branch> = <z9hG4bKe468.e73bf65.0>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) forward_reply: found module nathelper, passing reply to it 0(14154) forward_reply: found module tm, passing reply to it 0(14154) DEBUG: t_check: msg id=3 global id=2 T start=0xffffffffffffffff 0(14154) parse_headers: flags=22 0(14154) parse_headers: flags=8 0(14154) DEBUG: t_reply_matching: hash 34382 label 91206526 branch 0 0(14154) DEBUG:tm:REF_UNSAFE: after is 1 0(14154) DEBUG: t_reply_matching: reply matched (T=0x2ba62f3c14c8)! 0(14154) DEBUG: t_check: msg id=3 global id=3 T end=0x2ba62f3c14c8 0(14154) DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) 0(14154) parse_headers: flags=80 0(14154) Found param type 235, <rport> = <5060>; state=6 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c5c-b38bc-452a>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=80 0(14154) parse_headers: this is the second via 0(14154) DEBUG:tm:t_should_relay_response: T_code=100, new_code=180 0(14154) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 0(14154) old size: 466, new size: 413 0(14154) build_res_from_sip_res: copied size: orig:442, new: 389, rest: 24 msg= SIP/2.0 180 Ringing From: sip:anonymous@anonymous.com;tag=0-13c4-44db1c5c-b38bc-7e15 To: sip:500@192.168.39.54;tag=0-13c4-44db1c5c-b390c-6691 Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff@anonymous.com CSeq: 1 INVITE Via: SIP/2.0/UDP 192.168.39.50:5060;rport=5060;branch=z9hG4bK-44db1c5c-b38bc-452a Supported: 100rel User-Agent: SIP-RG Contact: sip:500@192.168.39.50:5060;nat=yes Content-Length: 0
0(14154) DEBUG:tm:relay_reply: sent buf=0x616348: SIP/2.0 1..., shmem=0x2ba62f3c3c50: SIP/2.0 1 0(14154) DEBUG: add_to_tail_of_timer[1]: 0x2ba62f3c16c8 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 1(14160) DEBUG: timer routine:4,tl=0x2ba62f3c16a8 next=(nil) 0(14154) SIP Reply (status): 0(14154) version: <SIP/2.0> 0(14154) status: <200> 0(14154) reason: <OK> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500@192.168.39.54] 0(14154) DEBUG: to body [sip:500@192.168.39.54] 0(14154) get_hdr_field: cseq <CSeq>: <1> <INVITE> 0(14154) Found param type 232, <branch> = <z9hG4bKe468.e73bf65.0>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) forward_reply: found module nathelper, passing reply to it 0(14154) forward_reply: found module tm, passing reply to it 0(14154) DEBUG: t_check: msg id=4 global id=3 T start=0xffffffffffffffff 0(14154) parse_headers: flags=22 0(14154) parse_headers: flags=8 0(14154) DEBUG: t_reply_matching: hash 34382 label 91206526 branch 0 0(14154) DEBUG:tm:REF_UNSAFE: after is 1 0(14154) DEBUG: t_reply_matching: reply matched (T=0x2ba62f3c14c8)! 0(14154) DEBUG: t_check: msg id=4 global id=4 T end=0x2ba62f3c14c8 0(14154) DEBUG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1) 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) Found param type 235, <rport> = <5060>; state=6 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c5c-b38bc-452a>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=ffffffffffffffff 0(14154) parse_headers: this is the second via 0(14154) DEBUG: get_hdr_body : content_length=158 0(14154) found end of header 0(14154) DEBUG:check_content_type: type <application/sdp> found valid 0(14154) parse_headers: flags=40 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b38bc-7e15 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:anonymous@anonymous.com} 0(14154) force_rtp_proxy2: proxy reply: 35028 192.168.39.54
0(14154) parse_headers: flags=80 0(14154) DEBUG:tm:t_should_relay_response: T_code=180, new_code=200 0(14154) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 0(14154) parse_headers: flags=2000 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) clen_builder: content-length: 176 (176) 0(14154) old size: 722, new size: 687 0(14154) build_res_from_sip_res: copied size: orig:722, new: 687, rest: 0 msg= SIP/2.0 200 OK From: sip:anonymous@anonymous.com;tag=0-13c4-44db1c5c-b38bc-7e15 To: sip:500@192.168.39.54;tag=0-13c4-44db1c5c-b390c-6691 Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff@anonymous.com CSeq: 1 INVITE Via: SIP/2.0/UDP 192.168.39.50:5060;rport=5060;branch=z9hG4bK-44db1c5c-b38bc-452a Supported: 100rel User-Agent: SIP-RG Contact: sip:500@192.168.39.50:5060;nat=yes Record-Route: sip:192.168.39.54;lr;ftag=0-13c4-44db1c5c-b38bc-7e15 Content-Type: application/sdp Content-Length: 176
v=0 o=SIP-N-TA 0 0 IN IP4 192.168.39.50 s=C0A82732 0000 C0A82732 0000 01 0 c=IN IP4 192.168.39.54 t=0 0 m=audio 35028 RTP/AVP 18 a=rtpmap:18 G729/8000 a=nortpproxy:yes
0(14154) DEBUG: add_to_tail_of_timer[2]: 0x2ba62f3c1548 0(14154) DEBUG:tm:relay_reply: sent buf=0x6166b8: SIP/2.0 2..., shmem=0x2ba62f3c3c50: SIP/2.0 2 0(14154) DEBUG: cleanup_uac_timers: RETR/FR timers reset 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 0(14154) SIP Request: 0(14154) method: <ACK> 0(14154) uri: sip:500@192.168.39.50:5060;nat=yes 0(14154) version: <SIP/2.0> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500@192.168.39.54] 0(14154) DEBUG: to body [sip:500@192.168.39.54] 0(14154) get_hdr_field: cseq <CSeq>: <1> <ACK> 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c5e-b3e5c-9f6>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) preparing to run routing scripts... 0(14154) DEBUG : sl_filter_ACK: to late to be a local ACK! 0(14154) parse_headers: flags=100 0(14154) DEBUG:maxfwd:is_maxfwd_present: value = 70 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) parse_headers: flags=80 0(14154) parse_headers: flags=80 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b38bc-7e15 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:anonymous@anonymous.com} 0(14154) parse_headers: flags=200 0(14154) is_preloaded: No 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.50] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.50] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) check_self: host != me 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.54] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) after_loose: Topmost route URI: 'sip:192.168.39.54;lr;ftag=0-13c4-44db1c5c-b38bc-7e15' is me 0(14154) parse_headers: flags=200 0(14154) DEBUG: get_hdr_body : content_length=0 0(14154) found end of header 0(14154) find_next_route: No next Route HF found 0(14154) after_loose: No next URI found 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) subst_run: running. r=0 0(14154) subst_run: matched (0, 34): [sip:500@192.168.39.50:5060;nat=yes] 0(14154) textops: subst_uri_f: match - old uri= [sip:500@192.168.39.50:5060;nat=yes], new uri= [sip:500@192.168.39.50:5060] 0(14154) DEBUG: t_newtran: msg id=5 , global msg id=4 , T on entrance=0xffffffffffffffff 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) parse_headers: flags=78 0(14154) t_lookup_request: start searching: hash=34382, isACK=1 0(14154) parse_headers: flags=38 0(14154) DEBUG: t_lookup_request: e2e proxy ACK found 0(14154) DEBUG:tm:REF_UNSAFE: after is 1 0(14154) DEBUG:tm:t_newtran: building branch for end2end ACK 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:tm:t_relay: forwarding ACK 0(14154) DEBUG: mk_proxy: doing DNS lookup... 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) Sending: ACK sip:500@192.168.39.50:5060 SIP/2.0 Record-Route: sip:192.168.39.54;lr=on;ftag=0-13c4-44db1c5c-b38bc-7e15 From: sip:anonymous@anonymous.com;tag=0-13c4-44db1c5c-b38bc-7e15 To: sip:500@192.168.39.54;tag=0-13c4-44db1c5c-b390c-6691 Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff@anonymous.com CSeq: 1 ACK Via: SIP/2.0/UDP 192.168.39.54;branch=z9hG4bKe468.e73bf65.2 Via: SIP/2.0/UDP 192.168.39.50:5060;rport=5060;branch=z9hG4bK-44db1c5e-b3e5c-9f6 Max-Forwards: 69 User-Agent: SIP-RG Contact: sip:400@192.168.39.50:5060;nat=yes Content-Length: 0 P-hint: rr-enforced
. 0(14154) orig. len=474, new_len=582, proto=1 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 1(14160) DEBUG: timer routine:1,tl=0x2ba62f3c16c8 next=(nil) 1(14160) DEBUG: timer routine:2,tl=0x2ba62f3c1548 next=(nil) 1(14160) DEBUG: wait_handler : removing 0x2ba62f3c14c8 from table 1(14160) DEBUG: delete transaction 0x2ba62f3c14c8 1(14160) DEBUG: wait_handler : done 0(14154) SIP Request: 0(14154) method: <INVITE> 0(14154) uri: sip:400@192.168.39.50:5060;nat=yes 0(14154) version: <SIP/2.0> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b38bc-7e15 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:anonymous@anonymous.com} 0(14154) DEBUG: get_hdr_field: <To> [62]; uri=[sip:anonymous@anonymous.com] 0(14154) DEBUG: to body [sip:anonymous@anonymous.com] 0(14154) get_hdr_field: cseq <CSeq>: <1> <INVITE> 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c63-b5374-2864>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) preparing to run routing scripts... 0(14154) parse_headers: flags=100 0(14154) DEBUG:maxfwd:is_maxfwd_present: value = 70 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) parse_headers: flags=80 0(14154) parse_headers: flags=80 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) parse_headers: flags=200 0(14154) is_preloaded: No 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.50] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.50] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) check_self: host != me 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.54] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) after_loose: Topmost route URI: 'sip:192.168.39.54;lr;ftag=0-13c4-44db1c5c-b38bc-7e15' is me 0(14154) parse_headers: flags=200 0(14154) DEBUG: get_hdr_body : content_length=318 0(14154) found end of header 0(14154) find_next_route: No next Route HF found 0(14154) after_loose: No next URI found 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) parse_headers: flags=40 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) DEBUG:check_content_type: type <application/sdp> found valid 0(14154) parse_headers: flags=40 0(14154) force_rtp_proxy2: proxy reply: 35030 192.168.39.54
0(14154) subst_run: running. r=0 0(14154) subst_run: matched (0, 34): [sip:400@192.168.39.50:5060;nat=yes] 0(14154) textops: subst_uri_f: match - old uri= [sip:400@192.168.39.50:5060;nat=yes], new uri= [sip:400@192.168.39.50:5060] 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) DEBUG:check_content_type: type <application/sdp> found valid 0(14154) parse_headers: flags=40 0(14154) force_rtp_proxy2: proxy reply: 35030 192.168.39.54
0(14154) DEBUG: t_newtran: msg id=6 , global msg id=5 , T on entrance=0xffffffffffffffff 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) parse_headers: flags=78 0(14154) t_lookup_request: start searching: hash=34382, isACK=0 0(14154) DEBUG: RFC3261 transaction matching failed 0(14154) DEBUG: t_lookup_request: no transaction found 0(14154) DEBUG:tm:t_relay: new INVITE 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) WARNING:vqm_resize: resize(0) called 0(14154) DEBUG:tm:_reply_light: reply sent out. buf=0x6166b8: SIP/2.0 1..., shmem=0x2ba62f3c3f30: SIP/2.0 1 0(14154) DEBUG:tm:_reply_light: finished 0(14154) DEBUG: mk_proxy: doing DNS lookup... 0(14154) parse_headers: flags=2000 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) clen_builder: content-length: 372 (372) 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) DEBUG: add_to_tail_of_timer[4]: 0x2ba62f3c16a8 0(14154) DEBUG: add_to_tail_of_timer[0]: 0x2ba62f3c16c8 0(14154) SER: new transaction fwd'ed 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 0(14154) SIP Reply (status): 0(14154) version: <SIP/2.0> 0(14154) status: <200> 0(14154) reason: <OK> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b38bc-7e15 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:anonymous@anonymous.com} 0(14154) DEBUG: get_hdr_field: <To> [62]; uri=[sip:anonymous@anonymous.com] 0(14154) DEBUG: to body [sip:anonymous@anonymous.com] 0(14154) get_hdr_field: cseq <CSeq>: <1> <INVITE> 0(14154) Found param type 232, <branch> = <z9hG4bKe468.f73bf65.0>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) forward_reply: found module nathelper, passing reply to it 0(14154) forward_reply: found module tm, passing reply to it 0(14154) DEBUG: t_check: msg id=7 global id=6 T start=0xffffffffffffffff 0(14154) parse_headers: flags=22 0(14154) parse_headers: flags=8 0(14154) DEBUG: t_reply_matching: hash 34382 label 91206527 branch 0 0(14154) DEBUG:tm:REF_UNSAFE: after is 1 0(14154) DEBUG: t_reply_matching: reply matched (T=0x2ba62f3c14c8)! 0(14154) DEBUG: t_check: msg id=7 global id=7 T end=0x2ba62f3c14c8 0(14154) DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) Found param type 235, <rport> = <5060>; state=6 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c63-b5374-2864>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=ffffffffffffffff 0(14154) parse_headers: this is the second via 0(14154) DEBUG: get_hdr_body : content_length=156 0(14154) found end of header 0(14154) DEBUG:check_content_type: type <application/sdp> found valid 0(14154) parse_headers: flags=40 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) force_rtp_proxy2: proxy reply: 35032 192.168.39.54
0(14154) parse_headers: flags=80 0(14154) DEBUG:tm:t_should_relay_response: T_code=100, new_code=200 0(14154) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 0(14154) parse_headers: flags=2000 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) clen_builder: content-length: 174 (174) 0(14154) old size: 645, new size: 615 0(14154) build_res_from_sip_res: copied size: orig:645, new: 615, rest: 0 msg= SIP/2.0 200 OK From: sip:500@192.168.39.54;tag=0-13c4-44db1c5c-b390c-6691 To: sip:anonymous@anonymous.com;tag=0-13c4-44db1c5c-b38bc-7e15 Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff@anonymous.com CSeq: 1 INVITE Via: SIP/2.0/UDP 192.168.39.50:5060;rport=5060;branch=z9hG4bK-44db1c63-b5374-2864 Supported: 100rel User-Agent: SIP-RG Contact: sip:400@192.168.39.50:5060;nat=yes Content-Type: application/sdp Content-Length: 174
v=0 o=SIP-N-TA 0 0 IN IP4 192.168.39.50 s=C0A82732 0000 C0A82732 0000 02 0 c=IN IP4 192.168.39.54 t=0 0 m=audio 35032 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=nortpproxy:yes
0(14154) DEBUG: add_to_tail_of_timer[2]: 0x2ba62f3c1548 0(14154) DEBUG:tm:relay_reply: sent buf=0x6166b8: SIP/2.0 2..., shmem=0x2ba62f3c3c50: SIP/2.0 2 0(14154) DEBUG: cleanup_uac_timers: RETR/FR timers reset 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 0(14154) SIP Request: 0(14154) method: <ACK> 0(14154) uri: sip:400@192.168.39.50:5060;nat=yes 0(14154) version: <SIP/2.0> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b38bc-7e15 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:anonymous@anonymous.com} 0(14154) DEBUG: get_hdr_field: <To> [62]; uri=[sip:anonymous@anonymous.com] 0(14154) DEBUG: to body [sip:anonymous@anonymous.com] 0(14154) get_hdr_field: cseq <CSeq>: <1> <ACK> 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c63-b5464-4f82>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) preparing to run routing scripts... 0(14154) DEBUG : sl_filter_ACK: to late to be a local ACK! 0(14154) parse_headers: flags=100 0(14154) DEBUG:maxfwd:is_maxfwd_present: value = 70 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) parse_headers: flags=80 0(14154) parse_headers: flags=80 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) parse_headers: flags=200 0(14154) is_preloaded: No 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.50] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.50] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) check_self: host != me 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.54] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) after_loose: Topmost route URI: 'sip:192.168.39.54;lr;ftag=0-13c4-44db1c5c-b38bc-7e15' is me 0(14154) parse_headers: flags=200 0(14154) DEBUG: get_hdr_body : content_length=0 0(14154) found end of header 0(14154) find_next_route: No next Route HF found 0(14154) after_loose: No next URI found 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) subst_run: running. r=0 0(14154) subst_run: matched (0, 34): [sip:400@192.168.39.50:5060;nat=yes] 0(14154) textops: subst_uri_f: match - old uri= [sip:400@192.168.39.50:5060;nat=yes], new uri= [sip:400@192.168.39.50:5060] 0(14154) DEBUG: t_newtran: msg id=8 , global msg id=7 , T on entrance=0xffffffffffffffff 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) parse_headers: flags=78 0(14154) t_lookup_request: start searching: hash=34382, isACK=1 0(14154) parse_headers: flags=38 0(14154) DEBUG: t_lookup_request: e2e proxy ACK found 0(14154) DEBUG:tm:REF_UNSAFE: after is 1 0(14154) DEBUG:tm:t_newtran: building branch for end2end ACK 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:tm:t_relay: forwarding ACK 0(14154) DEBUG: mk_proxy: doing DNS lookup... 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) Sending: ACK sip:400@192.168.39.50:5060 SIP/2.0 Record-Route: sip:192.168.39.54;lr=on;ftag=0-13c4-44db1c5c-b390c-6691 From: sip:500@192.168.39.54;tag=0-13c4-44db1c5c-b390c-6691 To: sip:anonymous@anonymous.com;tag=0-13c4-44db1c5c-b38bc-7e15 Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff@anonymous.com CSeq: 1 ACK Via: SIP/2.0/UDP 192.168.39.54;branch=z9hG4bKe468.f73bf65.2 Via: SIP/2.0/UDP 192.168.39.50:5060;rport=5060;branch=z9hG4bK-44db1c63-b5464-4f82 Max-Forwards: 69 User-Agent: SIP-RG Contact: sip:500@192.168.39.50:5060;nat=yes Content-Length: 0 P-hint: rr-enforced
. 0(14154) orig. len=480, new_len=583, proto=1 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 1(14160) DEBUG: timer routine:0,tl=0x2ba62f3c16c8 next=(nil) 1(14160) DEBUG: timer routine:4,tl=0x2ba62f3c16a8 next=(nil) 1(14160) DEBUG: timer routine:2,tl=0x2ba62f3c1548 next=(nil) 1(14160) DEBUG: wait_handler : removing 0x2ba62f3c14c8 from table 1(14160) DEBUG: delete transaction 0x2ba62f3c14c8 1(14160) DEBUG: wait_handler : done 0(14154) SIP Request: 0(14154) method: <BYE> 0(14154) uri: sip:500@192.168.39.50:5060;nat=yes 0(14154) version: <SIP/2.0> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500@192.168.39.54] 0(14154) DEBUG: to body [sip:500@192.168.39.54] 0(14154) get_hdr_field: cseq <CSeq>: <2> <BYE> 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c6a-b6f94-66d0>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) preparing to run routing scripts... 0(14154) parse_headers: flags=100 0(14154) DEBUG:maxfwd:is_maxfwd_present: value = 70 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) parse_headers: flags=80 0(14154) DEBUG: get_hdr_body : content_length=0 0(14154) found end of header 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b38bc-7e15 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:anonymous@anonymous.com} 0(14154) parse_headers: flags=200 0(14154) is_preloaded: No 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.50] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.50] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) check_self: host != me 0(14154) grep_sock_info - checking if host==us: 13==13 && [192.168.39.54] == [192.168.39.54] 0(14154) grep_sock_info - checking if port 5060 matches port 5060 0(14154) after_loose: Topmost route URI: 'sip:192.168.39.54;lr;ftag=0-13c4-44db1c5c-b38bc-7e15' is me 0(14154) parse_headers: flags=200 0(14154) found end of header 0(14154) find_next_route: No next Route HF found 0(14154) after_loose: No next URI found 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) subst_run: running. r=0 0(14154) subst_run: matched (0, 34): [sip:500@192.168.39.50:5060;nat=yes] 0(14154) textops: subst_uri_f: match - old uri= [sip:500@192.168.39.50:5060;nat=yes], new uri= [sip:500@192.168.39.50:5060] 0(14154) parse_headers: flags=40 0(14154) DEBUG: t_newtran: msg id=9 , global msg id=8 , T on entrance=0xffffffffffffffff 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) parse_headers: flags=78 0(14154) t_lookup_request: start searching: hash=34379, isACK=0 0(14154) DEBUG: RFC3261 transaction matching failed 0(14154) DEBUG: t_lookup_request: no transaction found 0(14154) DEBUG: mk_proxy: doing DNS lookup... 0(14154) check_via_address(192.168.39.50, 192.168.39.50, 0) 0(14154) DEBUG: add_to_tail_of_timer[4]: 0x2ba62f3c16a8 0(14154) DEBUG: add_to_tail_of_timer[0]: 0x2ba62f3c16c8 0(14154) SER: new transaction fwd'ed 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 0(14154) SIP Reply (status): 0(14154) version: <SIP/2.0> 0(14154) status: <200> 0(14154) reason: <OK> 0(14154) parse_headers: flags=2 0(14154) DEBUG: add_param: tag=0-13c4-44db1c5c-b390c-6691 0(14154) DEBUG:parse_to:end of header reached, state=29 0(14154) DBUG:parse_to: display={}, ruri={sip:500@192.168.39.54} 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500@192.168.39.54] 0(14154) DEBUG: to body [sip:500@192.168.39.54] 0(14154) get_hdr_field: cseq <CSeq>: <2> <BYE> 0(14154) Found param type 232, <branch> = <z9hG4bKb468.e8013011.0>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=2 0(14154) parse_headers: this is the first via 0(14154) After parse_msg... 0(14154) forward_reply: found module nathelper, passing reply to it 0(14154) forward_reply: found module tm, passing reply to it 0(14154) DEBUG: t_check: msg id=10 global id=9 T start=0xffffffffffffffff 0(14154) parse_headers: flags=22 0(14154) DEBUG: t_reply_matching: hash 34379 label 285413518 branch 0 0(14154) DEBUG:tm:REF_UNSAFE: after is 1 0(14154) DEBUG: t_reply_matching: reply matched (T=0x2ba62f3c14c8)! 0(14154) DEBUG: t_check: msg id=10 global id=10 T end=0x2ba62f3c14c8 0(14154) DEBUG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) 0(14154) parse_headers: flags=ffffffffffffffff 0(14154) Found param type 235, <rport> = <5060>; state=6 0(14154) Found param type 232, <branch> = <z9hG4bK-44db1c6a-b6f94-66d0>; state=16 0(14154) end of header reached, state=5 0(14154) parse_headers: Via found, flags=ffffffffffffffff 0(14154) parse_headers: this is the second via 0(14154) DEBUG: get_hdr_body : content_length=0 0(14154) found end of header 0(14154) ERROR: extract_body: message body has length zero 0(14154) ERROR: force_rtp_proxy2: can't extract body from the message 0(14154) parse_headers: flags=80 0(14154) DEBUG:tm:t_should_relay_response: T_code=0, new_code=200 0(14154) DEBUG:tm:relay_reply: branch=0, save=0, relay=0 0(14154) old size: 420, new size: 358 0(14154) build_res_from_sip_res: copied size: orig:277, new: 215, rest: 143 msg= SIP/2.0 200 OK From: sip:anonymous@anonymous.com;tag=0-13c4-44db1c5c-b38bc-7e15 To: sip:500@192.168.39.54;tag=0-13c4-44db1c5c-b390c-6691 Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff@anonymous.com CSeq: 2 BYE Via: SIP/2.0/UDP 192.168.39.50:5060;rport=5060;branch=z9hG4bK-44db1c6a-b6f94-66d0 Supported: 100rel User-Agent: SIP-RG Content-Length: 0
0(14154) WARNING:vqm_resize: resize(0) called 0(14154) DEBUG: add_to_tail_of_timer[2]: 0x2ba62f3c1548 0(14154) DEBUG:tm:relay_reply: sent buf=0x6166b8: SIP/2.0 2..., shmem=0x2ba62f3c3f30: SIP/2.0 2 0(14154) DEBUG: cleanup_uac_timers: RETR/FR timers reset 0(14154) DEBUG:tm:UNREF_UNSAFE: after is 0 0(14154) DEBUG:destroy_avp_list: destroying list (nil) 0(14154) receive_msg: cleaning up 1(14160) DEBUG: timer routine:0,tl=0x2ba62f3c16c8 next=(nil) 1(14160) DEBUG: timer routine:4,tl=0x2ba62f3c16a8 next=(nil) 1(14160) DEBUG: timer routine:2,tl=0x2ba62f3c1548 next=(nil) 1(14160) DEBUG: wait_handler : removing 0x2ba62f3c14c8 from table 1(14160) DEBUG: delete transaction 0x2ba62f3c14c8 1(14160) DEBUG: wait_handler : done 1(14160) INFO: signal 2 received 1(14160) Memory status (pkg): 1(14160) fm_status (0x605460): 1(14160) heap size= 1048576 1(14160) used= 23256, used+overhead=61944, free=986632 1(14160) max used (+overhead)= 65384 1(14160) dumping free list: 1(14160) hash = 13 fragments no.: 1, unused: 0 bucket size: 104 - 104 (first 104) 1(14160) hash = 23 fragments no.: 1, unused: 0 bucket size: 184 - 184 (first 184) 1(14160) hash = 39 fragments no.: 1, unused: 0 bucket size: 312 - 312 (first 312) 1(14160) hash = 851 fragments no.: 1, unused: 0 bucket size: 6808 - 6808 (first 6808) 1(14160) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 979224) 1(14160) TOTAL: 5 free fragments = 986632 free bytes 1(14160) ----------------------------- 0(14154) INT received, program terminates 2(14161) INFO: signal 15 received 2(14161) Memory status (pkg): 2(14161) fm_status (0x605460): 2(14161) heap size= 1048576 2(14161) used= 23576, used+overhead=62376, free=986200 2(14161) max used (+overhead)= 65384 2(14161) dumping free list: 2(14161) hash = 21 fragments no.: 1, unused: 0 bucket size: 168 - 168 (first 168) 2(14161) hash = 851 fragments no.: 1, unused: 0 bucket size: 6808 - 6808 (first 6808) 2(14161) hash = 2054 fragments no.: 1, unused: 0 bucket size: 524288 - 1048576 (first 979224) 2(14161) TOTAL: 3 free fragments = 986200 free bytes 2(14161) ----------------------------- 0(14154) pool_remove: Connection still kept in the pool 0(14154) pool_remove: Connection still kept in the pool 0(14154) pool_remove: Removing connection from the pool
-- Pavel D.Kuzin System Administrator Nodex ISP St. Petersburg, Russia pk@nodex.ru http://nodex.ru