rendered paste bodyApr 27 04:40:06 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: lookup(): '' Not found in usrloc
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: check_via_address(71.220.244.225, 192.168.1.170, 0)
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:06 log /usr/local/sbin/openser[3164]: receive_msg: cleaning up
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: SIP Request:
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: method: <NOTIFY>
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: uri: <sip:sip2.demo.com>
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: version: <SIP/2.0>
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: parse_headers: flags=2
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK-46337341>; state=16
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=2
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: parse_headers: this is the first via
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: After parse_msg...
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: preparing to run routing scripts...
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: parse_headers: flags=100
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DBUG:parse_to: display={}, ruri={sip:sip2.demo.com}
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:sip2.demo.com]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DEBUG: to body [<sip:sip2.demo.com> ]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: get_hdr_field: cseq <CSeq>: <5491> <NOTIFY>
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DEBUG:maxfwd:is_maxfwd_present: value = 70
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: check_via_address(70.245.76.121, 70.245.76.121, 0)
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: parse_headers: flags=80
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: found end of header
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DEBUG: add_param: tag=263a7e17dbc77445o0
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DBUG:parse_to: display={Timothy Dick}, ruri={sip:5618530300@sip2.demo.com}
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: parse_headers: flags=200
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: find_first_route: No Route headers found
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: loose_route: There is no Route HF
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: lookup(): '' Not found in usrloc
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: check_via_address(70.245.76.121, 70.245.76.121, 0)
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:14 log /usr/local/sbin/openser[3159]: receive_msg: cleaning up
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: SIP Request:
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: method: <INVITE>
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: uri: <sip:9492666205@sip2.demo.com:5060>
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: version: <SIP/2.0>
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=2
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=2
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: this is the first via
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: After parse_msg...
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: preparing to run routing scripts...
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=100
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: this is the second via
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK7ca3569c>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_field: <To> [31]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: to body [<sip:9492666205@64.24.35.216> ]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=200
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_body : content_length=232
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: found end of header
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: find_first_route: No Route headers found
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: loose_route: There is no Route HF
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: rewrite_uri: Rewriting Request-URI with 'sip:9492666205@192.168.1.102:5060'
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: ******* setting for branch 0 flags 40
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: subst_run: running. r=1
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: subst_str: no match
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=40
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: -------branch=0, branch flags=00000040
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=78
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: t_lookup_request: start searching: hash=27428, isACK=0
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: RFC3261 transaction matching failed
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: t_lookup_request: no transaction found
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: SIP Request:
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: method: <INVITE>
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: WARNING:vqm_resize: resize(0) called
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: uri: <sip:9492666205@sip2.demo.com:5060>
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: version: <SIP/2.0>
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=2
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:tm:_reply_light: reply sent out. buf=0x64de80: SIP/2.0 1..., shmem=0x2b2284ba1560: SIP/2.0 1
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:tm:_reply_light: finished
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=2
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: this is the first via
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: After parse_msg...
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: preparing to run routing scripts...
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=100
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: this is the second via
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DBG:check_against_rule_list: using list dns
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK7ca3569c>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:tm:set_timer: relative timeout is 500000
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: add_to_tail_of_timer[4]: 0x2b2284b9e660 (19500000)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:tm:set_timer: relative timeout is 30
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: add_to_tail_of_timer[0]: 0x2b2284b9e690 (49)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_field: <To> [31]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DBG:check_against_rule_list: using list dns
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG: to body [<sip:9492666205@64.24.35.216> ]
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:tm:set_timer: relative timeout is 500000
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: add_to_tail_of_timer[4]: 0x2b2284b9e818 (19500000)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:tm:set_timer: relative timeout is 30
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG: add_to_tail_of_timer[0]: 0x2b2284b9e848 (49)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:tm:t_relay_to: new transaction fwd'ed
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:18 log /usr/local/sbin/openser[3164]: receive_msg: cleaning up
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=200
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_body : content_length=232
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: found end of header
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: find_first_route: No Route headers found
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: loose_route: There is no Route HF
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: rewrite_uri: Rewriting Request-URI with 'sip:9492666205@192.168.1.102:5060'
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: ******* setting for branch 0 flags 40
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: subst_run: running. r=1
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: subst_str: no match
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=40
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: -------branch=0, branch flags=00000040
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: parse_headers: flags=78
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: t_lookup_request: start searching: hash=27428, isACK=0
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG: RFC3261 transaction matched, tid=42b6.e7d05087.0
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG: t_lookup_request: transaction found (T=0x2b2284b9e440)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG:tm:t_retransmit_reply: buf=0x2b2283d63280: SIP/2.0 1..., shmem=0x2b2284ba1560: SIP/2.0 1
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:18 log /usr/local/sbin/openser[3162]: receive_msg: cleaning up
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: SIP Reply (status):
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: version: <SIP/2.0>
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: status: <100>
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: reason: <Trying>
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: flags=2
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG: get_hdr_field: <To> [31]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG: to body [<sip:9492666205@64.24.35.216> ]
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=2
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: this is the first via
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: After parse_msg...
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: flags=22
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: flags=8
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG: t_reply_matching: hash 27428 label 319750510 branch 0
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG: t_reply_matching: reply matched (T=0x2b2284b9e440)!
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG: t_check: end=0x2b2284b9e440
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: this is the second via
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK7ca3569c>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: found end of header
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:tm:t_should_relay_response: T_code=100, new_code=100
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:tm:relay_reply: branch=0, save=0, relay=-1
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:tm:set_timer: relative timeout is 120
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG: add_to_tail_of_timer[1]: 0x2b2284b9e690 (139)
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:18 log /usr/local/sbin/openser[3159]: receive_msg: cleaning up
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: SIP Reply (status):
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: version: <SIP/2.0>
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: status: <180>
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: reason: <Ringing>
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: flags=2
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=2
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: this is the first via
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: After parse_msg...
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: flags=22
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: flags=8
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: t_reply_matching: hash 27428 label 319750510 branch 0
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: t_reply_matching: reply matched (T=0x2b2284b9e440)!
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: t_check: end=0x2b2284b9e440
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: this is the second via
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.0>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK7ca3569c>; state=6
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=80
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: found end of header
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:tm:t_should_relay_response: T_code=100, new_code=180
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: old size: 707, new size: 647
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: build_res_from_sip_res: copied size: orig:276, new: 216, rest: 431 msg= SIP/2.0 180 Ringing To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK7ca3569c;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Record-Route: <sip:64.24.35.216;lr=on;ftag=as7b808a8a> Server: Linksys/PAP2-3.1.9(LSa) Content-Length: 0
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:tm:relay_reply: sent buf=0x64d3d8: SIP/2.0 1..., shmem=0x2b2284ba21f0: SIP/2.0 1
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:tm:set_timer: relative timeout is 120
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG: add_to_tail_of_timer[1]: 0x2b2284b9e690 (139)
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:18 log /usr/local/sbin/openser[3157]: receive_msg: cleaning up
Apr 27 04:40:18 log /usr/local/sbin/openser[3167]: DEBUG: timer routine:4,tl=0x2b2284b9e660 next=0x2b2284b9e818, timeout=19500000
Apr 27 04:40:18 log /usr/local/sbin/openser[3167]: DEBUG: timer routine:4,tl=0x2b2284b9e818 next=(nil), timeout=19500000
Apr 27 04:40:18 log /usr/local/sbin/openser[3167]: DEBUG: retransmission_handler : request resending (t=0x2b2284b9e440, INVITE si ... )
Apr 27 04:40:18 log /usr/local/sbin/openser[3167]: DEBUG:tm:set_timer: relative timeout is 1000000
Apr 27 04:40:18 log /usr/local/sbin/openser[3167]: DEBUG: add_to_tail_of_timer[5]: 0x2b2284b9e818 (20500000)
Apr 27 04:40:18 log /usr/local/sbin/openser[3167]: DEBUG: retransmission_handler : done
Apr 27 04:40:19 log /usr/local/sbin/openser[3167]: DEBUG: timer routine:5,tl=0x2b2284b9e818 next=(nil), timeout=20500000
Apr 27 04:40:19 log /usr/local/sbin/openser[3167]: DEBUG: retransmission_handler : request resending (t=0x2b2284b9e440, INVITE si ... )
Apr 27 04:40:19 log /usr/local/sbin/openser[3167]: DEBUG:tm:set_timer: relative timeout is 2000000
Apr 27 04:40:19 log /usr/local/sbin/openser[3167]: DEBUG: add_to_tail_of_timer[6]: 0x2b2284b9e818 (22500000)
Apr 27 04:40:19 log /usr/local/sbin/openser[3167]: DEBUG: retransmission_handler : done
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: SIP Reply (status):
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: version: <SIP/2.0>
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: status: <200>
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: reason: <OK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.0>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: this is the first via
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: After parse_msg...
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=22
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=8
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: t_reply_matching: hash 27428 label 319750510 branch 0
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: t_reply_matching: reply matched (T=0x2b2284b9e440)!
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: t_check: end=0x2b2284b9e440
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: this is the second via
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.0>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK7ca3569c>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_body : content_length=235
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: found end of header
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=40
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: force_rtp_proxy2: proxy reply: 0
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: force_rtp_proxy2: incorrect port 0 in reply from rtp proxy
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=80
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:tm:t_should_relay_response: T_code=180, new_code=200
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: old size: 1117, new size: 1064
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: build_res_from_sip_res: copied size: orig:708, new: 655, rest: 409 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK7ca3569c;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Record-Route: <sip:64.24.35.216;lr=on;ftag=as7b808a8a> 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=- 313616 313616 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16392 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:40:20 log /usr/local/sbin/openser[3162]: DEBUG: add_to_tail_of_timer[2]: 0x2b2284b9e4c0 (26)
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:tm:relay_reply: sent buf=0x64dfc0: SIP/2.0 2..., shmem=0x2b2284ba2528: SIP/2.0 2
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: receive_msg: cleaning up
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: SIP Request:
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: method: <ACK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: uri: <sip:9492666205@OpenSER:5060;nat=yes>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: version: <SIP/2.0>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: this is the first via
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: After parse_msg...
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: preparing to run routing scripts...
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.2>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: this is the second via
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK2a457b3a>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=80
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=200
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: is_preloaded: No
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as7b808a8a' is loose router
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: found end of header
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: subst_run: running. r=1
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: subst_str: no match
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: -------branch=0, branch flags=00000000
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=78
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: t_lookup_request: start searching: hash=27428, isACK=1
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=38
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: t_lookup_request: e2e proxy ACK found
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:tm:t_newtran: building branch for end2end ACK
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DBG:check_against_rule_list: using list dns
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as7b808a8a SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK42b6.e610f031.3 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.2 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK2a457b3a;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:forward_request: orig. len=647, new_len=744, proto=1
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: receive_msg: cleaning up
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: SIP Request:
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: method: <ACK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: uri: <sip:OpenSER;lr=on;ftag=as7b808a8a>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: version: <SIP/2.0>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.3>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: this is the first via
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: After parse_msg...
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: preparing to run routing scripts...
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: this is the second via
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.2>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK2a457b3a>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=80
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=200
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: found end of header
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: find_first_route: No Route headers found
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: loose_route: There is no Route HF
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: lookup(): '' Not found in usrloc
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: receive_msg: cleaning up
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: SIP Reply (status):
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: version: <SIP/2.0>
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: status: <200>
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: reason: <OK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.0>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: this is the first via
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: After parse_msg...
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: flags=22
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: flags=8
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: t_reply_matching: hash 27428 label 319750510 branch 0
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: t_reply_matching: reply matched (T=0x2b2284b9e440)!
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: t_check: end=0x2b2284b9e440
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:tm:reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=1)
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: this is the second via
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.0>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK7ca3569c>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_body : content_length=235
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: found end of header
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: flags=40
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: force_rtp_proxy2: proxy reply: 0
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: force_rtp_proxy2: incorrect port 0 in reply from rtp proxy
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: parse_headers: flags=80
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:tm:t_should_relay_response: T_code=200, new_code=200
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: old size: 1117, new size: 1064
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: build_res_from_sip_res: copied size: orig:708, new: 655, rest: 409 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK7ca3569c;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Record-Route: <sip:64.24.35.216;lr=on;ftag=as7b808a8a> 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=- 313616 313616 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16392 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:40:20 log /usr/local/sbin/openser[3157]: DEBUG:tm:relay_reply: sent buf=0x64d930: SIP/2.0 2..., shmem=0x2b2284ba2528: SIP/2.0 2
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:20 log /usr/local/sbin/openser[3157]: receive_msg: cleaning up
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: SIP Request:
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: method: <ACK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: uri: <sip:9492666205@OpenSER:5060;nat=yes>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: version: <SIP/2.0>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: this is the first via
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: After parse_msg...
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: preparing to run routing scripts...
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.2>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: this is the second via
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK6d1ad44e>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=80
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=200
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: is_preloaded: No
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as7b808a8a' is loose router
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: found end of header
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: subst_run: running. r=1
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: subst_str: no match
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: -------branch=0, branch flags=00000000
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=78
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: t_lookup_request: start searching: hash=27428, isACK=1
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: parse_headers: flags=38
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: t_lookup_request: e2e proxy ACK found
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:tm:t_newtran: building branch for end2end ACK
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DBG:check_against_rule_list: using list dns
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as7b808a8a SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK42b6.e610f031.3 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.2 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK6d1ad44e;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:forward_request: orig. len=647, new_len=744, proto=1
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: SIP Request:
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: method: <ACK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: uri: <sip:OpenSER;lr=on;ftag=as7b808a8a>
Apr 27 04:40:20 log /usr/local/sbin/openser[3164]: receive_msg: cleaning up
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: version: <SIP/2.0>
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.3>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=2
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: this is the first via
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: After parse_msg...
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: preparing to run routing scripts...
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: this is the second via
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.2>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK6d1ad44e>; state=6
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=80
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: parse_headers: flags=200
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: found end of header
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: find_first_route: No Route headers found
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: loose_route: There is no Route HF
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: lookup(): '' Not found in usrloc
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:20 log /usr/local/sbin/openser[3162]: receive_msg: cleaning up
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: SIP Request:
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: method: <NOTIFY>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: uri: <sip:sip2.demo.com>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: version: <SIP/2.0>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=2
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK-c554ce9c>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=2
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: this is the first via
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: After parse_msg...
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: preparing to run routing scripts...
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=100
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=10
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={}, ruri={sip:sip2.demo.com}
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:sip2.demo.com]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: to body [<sip:sip2.demo.com> ]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: get_hdr_field: cseq <CSeq>: <532> <NOTIFY>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:maxfwd:is_maxfwd_present: value = 70
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=80
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: found end of header
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=afbb92f48b3b9d9bo0
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={demo NM}, ruri={sip:5057965751@sip2.demo.com}
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=200
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: find_first_route: No Route headers found
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: loose_route: There is no Route HF
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 14==9 && [sip2.demo.com] == [127.0.0.1]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 14==11 && [sip2.demo.com] == [OpenSER]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: lookup(): '' Not found in usrloc
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: check_via_address(71.220.244.225, 192.168.1.170, 0)
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: receive_msg: cleaning up
Apr 27 04:40:21 log /usr/local/sbin/openser[3167]: DEBUG: timer routine:6,tl=0x2b2284b9e818 next=(nil), timeout=22500000
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: SIP Reply (status):
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: version: <SIP/2.0>
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: status: <200>
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: reason: <OK>
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: flags=2
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.0>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=2
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: this is the first via
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: After parse_msg...
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: flags=22
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: flags=8
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: t_reply_matching: hash 27428 label 319750510 branch 0
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: t_reply_matching: reply matched (T=0x2b2284b9e440)!
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: t_check: end=0x2b2284b9e440
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:tm:reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=1)
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: this is the second via
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.0>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: Found param type 232, <branch> = <z9hG4bK7ca3569c>; state=6
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: get_hdr_body : content_length=235
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: found end of header
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: flags=40
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: force_rtp_proxy2: proxy reply: 0
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: force_rtp_proxy2: incorrect port 0 in reply from rtp proxy
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: parse_headers: flags=80
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:tm:t_should_relay_response: T_code=200, new_code=200
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: old size: 1117, new size: 1064
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: build_res_from_sip_res: copied size: orig:708, new: 655, rest: 409 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK7ca3569c;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Record-Route: <sip:64.24.35.216;lr=on;ftag=as7b808a8a> 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=- 313616 313616 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16392 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:40:21 log /usr/local/sbin/openser[3159]: DEBUG:tm:relay_reply: sent buf=0x64dfc0: SIP/2.0 2..., shmem=0x2b2284ba2528: SIP/2.0 2
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:21 log /usr/local/sbin/openser[3159]: receive_msg: cleaning up
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: SIP Request:
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: method: <ACK>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: uri: <sip:9492666205@OpenSER:5060;nat=yes>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: version: <SIP/2.0>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=2
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=2
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: this is the first via
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: After parse_msg...
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: preparing to run routing scripts...
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=8
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.2>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=8
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: this is the second via
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK184a552f>; state=6
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=8
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=100
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=80
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=200
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: is_preloaded: No
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as7b808a8a' is loose router
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: found end of header
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: subst_run: running. r=1
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: subst_str: no match
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: -------branch=0, branch flags=00000000
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=78
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: t_lookup_request: start searching: hash=27428, isACK=1
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=38
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: t_lookup_request: e2e proxy ACK found
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:tm:t_newtran: building branch for end2end ACK
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DBG:check_against_rule_list: using list dns
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as7b808a8a SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK42b6.e610f031.3 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.2 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK184a552f;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:forward_request: orig. len=647, new_len=744, proto=1
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: receive_msg: cleaning up
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: SIP Request:
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: method: <ACK>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: uri: <sip:OpenSER;lr=on;ftag=as7b808a8a>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: version: <SIP/2.0>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=2
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.3>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=2
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: this is the first via
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: After parse_msg...
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: preparing to run routing scripts...
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=8
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=8
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: this is the second via
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.2>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=8
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK184a552f>; state=6
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=8
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=100
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=80
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: parse_headers: flags=200
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: found end of header
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: find_first_route: No Route headers found
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: loose_route: There is no Route HF
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: lookup(): '' Not found in usrloc
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:21 log /usr/local/sbin/openser[3157]: receive_msg: cleaning up
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: SIP Reply (status):
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: version: <SIP/2.0>
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: status: <200>
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: reason: <OK>
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: flags=2
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.0>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=2
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: this is the first via
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: After parse_msg...
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: flags=22
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: flags=8
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: t_reply_matching: hash 27428 label 319750510 branch 0
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: t_reply_matching: reply matched (T=0x2b2284b9e440)!
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: t_check: end=0x2b2284b9e440
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:tm:reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=1)
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: this is the second via
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.0>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK7ca3569c>; state=6
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=ffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_body : content_length=235
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: found end of header
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:check_content_type: type <application/sdp> found valid
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: flags=40
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: force_rtp_proxy2: proxy reply: 0
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: force_rtp_proxy2: incorrect port 0 in reply from rtp proxy
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: parse_headers: flags=80
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:tm:t_should_relay_response: T_code=200, new_code=200
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: old size: 1117, new size: 1064
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: build_res_from_sip_res: copied size: orig:708, new: 655, rest: 409 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK7ca3569c;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Record-Route: <sip:64.24.35.216;lr=on;ftag=as7b808a8a> 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=- 313616 313616 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16392 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:40:23 log /usr/local/sbin/openser[3162]: DEBUG:tm:relay_reply: sent buf=0x64dfc0: SIP/2.0 2..., shmem=0x2b2284ba2528: SIP/2.0 2
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:23 log /usr/local/sbin/openser[3162]: receive_msg: cleaning up
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: SIP Request:
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: method: <ACK>
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: uri: <sip:9492666205@OpenSER:5060;nat=yes>
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: version: <SIP/2.0>
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=2
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=2
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: this is the first via
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: After parse_msg...
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: preparing to run routing scripts...
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=100
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.2>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: this is the second via
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK781b9af3>; state=6
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=80
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=200
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: is_preloaded: No
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as7b808a8a' is loose router
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: found end of header
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: subst_run: running. r=1
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: subst_str: no match
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: -------branch=0, branch flags=00000000
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=78
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: t_lookup_request: start searching: hash=27428, isACK=1
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=38
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:tm:REF_UNSAFE: after is 1
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: t_lookup_request: e2e proxy ACK found
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:tm:t_newtran: building branch for end2end ACK
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DBG:check_against_rule_list: using list dns
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as7b808a8a SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK42b6.e610f031.3 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.2 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK781b9af3;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:forward_request: orig. len=647, new_len=744, proto=1
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:tm:UNREF_UNSAFE: after is 0
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: receive_msg: cleaning up
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: SIP Request:
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: method: <ACK>
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: uri: <sip:OpenSER;lr=on;ftag=as7b808a8a>
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: version: <SIP/2.0>
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=2
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.3>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=2
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: this is the first via
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: After parse_msg...
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: preparing to run routing scripts...
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=100
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: this is the second via
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK42b6.f86a77f.2>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 232, <branch> = <z9hG4bK781b9af3>; state=6
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: end of header reached, state=5
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: Via found, flags=100
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=80
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: parse_headers: flags=200
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: found end of header
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: find_first_route: No Route headers found
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: loose_route: There is no Route HF
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: lookup(): '' Not found in usrloc
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:23 log /usr/local/sbin/openser[3164]: receive_msg: cleaning up
Apr 27 04:40:25 log /usr/local/sbin/openser[3167]: DEBUG: timer routine:2,tl=0x2b2284b9e4c0 next=(nil), timeout=26
Apr 27 04:40:25 log /usr/local/sbin/openser[3167]: DEBUG: wait_handler : removing 0x2b2284b9e440 from table
Apr 27 04:40:25 log /usr/local/sbin/openser[3167]: DEBUG: delete transaction 0x2b2284b9e440
Apr 27 04:40:25 log /usr/local/sbin/openser[3167]: DEBUG: wait_handler : done
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: SIP Reply (status):
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: version: <SIP/2.0>
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: status: <200>
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: reason: <OK>
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: parse_headers: flags=2
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: get_hdr_field: cseq <CSeq>: <102> <INVITE>
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e610f031.0>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=2
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: parse_headers: this is the first via
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: After parse_msg...
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG:forward_reply: found module nathelper, passing reply to it
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG:forward_reply: found module tm, passing reply to it
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG: t_check: start=0xffffffffffffffff
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: parse_headers: flags=22
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: parse_headers: flags=8
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG: t_reply_matching: hash 27428 label 319750510 branch 0
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG: t_reply_matching: no matching transaction exists
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG: t_reply_matching: failure to match a transaction
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG: t_check: end=(nil)
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: parse_headers: flags=4
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.0>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: parse_headers: Via found, flags=4
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: parse_headers: this is the second via
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: old size: 1117, new size: 1057
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: build_res_from_sip_res: copied size: orig:271, new: 211, rest: 846 msg= SIP/2.0 200 OK To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 INVITE Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.0 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=z9hG4bK42b6.f86a77f.0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK7ca3569c;rport=5060 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Record-Route: <sip:64.24.35.216;lr=on;ftag=as7b808a8a> Contact: John Doe <sip:9492666205@192.168.1.102:5060> 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=- 313616 313616 IN IP4 192.168.1.102 s=- c=IN IP4 192.168.1.102 t=0 0 m=audio 16392 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:40:27 log /usr/local/sbin/openser[3157]: DEBUG:update_sock_struct_from_via: using 'rport'
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG:update_sock_struct_from_via: using via host
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG:update_sock_struct_from_via: trying SRV lookup
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG:forward_reply: reply forwarded to Gateway:0
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:27 log /usr/local/sbin/openser[3157]: receive_msg: cleaning up
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: SIP Request:
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: method: <ACK>
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: uri: <sip:9492666205@OpenSER:5060>
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: version: <SIP/2.0>
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=2
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=2
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: this is the first via
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: After parse_msg...
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: preparing to run routing scripts...
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=100
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <0>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: this is the second via
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK72e1e2fe>; state=6
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:maxfwd:is_maxfwd_present: value = 68
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=80
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=200
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: is_preloaded: No
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: after_strict: Next hop: 'sip:OpenSER;lr=on;ftag=as7b808a8a' is loose router
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: found end of header
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: rewrite_uri: Rewriting Request-URI with 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: after_strict: The last route URI: 'sip:OpenSER;lr=on;ftag=as7b808a8a'
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: subst_run: running. r=1
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: subst_str: no match
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: -------branch=0, branch flags=00000000
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=ffffffffffffffff
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=78
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: t_lookup_request: start searching: hash=27428, isACK=1
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: RFC3261 transaction matching failed
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: t_lookup_request: no transaction found
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:tm:t_relay: forwarding ACK
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: mk_proxy: doing DNS lookup...
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: check_via_address(Gateway, Gateway, 0)
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DBG:check_against_rule_list: using list dns
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:forward_request: sending: ACK sip:OpenSER;lr=on;ftag=as7b808a8a SIP/2.0 Record-Route: <sip:OpenSER;lr=on;ftag=as7b808a8a> Record-Route: <sip:Gateway;lr=on;ftag=as7b808a8a> Via: SIP/2.0/UDP OpenSER;branch=z9hG4bK42b6.e7d05087.2 Via: SIP/2.0/UDP Gateway;rport=5060;branch=z9hG4bK42b6.e7d05087.2 Via: SIP/2.0/UDP 64.24.35.216;rport=5060;branch=0 Via: SIP/2.0/UDP 64.24.35.73:5060;branch=z9hG4bK72e1e2fe;rport=5060 From: "7135178240" <sip:7135178240@64.24.35.73>;tag=as7b808a8a To: <sip:9492666205@64.24.35.216>;tag=65396076d1b82591i0 Contact: <sip:7135178240@64.24.35.73> Call-ID: 12bb67c3553a51ad0406f7aa5e5cdd43@64.24.35.73 CSeq: 102 ACK Max-Forwards: 67 Content-Length: 0 P-hint: rr-enforced P-hint: rr-enforced .
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:forward_request: orig. len=619, new_len=724, proto=1
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: receive_msg: cleaning up
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: SIP Request:
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: method: <ACK>
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: uri: <sip:OpenSER;lr=on;ftag=as7b808a8a>
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: version: <SIP/2.0>
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=2
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=2
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: this is the first via
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: After parse_msg...
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: preparing to run routing scripts...
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG : sl_filter_ACK: to late to be a local ACK!
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=100
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK42b6.e7d05087.2>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: this is the second via
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=6
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <0>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 232, <branch> = <z9hG4bK72e1e2fe>; state=6
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: Found param type 235, <rport> = <5060>; state=16
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: end of header reached, state=5
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: Via found, flags=100
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=65396076d1b82591i0
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={}, ruri={sip:9492666205@64.24.35.216}
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_field: <To> [54]; uri=[sip:9492666205@64.24.35.216]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: to body [<sip:9492666205@64.24.35.216>]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: get_hdr_field: cseq <CSeq>: <102> <ACK>
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:maxfwd:is_maxfwd_present: value = 67
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: check_via_address(OpenSER, OpenSER, 0)
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=80
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: add_param: tag=as7b808a8a
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:parse_to:end of header reached, state=29
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DBUG:parse_to: display={"7135178240"}, ruri={sip:7135178240@64.24.35.73}
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: parse_headers: flags=200
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG: get_hdr_body : content_length=0
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: found end of header
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: find_first_route: No Route headers found
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: loose_route: There is no Route HF
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==9 && [OpenSER] == [127.0.0.1]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if host==us: 11==11 && [OpenSER] == [OpenSER]
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: grep_sock_info - checking if port 5060 matches port 5060
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: lookup(): '' Not found in usrloc
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: DEBUG:destroy_avp_list: destroying list (nil)
Apr 27 04:40:27 log /usr/local/sbin/openser[3162]: receive_msg: cleaning up