-- Logs begin at Sat 1970-01-03 22:42:13 UTC. --
Jan 03 23:10:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:10:03 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:10:03 colibri-imx6-jfl opensips[22126]: Jan  3 23:10:03 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:02 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:02 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:02 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:02 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:02 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:02 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:11:02 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:02 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:05 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:05 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:05 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:05 [22133] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:05 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:05 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:11:05 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:05 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_handle_req: content-length= 1275
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0abb8, currently in state 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg: SIP Request:
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  method:  <INVITE>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPja8fae4b5-47ab-4e1e-a383-b722d30cfe5b>; state=6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bea0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c430
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c434)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8c430
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bea0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c40c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c410)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8c40c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bea0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8bf50
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8bf54)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8bf50
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bea0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c430
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c434)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8c430
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: end of header reached, state=10
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: <To> [28]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: ]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: cseq <CSeq>: <18895> <INVITE>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: content_length=1275
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:uri:has_totag: no totag
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_lookup_request: start searching: hash=14354, isACK=0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:grep_sock_info: checking if host==us: 9==13 &&  [127.0.0.1] == [192.168.0.101]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:grep_sock_info: checking if host==us: 9==9 &&  [127.0.0.1] == [127.0.0.1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=10000
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:auth:pre_auth: credentials with given realm not found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:auth:reserve_nonce_index: second= 6, sec_monit= -1,  index= 2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:auth:build_auth_hf: nonce index= 2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest realm="localhost", nonce="0003e931000000027e1d8ef47a32bffaf7e53d685b1d06d7"
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: '
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8) already in this process ( 4 ) , fd = 20
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:proto_tcp_send: sending via fd 20...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=564 fd=20
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:destroy_avp_list: destroying list 0x74e0ae04
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: cleaning up
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0abb8, currently in state 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg: SIP Request:
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  method:  <ACK>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPja8fae4b5-47ab-4e1e-a383-b722d30cfe5b>; state=6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=8
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to_param: tag=eceb1bcf84571fc39d3d39a20adc6c5a.972b
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: <To> [70]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: cleaning up
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_handle_req: content-length= 1275
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0abb8, currently in state 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg: SIP Request:
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  method:  <INVITE>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj4f17ad4a-7b3b-4e73-b62b-51d4872a987f>; state=6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c3e0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c40c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c410)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8c40c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c3e0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8bf50
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8bf54)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8bf50
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c3e0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c430
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c434)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8c430
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c3e0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c40c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c410)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8c40c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: end of header reached, state=10
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: <To> [28]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: ]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: cseq <CSeq>: <18896> <INVITE>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: content_length=1275
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:uri:has_totag: no totag
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_lookup_request: start searching: hash=14351, isACK=0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:grep_sock_info: checking if host==us: 9==13 &&  [127.0.0.1] == [192.168.0.101]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:grep_sock_info: checking if host==us: 9==9 &&  [127.0.0.1] == [127.0.0.1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:auth:check_nonce: comparing [0003e931000000027e1d8ef47a32bffaf7e53d685b1d06d7] and [0003e931000000027e1d8ef47a32bffaf7e53d685b1d06d7]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bf00
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b818d4
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b818d8)[0]=[ha1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:auth:check_response: our result = '3b3958c274faa2e94260b5c565e90c1b'
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:auth:check_response: authorization is OK
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:auth:post_auth: nonce index= 2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b818d4
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:uri:check_username: Digest username and URI username match
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: int 20 : 0 / 2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:w_create_dialog2: will ping caller
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:w_create_dialog2: will ping callee
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:w_create_dialog2: bye on timeout activated
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:build_new_dlg: new dialog 0x74e0b4a0 (c=62002d5c-2239-4c37-b79d-55d7d8950807,f=sip:intercomA_5dtUWgwgqzR6@127.0.0.1,t=sip:g1r2u3p4o5@127.0.0.1,ft=75c10657-747e-4fd9-bcb6-da450b48f78f) on hash 848
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:init_leg_info: route_set , contact sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob, cseq 18896 and bind_addr tcp:127.0.0.1:5060
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:dlg_add_leg_info: set leg 0 for 0x74e0b4a0: tag=<75c10657-747e-4fd9-bcb6-da450b48f78f> rcseq=<0>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:link_dlg: ref dlg 0x74e0b4a0 with 3 -> 3 in h_entry 0x74de08f4 - 848
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:rr:add_rr_param: adding (;did=053.6bc102e5)
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:rr:add_rr_param: second RR lump found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_CALL_DURATION']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c72c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b817d4
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b817d8)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b817d4
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:get_dlg_by_val: dlg in state 1 to check
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:check_dlg_value_unsafe: looking for <caller> with <intercomB_zBajvxWEQVHE>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:check_dlg_value_unsafe: var NOT found!
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:w_get_dlg_info: no dialog found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: [78B blob data]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:new_dlg_val: inserting <caller>=<intercomA_5dtUWgwgqzR6>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:new_dlg_val: inserting <callee>=<g1r2u3p4o5>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [UPDATE GeneralConfigurations set Value = 'yes' where Attribute = 'EXISTS_INTERCOM_CALL']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: od: invalid option -- 'A'
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: BusyBox v1.22.1 (2016-03-29 09:43:20 BRT) multi-call binary.
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Usage: od [-aBbcDdeFfHhIiLlOovXx] [FILE]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22130] DBG:mi_fifo:mi_parse_node: end of input tree
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22130] DBG:mi_fifo:mi_fifo_server: done parsing the mi tree
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22130] DBG:dialog:internal_mi_print_dlgs: printing 0 dialogs, idx=0, cnt=0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialplan:dp_translate_f: dpid is 0 partition is default
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialplan:dp_get_svalue: searching 15
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialplan:dp_translate_f: input is g1r2u3p4o5
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialplan:dp_translate_f: no information available for dpid 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:sig_usr: SIGCHLD received from 22362 (status=0), ignoring
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:registrar:lookup: found a complete match
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:registrar:lookup: setting as ruri <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:registrar:lookup: looking for branches
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_newtran: transaction on entrance=(nil)
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=78
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_lookup_request: start searching: hash=14351, isACK=0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:run_reqin_callbacks: trans=0x74e0bc08, callback type 1, id 0 entered
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:dlg_onreq: t hash_index = 14351, t label = 959782003
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:_shm_resize: resize(0) called
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8) already in this process ( 4 ) , fd = 20
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:proto_tcp_send: sending via fd 20...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=401 fd=20
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:_reply_light: reply sent out. buf=0x76b8ca54: SIP/2.0 1..., shmem=0x74e0e368: SIP/2.0 1
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:_reply_light: finished
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:buf_init: initializing...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: new branch at sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select domain from domain where attrs = 'Public']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c72c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c758
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c75c)[0]=[domain]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8c758
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:check_ip_address: params 127.0.0.1, 127.0.0.1, 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : icchw.jflddns.com.br
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:comp_scriptvar: str 20 : in_another_network
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:do_action_set_adv_address: setting adv address = [icchw.jflddns.com.br]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_PUBLIC_IP']
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c72c
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8ca78
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8ca7c)[0]=[Value]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:db_free_columns: freeing result columns at 0x76b8ca78
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:parse_headers: flags=2000
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:build_req_buf_from_sip_req: id added: <;i=1>, rcv proto=2
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 4 (22133)
Jan 03 23:11:15 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=19
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=21
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:proto_tcp_send: sending via fd 21...
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=2220 fd=21
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:insert_timer_unsafe: [0]: 0x74e0bd98 (283)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_relay_to: new transaction fwd'ed
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [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:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [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:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 2 in entry 0x74de08f4
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:receive_msg: cleaning up
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:15 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Ignoring callid  "62002d5c-2239-4c37-b79d-55d7d8950807"
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22133] DBG:core:sig_usr: SIGCHLD received from 22340 (status=0), ignoring
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_msg:  status:  <100>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_msg:  reason:  <Trying>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKf083.37c15393.0>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <60395>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 234, <received> = <127.0.0.1>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj4f17ad4a-7b3b-4e73-b62b-51d4872a987f>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: via found, flags=22
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_to: end of header reached, state=10
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: <To> [28]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: ]
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <18896> <INVITE>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_reply_matching: hash 14351 label 959782003 branch 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e0bc08] after is 1
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e0bc08)!
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 2, id 2 entered
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_check: end=0x74e0bc08
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: content_length=0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_check_status: checked status is <100>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_check_status: checked status is <100>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_should_relay_response: T_code=100, new_code=100
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:relay_reply: branch=0, save=0, relay=-1
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:reply_received: FR_INV_TIMER = 360
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:set_timer: relative timeout is 360
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:insert_timer_unsafe: [1]: 0x74e0bd98 (553)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_msg:  status:  <180>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_msg:  reason:  <Ringing>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKf083.37c15393.0>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <60395>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 234, <received> = <127.0.0.1>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj4f17ad4a-7b3b-4e73-b62b-51d4872a987f>; state=6
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: via found, flags=22
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_to_param: tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <18896> <INVITE>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_reply_matching: hash 14351 label 959782003 branch 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e0bc08] after is 1
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e0bc08)!
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 2, id 2 entered
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_check: end=0x74e0bc08
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: content_length=0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_check_status: checked status is <180>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_check_status: checked status is <180>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [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:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c358
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[attr]
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:comp_scriptvar: str 29 : in_another_network
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:comp_scriptvar: str 20 : in_another_network
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_should_relay_response: T_code=100, new_code=180
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 8, id 0 entered
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:dialog:push_reply_in_dialog: 0x74e0b4a0 totag in rpl is <7f0fa23f57764dc3834a3a0b30e4a363> (32)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:dialog:push_reply_in_dialog: new branch with tag <7f0fa23f57764dc3834a3a0b30e4a363>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:dialog:init_leg_info: route_set , contact , cseq 18896 and bind_addr tcp:192.168.0.101:5060
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:dialog:dlg_add_leg_info: set leg 1 for 0x74e0b4a0: tag=<7f0fa23f57764dc3834a3a0b30e4a363> rcseq=<18896>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:parse_headers: flags=2000
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:build_res_buf_from_sip_res:  old size: 746, new size: 644
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:build_res_buf_from_sip_res: copied size: orig:123, new: 21, rest: 623 msg=
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: SIP/2.0 180 Ringing
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 127.0.0.1:60395;rport=60395;received=127.0.0.1;branch=z9hG4bKPj4f17ad4a-7b3b-4e73-b62b-51d4872a987f;alias
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Record-Route: <sip:icchw.jflddns.com.br;transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Call-ID: 62002d5c-2239-4c37-b79d-55d7d8950807
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: From: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: To: <sip:g1r2u3p4o5@127.0.0.1>;tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: CSeq: 18896 INVITE
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Contact: <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>;+sip.ice
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Content-Length:  0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 64, id 0 entered
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 1 to state 2, due event 2
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8), acquiring fd
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22137] DBG:core:handle_worker: read response= 74e0abb8, 1, fd -1 from 5 (22134)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_conn_get: c= 0x74e0abb8, n=8, Usock=21
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0abb8 n=4 fd=23
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:proto_tcp_send: sending via fd 23...
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=644 fd=23
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:relay_reply: sent buf=0x76b8cb80: SIP/2.0 1..., shmem=0x74e0eff0: SIP/2.0 1
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 128, id 1 entered
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:reply_received: FR_INV_TIMER = 360
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:set_timer: relative timeout is 360
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:insert_timer_unsafe: [1]: 0x74e0bd98 (553)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:11:16 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:16 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_handle_req: content-length= 666
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_msg:  status:  <200>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_msg:  reason:  <OK>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKf083.37c15393.0>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <60395>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 234, <received> = <127.0.0.1>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj4f17ad4a-7b3b-4e73-b62b-51d4872a987f>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: via found, flags=22
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to_param: tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <18896> <INVITE>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_reply_matching: hash 14351 label 959782003 branch 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e0bc08] after is 1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e0bc08)!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 2, id 2 entered
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_check: end=0x74e0bc08
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: content_length=666
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_check_status: checked status is <200>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [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:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c578
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[attr]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:comp_scriptvar: str 29 : in_another_network
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:comp_scriptvar: str 20 : in_another_network
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:destroy_index_avp: AVP with the specified index not found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_should_relay_response: T_code=180, new_code=200
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 8, id 0 entered
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:push_reply_in_dialog: 0x74e0b4a0 totag in rpl is <7f0fa23f57764dc3834a3a0b30e4a363> (32)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:push_reply_in_dialog: branch with tag <7f0fa23f57764dc3834a3a0b30e4a363> already exists
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:push_reply_in_dialog: Skipping 1 ,0, 0, 1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:print_rr_body: current rr is <sip:icchw.jflddns.com.br;transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:print_rr_body: skipping 1 route records
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:print_rr_body: out rr []
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:print_rr_body: we have 1 records
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:dlg_update_routing: dialog 0x74e0b4a0[1]: rr=<> contact=<sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=2000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:build_res_buf_from_sip_res:  old size: 1542, new size: 1440
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:build_res_buf_from_sip_res: copied size: orig:118, new: 16, rest: 1424 msg=
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: SIP/2.0 200 OK
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 127.0.0.1:60395;rport=60395;received=127.0.0.1;branch=z9hG4bKPj4f17ad4a-7b3b-4e73-b62b-51d4872a987f;alias
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Record-Route: <sip:icchw.jflddns.com.br;transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Call-ID: 62002d5c-2239-4c37-b79d-55d7d8950807
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: From: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: To: <sip:g1r2u3p4o5@127.0.0.1>;tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: CSeq: 18896 INVITE
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Contact: <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>;+sip.ice
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Supported: replaces, 100rel, timer, norefersub
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Session-Expires: 1800;refresher=uac
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Require: timer
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Content-Type: application/sdp
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Content-Length:   666
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: v=0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: o=- 3686656327 3686656329 IN IP4 131.221.240.71
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: s=pjmedia
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: b=AS:352
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: t=0 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=X-nat:1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: m=audio 49671 RTP/AVP 8 96
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: c=IN IP4 131.221.240.71
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: b=TIAS:64000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=rtcp:49674 IN IP4 131.221.240.71
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=sendrecv
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=rtpmap:8 PCMA/8000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=ice-ufrag:488663ee
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=ice-pwd:51c3564a
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=candidate:Sc0a80068 1 UDP 1862270975 131.221.240.71 49671 typ srflx raddr 192.168.0.104 rport 49671
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=candidate:Hc0a80068 1 UDP 1694498815 192.168.0.104 49671 typ host
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=candidate:Sc0a80068 2 UDP 1862270974 131.221.240.71 49674 typ srflx raddr 192.168.0.104 rport 49674
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=candidate:Hc0a80068 2 UDP 1694498814 192.168.0.104 49674 typ host
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=rtpmap:96 telephone-event/8000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=fmtp:96 0-16
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:update_totag_set: new totag
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:insert_timer_unsafe: [2]: 0x74e0bc50 (200)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 64, id 0 entered
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 2 to state 3, due event 3
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:dlg_onreply: dialog 0x74e0b4a0 confirmed
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:insert_dlg_timer_unsafe: inserting 0x74e0b4dc for 255
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 3
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:insert_ping_timer: Inserted dlg [0x74e0b4a0] in ping timer list
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 4
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8), acquiring fd
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:handle_worker: read response= 74e0abb8, 1, fd -1 from 5 (22134)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_conn_get: c= 0x74e0abb8, n=8, Usock=21
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0abb8 n=4 fd=23
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:proto_tcp_send: sending via fd 23...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=1440 fd=23
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:relay_reply: sent buf=0x76b8d2d0: SIP/2.0 2..., shmem=0x74e0f324: SIP/2.0 2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 128, id 1 entered
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: [73B blob data]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:new_dlg_val: inserting <accX_leg>=<>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: [71B blob data]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:new_dlg_val: inserting <accX_flags>=<>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:new_dlg_val: inserting <accX_table>=<acc>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74de08f4
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:probe_max_sock_buff: getsockopt: snd is initially 327680
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] INFO:core:probe_max_sock_buff: using snd buffer of 320 kb
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 26
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:print_ip: tcpconn_new: new tcp connection to: 131.221.240.71
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:tcpconn_new: on port 54925, proto 2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:tcpconn_add: hashes: 782, 3
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:handle_new_connect: new connection: 0x74e0f084 26 flags: 0006
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:send2child: to tcp child 2 0(22135), 0x74e0f084 rw 1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:handle_io: We have received conn 0x74e0f084 with rw 1 on fd 24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [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:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0f084, currently in state 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_msg: SIP Request:
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_msg:  method:  <ACK>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj65e7e2f0-ffe6-4bb2-a876-509824cb9faf>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: this is the first via
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:sl:sl_filter_ACK: too late to be a local ACK!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:check_ip_address: params 131.221.240.71, 192.168.0.101, 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to_param: tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: cseq <CSeq>: <18896> <ACK>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: content_length=0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:uri:has_totag: totag found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=200
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:is_preloaded: No
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if host==us: 14==13 &&  [131.221.240.71] == [192.168.0.101]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 56495
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [131.221.240.71] == [127.0.0.1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 56495
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:check_self: host != me
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if host==us: 20==13 &&  [icchw.jflddns.com.br] == [192.168.0.101]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if host==us: 20==9 &&  [icchw.jflddns.com.br] == [127.0.0.1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:after_loose: Topmost route URI: 'sip:icchw.jflddns.com.br;transport=tcp;lr;did=053.6bc102e5' is me
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=200
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:find_next_route: No next Route HF found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:after_loose: No next URI found!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:run_rr_callbacks: callback id 1 entered with <transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_onroute: route param is '053.6bc102e5' (len=12)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:lookup_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:lookup_dlg: dialog id=1579162806 found on entry 848
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=58
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:evi_param_set: adding string param
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:evi_param_set: adding string param
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:evi_param_set: adding int param
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:evi_param_set: adding int param
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 3 to state 4, due event 6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_onroute: sequential request successfully processed (dst_leg=1)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_onroute: dialog_timeout: 60
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_validate_dialog: CSEQ validation passed
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:compare_uris: straight-forward URI match
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_validate_dialog: Remote contact successfully validated
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:get_route_set: Route [sip:icchw.jflddns.com.br;transport=tcp;lr;did=053.6bc102e5] has been deleted
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_validate_dialog: Route Headers successfully validated
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:check_route_param: params are <;transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:add_rr_param: adding (;nat=yes)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=78
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_lookup_request: start searching: hash=14351, isACK=1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=38
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_lookup_request: REF_UNSAFE:[0x74e0bc08] after is 1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_lookup_request: e2e proxy ACK found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_newtran: building branch for end2end ACK - flags=1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_relay_to: forwarding ACK
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=2000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:build_req_buf_from_sip_req: id added: <;i=3>, rcv proto=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:forward_request: sending:
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: ACK sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob SIP/2.0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 192.168.0.101:5060;branch=z9hG4bKf083.37c15393.2;i=3
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 192.168.0.101:54925;received=131.221.240.71;rport=54925;branch=z9hG4bKPj65e7e2f0-ffe6-4bb2-a876-509824cb9faf;alias
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Max-Forwards: 70
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: From: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: To: <sip:g1r2u3p4o5@127.0.0.1>;tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Call-ID: 62002d5c-2239-4c37-b79d-55d7d8950807
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: CSeq: 18896 ACK
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Content-Length:  0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: .
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:forward_request: orig. len=504, new_len=536, proto=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 6 (22135)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=23
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=25
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:proto_tcp_send: sending via fd 25...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=536 fd=25
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [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:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [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:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74de08f4
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:destroy_avp_list: destroying list 0x74e0f2d0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:receive_msg: cleaning up
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_handle_req: content-length= 604
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0f084, currently in state 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_msg: SIP Request:
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_msg:  method:  <UPDATE>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPjb93197cc-6e1e-49f1-887a-8bef8ce72bd6>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: this is the first via
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c5bc
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c548
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c54c)[0]=[Value]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8c548
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c5bc
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c548
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c54c)[0]=[Value]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8c548
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c5bc
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c548
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c54c)[0]=[Value]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8c548
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8c5bc
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8c548
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8c54c)[0]=[Value]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:db_free_columns: freeing result columns at 0x76b8c548
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:check_ip_address: params 131.221.240.71, 192.168.0.101, 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to_param: tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: cseq <CSeq>: <18897> <UPDATE>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: content_length=604
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_params: Parsing params for:[+sip.ice]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:uri:has_totag: totag found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=200
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:is_preloaded: No
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if host==us: 14==13 &&  [131.221.240.71] == [192.168.0.101]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 56495
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [131.221.240.71] == [127.0.0.1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 56495
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:check_self: host != me
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if host==us: 20==13 &&  [icchw.jflddns.com.br] == [192.168.0.101]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if host==us: 20==9 &&  [icchw.jflddns.com.br] == [127.0.0.1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:after_loose: Topmost route URI: 'sip:icchw.jflddns.com.br;transport=tcp;lr;did=053.6bc102e5' is me
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=200
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:find_next_route: No next Route HF found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:after_loose: No next URI found!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:run_rr_callbacks: callback id 1 entered with <transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_onroute: route param is '053.6bc102e5' (len=12)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:lookup_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:lookup_dlg: dialog id=1579162806 found on entry 848
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=58
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 4 to state 4, due event 8
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_onroute: sequential request successfully processed (dst_leg=1)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_onroute: dialog_timeout: 60
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:switch_cseqs: prev_cseq = 18896 for leg 1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_update_cseq: dlg 0x74e0b4a0[1]: cseq is 18897
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_validate_dialog: CSEQ validation passed
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:compare_uris: straight-forward URI match
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_validate_dialog: Remote contact successfully validated
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:get_route_set: Route [sip:icchw.jflddns.com.br;transport=tcp;lr;did=053.6bc102e5] has been deleted
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:dlg_validate_dialog: Route Headers successfully validated
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:check_route_param: params are <;transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:rr:add_rr_param: adding (;nat=yes)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=78
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_lookup_request: start searching: hash=14352, isACK=0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:run_reqin_callbacks: trans=0x74e0f8e4, callback type 1, id 0 entered
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:parse_headers: flags=2000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:build_req_buf_from_sip_req: id added: <;i=3>, rcv proto=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 6 (22135)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=23
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=25
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:proto_tcp_send: sending via fd 25...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=1369 fd=25
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:insert_timer_unsafe: [0]: 0x74e0fa74 (285)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_relay_to: new transaction fwd'ed
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [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:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [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:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0f8e4] after is 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 5 in entry 0x74de08f4
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:receive_msg: cleaning up
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22135] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_handle_req: content-length= 456
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_msg:  status:  <200>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_msg:  reason:  <OK>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK0183.91eb4fa5.0>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 236, <i> = <3>; state=16
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <54925>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPjb93197cc-6e1e-49f1-887a-8bef8ce72bd6>; state=6
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: via found, flags=22
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to_param: tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <18897> <UPDATE>
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_reply_matching: hash 14352 label 1525988889 branch 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e0f8e4] after is 1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e0f8e4)!
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_check: end=0x74e0f8e4
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:parse_headers: flags=2000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:get_hdr_field: content_length=456
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:build_res_buf_from_sip_res:  old size: 1258, new size: 1163
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:build_res_buf_from_sip_res: copied size: orig:111, new: 16, rest: 1147 msg=
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: SIP/2.0 200 OK
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 192.168.0.101:54925;rport=54925;received=131.221.240.71;branch=z9hG4bKPjb93197cc-6e1e-49f1-887a-8bef8ce72bd6;alias
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Call-ID: 62002d5c-2239-4c37-b79d-55d7d8950807
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: From: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: To: <sip:g1r2u3p4o5@127.0.0.1>;tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: CSeq: 18897 UPDATE
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Session-Expires: 1800;refresher=uac
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Require: timer
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Contact: <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>;+sip.ice
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Supported: replaces, 100rel, timer, norefersub
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Content-Type: application/sdp
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Content-Length:   456
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: v=0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: o=- 3686656327 3686656330 IN IP4 192.168.0.104
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: s=pjmedia
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: b=AS:84
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: t=0 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=X-nat:1
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: m=audio 49671 RTP/AVP 8 96
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: c=IN IP4 192.168.0.104
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: b=TIAS:64000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=sendrecv
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=rtpmap:8 PCMA/8000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=ice-ufrag:488663ee
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=ice-pwd:51c3564a
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=rtcp:49674 IN IP4 192.168.0.104
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=candidate:Hc0a80068 1 UDP 1694498815 192.168.0.104 49671 typ host
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=candidate:Hc0a80068 2 UDP 1694498814 192.168.0.104 49674 typ host
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=rtpmap:96 telephone-event/8000
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: a=fmtp:96 0-16
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:_shm_resize: resize(0) called
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:insert_timer_unsafe: [2]: 0x74e0f92c (200)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_conn_get: tcp connection found (0x74e0f084), acquiring fd
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_conn_get: c= 0x74e0f084, n=8, Usock=21
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22137] DBG:core:handle_worker: read response= 74e0f084, 1, fd -1 from 5 (22134)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0f084 n=4 fd=23
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:proto_tcp_send: sending via fd 23...
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0f084
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:proto_tcp_send: after write: c= 0x74e0f084 n=1163 fd=23
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:relay_reply: sent buf=0x76b8ce14: SIP/2.0 2..., shmem=0x74e12198: SIP/2.0 2
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0f8e4] after is 0
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:11:18 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:18 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:timer_routine: timer routine:2,tl=0x74e0bc50 next=0x74e0f92c, timeout=200
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:wait_handler: removing 0x74e0bc08 from table
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:delete_cell: delete transaction 0x74e0bc08
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:dialog:next_state_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74de08f4
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 4 to state 4, due event 1
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:wait_handler: done
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:timer_routine: timer routine:2,tl=0x74e0f92c next=(nil), timeout=200
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:wait_handler: removing 0x74e0f8e4 from table
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:delete_cell: delete transaction 0x74e0f8e4
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:run_trans_callbacks: trans=0x74e0f8e4, callback type 4096, id 0 entered
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 3 in entry 0x74de08f4
Jan 03 23:11:23 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:23 [22133] DBG:tm:wait_handler: done
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 4
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:dialog:send_leg_msg: sending [OPTIONS] to caller (0)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:t_uac: next_hop=<sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:t_uac: sending socket is 127.0.0.1
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:dlg2hash: 23433
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:print_request_uri: sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:t_uac: building sip_msg from buffer
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_msg: SIP Request:
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_msg:  method:  <OPTIONS>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_msg:  uri:     <sip:intercomA_5dtUWgwgqzR6@127.0.0.1:60395;transport=TCP;ob>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK98b5.23eeb7a4.0>; state=16
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: this is the first via
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_to: display={}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: <To> [81]; uri=[sip:intercomA_5dtUWgwgqzR6@127.0.0.1]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: to body [<sip:intercomA_5dtUWgwgqzR6@127.0.0.1>]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: cseq <CSeq>: <1> <OPTIONS>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: content_length=0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: flags=78
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:t_uac: Change in local route -> rebuilding buffer
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: flags=2000
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:extract_ftc_hdrs: flags = 15
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:extract_ftc_hdrs: hdr 2 extracted as <To: <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:extract_ftc_hdrs: hdr 1 extracted as <From: <sip:g1r2u3p4o5@127.0.0.1>;tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:extract_ftc_hdrs: hdr 8 extracted as <Call-ID: 62002d5c-2239-4c37-b79d-55d7d8950807
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:tcp_conn_get: tcp connection found (0x74e0abb8), acquiring fd
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22137] DBG:core:handle_worker: read response= 74e0abb8, 1, fd -1 from 7 (22136)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:tcp_conn_get: c= 0x74e0abb8, n=8, Usock=25
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0abb8 n=4 fd=26
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:proto_tcp_send: sending via fd 26...
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0abb8
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:proto_tcp_send: after write: c= 0x74e0abb8 n=441 fd=26
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:insert_timer_unsafe: [0]: 0x74e0fa74 (300)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74de08f4
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:dialog:send_leg_msg: sending [OPTIONS] to callee (1)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 6
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:t_uac: next_hop=<sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:t_uac: sending socket is 192.168.0.101
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:dlg2hash: 14366
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:print_request_uri: sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:t_uac: building sip_msg from buffer
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_msg: SIP Request:
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_msg:  method:  <OPTIONS>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_msg:  uri:     <sip:g1r2u3p4o5@131.221.240.71:56495;transport=TCP;ob>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKe183.127c4cf2.0>; state=16
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: this is the first via
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_to_param: tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: cseq <CSeq>: <18898> <OPTIONS>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: content_length=0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: flags=78
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:t_uac: Change in local route -> rebuilding buffer
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:parse_headers: flags=2000
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:extract_ftc_hdrs: flags = 15
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:extract_ftc_hdrs: hdr 2 extracted as <To: <sip:g1r2u3p4o5@127.0.0.1>;tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:extract_ftc_hdrs: hdr 1 extracted as <From: <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:extract_ftc_hdrs: hdr 8 extracted as <Call-ID: 62002d5c-2239-4c37-b79d-55d7d8950807
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: >
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 7 (22136)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=25
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=26
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:proto_tcp_send: sending via fd 26...
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=442 fd=26
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:tm:insert_timer_unsafe: [0]: 0x74e0bd98 (300)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22136] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 5 in entry 0x74de08f4
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0abb8, currently in state 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_msg:  status:  <500>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_msg:  reason:  <Unhandled by dialog usages>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_headers: flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_via_param: found param type 234, <received> = <127.0.0.1>; state=6
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK98b5.23eeb7a4.0>; state=16
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_headers: this is the first via
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:t_check: start=0xffffffff
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_headers: flags=22
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:parse_to: display={}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:get_hdr_field: <To> [81]; uri=[sip:intercomA_5dtUWgwgqzR6@127.0.0.1]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:get_hdr_field: to body [<sip:intercomA_5dtUWgwgqzR6@127.0.0.1>]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:get_hdr_field: cseq <CSeq>: <1> <OPTIONS>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:t_reply_matching: hash 23433 label 1249635890 branch 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e0f8e4] after is 1
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:t_reply_matching: reply matched (T=0x74e0f8e4)!
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:t_check: end=0x74e0f8e4
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:t_should_relay_response: T_code=0, new_code=500
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:t_pick_branch: picked branch 0, code 500 (prio=700)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=500, flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:local_reply: branch=0, save=0, winner=0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:local_reply: local transaction completed
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:run_trans_callbacks: trans=0x74e0f8e4, callback type 256, id 0 entered
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:dialog:reply_from_caller: Status Code received =  [500]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:insert_timer_unsafe: [2]: 0x74e0f92c (215)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0f8e4] after is 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:receive_msg: cleaning up
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22133] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_msg:  status:  <500>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_msg:  reason:  <Unhandled by dialog usages>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKe183.127c4cf2.0>; state=16
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:t_check: start=0xffffffff
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_headers: flags=22
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_to_param: tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:get_hdr_field: <To> [65]; uri=[sip:g1r2u3p4o5@127.0.0.1]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:get_hdr_field: to body [<sip:g1r2u3p4o5@127.0.0.1>]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <18898> <OPTIONS>
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:t_reply_matching: hash 14366 label 801425185 branch 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e0bc08] after is 1
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:t_reply_matching: reply matched (T=0x74e0bc08)!
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:t_check: end=0x74e0bc08
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:t_should_relay_response: T_code=0, new_code=500
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:t_pick_branch: picked branch 0, code 500 (prio=700)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=500, flags=2
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:local_reply: branch=0, save=0, winner=0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:local_reply: local transaction completed
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:run_trans_callbacks: trans=0x74e0bc08, callback type 256, id 0 entered
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:dialog:reply_from_callee: Status Code received =  [500]
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:insert_timer_unsafe: [2]: 0x74e0bc50 (215)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e0bc08] after is 0
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:11:33 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:33 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0b110, currently in state 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_msg: SIP Request:
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_msg:  method:  <BYE>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_msg:  uri:     <sip:intercomA_5dtUWgwgqzR6@131.221.240.71:54925;transport=TCP;ob>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=2
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPje0a3dc131d1e497b8f4e9af2898637f1>; state=6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: this is the first via
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:receive_msg: preparing to run routing scripts...
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_A_NAME']
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_INTERCOM_B_NAME']
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_MAIN_USER']
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:ops_dbquery_avps: query [select Value from GeneralConfigurations where Attribute = 'CONFIGURATION_SIP_USER']
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_new_result: allocate 28 bytes for result set at 0x76b8bdf8
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_get_columns: 1 columns returned from the query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x76b8be24
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_get_columns: RES_NAMES(0x76b8be28)[0]=[Value]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp_print_results: rows [1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp_print_results: row [0]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:db_free_columns: freeing result columns at 0x76b8be24
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:check_ip_address: params 131.221.240.71, 131.221.240.71, 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:get_hdr_field: <To> [87]; uri=[sip:intercomA_5dtUWgwgqzR6@127.0.0.1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:get_hdr_field: to body ["ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:get_hdr_field: cseq <CSeq>: <32453> <BYE>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:get_hdr_field: content_length=0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:uri:has_totag: totag found
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=200
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:rr:is_preloaded: No
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:grep_sock_info: checking if host==us: 14==13 &&  [131.221.240.71] == [192.168.0.101]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:grep_sock_info: checking if port 5060 matches port 54925
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:grep_sock_info: checking if host==us: 14==9 &&  [131.221.240.71] == [127.0.0.1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:grep_sock_info: checking if port 5060 matches port 54925
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:check_self: host != me
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:grep_sock_info: checking if host==us: 20==13 &&  [icchw.jflddns.com.br] == [192.168.0.101]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:grep_sock_info: checking if host==us: 20==9 &&  [icchw.jflddns.com.br] == [127.0.0.1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:rr:after_loose: Topmost route URI: 'sip:icchw.jflddns.com.br;transport=tcp;lr;did=053.6bc102e5' is me
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=200
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:get_hdr_field: found end of header
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:rr:find_next_route: No next Route HF found
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:rr:after_loose: No next URI found!
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:rr:run_rr_callbacks: callback id 1 entered with <transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:dlg_onroute: route param is '053.6bc102e5' (len=12)
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:lookup_dlg: ref dlg 0x74e0b4a0 with 1 -> 6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:lookup_dlg: dialog id=1579162806 found on entry 848
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=58
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_to_param: tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_to: display={}, ruri={sip:g1r2u3p4o5@127.0.0.1}
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:evi_param_set: adding string param
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:evi_param_set: adding int param
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:next_state_dlg: dialog 0x74e0b4a0 changed from state 4 to state 5, due event 7
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:init_dlg_term_reason: Setting DLG term reason to [Upstream BYE]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:dlg_onroute: BYE successfully processed - dst_leg = 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=20
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:update_msg_cseq: null str provided. Using only int value for cseq
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:update_msg_cseq: Message CSEQ translated from [32453] to [2]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:run_dlg_callbacks: dialog=0x74e0b4a0, type=32
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:acc:acc_dlg_callback: flags[0x74e0ae68] ref counter value after referencing [1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_core>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: [68B blob data]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_db>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: [68B blob data]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_leg>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:fetch_dlg_value: var found-> <>!
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_created>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: [70B blob data]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:fetch_dlg_value: looking for <accX_table>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:fetch_dlg_value: var found-> <acc>!
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 2 -> 4 in entry 0x74de08f4
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:dlg_validate_dialog: CSEQ validation passed
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:unescape_user: unescaped string is <intercomA_5dtUWgwgqzR6>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:unescape_user: unescaped string is <intercomA_5dtUWgwgqzR6>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:compare_uris: Different URI field - host
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [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:54925;transport=TCP;ob]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:buf_init: initializing...
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: In-Dialog BYE from 131.221.240.71 (callid=62002d5c-2239-4c37-b79d-55d7d8950807) is not valid according to dialog
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:comp_scriptvar: str 20 : g1r2u3p4o5
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:comp_scriptvar: str 20 : intercomA_5dtUWgwgqzR6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:ops_dbquery_avps: query [UPDATE GeneralConfigurations SET Value='no' WHERE Attribute = 'EXISTS_INTERCOM_CALL']
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:rr:check_route_param: params are <;transport=tcp;lr;did=053.6bc102e5>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=ffffffffffffffff
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=78
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:tm:t_lookup_request: start searching: hash=9174, isACK=0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:tm:t_lookup_request: no transaction found
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:tm:run_reqin_callbacks: trans=0x74e12634, callback type 1, id 0 entered
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:dialog:ref_dlg: ref dlg 0x74e0b4a0 with 1 -> 5
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:mk_proxy: doing DNS lookup...
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:parse_headers: flags=2000
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:build_req_buf_from_sip_req: id added: <;i=2>, rcv proto=2
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:tcp_conn_get: tcp connection found (0x74e0f084), acquiring fd
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:tcp_conn_get: c= 0x74e0f084, n=8, Usock=21
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22137] DBG:core:handle_worker: read response= 74e0f084, 1, fd -1 from 5 (22134)
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0f084 n=4 fd=23
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:proto_tcp_send: sending via fd 23...
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0f084
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:core:proto_tcp_send: after write: c= 0x74e0f084 n=570 fd=23
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:tm:insert_timer_unsafe: [0]: 0x74e127c4 (303)
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22134] DBG:tm:t_relay_to: new transaction fwd'ed
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [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:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:tcp_handle_req: content-length= 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:tcp_handle_req: Nothing more to read on TCP conn 0x74e0f084, currently in state 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_msg: SIP Reply  (status):
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_msg:  version: <SIP/2.0>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_msg:  status:  <200>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_msg:  reason:  <OK>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_headers: flags=2
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK6d32.4bf55444.0>; state=6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via_param: found param type 236, <i> = <2>; state=16
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_headers: via found, flags=2
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_headers: this is the first via
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:receive_msg: After parse_msg...
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:forward_reply: found module tm, passing reply to it
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:t_check: start=0xffffffff
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_headers: flags=22
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via_param: found param type 235, <rport> = <56495>; state=6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via_param: found param type 234, <received> = <131.221.240.71>; state=6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPje0a3dc131d1e497b8f4e9af2898637f1>; state=6
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_via: end of header reached, state=5
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_headers: via found, flags=22
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_headers: parse_headers: this is the second via
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_to_param: tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_to: end of header reached, state=29
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_to: display={"ert"}, ruri={sip:intercomA_5dtUWgwgqzR6@127.0.0.1}
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:get_hdr_field: <To> [87]; uri=[sip:intercomA_5dtUWgwgqzR6@127.0.0.1]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:get_hdr_field: to body ["ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:get_hdr_field: cseq <CSeq>: <2> <BYE>
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:t_reply_matching: hash 9174 label 1145397172 branch 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:t_reply_matching: REF_UNSAFE:[0x74e12634] after is 2
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:t_reply_matching: reply matched (T=0x74e12634)!
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:t_check: end=0x74e12634
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:run_trans_callbacks: trans=0x74e12634, callback type 8, id 0 entered
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_headers: flags=20
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:dialog:update_msg_cseq: Message CSEQ translated from [2] to [32453]
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:parse_headers: flags=2000
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:get_hdr_field: content_length=0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:build_res_buf_from_sip_res:  old size: 485, new size: 394
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:build_res_buf_from_sip_res: copied size: orig:457, new: 366, rest: 28 msg=
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: SIP/2.0 200 OK
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Via: SIP/2.0/TCP 131.221.240.71:56495;rport=56495;received=131.221.240.71;branch=z9hG4bKPje0a3dc131d1e497b8f4e9af2898637f1;alias
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Call-ID: 62002d5c-2239-4c37-b79d-55d7d8950807
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: From: <sip:g1r2u3p4o5@127.0.0.1>;tag=7f0fa23f57764dc3834a3a0b30e4a363
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: To: "ert" <sip:intercomA_5dtUWgwgqzR6@127.0.0.1>;tag=75c10657-747e-4fd9-bcb6-da450b48f78f
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: CSeq: 32453 BYE
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Content-Length:  0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:_shm_resize: resize(0) called
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:insert_timer_unsafe: [2]: 0x74e1267c (218)
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:tcp_conn_get: con found in state 0
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:tcp_conn_get: tcp connection found (0x74e0b110), acquiring fd
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:tcp_conn_get: c= 0x74e0b110, n=8, Usock=23
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22137] DBG:core:handle_worker: read response= 74e0b110, 1, fd -1 from 6 (22135)
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:tcp_conn_get: after receive_fd: c= 0x74e0b110 n=4 fd=25
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:proto_tcp_send: sending via fd 25...
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:async_tsend_stream: Async successful write from first try on 0x74e0b110
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:proto_tcp_send: after write: c= 0x74e0b110 n=394 fd=25
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:relay_reply: sent buf=0x76b8c66c: SIP/2.0 2..., shmem=0x74e12198: SIP/2.0 2
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e12634] after is 1
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:receive_msg: cleaning up
Jan 03 23:11:35 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:35 [22135] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [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:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:avpops:db_query_avp: no result after query
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:avpops:db_close_query: close avp query
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:db_sqlite:db_sqlite_free_result: nothing to free!
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:tm:t_unref: UNREF_UNSAFE: [0x74e12634] after is 0
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 4 in entry 0x74de08f4
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:core:destroy_avp_list: destroying list (nil)
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:core:receive_msg: cleaning up
Jan 03 23:11:36 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:36 [22134] DBG:core:tcp_read_req: tcp_read_req end
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:tm:timer_routine: timer routine:2,tl=0x74e0f92c next=0x74e0bc50, timeout=215
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:tm:wait_handler: removing 0x74e0f8e4 from table
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:tm:delete_cell: delete transaction 0x74e0f8e4
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 3 in entry 0x74de08f4
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:tm:wait_handler: done
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:tm:timer_routine: timer routine:2,tl=0x74e0bc50 next=(nil), timeout=215
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:tm:wait_handler: removing 0x74e0bc08 from table
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:tm:delete_cell: delete transaction 0x74e0bc08
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:dialog:unref_dlg: unref dlg 0x74e0b4a0 with 1 -> 2 in entry 0x74de08f4
Jan 03 23:11:38 colibri-imx6-jfl opensips[22126]: Jan  3 23:11:38 [22133] DBG:tm:wait_handler: done