rendered paste bodyApr 27 04:24:15 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: lookup(): '' Not found in usrloc
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: check_via_address(71.220.244.225, 192.168.1.170, 0)
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:15 log /usr/local/sbin/openser[2833]: receive_msg: cleaning up
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: SIP Request:
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: method: <NOTIFY>
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: uri: <sip:sip2.demo.com>
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: version: <SIP/2.0>
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: parse_headers: flags=2
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK-e3baadac>; state=16
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=2
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: parse_headers: this is the first via
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: After parse_msg...
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: preparing to run routing scripts...
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: parse_headers: flags=100
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={}, ruri={sip:sip2.demo.com}
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:sip2.demo.com]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DEBUG: to body [<sip:sip2.demo.com> ]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: get_hdr_field: cseq <CSeq>: <5428> <NOTIFY>
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DEBUG:maxfwd:is_maxfwd_present: value = 70
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: check_via_address(70.245.76.121, 70.245.76.121, 0)
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: parse_headers: flags=80
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: found end of header
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=263a7e17dbc77445o0
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={Timothy Dick}, ruri={sip:5618530300@sip2.demo.com}
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: parse_headers: flags=200
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: find_first_route: No Route headers found
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: loose_route: There is no Route HF
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: lookup(): '' Not found in usrloc
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: check_via_address(70.245.76.121, 70.245.76.121, 0)
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:24 log /usr/local/sbin/openser[2828]: receive_msg: cleaning up
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: SIP Request:
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: method: <INVITE>
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: uri: <sip:9492666205@sip2.demo.com:5060>
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: version: <SIP/2.0>
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=2
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.0>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=2
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: this is the first via
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: After parse_msg...
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: preparing to run routing scripts...
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=100
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.0>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=100
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: this is the second via
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK75fe20c9>; state=6
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=100
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_field: <To> [31]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: to body [<sip:9492666205@64.24.35.216> ]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=200
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_body : content_length=232
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: found end of header
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: find_first_route: No Route headers found
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: loose_route: There is no Route HF
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: rewrite_uri: Rewriting Request-URI with 'sip:9492666205@192.168.1.102:5060'
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: subst_run: running. r=1
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: subst_str: no match
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=40
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=78
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: t_lookup_request: start searching: hash=52201, isACK=0
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: RFC3261 transaction matching failed
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: t_lookup_request: no transaction found
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: WARNING:vqm_resize: resize(0) called
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:_reply_light: reply sent out. buf=0x64c318: SIP/2.0 1..., shmem=0x2b16c2136018: SIP/2.0 1
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:_reply_light: finished
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DBG:check_against_rule_list: using list dns
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:set_timer: relative timeout is 500000
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: add_to_tail_of_timer[4]: 0x2b16c2133118 (152100000)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:set_timer: relative timeout is 30
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: add_to_tail_of_timer[0]: 0x2b16c2133148 (181)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:t_relay_to: new transaction fwd'ed
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: receive_msg: cleaning up
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: SIP Reply (status):
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: version: <SIP/2.0>
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: status: <100>
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: reason: <Trying>
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: flags=2
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG: get_hdr_field: <To> [31]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG: to body [<sip:9492666205@64.24.35.216> ]
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.0>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: Via found, flags=2
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: this is the first via
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: After parse_msg...
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: flags=22
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: flags=8
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG: t_reply_matching: hash 52201 label 1327305443 branch 0
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG: t_reply_matching: reply matched (T=0x2b16c2132ef8)!
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG: t_check: end=0x2b16c2132ef8
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.0>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: Via found, flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: this is the second via
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.0>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: Via found, flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: Found param type 232, <branch> = <z9hG4bK75fe20c9>; state=6
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: parse_headers: Via found, flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: found end of header
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:tm:t_should_relay_response: T_code=100, new_code=100
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:tm:relay_reply: branch=0, save=0, relay=-1
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:tm:set_timer: relative timeout is 120
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG: add_to_tail_of_timer[1]: 0x2b16c2133148 (271)
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:28 log /usr/local/sbin/openser[2830]: receive_msg: cleaning up
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: SIP Reply (status):
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: version: <SIP/2.0>
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: status: <180>
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: reason: <Ringing>
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=2
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.0>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=2
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: this is the first via
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: After parse_msg...
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=22
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=8
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: t_reply_matching: hash 52201 label 1327305443 branch 0
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: t_reply_matching: reply matched (T=0x2b16c2132ef8)!
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: t_check: end=0x2b16c2132ef8
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.0>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: this is the second via
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.0>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK75fe20c9>; state=6
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=80
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: found end of header
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:t_should_relay_response: T_code=100, new_code=180
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: old size: 708, new size: 648
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: build_res_from_sip_res: copied size: orig:276, new: 216, rest: 432 msg= SIP/2.0 180 Ringing To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK75fe20c9;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Record-Route: <sip:64.24.35.216;lr=on;ftag=as710aca5e> Server: Linksys/PAP2-3.1.9(LSa) Content-Length: 0
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:relay_reply: sent buf=0x64c018: SIP/2.0 1..., shmem=0x2b16c21367a8: SIP/2.0 1
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:set_timer: relative timeout is 120
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG: add_to_tail_of_timer[1]: 0x2b16c2133148 (271)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:28 log /usr/local/sbin/openser[2828]: receive_msg: cleaning up
Apr 27 04:24:28 log /usr/local/sbin/openser[2835]: DEBUG: timer routine:4,tl=0x2b16c2133118 next=(nil), timeout=152100000
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: SIP Reply (status):
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: version: <SIP/2.0>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: status: <200>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: reason: <OK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.0>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: this is the first via
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: After parse_msg...
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=22
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=8
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: t_reply_matching: hash 52201 label 1327305443 branch 0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: t_reply_matching: reply matched (T=0x2b16c2132ef8)!
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: t_check: end=0x2b16c2132ef8
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.0>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: this is the second via
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.0>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK75fe20c9>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_body : content_length=235
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: found end of header
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=40
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: ERROR: send_rtpp_command: can't send command to a RTP proxy
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: send_rtpp_command(): proxy <udp:127.0.0.1:7890> does not responding, disable it
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: WARNING: rtpp_test: can't get version of the RTP proxy
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: WARNING: rtpp_test: support for RTP proxy <udp:127.0.0.1:7890>has been disabled temporarily
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: ERROR: force_rtp_proxy2: no available proxies
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=80
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:t_should_relay_response: T_code=180, new_code=200
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: old size: 1118, new size: 1065
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: build_res_from_sip_res: copied size: orig:709, new: 656, rest: 409 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK75fe20c9;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Record-Route: <sip:64.24.35.216;lr=on;ftag=as710aca5e> Contact: John Doe <sip:9492666205@24.162.48.94:1203;nat=yes> Server: Linksys/PAP2-3.1.9(LSa) Content-Length: 235 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 218620 218620 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16388 RTP/AVP 0 100 101 a=rtpmap:0 PCMU/8000 a=rtpmap:100 NSE/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_to_tail_of_timer[2]: 0x2b16c2132f78 (158)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:relay_reply: sent buf=0x64c1c8: SIP/2.0 2..., shmem=0x2b16c2136ae0: SIP/2.0 2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: receive_msg: cleaning up
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: SIP Request:
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: method: <ACK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: uri: <sip:9492666205@OpenSER:5060;nat=yes>
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: version: <SIP/2.0>
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: this is the first via
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: After parse_msg...
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: preparing to run routing scripts...
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: this is the second via
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK5b365f0e>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=80
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=200
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: is_preloaded: No
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as710aca5e' is loose router
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: found end of header
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as710aca5e'
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as710aca5e'
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: subst_run: running. r=1
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: subst_str: no match
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=78
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: t_lookup_request: start searching: hash=52201, isACK=1
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: parse_headers: flags=38
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG: t_lookup_request: e2e proxy ACK found
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:tm:t_newtran: building branch for end2end ACK
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DBG:check_against_rule_list: using list dns
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as710aca5e SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK9ebc.3e21d1f4.2 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.2 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK5b365f0e;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:forward_request: orig. len=648, new_len=745, proto=1
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: SIP Request:
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: method: <ACK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: uri: <sip:OpenSER;lr=on;ftag=as710aca5e>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: version: <SIP/2.0>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: this is the first via
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: After parse_msg...
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: preparing to run routing scripts...
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: this is the second via
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK5b365f0e>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=80
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=200
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: found end of header
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: find_first_route: No Route headers found
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: loose_route: There is no Route HF
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: lookup(): '' Not found in usrloc
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: receive_msg: cleaning up
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:30 log /usr/local/sbin/openser[2828]: receive_msg: cleaning up
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: SIP Reply (status):
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: version: <SIP/2.0>
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: status: <200>
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: reason: <OK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.0>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: Via found, flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: this is the first via
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: After parse_msg...
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: flags=22
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: flags=8
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: t_reply_matching: hash 52201 label 1327305443 branch 0
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: t_reply_matching: reply matched (T=0x2b16c2132ef8)!
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: t_check: end=0x2b16c2132ef8
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:tm:reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=1)
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.0>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: this is the second via
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.0>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: Found param type 232, <branch> = <z9hG4bK75fe20c9>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: get_hdr_body : content_length=235
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: found end of header
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: flags=40
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: ERROR: send_rtpp_command: can't send command to a RTP proxy
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: send_rtpp_command(): proxy <udp:127.0.0.1:7890> does not responding, disable it
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: WARNING: rtpp_test: can't get version of the RTP proxy
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: WARNING: rtpp_test: support for RTP proxy <udp:127.0.0.1:7890>has been disabled temporarily
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: ERROR: force_rtp_proxy2: no available proxies
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: parse_headers: flags=80
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:tm:t_should_relay_response: T_code=200, new_code=200
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: old size: 1118, new size: 1065
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: build_res_from_sip_res: copied size: orig:709, new: 656, rest: 409 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK75fe20c9;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Record-Route: <sip:64.24.35.216;lr=on;ftag=as710aca5e> Contact: John Doe <sip:9492666205@24.162.48.94:1203;nat=yes> Server: Linksys/PAP2-3.1.9(LSa) Content-Length: 235 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 218620 218620 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16388 RTP/AVP 0 100 101 a=rtpmap:0 PCMU/8000 a=rtpmap:100 NSE/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:tm:relay_reply: sent buf=0x64b9f0: SIP/2.0 2..., shmem=0x2b16c2136ae0: SIP/2.0 2
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:30 log /usr/local/sbin/openser[2830]: receive_msg: cleaning up
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: SIP Request:
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: method: <ACK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: uri: <sip:9492666205@OpenSER:5060;nat=yes>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: version: <SIP/2.0>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: this is the first via
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: After parse_msg...
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: preparing to run routing scripts...
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: this is the second via
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK12d9f918>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=80
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=200
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: is_preloaded: No
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as710aca5e' is loose router
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: found end of header
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as710aca5e'
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as710aca5e'
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: subst_run: running. r=1
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: subst_str: no match
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=78
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: t_lookup_request: start searching: hash=52201, isACK=1
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=38
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: t_lookup_request: e2e proxy ACK found
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:t_newtran: building branch for end2end ACK
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBG:check_against_rule_list: using list dns
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as710aca5e SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK9ebc.3e21d1f4.2 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.2 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK12d9f918;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:forward_request: orig. len=648, new_len=745, proto=1
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: receive_msg: cleaning up
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: SIP Request:
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: method: <ACK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: uri: <sip:OpenSER;lr=on;ftag=as710aca5e>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: version: <SIP/2.0>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: this is the first via
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: After parse_msg...
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: preparing to run routing scripts...
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: this is the second via
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.2>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK12d9f918>; state=6
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=80
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: parse_headers: flags=200
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: found end of header
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: find_first_route: No Route headers found
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: loose_route: There is no Route HF
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: lookup(): '' Not found in usrloc
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:30 log /usr/local/sbin/openser[2833]: receive_msg: cleaning up
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: SIP Request:
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: method: <NOTIFY>
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: uri: <sip:sip2.demo.com>
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: version: <SIP/2.0>
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: parse_headers: flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: Found param type 232, <branch> = <z9hG4bK-88b75579>; state=16
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: end of header reached, state=5
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: parse_headers: Via found, flags=2
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: parse_headers: this is the first via
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: After parse_msg...
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: preparing to run routing scripts...
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: parse_headers: flags=100
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DBUG:parse_to: display={}, ruri={sip:sip2.demo.com}
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:sip2.demo.com]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DEBUG: to body [<sip:sip2.demo.com> ]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: get_hdr_field: cseq <CSeq>: <471> <NOTIFY>
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DEBUG:maxfwd:is_maxfwd_present: value = 70
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: parse_headers: flags=80
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: found end of header
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DEBUG: add_param: tag=afbb92f48b3b9d9bo0
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DBUG:parse_to: display={demo NM}, ruri={sip:5057965751@sip2.demo.com}
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: parse_headers: flags=200
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: find_first_route: No Route headers found
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: loose_route: There is no Route HF
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: lookup(): '' Not found in usrloc
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: check_via_address(71.220.244.225, 192.168.1.170, 0)
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:30 log /usr/local/sbin/openser[2826]: receive_msg: cleaning up
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: SIP Reply (status):
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: version: <SIP/2.0>
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: status: <200>
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: reason: <OK>
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=2
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.0>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=2
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: this is the first via
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: After parse_msg...
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=22
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=8
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: t_reply_matching: hash 52201 label 1327305443 branch 0
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: t_reply_matching: reply matched (T=0x2b16c2132ef8)!
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: t_check: end=0x2b16c2132ef8
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:tm:reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=1)
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.0>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: this is the second via
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.0>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK75fe20c9>; state=6
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_body : content_length=235
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: found end of header
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=40
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: ERROR: force_rtp_proxy2: no available proxies
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=80
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:tm:t_should_relay_response: T_code=200, new_code=200
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: old size: 1118, new size: 1065
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: build_res_from_sip_res: copied size: orig:709, new: 656, rest: 409 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK75fe20c9;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Record-Route: <sip:64.24.35.216;lr=on;ftag=as710aca5e> Contact: John Doe <sip:9492666205@24.162.48.94:1203;nat=yes> Server: Linksys/PAP2-3.1.9(LSa) Content-Length: 235 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 218620 218620 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16388 RTP/AVP 0 100 101 a=rtpmap:0 PCMU/8000 a=rtpmap:100 NSE/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:tm:relay_reply: sent buf=0x64c1c8: SIP/2.0 2..., shmem=0x2b16c2136ae0: SIP/2.0 2
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: receive_msg: cleaning up
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: SIP Request:
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: method: <ACK>
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: uri: <sip:9492666205@OpenSER:5060;nat=yes>
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: version: <SIP/2.0>
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=2
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.2>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: Via found, flags=2
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: this is the first via
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: After parse_msg...
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: preparing to run routing scripts...
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=8
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.2>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: Via found, flags=8
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: this is the second via
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: Found param type 232, <branch> = <z9hG4bK2026c162>; state=6
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: Via found, flags=8
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=100
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=80
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=200
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: is_preloaded: No
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as710aca5e' is loose router
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: found end of header
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as710aca5e'
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as710aca5e'
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: subst_run: running. r=1
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: subst_str: no match
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=78
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: t_lookup_request: start searching: hash=52201, isACK=1
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: parse_headers: flags=38
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG: t_lookup_request: e2e proxy ACK found
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:tm:t_newtran: building branch for end2end ACK
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DBG:check_against_rule_list: using list dns
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as710aca5e SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK9ebc.3e21d1f4.2 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.2 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK2026c162;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:forward_request: orig. len=648, new_len=745, proto=1
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: SIP Request:
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: method: <ACK>
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: uri: <sip:OpenSER;lr=on;ftag=as710aca5e>
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: version: <SIP/2.0>
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=2
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.2>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=2
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: this is the first via
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: After parse_msg...
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: preparing to run routing scripts...
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=8
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.2>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=8
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: this is the second via
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.2>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=8
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 232, <branch> = <z9hG4bK2026c162>; state=6
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: end of header reached, state=5
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: Via found, flags=8
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=100
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=80
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: parse_headers: flags=200
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: found end of header
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: find_first_route: No Route headers found
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: loose_route: There is no Route HF
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: lookup(): '' Not found in usrloc
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:31 log /usr/local/sbin/openser[2833]: receive_msg: cleaning up
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:31 log /usr/local/sbin/openser[2826]: receive_msg: cleaning up
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: SIP Reply (status):
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: version: <SIP/2.0>
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: status: <200>
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: reason: <OK>
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=2
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.0>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=2
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: this is the first via
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: After parse_msg...
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=22
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=8
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: t_reply_matching: hash 52201 label 1327305443 branch 0
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: t_reply_matching: reply matched (T=0x2b16c2132ef8)!
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: t_check: end=0x2b16c2132ef8
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:tm:reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=1)
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.0>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: this is the second via
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.0>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK75fe20c9>; state=6
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_body : content_length=235
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: found end of header
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=40
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: ERROR: send_rtpp_command: can't send command to a RTP proxy
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: send_rtpp_command(): proxy <udp:127.0.0.1:7890> does not responding, disable it
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: WARNING: rtpp_test: can't get version of the RTP proxy
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: WARNING: rtpp_test: support for RTP proxy <udp:127.0.0.1:7890>has been disabled temporarily
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: ERROR: force_rtp_proxy2: no available proxies
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=80
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:tm:t_should_relay_response: T_code=200, new_code=200
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: old size: 1118, new size: 1065
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: build_res_from_sip_res: copied size: orig:709, new: 656, rest: 409 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK75fe20c9;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Record-Route: <sip:64.24.35.216;lr=on;ftag=as710aca5e> Contact: John Doe <sip:9492666205@24.162.48.94:1203;nat=yes> Server: Linksys/PAP2-3.1.9(LSa) Content-Length: 235 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 218620 218620 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16388 RTP/AVP 0 100 101 a=rtpmap:0 PCMU/8000 a=rtpmap:100 NSE/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:tm:relay_reply: sent buf=0x64ca50: SIP/2.0 2..., shmem=0x2b16c2136ae0: SIP/2.0 2
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: receive_msg: cleaning up
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: SIP Request:
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: method: <ACK>
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: uri: <sip:9492666205@OpenSER:5060;nat=yes>
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: version: <SIP/2.0>
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=2
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.2>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: Via found, flags=2
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: this is the first via
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: After parse_msg...
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: preparing to run routing scripts...
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=100
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.2>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: Via found, flags=100
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: this is the second via
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: Found param type 232, <branch> = <z9hG4bK4603c7ad>; state=6
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: Via found, flags=100
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=80
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=200
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: is_preloaded: No
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as710aca5e' is loose router
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: found end of header
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as710aca5e'
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as710aca5e'
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: subst_run: running. r=1
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: subst_str: no match
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=ffffffffffffffff
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=78
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: t_lookup_request: start searching: hash=52201, isACK=1
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: parse_headers: flags=38
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG: t_lookup_request: e2e proxy ACK found
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:tm:t_newtran: building branch for end2end ACK
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DBG:check_against_rule_list: using list dns
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as710aca5e SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as710aca5e> Record-Route: <sip:Gateway;lr=on;ftag=as710aca5e> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK9ebc.3e21d1f4.2 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK9ebc.e6c38f54.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK9ebc.9c70fae1.2 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK4603c7ad;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as710aca5e To: <sip:9492666205@64.24.35.216>;tag=b79970d0a6a94debi0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 5cf60b7c7e68b6be0b61893352ba53ea@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:forward_request: orig. len=648, new_len=745, proto=1
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: SIP Request:
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: method: <ACK>
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: uri: <sip:OpenSER;lr=on;ftag=as710aca5e>
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: version: <SIP/2.0>
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=2
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.3e21d1f4.2>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=2
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: this is the first via
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: After parse_msg...
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: preparing to run routing scripts...
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=100
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.e6c38f54.2>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=100
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: this is the second via
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK9ebc.9c70fae1.2>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=100
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 232, <branch> = <z9hG4bK4603c7ad>; state=6
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: end of header reached, state=5
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: Via found, flags=100
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=b79970d0a6a94debi0
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=80
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: add_param: tag=as710aca5e
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: parse_headers: flags=200
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: found end of header
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: find_first_route: No Route headers found
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: loose_route: There is no Route HF
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: lookup(): '' Not found in usrloc
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:33 log /usr/local/sbin/openser[2828]: receive_msg: cleaning up
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:24:33 log /usr/local/sbin/openser[2826]: receive_msg: cleaning up
Apr 27 04:24:34 log /usr/local/sbin/openser[2835]: DEBUG: timer routine:2,tl=0x2b16c2132f78 next=(nil), timeout=158
Apr 27 04:24:34 log /usr/local/sbin/openser[2835]: DEBUG: wait_handler : removing 0x2b16c2132ef8 from table
Apr 27 04:24:34 log /usr/local/sbin/openser[2835]: DEBUG: delete transaction 0x2b16c2132ef8
Apr 27 04:24:34 log /usr/local/sbin/openser[2835]: DEBUG: wait_handler : done