[Users] nathelper & fax = bug ?

Pavel D. Kuzin pk at nodex.ru
Thu Aug 10 13:57:29 CEST 2006


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 at 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 at 192.168.39.54}
 0(14154) DEBUG: get_hdr_field: <To> [25]; uri=[sip:500 at 192.168.39.54]
 0(14154) DEBUG: to body [<sip:500 at 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 at 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 at 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 at 192.168.39.54}
 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500 at 192.168.39.54]
 0(14154) DEBUG: to body [<sip:500 at 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 at 192.168.39.54}
 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500 at 192.168.39.54]
 0(14154) DEBUG: to body [<sip:500 at 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 at anonymous.com>;tag=0-13c4-44db1c5c-b38bc-7e15
To: <sip:500 at 192.168.39.54>;tag=0-13c4-44db1c5c-b390c-6691
Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff at 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 at 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 at 192.168.39.54}
 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500 at 192.168.39.54]
 0(14154) DEBUG: to body [<sip:500 at 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 at 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 at anonymous.com>;tag=0-13c4-44db1c5c-b38bc-7e15
To: <sip:500 at 192.168.39.54>;tag=0-13c4-44db1c5c-b390c-6691
Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff at 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 at 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 at 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 at 192.168.39.54}
 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500 at 192.168.39.54]
 0(14154) DEBUG: to body [<sip:500 at 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 at 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 at 192.168.39.50:5060;nat=yes]
 0(14154) textops: subst_uri_f: match - old uri= [sip:500 at 192.168.39.50:5060;nat=yes], new uri= [sip:500 at 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 at 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 at anonymous.com>;tag=0-13c4-44db1c5c-b38bc-7e15
To: <sip:500 at 192.168.39.54>;tag=0-13c4-44db1c5c-b390c-6691
Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff at 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 at 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 at 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 at anonymous.com}
 0(14154) DEBUG: get_hdr_field: <To> [62]; uri=[sip:anonymous at anonymous.com]
 0(14154) DEBUG: to body [<sip:anonymous at 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 at 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 at 192.168.39.50:5060;nat=yes]
 0(14154) textops: subst_uri_f: match - old uri= [sip:400 at 192.168.39.50:5060;nat=yes], new uri= [sip:400 at 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 at anonymous.com}
 0(14154) DEBUG: get_hdr_field: <To> [62]; uri=[sip:anonymous at anonymous.com]
 0(14154) DEBUG: to body [<sip:anonymous at 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 at 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 at 192.168.39.54>;tag=0-13c4-44db1c5c-b390c-6691
To: <sip:anonymous at anonymous.com>;tag=0-13c4-44db1c5c-b38bc-7e15
Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff at 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 at 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 at 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 at anonymous.com}
 0(14154) DEBUG: get_hdr_field: <To> [62]; uri=[sip:anonymous at anonymous.com]
 0(14154) DEBUG: to body [<sip:anonymous at 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 at 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 at 192.168.39.50:5060;nat=yes]
 0(14154) textops: subst_uri_f: match - old uri= [sip:400 at 192.168.39.50:5060;nat=yes], new uri= [sip:400 at 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 at 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 at 192.168.39.54>;tag=0-13c4-44db1c5c-b390c-6691
To: <sip:anonymous at anonymous.com>;tag=0-13c4-44db1c5c-b38bc-7e15
Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff at 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 at 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 at 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 at 192.168.39.54}
 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500 at 192.168.39.54]
 0(14154) DEBUG: to body [<sip:500 at 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 at 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 at 192.168.39.50:5060;nat=yes]
 0(14154) textops: subst_uri_f: match - old uri= [sip:500 at 192.168.39.50:5060;nat=yes], new uri= [sip:500 at 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 at 192.168.39.54}
 0(14154) DEBUG: get_hdr_field: <To> [56]; uri=[sip:500 at 192.168.39.54]
 0(14154) DEBUG: to body [<sip:500 at 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 at anonymous.com>;tag=0-13c4-44db1c5c-b38bc-7e15
To: <sip:500 at 192.168.39.54>;tag=0-13c4-44db1c5c-b390c-6691
Call-ID: c8ea3c-0-13c4-44db1c5c-b38bc-31ff at 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 at nodex.ru
http://nodex.ru




More information about the sr-users mailing list