May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: SIP Request:
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: method: <INVITE>
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: uri: <sip:*721111111111@sip.demo.com:5060>
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: version: <SIP/2.0>
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: Found param type 235, <rport> = <n/a>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: Found param type 232, <branch> = <z9hG4bKc0a8007e000000ae464b1024000009d60000062b>; state=16
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: end of header reached, state=5
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: Via found, flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: this is the first via
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: After parse_msg...
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: preparing to run routing scripts...
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=100
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG: get_hdr_body : content_length=339
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: get_hdr_field: cseq <CSeq>: <1> <INVITE>
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG:maxfwd:is_maxfwd_present: value = 70
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: comp_scriptvar: str 20 : UAC
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=8
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG:parse_to:end of header reached, state=10
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DBUG:parse_to: display={}, ruri={sip:*721111111111@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG: get_hdr_field: <To> [41]; uri=[sip:*721111111111@sip.demo.com:5060]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG: to body [<sip:*721111111111@sip.demo.com:5060> ]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: comp_scriptvar: str 20 : 13
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG: add_param: tag=2140826409449
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG:parse_to:end of header reached, state=29
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DBUG:parse_to: display={"unknown"}, ruri={sip:9492666205@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: comp_scriptvar: str 20 : 10
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: check_via_address(UAC, 192.168.0.126, 0)
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: found end of header
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG:check_content_type: type <application/sdp> found valid
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=40
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: force_rtp_proxy2: proxy reply: 37950
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=200
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: find_first_route: No Route headers found
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: loose_route: There is no Route HF
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if host==us: 14==9 && [sip.demo.com] == [127.0.0.1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if host==us: 14==11 && [sip.demo.com] == [OpenSER]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if host==us: 14==9 && [sip.demo.com] == [127.0.0.1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if host==us: 14==11 && [sip.demo.com] == [OpenSER]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: lookup(): '*721111111111' Not found in usrloc
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if host==us: 14==9 && [sip.demo.com] == [127.0.0.1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if host==us: 14==11 && [sip.demo.com] == [OpenSER]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if host==us: 14==9 && [sip.demo.com] == [127.0.0.1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if host==us: 14==11 && [sip.demo.com] == [OpenSER]
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: does_uri_exit(): User in request uri does not exist
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=80
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=10000
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: pre_auth(): Credentials with given realm not found
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: build_auth_hf(): 'Proxy-Authenticate: Digest realm="sip.demo.com", nonce="464b120f8ef9308ce7ad57d2d140ad4a24d7462f", qop="auth" '
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: check_via_address(UAC, 192.168.0.126, 0)
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: DEBUG:destroy_avp_list: destroying list 0x2b2b3a9caf20
May 16 09:10:43 hostname /usr/local/sbin/openser[19433]: receive_msg: cleaning up
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: SIP Request:
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: method: <ACK>
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: uri: <sip:*721111111111@sip.demo.com:5060>
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: version: <SIP/2.0>
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: parse_headers: flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: Found param type 235, <rport> = <n/a>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: Found param type 232, <branch> = <z9hG4bKc0a8007e000000ae464b1024000009d60000062b>; state=16
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: end of header reached, state=5
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: parse_headers: Via found, flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: parse_headers: this is the first via
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: After parse_msg...
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: preparing to run routing scripts...
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: parse_headers: flags=8
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: get_hdr_body : content_length=0
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: get_hdr_field: cseq <CSeq>: <1> <ACK>
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: add_param: tag=329cfeaa6ded039da25ff8cbb8668bd2.1c03
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG:parse_to:end of header reached, state=29
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DBUG:parse_to: display={}, ruri={sip:*721111111111@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: get_hdr_field: <To> [83]; uri=[sip:*721111111111@sip.demo.com:5060]
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: to body [<sip:*721111111111@sip.demo.com:5060>]
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: sl_filter_ACK : local ACK found -> dropping it!
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG:destroy_avp_list: destroying list (nil)
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: receive_msg: cleaning up
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: SIP Request:
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: method: <INVITE>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: uri: <sip:*721111111111@sip.demo.com:5060>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: version: <SIP/2.0>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 235, <rport> = <n/a>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 232, <branch> = <z9hG4bKc0a8007e000000ae464b1024000028270000062c>; state=16
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: end of header reached, state=5
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: Via found, flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: this is the first via
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: After parse_msg...
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: preparing to run routing scripts...
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=100
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: get_hdr_body : content_length=339
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: get_hdr_field: cseq <CSeq>: <2> <INVITE>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:maxfwd:is_maxfwd_present: value = 70
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: comp_scriptvar: str 20 : UAC
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=8
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:parse_to:end of header reached, state=10
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBUG:parse_to: display={}, ruri={sip:*721111111111@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: get_hdr_field: <To> [41]; uri=[sip:*721111111111@sip.demo.com:5060]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: to body [<sip:*721111111111@sip.demo.com:5060> ]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: comp_scriptvar: str 20 : 13
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: add_param: tag=2140826409449
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:parse_to:end of header reached, state=29
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBUG:parse_to: display={"unknown"}, ruri={sip:9492666205@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: comp_scriptvar: str 20 : 10
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: check_via_address(UAC, 192.168.0.126, 0)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: found end of header
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:check_content_type: type <application/sdp> found valid
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=40
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: force_rtp_proxy2: proxy reply: 37950
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=200
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: find_first_route: No Route headers found
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: loose_route: There is no Route HF
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if host==us: 14==9 && [sip.demo.com] == [127.0.0.1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if host==us: 14==11 && [sip.demo.com] == [OpenSER]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if host==us: 14==9 && [sip.demo.com] == [127.0.0.1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if host==us: 14==11 && [sip.demo.com] == [OpenSER]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: lookup(): '*721111111111' Not found in usrloc
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if host==us: 14==9 && [sip.demo.com] == [127.0.0.1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if host==us: 14==11 && [sip.demo.com] == [OpenSER]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if host==us: 14==9 && [sip.demo.com] == [127.0.0.1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if host==us: 14==11 && [sip.demo.com] == [OpenSER]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: grep_sock_info - checking if port 5060 matches port 5060
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: does_uri_exit(): User in request uri does not exist
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=80
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: check_nonce(): comparing [464b120f8ef9308ce7ad57d2d140ad4a24d7462f] and [464b120f8ef9308ce7ad57d2d140ad4a24d7462f]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: check_response(): Our result = '2d9de0c9d943461637cb74427d67de5b'
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: check_response(): Authorization is OK
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: avpops:ops_dbquery_avps: query [SELECT id FROM accounts WHERE username = '9492666205']
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: avpops:db_query_avp: rows [1]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: avpops:db_query_avp: row [0]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: close avp query
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: tr_eval_string: i=0 j=3
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: tr_eval_string: i=3 j=0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: avpops:ops_dbquery_avps: query [UPDATE table.accounts_features SET value = '1', date = NOW() WHERE account_id = '25' AND `key` = 'forward_type']
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: avpops:db_query_avp: no result after query
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: close avp query
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: avpops:ops_dbquery_avps: query [UPDATE table.accounts_features SET value = '1111111111', date = NOW() WHERE account_id = '25' AND `key` = 'forward_phone_num']
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: avpops:db_query_avp: no result after query
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: close avp query
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: MY RU IS sip:call_forward_enable@OpenSER:5070
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_newtran: T on entrance=0xffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=78
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: t_lookup_request: start searching: hash=37830, isACK=0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: RFC3261 transaction matching failed
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_lookup_request: no transaction found
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBG: trans=0x2b2b3a9cafd0, callback type 1, id 0 entered
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=78
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: noisy_timer set for accounting
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:rr:is_direction: param ftag not found
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: check_via_address(UAC, 192.168.0.126, 0)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: WARNING:vqm_resize: resize(0) called
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:_reply_light: reply sent out. buf=0x667728: SIP/2.0 1..., shmem=0x2b2b3a9ce110: SIP/2.0 1
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:_reply_light: finished
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: mk_proxy: doing DNS lookup...
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=2000
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: clen_builder: content-length: 355 (355)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: check_via_address(UAC, 192.168.0.126, 0)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBG:check_against_rule_list: using list dns
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:set_timer: relative timeout is 500000
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: add_to_tail_of_timer[4]: 0x2b2b3a9cb1f0 (10400000)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:set_timer: relative timeout is 30
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: add_to_tail_of_timer[0]: 0x2b2b3a9cb220 (39)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:t_relay_to: new transaction fwd'ed
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: comp_scriptvar: str 20 : 13
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: ERROR:tm:t_forward_nonack: no branch for forwarding
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: ERROR:tm:w_t_relay: t_forward_nonack failed
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:sl:sl_reply_error: error text is Server error occurred (1/SL)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: check_via_address(UAC, 192.168.0.126, 0)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:UNREF_UNSAFE: after is 0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:destroy_avp_list: destroying list (nil)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: receive_msg: cleaning up
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: SIP Reply (status):
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: version: <SIP/2.0>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: status: <100>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: reason: <Trying>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 232, <branch> = <z9hG4bK6c39.1a0f1602.0>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 234, <received> = <OpenSER>; state=16
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: end of header reached, state=5
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: Via found, flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: this is the first via
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: After parse_msg...
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:forward_reply: found module nathelper, passing reply to it
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=20
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 234, <received> = <UAC>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 235, <rport> = <5060>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 232, <branch> = <z9hG4bKc0a8007e000000ae464b1024000028270000062c>; state=16
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: end of header reached, state=5
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: Via found, flags=20
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: this is the second via
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:parse_to:end of header reached, state=10
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBUG:parse_to: display={}, ruri={sip:*721111111111@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: get_hdr_field: <To> [41]; uri=[sip:*721111111111@sip.demo.com:5060]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: to body [<sip:*721111111111@sip.demo.com:5060> ]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: get_hdr_field: cseq <CSeq>: <2> <INVITE>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:forward_reply: found module tm, passing reply to it
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_check: start=0xffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=22
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=8
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_reply_matching: hash 37830 label 543289505 branch 0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:REF_UNSAFE: after is 1
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_reply_matching: reply matched (T=0x2b2b3a9cafd0)!
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBG: trans=0x2b2b3a9cafd0, callback type 2, id 0 entered
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_check: end=0x2b2b3a9cafd0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=80
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:t_should_relay_response: T_code=100, new_code=100
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:relay_reply: branch=0, save=0, relay=-1
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:reply_received: FR_INV_TIMER = 60
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:set_timer: relative timeout is 60
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: add_to_tail_of_timer[1]: 0x2b2b3a9cb220 (69)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:UNREF_UNSAFE: after is 0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:destroy_avp_list: destroying list (nil)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: receive_msg: cleaning up
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: SIP Reply (status):
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: version: <SIP/2.0>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: status: <200>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: reason: <OK>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 232, <branch> = <z9hG4bK6c39.1a0f1602.0>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 234, <received> = <OpenSER>; state=16
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: end of header reached, state=5
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: Via found, flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: this is the first via
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: After parse_msg...
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:forward_reply: found module nathelper, passing reply to it
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=20
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 234, <received> = <UAC>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 235, <rport> = <5060>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: Found param type 232, <branch> = <z9hG4bKc0a8007e000000ae464b1024000028270000062c>; state=16
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: end of header reached, state=5
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: Via found, flags=20
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: this is the second via
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: add_param: tag=as750bde97
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:parse_to:end of header reached, state=29
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBUG:parse_to: display={}, ruri={sip:*721111111111@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: get_hdr_field: <To> [56]; uri=[sip:*721111111111@sip.demo.com:5060]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: to body [<sip:*721111111111@sip.demo.com:5060>]
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: get_hdr_field: cseq <CSeq>: <2> <INVITE>
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:forward_reply: found module tm, passing reply to it
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_check: start=0xffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=22
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=8
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_reply_matching: hash 37830 label 543289505 branch 0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:REF_UNSAFE: after is 1
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_reply_matching: reply matched (T=0x2b2b3a9cafd0)!
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=8
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBG: trans=0x2b2b3a9cafd0, callback type 2, id 0 entered
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=8
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: t_check: end=0x2b2b3a9cafd0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=80
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: get_hdr_body : content_length=285
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: found end of header
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:check_content_type: type <application/sdp> found valid
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=40
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: add_param: tag=2140826409449
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:parse_to:end of header reached, state=29
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBUG:parse_to: display={"unknown"}, ruri={sip:9492666205@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: force_rtp_proxy2: proxy reply: 37952
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:t_should_relay_response: T_code=100, new_code=200
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=2000
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: parse_headers: flags=ffffffffffffffff
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: clen_builder: content-length: 303 (303)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: old size: 992, new size: 929
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: build_res_from_sip_res: copied size: orig:992, new: 929, rest: 0 msg= SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.126;received=UAC;rport=5060;branch=z9hG4bKc0a8007e000000ae464b1024000028270000062c Record-Route: <sip:OpenSER;lr=on;ftag=2140826409449> From: "unknown"<sip:9492666205@sip.demo.com:5060>;tag=2140826409449 To: <sip:*721111111111@sip.demo.com:5060>;tag=as750bde97 Call-ID: 86463016-91CB-495B-99A5-91C369DAC7AD@192.168.0.126 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: <sip:call_forward_enable@OpenSER:5070> Content-Type: application/sdp Content-Length: 303 v=0 o=root 15109 15109 IN IP4 OpenSER s=session c=IN IP4 OpenSER t=0 0 m=audio 37952 RTP/AVP 3 0 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv a=nortpproxy:yes
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: update_totag_set: new totag
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: add_to_tail_of_timer[2]: 0x2b2b3a9cb050 (14)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:relay_reply: sent buf=0x667b38: SIP/2.0 2..., shmem=0x2b2b3a9ce8b8: SIP/2.0 2
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DBG: trans=0x2b2b3a9cafd0, callback type 128, id 0 entered
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: flat_get_connection: Connection not found in the pool
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:tm:UNREF_UNSAFE: after is 0
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: DEBUG:destroy_avp_list: destroying list (nil)
May 16 09:10:43 hostname /usr/local/sbin/openser[19427]: receive_msg: cleaning up
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: SIP Request:
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: method: <ACK>
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: uri: <sip:*721111111111@sip.demo.com:5060>
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: version: <SIP/2.0>
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: parse_headers: flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: Found param type 235, <rport> = <n/a>; state=6
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: Found param type 232, <branch> = <z9hG4bKc0a8007e000000ae464b1024000028270000062c>; state=16
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: end of header reached, state=5
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: parse_headers: Via found, flags=2
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: parse_headers: this is the first via
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: After parse_msg...
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: preparing to run routing scripts...
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: parse_headers: flags=8
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: get_hdr_body : content_length=0
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: get_hdr_field: cseq <CSeq>: <2> <ACK>
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: add_param: tag=329cfeaa6ded039da25ff8cbb8668bd2.4605
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG:parse_to:end of header reached, state=29
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DBUG:parse_to: display={}, ruri={sip:*721111111111@sip.demo.com:5060}
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: get_hdr_field: <To> [83]; uri=[sip:*721111111111@sip.demo.com:5060]
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: to body [<sip:*721111111111@sip.demo.com:5060>]
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG: sl_filter_ACK : local ACK found -> dropping it!
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: DEBUG:destroy_avp_list: destroying list (nil)
May 16 09:10:43 hostname /usr/local/sbin/openser[19435]: receive_msg: cleaning up