-- Logs begin at Sat 1970-01-03 22:42:13 UTC. --
Jan 03 23:13:01 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:01 [22134] DBG:avpops:db_query_avp: no result after query
Jan 03 23:13:01 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:01 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:01 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:01 [22134] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:13:01 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:01 [22134] DBG:core:destroy_avp_list: destroying list 0x74e0bae0
Jan 03 23:13:01 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:01 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:13:01 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:01 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:03 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:03 [22133] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:13:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:03 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:13:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:03 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_handle_req: content-length= 1275
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0abb8, currently in state 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg: SIP Request:
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  method:  <INVITE>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPjffb0391f-59ea-4d12-a4ac-ebdb3ca33a11>; state=6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c700
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c700
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c700
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c700
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: end of header reached, state=10
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: <To> [28]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: ]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: cseq <CSeq>: <4371> <INVITE>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: content_length=1275
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:uri:has_totag: no totag
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_lookup_request: start searching: hash=42991, isACK=0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:grep_sock_info: checking if host==us: 9==13 &&  [127.0.0.1] == [192.168.0.101]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:grep_sock_info: checking if host==us: 9==9 &&  [127.0.0.1] == [127.0.0.1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=10000
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:auth:pre_auth: credentials with given realm not found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:auth:reserve_nonce_index: second= 5, sec_monit= 1,  index= 4
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:auth:build_auth_hf: nonce index= 4
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest realm="localhost", nonce="0003e9ca00000004a196501159f2240cd52f3202f25c7aa3"
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: '
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8) already in this process ( 4 ) , fd = 20
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:proto_tcp_send: sending via fd 20...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=563 fd=20
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:destroy_avp_list: destroying list 0x74e0f268
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: cleaning up
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0abb8, currently in state 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg: SIP Request:
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  method:  <ACK>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPjffb0391f-59ea-4d12-a4ac-ebdb3ca33a11>; state=6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=8
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to_param: tag=eceb1bcf84571fc39d3d39a20adc6c5a.8823
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: <To> [70]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: cleaning up
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_handle_req: content-length= 1275
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0abb8, currently in state 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg: SIP Request:
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  method:  <INVITE>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj8416898b-7449-4cce-ba29-b3f719041a74>; state=6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bf00
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bf00
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bf00
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bf00
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: end of header reached, state=10
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: <To> [28]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: ]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: cseq <CSeq>: <4372> <INVITE>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: content_length=1275
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:uri:has_totag: no totag
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_lookup_request: start searching: hash=42988, isACK=0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:grep_sock_info: checking if host==us: 9==13 &&  [127.0.0.1] == [192.168.0.101]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:grep_sock_info: checking if host==us: 9==9 &&  [127.0.0.1] == [127.0.0.1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:auth:check_nonce: comparing [0003e9ca00000004a196501159f2240cd52f3202f25c7aa3] and [0003e9ca00000004a196501159f2240cd52f3202f25c7aa3]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b81924
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[ha1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:auth:check_response: our result = '92a291c0d38669bed048b645187bc09e'
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:auth:check_response: authorization is OK
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:auth:post_auth: nonce index= 4
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:uri:check_username: Digest username and URI username match
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: int 20 : 0 / 2
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:w_create_dialog2: will ping caller
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:w_create_dialog2: will ping callee
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:w_create_dialog2: bye on timeout activated
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:build_new_dlg: new dialog 0x74e0b4a0 (c=df32560e-3455-466c-bcde-db3869ea035d,f=sip:intercomA_5dtUWgwgqzR6@127.0.0.1,t=sip:g1r2u3p4o5@127.0.0.1,ft=825d1794-6b98-4cc2-aaa0-7516c3e0cd15) on hash 348
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:init_leg_info: route_set , contact sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob, cseq 4372 and bind_addr tcp:127.0.0.1:5060
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:dlg_add_leg_info: set leg 0 for 0x74e0b4a0: tag=<825d1794-6b98-4cc2-aaa0-7516c3e0cd15> rcseq=<0>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:link_dlg: ref dlg 0x74e0b4a0 with 3 -> 3 in h_entry 0x74dde1e4 - 348
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:rr:add_rr_param: adding (;did=c51.3f6ae775)
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:rr:add_rr_param: second RR lump found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_CALL_DURATION']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8dd04
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cbd4)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cbd0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:get_dlg_by_val: dlg in state 1 to check
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:check_dlg_value_unsafe: looking for <caller> with <intercomB_zBajvxWEQVHE>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:check_dlg_value_unsafe: var NOT found!
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:w_get_dlg_info: no dialog found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: [78B blob data]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:new_dlg_val: inserting <caller>=<intercomA_5dtUWgwgqzR6>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:new_dlg_val: inserting <callee>=<g1r2u3p4o5>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [UPDATE GeneralConfigurations set Value = 'yes' where Attribute = 'EXISTS_INTERCOM_CALL']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: od: invalid option -- 'A'
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: BusyBox v1.22.1 (2016-03-29 09:43:20 BRT) multi-call binary.
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Usage: od [-aBbcDdeFfHhIiLlOovXx] [FILE]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp: no result after query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialplan:dp_translate_f: dpid is 0 partition is default
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialplan:dp_get_svalue: searching 15
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialplan:dp_translate_f: input is g1r2u3p4o5
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialplan:dp_translate_f: no information available for dpid 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:sig_usr: SIGCHLD received from 22527 (status=0), ignoring
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:registrar:lookup: found a complete match
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:registrar:lookup: setting as ruri <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:registrar:lookup: looking for branches
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_newtran: transaction on entrance=(nil)
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_lookup_request: start searching: hash=42988, isACK=0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:run_reqin_callbacks: trans=0x74e12634, callback type 1, id 0 entered
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:dlg_onreq: t hash_index = 42988, t label = 674843408
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:_shm_resize: resize(0) called
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8) already in this process ( 4 ) , fd = 20
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:proto_tcp_send: sending via fd 20...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=400 fd=20
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:_reply_light: reply sent out. buf=0x76b8ddb4: SIP/2.0 1..., shmem=0x74e12364: SIP/2.0 1
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:_reply_light: finished
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: new branch at sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select domain from domain where attrs = 'Public']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8dd04
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cab8
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cabc)[0]=[domain]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cab8
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : icchw.jflddns.com.br
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:comp_scriptvar: str 20 : in_another_network
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:do_action_set_adv_address: setting adv address = [icchw.jflddns.com.br]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_PUBLIC_IP']
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8dd04
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8cab8
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8cabc)[0]=[Value]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8cab8
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:parse_headers: flags=2000
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:build_req_buf_from_sip_req: id added: <;i=1>, rcv proto=2
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 4 (22133)
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=19
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=21
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:proto_tcp_send: sending via fd 21...
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=2219 fd=21
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:insert_timer_unsafe: [0]: 0x74e127c4 (436)
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_relay_to: new transaction fwd'ed
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [DELETE FROM acc WHERE time IN (SELECT time FROM acc UNION SELECT time FROM missed_calls ORDER BY time DESC LIMIT 300 OFFSET 150)]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp: no result after query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:ops_dbquery_avps: query [DELETE FROM missed_calls WHERE time IN (SELECT time FROM acc UNION SELECT time FROM missed_calls ORDER BY time DESC LIMIT 300 OFFSET 150)]
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_query_avp: no result after query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e12634] after is 0
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 2 in entry 0x74dde1e4
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:receive_msg: cleaning up
Jan 03 23:13:48 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22130] DBG:mi_fifo:mi_parse_node: end of input tree
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22130] DBG:mi_fifo:mi_fifo_server: done parsing the mi tree
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:48 [22130] DBG:dialog:internal_mi_print_dlgs: printing 0 dialogs, idx=0, cnt=0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_msg:  status:  <100>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_msg:  reason:  <Trying>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKce7a.01b49382.0>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <60395>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 234, <received> = <127.0.0.1>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj8416898b-7449-4cce-ba29-b3f719041a74>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: via found, flags=22
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_to: end of header reached, state=10
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: <To> [28]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: ]
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <4372> <INVITE>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_reply_matching: hash 42988 label 674843408 branch 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e12634] after is 1
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e12634)!
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 2, id 2 entered
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_check: end=0x74e12634
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: content_length=0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_check_status: checked status is <100>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_check_status: checked status is <100>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_should_relay_response: T_code=100, new_code=100
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:relay_reply: branch=0, save=0, relay=-1
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:reply_received: FR_INV_TIMER = 360
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:set_timer: relative timeout is 360
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:insert_timer_unsafe: [1]: 0x74e127c4 (706)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e12634] after is 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Ignoring callid  "df32560e-3455-466c-bcde-db3869ea035d"
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22133] DBG:core:sig_usr: SIGCHLD received from 22506 (status=0), ignoring
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_msg:  status:  <180>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_msg:  reason:  <Ringing>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKce7a.01b49382.0>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <60395>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 234, <received> = <127.0.0.1>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj8416898b-7449-4cce-ba29-b3f719041a74>; state=6
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: via found, flags=22
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_to_param: tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <4372> <INVITE>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_reply_matching: hash 42988 label 674843408 branch 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e12634] after is 1
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e12634)!
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 2, id 2 entered
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_check: end=0x74e12634
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: content_length=0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_check_status: checked status is <180>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_check_status: checked status is <180>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:avpops:ops_dbquery_avps: query [select attr from location where contact like 'sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395%' and username = 'intercomA_5dtUWgwgqzR6']
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c134
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[attr]
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:comp_scriptvar: str 29 : in_another_network
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:comp_scriptvar: str 20 : in_another_network
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_should_relay_response: T_code=100, new_code=180
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 8, id 0 entered
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:dialog:push_reply_in_dialog: 0x74e0b4a0 totag in rpl is <6a19c596239b42d096d0fbeb119d3233> (32)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:dialog:push_reply_in_dialog: new branch with tag <6a19c596239b42d096d0fbeb119d3233>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:dialog:init_leg_info: route_set , contact , cseq 4372 and bind_addr tcp:192.168.0.101:5060
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:dialog:dlg_add_leg_info: set leg 1 for 0x74e0b4a0: tag=<6a19c596239b42d096d0fbeb119d3233> rcseq=<4372>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:parse_headers: flags=2000
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:build_res_buf_from_sip_res:  old size: 745, new size: 643
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:build_res_buf_from_sip_res: copied size: orig:123, new: 21, rest: 622 msg=
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: SIP/2.0 180 Ringing
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 127.0.0.1:60395;rport=60395;received=127.0.0.1;branch=z9hG4bKPj8416898b-7449-4cce-ba29-b3f719041a74;alias
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Record-Route: <sip:icchw.jflddns.com.br;transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Call-ID: df32560e-3455-466c-bcde-db3869ea035d
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: From: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: To: <sip:g1r2u3p4o5@127.0.0.1>;tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: CSeq: 4372 INVITE
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Contact: <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>;+sip.ice
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Content-Length:  0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 64, id 0 entered
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 1 to state 2, due event 2
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8), acquiring fd
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22137] DBG:core:handle_worker: read response= 74e0abb8, 1, fd -1 from 5 (22134)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_conn_get: c= 0x74e0abb8, n=8, Usock=21
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0abb8 n=4 fd=23
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:proto_tcp_send: sending via fd 23...
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=643 fd=23
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:relay_reply: sent buf=0x76b8cb80: SIP/2.0 1..., shmem=0x74e11df8: SIP/2.0 1
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 128, id 1 entered
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:reply_received: FR_INV_TIMER = 360
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:set_timer: relative timeout is 360
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:insert_timer_unsafe: [1]: 0x74e127c4 (706)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e12634] after is 0
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:13:49 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:49 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_handle_req: content-length= 666
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_msg:  status:  <200>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_msg:  reason:  <OK>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKce7a.01b49382.0>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <60395>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 234, <received> = <127.0.0.1>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj8416898b-7449-4cce-ba29-b3f719041a74>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: via found, flags=22
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to_param: tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <4372> <INVITE>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_reply_matching: hash 42988 label 674843408 branch 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e12634] after is 1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e12634)!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 2, id 2 entered
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_check: end=0x74e12634
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: content_length=666
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_check_status: checked status is <200>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:avpops:ops_dbquery_avps: query [select attr from location where contact like 'sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395%' and username = 'intercomA_5dtUWgwgqzR6']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c53c
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c1e4
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c1e8)[0]=[attr]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8c1e4
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:comp_scriptvar: str 29 : in_another_network
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:comp_scriptvar: str 20 : in_another_network
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_should_relay_response: T_code=180, new_code=200
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 8, id 0 entered
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:push_reply_in_dialog: 0x74e0b4a0 totag in rpl is <6a19c596239b42d096d0fbeb119d3233> (32)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:push_reply_in_dialog: branch with tag <6a19c596239b42d096d0fbeb119d3233> already exists
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:push_reply_in_dialog: Skipping 1 ,0, 0, 1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:print_rr_body: current rr is <sip:icchw.jflddns.com.br;transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:print_rr_body: skipping 1 route records
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:print_rr_body: out rr []
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:print_rr_body: we have 1 records
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:dlg_update_routing: dialog 0x74e0b4a0[1]: rr=<> contact=<sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=2000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:build_res_buf_from_sip_res:  old size: 1541, new size: 1439
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:build_res_buf_from_sip_res: copied size: orig:118, new: 16, rest: 1423 msg=
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: SIP/2.0 200 OK
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 127.0.0.1:60395;rport=60395;received=127.0.0.1;branch=z9hG4bKPj8416898b-7449-4cce-ba29-b3f719041a74;alias
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Record-Route: <sip:icchw.jflddns.com.br;transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Call-ID: df32560e-3455-466c-bcde-db3869ea035d
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: From: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: To: <sip:g1r2u3p4o5@127.0.0.1>;tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: CSeq: 4372 INVITE
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Contact: <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>;+sip.ice
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Supported: replaces, 100rel, timer, norefersub
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Session-Expires: 1800;refresher=uac
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Require: timer
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Content-Type: application/sdp
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Content-Length:   666
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: v=0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: o=- 3686656480 3686656482 IN IP4 131.221.240.71
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: s=pjmedia
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: b=AS:352
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: t=0 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=X-nat:1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: m=audio 49259 RTP/AVP 8 96
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: c=IN IP4 131.221.240.71
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: b=TIAS:64000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=rtcp:49262 IN IP4 131.221.240.71
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=sendrecv
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=rtpmap:8 PCMA/8000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=ice-ufrag:43b3443e
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=ice-pwd:37f01890
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=candidate:Sc0a80068 1 UDP 1862270975 131.221.240.71 49259 typ srflx raddr 192.168.0.104 rport 49259
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=candidate:Hc0a80068 1 UDP 1694498815 192.168.0.104 49259 typ host
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=candidate:Sc0a80068 2 UDP 1862270974 131.221.240.71 49262 typ srflx raddr 192.168.0.104 rport 49262
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=candidate:Hc0a80068 2 UDP 1694498814 192.168.0.104 49262 typ host
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=rtpmap:96 telephone-event/8000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=fmtp:96 0-16
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:update_totag_set: new totag
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:insert_timer_unsafe: [2]: 0x74e1267c (353)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 64, id 0 entered
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 2 to state 3, due event 3
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:dlg_onreply: dialog 0x74e0b4a0 confirmed
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:insert_dlg_timer_unsafe: inserting 0x74e0b4dc for 408
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 3
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:insert_ping_timer: Inserted dlg [0x74e0b4a0] in ping timer list
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 4
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8), acquiring fd
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:handle_worker: read response= 74e0abb8, 1, fd -1 from 5 (22134)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_conn_get: c= 0x74e0abb8, n=8, Usock=21
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0abb8 n=4 fd=23
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:proto_tcp_send: sending via fd 23...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=1439 fd=23
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:relay_reply: sent buf=0x76b8d2d0: SIP/2.0 2..., shmem=0x74e0f324: SIP/2.0 2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 128, id 1 entered
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: [73B blob data]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:new_dlg_val: inserting <accX_leg>=<>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: [71B blob data]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:new_dlg_val: inserting <accX_flags>=<>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:new_dlg_val: inserting <accX_table>=<acc>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e12634] after is 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74dde1e4
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:probe_max_sock_buff: getsockopt: snd is initially 327680
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] INFO:core:probe_max_sock_buff: using snd buffer of 320 kb
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 26
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:print_ip: tcpconn_new: new tcp connection to: 131.221.240.71
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:tcpconn_new: on port 52344, proto 2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:tcpconn_add: hashes: 507, 4
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:handle_new_connect: new connection: 0x74e0f084 26 flags: 0006
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:send2child: to tcp child 2 0(22135), 0x74e0f084 rw 1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:handle_io: We have received conn 0x74e0f084 with rw 1 on fd 24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:io_watch_add: [TCP_worker] io_watch_add op (24 on 5) (0x1875e8, 24, 19, 0x74e0f084,1), fd_no=2/1024
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0f084, currently in state 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_msg: SIP Request:
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_msg:  method:  <ACK>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj33580c35-bfac-4e72-bac0-7ba52f6a335b>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: this is the first via
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:sl:sl_filter_ACK: too late to be a local ACK!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c5bc
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c548
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c54c)[0]=[Value]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8c548
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c5bc
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c548
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c54c)[0]=[Value]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8c548
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c5bc
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c548
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c54c)[0]=[Value]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8c548
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c5bc
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c548
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c54c)[0]=[Value]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8c548
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:check_ip_address: params 131.221.240.71, 192.168.0.101, 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to_param: tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: cseq <CSeq>: <4372> <ACK>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: content_length=0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:uri:has_totag: totag found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=200
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:is_preloaded: No
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if host==us: 14==13 &&  [131.221.240.71] == [192.168.0.101]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 56495
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [131.221.240.71] == [127.0.0.1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 56495
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:check_self: host != me
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if host==us: 20==13 &&  [icchw.jflddns.com.br] == [192.168.0.101]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if host==us: 20==9 &&  [icchw.jflddns.com.br] == [127.0.0.1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:after_loose: Topmost route URI: 'sip:icchw.jflddns.com.br;transport=tcp;lr;did=c51.3f6ae775' is me
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=200
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:find_next_route: No next Route HF found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:after_loose: No next URI found!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:run_rr_callbacks: callback id 1 entered with <transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_onroute: route param is 'c51.3f6ae775' (len=12)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:lookup_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:lookup_dlg: dialog id=1467918067 found on entry 348
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=58
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:evi_param_set: adding string param
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:evi_param_set: adding string param
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:evi_param_set: adding int param
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:evi_param_set: adding int param
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 3 to state 4, due event 6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_onroute: sequential request successfully processed (dst_leg=1)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_onroute: dialog_timeout: 60
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_validate_dialog: CSEQ validation passed
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:compare_uris: straight-forward URI match
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_validate_dialog: Remote contact successfully validated
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:get_route_set: Route [sip:icchw.jflddns.com.br;transport=tcp;lr;did=c51.3f6ae775] has been deleted
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_validate_dialog: Route Headers successfully validated
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:check_route_param: params are <;transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:add_rr_param: adding (;nat=yes)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=78
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_lookup_request: start searching: hash=42988, isACK=1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=38
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_lookup_request: REF_UNSAFE:[0x74e12634] after is 1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_lookup_request: e2e proxy ACK found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_newtran: building branch for end2end ACK - flags=1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_relay_to: forwarding ACK
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=2000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:build_req_buf_from_sip_req: id added: <;i=4>, rcv proto=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:forward_request: sending:
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: ACK sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob SIP/2.0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 192.168.0.101:5060;branch=z9hG4bKce7a.01b49382.2;i=4
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 192.168.0.101:52344;received=131.221.240.71;rport=52344;branch=z9hG4bKPj33580c35-bfac-4e72-bac0-7ba52f6a335b;alias
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Max-Forwards: 70
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: From: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: To: <sip:g1r2u3p4o5@127.0.0.1>;tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Call-ID: df32560e-3455-466c-bcde-db3869ea035d
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: CSeq: 4372 ACK
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Content-Length:  0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: .
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:forward_request: orig. len=503, new_len=535, proto=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=23
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 6 (22135)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=25
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:proto_tcp_send: sending via fd 25...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=535 fd=25
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [DELETE FROM acc WHERE time IN (SELECT time FROM acc UNION SELECT time FROM missed_calls ORDER BY time DESC LIMIT 300 OFFSET 150)]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp: no result after query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [DELETE FROM missed_calls WHERE time IN (SELECT time FROM acc UNION SELECT time FROM missed_calls ORDER BY time DESC LIMIT 300 OFFSET 150)]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp: no result after query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x74e12634] after is 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74dde1e4
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:destroy_avp_list: destroying list 0x74e0b45c
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:receive_msg: cleaning up
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_handle_req: content-length= 604
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0f084, currently in state 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_msg: SIP Request:
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_msg:  method:  <UPDATE>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj66c8193c-bf58-45d9-88d9-418a707e7369>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: this is the first via
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:check_ip_address: params 131.221.240.71, 192.168.0.101, 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to_param: tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: cseq <CSeq>: <4373> <UPDATE>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: content_length=604
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:uri:has_totag: totag found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=200
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:is_preloaded: No
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if host==us: 14==13 &&  [131.221.240.71] == [192.168.0.101]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 56495
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [131.221.240.71] == [127.0.0.1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 56495
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:check_self: host != me
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if host==us: 20==13 &&  [icchw.jflddns.com.br] == [192.168.0.101]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if host==us: 20==9 &&  [icchw.jflddns.com.br] == [127.0.0.1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:after_loose: Topmost route URI: 'sip:icchw.jflddns.com.br;transport=tcp;lr;did=c51.3f6ae775' is me
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=200
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:get_hdr_field: found end of header
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:find_next_route: No next Route HF found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:after_loose: No next URI found!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:run_rr_callbacks: callback id 1 entered with <transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_onroute: route param is 'c51.3f6ae775' (len=12)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:lookup_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:lookup_dlg: dialog id=1467918067 found on entry 348
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=58
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 4 to state 4, due event 8
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_onroute: sequential request successfully processed (dst_leg=1)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_onroute: dialog_timeout: 60
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:switch_cseqs: prev_cseq = 4372 for leg 1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_update_cseq: dlg 0x74e0b4a0[1]: cseq is 4373
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_validate_dialog: CSEQ validation passed
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:compare_uris: straight-forward URI match
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_validate_dialog: Remote contact successfully validated
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:get_route_set: Route [sip:icchw.jflddns.com.br;transport=tcp;lr;did=c51.3f6ae775] has been deleted
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:dlg_validate_dialog: Route Headers successfully validated
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:check_route_param: params are <;transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:rr:add_rr_param: adding (;nat=yes)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=78
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_lookup_request: start searching: hash=42989, isACK=0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:run_reqin_callbacks: trans=0x74e0bc08, callback type 1, id 0 entered
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:parse_headers: flags=2000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:build_req_buf_from_sip_req: id added: <;i=4>, rcv proto=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 6 (22135)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=23
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=25
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:proto_tcp_send: sending via fd 25...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=1368 fd=25
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:insert_timer_unsafe: [0]: 0x74e0bd98 (439)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_relay_to: new transaction fwd'ed
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [DELETE FROM acc WHERE time IN (SELECT time FROM acc UNION SELECT time FROM missed_calls ORDER BY time DESC LIMIT 300 OFFSET 150)]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp: no result after query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:ops_dbquery_avps: query [DELETE FROM missed_calls WHERE time IN (SELECT time FROM acc UNION SELECT time FROM missed_calls ORDER BY time DESC LIMIT 300 OFFSET 150)]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_query_avp: no result after query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 5 in entry 0x74dde1e4
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:receive_msg: cleaning up
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22135] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_handle_req: content-length= 456
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_msg:  status:  <200>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_msg:  reason:  <OK>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKde7a.735bba55.0>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 236, <i> = <4>; state=16
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <52344>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj66c8193c-bf58-45d9-88d9-418a707e7369>; state=6
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: via found, flags=22
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to_param: tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <4373> <UPDATE>
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_reply_matching: hash 42989 label 1437316407 branch 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e0bc08] after is 1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e0bc08)!
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_check: end=0x74e0bc08
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:parse_headers: flags=2000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:get_hdr_field: content_length=456
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:build_res_buf_from_sip_res:  old size: 1257, new size: 1162
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:build_res_buf_from_sip_res: copied size: orig:111, new: 16, rest: 1146 msg=
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: SIP/2.0 200 OK
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 192.168.0.101:52344;rport=52344;received=131.221.240.71;branch=z9hG4bKPj66c8193c-bf58-45d9-88d9-418a707e7369;alias
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Call-ID: df32560e-3455-466c-bcde-db3869ea035d
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: From: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: To: <sip:g1r2u3p4o5@127.0.0.1>;tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: CSeq: 4373 UPDATE
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Session-Expires: 1800;refresher=uac
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Require: timer
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Contact: <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>;+sip.ice
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Supported: replaces, 100rel, timer, norefersub
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Content-Type: application/sdp
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Content-Length:   456
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: v=0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: o=- 3686656480 3686656483 IN IP4 192.168.0.104
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: s=pjmedia
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: b=AS:84
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: t=0 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=X-nat:1
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: m=audio 49259 RTP/AVP 8 96
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: c=IN IP4 192.168.0.104
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: b=TIAS:64000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=sendrecv
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=rtpmap:8 PCMA/8000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=ice-ufrag:43b3443e
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=ice-pwd:37f01890
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=rtcp:49262 IN IP4 192.168.0.104
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=candidate:Hc0a80068 1 UDP 1694498815 192.168.0.104 49259 typ host
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=candidate:Hc0a80068 2 UDP 1694498814 192.168.0.104 49262 typ host
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=rtpmap:96 telephone-event/8000
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: a=fmtp:96 0-16
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:_shm_resize: resize(0) called
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:insert_timer_unsafe: [2]: 0x74e0bc50 (354)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_conn_get: tcp connection found (0x74e0f084), acquiring fd
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_conn_get: c= 0x74e0f084, n=8, Usock=21
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22137] DBG:core:handle_worker: read response= 74e0f084, 1, fd -1 from 5 (22134)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0f084 n=4 fd=23
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:proto_tcp_send: sending via fd 23...
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0f084
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:proto_tcp_send: after write: c= 0x74e0f084 n=1162 fd=23
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:relay_reply: sent buf=0x76b8ce14: SIP/2.0 2..., shmem=0x74e0d7b8: SIP/2.0 2
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:13:51 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:51 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:13:55 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:55 [22133] DBG:tm:timer_routine: timer routine:2,tl=0x74e1267c next=(nil), timeout=353
Jan 03 23:13:55 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:55 [22133] DBG:tm:wait_handler: removing 0x74e12634 from table
Jan 03 23:13:55 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:55 [22133] DBG:tm:delete_cell: delete transaction 0x74e12634
Jan 03 23:13:55 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:55 [22133] DBG:dialog:next_state_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74dde1e4
Jan 03 23:13:55 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:55 [22133] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 4 to state 4, due event 1
Jan 03 23:13:55 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:55 [22133] DBG:tm:wait_handler: done
Jan 03 23:13:56 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:56 [22134] DBG:tm:timer_routine: timer routine:2,tl=0x74e0bc50 next=(nil), timeout=354
Jan 03 23:13:56 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:56 [22134] DBG:tm:wait_handler: removing 0x74e0bc08 from table
Jan 03 23:13:56 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:56 [22134] DBG:tm:delete_cell: delete transaction 0x74e0bc08
Jan 03 23:13:56 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:56 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 4096, id 0 entered
Jan 03 23:13:56 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:56 [22134] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 3 in entry 0x74dde1e4
Jan 03 23:13:56 colibri-imx6-jfl opensips[22126]: Jan  3 23:13:56 [22134] DBG:tm:wait_handler: done
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 4
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:send_leg_msg: sending [OPTIONS] to caller (0)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_uac: next_hop=<sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_uac: sending socket is 127.0.0.1
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:dlg2hash: 27027
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:print_request_uri: sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_uac: building sip_msg from buffer
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg: SIP Request:
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  method:  <OPTIONS>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  uri:     <sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK3996.8d07be87.0>; state=16
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to: display={}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: <To> [81]; uri=[sip:intercomA_5dtUWgwgqzR6@127.0.0.1]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: to body [<sip:intercomA_5dtUWgwgqzR6@127.0.0.1>]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: cseq <CSeq>: <1> <OPTIONS>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: content_length=0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: found end of header
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_uac: Change in local route -> rebuilding buffer
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=2000
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:extract_ftc_hdrs: flags = 15
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:extract_ftc_hdrs: hdr 2 extracted as <To: <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:extract_ftc_hdrs: hdr 1 extracted as <From: <sip:g1r2u3p4o5@127.0.0.1>;tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:extract_ftc_hdrs: hdr 8 extracted as <Call-ID: df32560e-3455-466c-bcde-db3869ea035d
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8) already in this process ( 4 ) , fd = 20
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:proto_tcp_send: sending via fd 20...
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=441 fd=20
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:insert_timer_unsafe: [0]: 0x74e0bd98 (450)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74dde1e4
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:send_leg_msg: sending [OPTIONS] to callee (1)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 6
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_uac: next_hop=<sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_uac: sending socket is 192.168.0.101
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:dlg2hash: 42986
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:print_request_uri: sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_uac: building sip_msg from buffer
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg: SIP Request:
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  method:  <OPTIONS>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKae7a.45baa6d3.0>; state=16
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to_param: tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: cseq <CSeq>: <4374> <OPTIONS>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: content_length=0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: found end of header
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_uac: Change in local route -> rebuilding buffer
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=2000
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:extract_ftc_hdrs: flags = 15
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:extract_ftc_hdrs: hdr 2 extracted as <To: <sip:g1r2u3p4o5@127.0.0.1>;tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:extract_ftc_hdrs: hdr 1 extracted as <From: <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:extract_ftc_hdrs: hdr 8 extracted as <Call-ID: df32560e-3455-466c-bcde-db3869ea035d
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 4 (22133)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=19
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=21
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:proto_tcp_send: sending via fd 21...
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=441 fd=21
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:insert_timer_unsafe: [0]: 0x74e127c4 (450)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 5 in entry 0x74dde1e4
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0abb8, currently in state 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  status:  <500>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_msg:  reason:  <Unhandled by dialog usages>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_via_param: found param type 234, <received> = <127.0.0.1>; state=6
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK3996.8d07be87.0>; state=16
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:receive_msg: After parse_msg...
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_check: start=0xffffffff
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_headers: flags=22
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:parse_to: display={}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: <To> [81]; uri=[sip:intercomA_5dtUWgwgqzR6@127.0.0.1]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: to body [<sip:intercomA_5dtUWgwgqzR6@127.0.0.1>]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:get_hdr_field: cseq <CSeq>: <1> <OPTIONS>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_reply_matching: hash 27027 label 2028695768 branch 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e0bc08] after is 1
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_reply_matching: reply matched (T=0x74e0bc08)!
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_check: end=0x74e0bc08
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_should_relay_response: T_code=0, new_code=500
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_pick_branch: picked branch 0, code 500 (prio=700)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=500, flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:local_reply: branch=0, save=0, winner=0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:local_reply: local transaction completed
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 256, id 0 entered
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:dialog:reply_from_caller: Status Code received =  [500]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:insert_timer_unsafe: [2]: 0x74e0bc50 (365)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:receive_msg: cleaning up
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_msg:  status:  <500>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_msg:  reason:  <Unhandled by dialog usages>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKae7a.45baa6d3.0>; state=16
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_to_param: tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <4374> <OPTIONS>
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:t_reply_matching: hash 42986 label 1030400852 branch 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e12634] after is 1
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e12634)!
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:t_check: end=0x74e12634
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:t_should_relay_response: T_code=0, new_code=500
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:t_pick_branch: picked branch 0, code 500 (prio=700)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=500, flags=2
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:local_reply: branch=0, save=0, winner=0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:local_reply: local transaction completed
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 256, id 0 entered
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:dialog:reply_from_callee: Status Code received =  [500]
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:insert_timer_unsafe: [2]: 0x74e1267c (365)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e12634] after is 0
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:14:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:03 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:tm:timer_routine: timer routine:2,tl=0x74e0bc50 next=0x74e1267c, timeout=365
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:tm:wait_handler: removing 0x74e0bc08 from table
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:tm:delete_cell: delete transaction 0x74e0bc08
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74dde1e4
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:tm:wait_handler: done
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:tm:timer_routine: timer routine:2,tl=0x74e1267c next=(nil), timeout=365
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:tm:wait_handler: removing 0x74e12634 from table
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:tm:delete_cell: delete transaction 0x74e12634
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 3 in entry 0x74dde1e4
Jan 03 23:14:08 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:08 [22133] DBG:tm:wait_handler: done
Jan 03 23:14:24 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:24 [22135] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:14:24 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:24 [22135] DBG:core:tcp_read: EOF on 0x74e0f084, FD 24
Jan 03 23:14:24 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:24 [22135] DBG:core:tcp_read_req: EOF received
Jan 03 23:14:24 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:24 [22135] DBG:core:io_watch_del: [TCP_worker] io_watch_del op on index 0 24 (0x1875e8, 24, 0, 0x10,0x3) fd_no=3 called
Jan 03 23:14:24 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:24 [22135] DBG:core:tcpconn_release:  releasing con 0x74e0f084, state -1, fd=-1, id=4
Jan 03 23:14:24 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:24 [22135] DBG:core:tcpconn_release:  extra_data (nil)
Jan 03 23:14:24 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:24 [22137] DBG:core:handle_tcp_worker: reader response= 74e0f084, -1 from 2
Jan 03 23:14:24 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:24 [22137] DBG:core:tcpconn_destroy: destroying connection 0x74e0f084, flags 0006
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_msg: SIP Request:
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_msg:  method:  <BYE>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_msg:  uri:     <sip:intercomA_5dtUWgwgqzR6@131.221.240.71:52344;transport=TCP;ob>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPjcc7199e02a3d4f3f98e29cea56fc00b7>; state=6
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bd40
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bd40
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bd40
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bd40
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:check_ip_address: params 131.221.240.71, 131.221.240.71, 0
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_to_param: tag=825d1794-6b98-4cc2-aaa0-7516c3e0cd15
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:get_hdr_field: <To> [87]; uri=[sip:intercomA_5dtUWgwgqzR6@127.0.0.1]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:get_hdr_field: to body ["ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <15804> <BYE>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:get_hdr_field: content_length=0
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:uri:has_totag: totag found
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_headers: flags=200
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:rr:is_preloaded: No
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:grep_sock_info: checking if host==us: 14==13 &&  [131.221.240.71] == [192.168.0.101]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:grep_sock_info: checking if port 5060 matches port 52344
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [131.221.240.71] == [127.0.0.1]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:grep_sock_info: checking if port 5060 matches port 52344
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:check_self: host != me
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:grep_sock_info: checking if host==us: 20==13 &&  [icchw.jflddns.com.br] == [192.168.0.101]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:grep_sock_info: checking if host==us: 20==9 &&  [icchw.jflddns.com.br] == [127.0.0.1]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:rr:after_loose: Topmost route URI: 'sip:icchw.jflddns.com.br;transport=tcp;lr;did=c51.3f6ae775' is me
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_headers: flags=200
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:rr:find_next_route: No next Route HF found
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:rr:after_loose: No next URI found!
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:rr:run_rr_callbacks: callback id 1 entered with <transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:dlg_onroute: route param is 'c51.3f6ae775' (len=12)
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:lookup_dlg: ref dlg 0x74e0b4a0 with 1 -> 4
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:lookup_dlg: dialog id=1467918067 found on entry 348
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_headers: flags=58
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_to_param: tag=6a19c596239b42d096d0fbeb119d3233
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 4 to state 5, due event 7
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:init_dlg_term_reason: Setting DLG term reason to [Upstream BYE]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:dlg_onroute: BYE successfully processed - dst_leg = 0
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:parse_headers: flags=20
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:update_msg_cseq: null str provided. Using only int value for cseq
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:update_msg_cseq: Message CSEQ translated from [15804] to [2]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:run_dlg_callbacks: dialog=0x74e0b4a0, type=32
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:acc:acc_dlg_callback: flags[0x74e0ae54] ref counter value after referencing [1]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_core>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: [68B blob data]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_db>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: [68B blob data]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_leg>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:fetch_dlg_value: var found-> <>!
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_created>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: [70B blob data]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_table>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:fetch_dlg_value: var found-> <acc>!
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 2 -> 2 in entry 0x74dde1e4
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:dialog:dlg_validate_dialog: CSEQ validation passed
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:unescape_user: unescaped string is <intercomA_5dtUWgwgqzR6>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:unescape_user: unescaped string is <intercomA_5dtUWgwgqzR6>
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:compare_uris: Different URI field - host
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] ERROR:dialog:dlg_validate_dialog: failed to validate remote contact: dlg=[sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob] , req=[sip:intercomA_5dtUWgwgqzR6@131.221.240.71:52344;transport=TCP;ob]
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: In-Dialog BYE from 131.221.240.71 (callid=df32560e-3455-466c-bcde-db3869ea035d) is not valid according to dialog
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:14:31 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:31 [22134] DBG:avpops:ops_dbquery_avps: query [UPDATE GeneralConfigurations SET Value='no' WHERE Attribute = 'EXISTS_INTERCOM_CALL']
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:avpops:db_query_avp: no result after query
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:rr:check_route_param: params are <;transport=tcp;lr;did=c51.3f6ae775>
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:parse_headers: flags=78
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:tm:t_lookup_request: start searching: hash=42052, isACK=0
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:tm:run_reqin_callbacks: trans=0x74e12634, callback type 1, id 0 entered
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 3
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:parse_headers: flags=2000
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:build_req_buf_from_sip_req: id added: <;i=2>, rcv proto=2
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:proto_tcp_send: no open tcp connection found, opening new one, async = 1
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: getsockopt: snd is initially 16384
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: trying : 32768
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: setting snd: set=32768,verify=65536
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: trying : 65536
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: setting snd: set=65536,verify=131072
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: trying : 131072
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: setting snd: set=131072,verify=262144
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: trying : 262144
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:probe_max_sock_buff: setting snd: set=262144,verify=327680
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] INFO:core:probe_max_sock_buff: using snd buffer of 320 kb
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 23
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:tcpconn_async_connect: Polling is overdue
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:tcpconn_async_connect: Create connection for async connect
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:print_ip: tcpconn_new: new tcp connection to: 131.221.240.71
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:tcpconn_new: on port 52344, proto 2
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:core:proto_tcp_send: Successfully started async connection
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:tm:insert_timer_unsafe: [0]: 0x74e127c4 (480)
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:tm:t_relay_to: new transaction fwd'ed
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22134] DBG:avpops:ops_dbquery_avps: query [DELETE FROM acc WHERE time IN (SELECT time FROM acc UNION SELECT time FROM missed_calls ORDER BY time DESC LIMIT 300 OFFSET 150)]
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22137] DBG:core:handle_worker: read response= 74e0f084, 3, fd 26 from 5 (22134)
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22137] DBG:core:tcpconn_add: hashes: 507, 5
Jan 03 23:14:32 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:32 [22137] DBG:core:io_watch_add: [TCP_main] io_watch_add op (26 on 5) (0x1875e8, 26, 19, 0x74e0f084,2), fd_no=17/1024
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:avpops:db_query_avp: no result after query
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:avpops:ops_dbquery_avps: query [DELETE FROM missed_calls WHERE time IN (SELECT time FROM acc UNION SELECT time FROM missed_calls ORDER BY time DESC LIMIT 300 OFFSET 150)]
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:avpops:db_query_avp: no result after query
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e12634] after is 0
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 2 in entry 0x74dde1e4
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22133] DBG:dialog:dlg_options_routine: dialog 0x74e0b4a0-df32560e-3455-466c-bcde-db3869ea035d has terminated
Jan 03 23:14:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:14:33 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 1 in entry 0x74dde1e4