Hi, i am gonna step by step closer but..it still not working. This a log from opensips.log:
tail -f /var/log/opensips.log Dec 5 16:42:06 opensips /sbin/opensips[22222]: DBG:tm:timer_routine: timer routine:2,tl=0xaf3edca0 next=(nil), timeout=237 Dec 5 16:42:06 opensips /sbin/opensips[22222]: DBG:tm:wait_handler: removing 0xaf3edc58 from table Dec 5 16:42:06 opensips /sbin/opensips[22222]: DBG:tm:delete_cell: delete transaction 0xaf3edc58 Dec 5 16:42:06 opensips /sbin/opensips[22222]: DBG:tm:wait_handler: done Dec 5 16:42:08 opensips /sbin/opensips[22216]: DBG:core:udp_rcv_loop: probing packet received len = 4 Dec 5 16:42:38 opensips /sbin/opensips[22217]: DBG:core:udp_rcv_loop: probing packet received len = 4 Dec 5 16:43:01 opensips /sbin/opensips[22211]: DBG:mi_fifo:mi_parse_tree: adding node <> ; val <all> Dec 5 16:43:01 opensips /sbin/opensips[22211]: DBG:mi_fifo:mi_parse_node: end of input tree Dec 5 16:43:01 opensips /sbin/opensips[22211]: DBG:mi_fifo:mi_fifo_server: done parsing the mi tree Dec 5 16:43:08 opensips /sbin/opensips[22216]: DBG:core:udp_rcv_loop: probing packet received len = 4 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_msg: SIP Request: Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_msg: method: <INVITE> Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_msg: uri: <sip:00522375568@10.9.101.166:5060;user=phone> Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_msg: version: <SIP/2.0> Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=2 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_via: end of header reached, state=5 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: via found, flags=2 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: this is the first via Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:receive_msg: After parse_msg... Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:receive_msg: preparing to run routing scripts... Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:siptrace:sip_trace: nothing to trace... Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=100 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_to: end of header reached, state=9 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_to: display={}, ruri={sip:00522375568@10.9.101.166:5060} Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: <To> [35]; uri=[sip:00522375568@10.9.101.166:5060] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: to body [sip:00522375568@10.9.101.166:5060#015#012] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE> Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:maxfwd:is_maxfwd_present: value = 70 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:uri:has_totag: no totag Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=78 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: start searching: hash=58302, isACK=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: proceeding to pre-RFC3261 transaction matching Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: no transaction found Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_to_param: tag=B080AAD539C5 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_to: end of header reached, state=29 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_to: display={}, ruri={sip:+390522375507@172.16.52.7:5061} Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if host==us: 11==9 && [172.16.52.7] == [127.0.0.1] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if port 5060 matches port 5061 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if host==us: 11==12 && [172.16.52.7] == [10.9.101.166] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if port 5060 matches port 5061 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if host==us: 11==9 && [172.16.52.7] == [127.0.0.1] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if port 5060 matches port 5061 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if host==us: 11==12 && [172.16.52.7] == [10.9.101.166] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if port 5060 matches port 5061 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:check_self: host != me Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=200 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: content_length=188 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: found end of header Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:rr:find_first_route: No Route headers found Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:rr:loose_route: There is no Route HF Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [10.9.101.166] == [127.0.0.1] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [10.9.101.166] == [10.9.101.166] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:avpops:ops_dbload_avps: attr dbp Linea-LW Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_new_result: allocate 28 bytes for result set at 0x81d6744 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_allocate_columns: allocate 48 bytes for result columns at 0x81d70c0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81d70cc)[0]=[value] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81d70d4)[1]=[attribute] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81d70dc)[2]=[type] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: use DB_INT result type Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_allocate_rows: allocate 68 bytes for result rows and values at 0x81d70fc Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_str2val: converting STRING [y] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_str2val: converting STRING [Linea-LW] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_str2val: converting INT [0] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:avpops:db_close_query: close avp query Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_free_columns: freeing result columns at 0x81d70c0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_free_rows: freeing 1 rows Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_free_row: freeing row values at 0x81d7104 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_free_rows: freeing rows at 0x81d70fc Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_free_result: freeing result set at 0x81d6744 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:avpops:ops_dbload_avps: loaded avps = 1 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:buf_init: initializing... *Dec 5 16:43:24 opensips /sbin/opensips[22217]: AVP_DB_LOAD Invocato!!!!!!!!!!!!!!sip:+390522375507@172.16.52.7:5061* Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:avpops:ops_check_avp: check <y> against <y> as str /33554433 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_new_result: allocate 28 bytes for result set at 0x81d6744 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_allocate_columns: allocate 32 bytes for result columns at 0x81d70c0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81d70c8)[0]=[username] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81d70d0)[1]=[domain] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type *Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query* Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:alias_db:alias_db_query: no alias found for R-URI Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_free_columns: freeing result columns at 0x81d70c0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_free_rows: freeing 0 rows Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:db_free_result: freeing result set at 0x81d6744 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:registrar:lookup: '00522375568' Not found in usrloc Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:t_newtran: transaction on entrance=(nil) Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=ffffffffffffffff Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=78 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: start searching: hash=58302, isACK=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: proceeding to pre-RFC3261 transaction matching Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: no transaction found Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:run_reqin_callbacks: trans=0xaf3edc58, callback type 1, id 2 entered Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=40 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:run_reqin_callbacks: trans=0xaf3edc58, callback type 1, id 1 entered Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:run_reqin_callbacks: trans=0xaf3edc58, callback type 1, id 0 entered Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=78 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=ffffffffffffffff Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:check_ip_address: params 172.16.52.7, 172.16.52.7, 0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:_shm_resize: resize(0) called Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:set_timer: relative timeout is 500000 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:insert_timer_unsafe: [4]: 0xaf3edd20 (316600000) Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:set_timer: relative timeout is 30 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:insert_timer_unsafe: [0]: 0xaf3edd3c (346) Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:_reply_light: reply sent out. buf=0x81d863c: SIP/2.0 4..., shmem=0xaf3efa90: SIP/2.0 4 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:run_trans_callbacks: trans=0xaf3edc58, callback type 128, id 3 entered Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:run_trans_callbacks: trans=0xaf3edc58, callback type 128, id 2 entered Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=40 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:siptrace:trace_onreply_out: dest [udp:172.16.52.7:5061] Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:siptrace:trace_onreply_out: storing info 10... Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x81d3ffc (tail=136132840) MC=0x81d391c Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=323; type=252; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=48; type=254; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=20; type=254; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=36; type=12; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=12; type=254; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in... Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_msg: SIP Request: Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_msg: method: <ACK> Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_msg: uri: <sip:00522375568@10.9.101.166:5060> Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_msg: version: <SIP/2.0> Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_headers: flags=2 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_via: end of header reached, state=5 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_headers: via found, flags=2 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_headers: this is the first via Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:receive_msg: After parse_msg... Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:receive_msg: preparing to run routing scripts... Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:sl:sl_filter_ACK: to late to be a local ACK! Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:siptrace:sip_trace: nothing to trace... Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_headers: flags=100 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_to_param: tag=155c340f586c28d0300cf5a6ccf90d99-de38 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_to: end of header reached, state=29 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_to: display={}, ruri={sip:00522375568@10.9.101.166:5060} Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: <To> [77]; uri=[sip:00522375568@10.9.101.166:5060] Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: to body [sip:00522375568@10.9.101.166:5060] Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:maxfwd:is_maxfwd_present: value = 70 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:uri:has_totag: totag found Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_headers: flags=200 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <ACK> Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: content_length=0 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: found end of header Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:rr:find_first_route: No Route headers found Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:rr:loose_route: There is no Route HF Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:parse_headers: flags=78 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:tm:t_lookup_request: start searching: hash=58302, isACK=1 Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:tm:t_lookup_request: proceeding to pre-RFC3261 transaction matching Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:tm:t_lookup_request: no transaction found Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:destroy_avp_list: destroying list (nil) Dec 5 16:43:24 opensips /sbin/opensips[22218]: DBG:core:receive_msg: cleaning up Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:_reply_light: finished Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaf3edc58] after is 0 Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:destroy_avp_list: destroying list (nil) Dec 5 16:43:24 opensips /sbin/opensips[22217]: DBG:core:receive_msg: cleaning up Dec 5 16:43:24 opensips /sbin/opensips[22222]: DBG:tm:utimer_routine: timer routine:4,tl=0xaf3edd20 next=(nil), timeout=316600000 Dec 5 16:43:24 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : reply resending (t=0xaf3edc58, SIP/2.0 4 ... ) Dec 5 16:43:24 opensips /sbin/opensips[22222]: DBG:tm:t_retransmit_reply: buf=0xb74345a0: SIP/2.0 4..., shmem=0xaf3efa90: SIP/2.0 4 Dec 5 16:43:24 opensips /sbin/opensips[22222]: DBG:tm:set_timer: relative timeout is 1000000 Dec 5 16:43:24 opensips /sbin/opensips[22222]: DBG:tm:insert_timer_unsafe: [5]: 0xaf3edd20 (317600000) Dec 5 16:43:24 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : done Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_msg: SIP Request: Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_msg: method: <ACK> Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_msg: uri: <sip:00522375568@10.9.101.166:5060> Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_msg: version: <SIP/2.0> Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_headers: flags=2 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_via: end of header reached, state=5 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_headers: via found, flags=2 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_headers: this is the first via Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:receive_msg: After parse_msg... Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:receive_msg: preparing to run routing scripts... Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:sl:sl_filter_ACK: to late to be a local ACK! Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:siptrace:sip_trace: nothing to trace... Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_headers: flags=100 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_to_param: tag=155c340f586c28d0300cf5a6ccf90d99-de38 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_to: end of header reached, state=29 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_to: display={}, ruri={sip:00522375568@10.9.101.166:5060} Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: <To> [77]; uri=[sip:00522375568@10.9.101.166:5060] Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: to body [sip:00522375568@10.9.101.166:5060] Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:maxfwd:is_maxfwd_present: value = 70 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:uri:has_totag: totag found Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_headers: flags=200 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <ACK> Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: content_length=0 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: found end of header Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:rr:find_first_route: No Route headers found Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:rr:loose_route: There is no Route HF Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:parse_headers: flags=78 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:tm:t_lookup_request: start searching: hash=58302, isACK=1 Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:tm:t_lookup_request: proceeding to pre-RFC3261 transaction matching Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:tm:t_lookup_request: no transaction found Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:destroy_avp_list: destroying list (nil) Dec 5 16:43:24 opensips /sbin/opensips[22219]: DBG:core:receive_msg: cleaning up Dec 5 16:43:25 opensips /sbin/opensips[22222]: DBG:tm:utimer_routine: timer routine:5,tl=0xaf3edd20 next=(nil), timeout=317600000 Dec 5 16:43:25 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : reply resending (t=0xaf3edc58, SIP/2.0 4 ... ) Dec 5 16:43:25 opensips /sbin/opensips[22222]: DBG:tm:t_retransmit_reply: buf=0xb74345a0: SIP/2.0 4..., shmem=0xaf3efa90: SIP/2.0 4 Dec 5 16:43:25 opensips /sbin/opensips[22222]: DBG:tm:set_timer: relative timeout is 2000000 Dec 5 16:43:25 opensips /sbin/opensips[22222]: DBG:tm:insert_timer_unsafe: [6]: 0xaf3edd20 (319600000) Dec 5 16:43:25 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : done Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_msg: SIP Request: Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_msg: method: <ACK> Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_msg: uri: <sip:00522375568@10.9.101.166:5060> Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_msg: version: <SIP/2.0> Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_headers: flags=2 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_via: end of header reached, state=5 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_headers: via found, flags=2 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_headers: this is the first via Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:receive_msg: After parse_msg... Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:receive_msg: preparing to run routing scripts... Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:sl:sl_filter_ACK: to late to be a local ACK! Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:siptrace:sip_trace: nothing to trace... Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_headers: flags=100 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_to_param: tag=155c340f586c28d0300cf5a6ccf90d99-de38 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_to: end of header reached, state=29 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_to: display={}, ruri={sip:00522375568@10.9.101.166:5060} Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:get_hdr_field: <To> [77]; uri=[sip:00522375568@10.9.101.166:5060] Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:get_hdr_field: to body [sip:00522375568@10.9.101.166:5060] Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:maxfwd:is_maxfwd_present: value = 70 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:uri:has_totag: totag found Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_headers: flags=200 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <ACK> Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:get_hdr_field: content_length=0 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:get_hdr_field: found end of header Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:rr:find_first_route: No Route headers found Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:rr:loose_route: There is no Route HF Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:parse_headers: flags=78 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:tm:t_lookup_request: start searching: hash=58302, isACK=1 Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:tm:t_lookup_request: proceeding to pre-RFC3261 transaction matching Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:tm:t_lookup_request: no transaction found Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:destroy_avp_list: destroying list (nil) Dec 5 16:43:25 opensips /sbin/opensips[22216]: DBG:core:receive_msg: cleaning up Dec 5 16:43:27 opensips /sbin/opensips[22222]: DBG:tm:utimer_routine: timer routine:6,tl=0xaf3edd20 next=(nil), timeout=319600000 Dec 5 16:43:27 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : reply resending (t=0xaf3edc58, SIP/2.0 4 ... ) Dec 5 16:43:27 opensips /sbin/opensips[22222]: DBG:tm:t_retransmit_reply: buf=0xb74345a0: SIP/2.0 4..., shmem=0xaf3efa90: SIP/2.0 4 Dec 5 16:43:27 opensips /sbin/opensips[22222]: DBG:tm:set_timer: relative timeout is 4000000 Dec 5 16:43:27 opensips /sbin/opensips[22222]: DBG:tm:insert_timer_unsafe: [7]: 0xaf3edd20 (323600000) Dec 5 16:43:27 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : done Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_msg: SIP Request: Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_msg: method: <ACK> Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_msg: uri: <sip:00522375568@10.9.101.166:5060> Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_msg: version: <SIP/2.0> Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_headers: flags=2 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_via: end of header reached, state=5 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_headers: via found, flags=2 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_headers: this is the first via Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:receive_msg: After parse_msg... Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:receive_msg: preparing to run routing scripts... Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:sl:sl_filter_ACK: to late to be a local ACK! Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:siptrace:sip_trace: nothing to trace... Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_headers: flags=100 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_to_param: tag=155c340f586c28d0300cf5a6ccf90d99-de38 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_to: end of header reached, state=29 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_to: display={}, ruri={sip:00522375568@10.9.101.166:5060} Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: <To> [77]; uri=[sip:00522375568@10.9.101.166:5060] Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: to body [sip:00522375568@10.9.101.166:5060] Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:maxfwd:is_maxfwd_present: value = 70 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:uri:has_totag: totag found Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_headers: flags=200 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <ACK> Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: content_length=0 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:get_hdr_field: found end of header Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:rr:find_first_route: No Route headers found Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:rr:loose_route: There is no Route HF Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:parse_headers: flags=78 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:tm:t_lookup_request: start searching: hash=58302, isACK=1 Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:tm:t_lookup_request: proceeding to pre-RFC3261 transaction matching Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:tm:t_lookup_request: no transaction found Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:destroy_avp_list: destroying list (nil) Dec 5 16:43:27 opensips /sbin/opensips[22218]: DBG:core:receive_msg: cleaning up Dec 5 16:43:31 opensips /sbin/opensips[22222]: DBG:tm:utimer_routine: timer routine:7,tl=0xaf3edd20 next=(nil), timeout=323600000 Dec 5 16:43:31 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : reply resending (t=0xaf3edc58, SIP/2.0 4 ... ) Dec 5 16:43:31 opensips /sbin/opensips[22222]: DBG:tm:t_retransmit_reply: buf=0xb74345a0: SIP/2.0 4..., shmem=0xaf3efa90: SIP/2.0 4 Dec 5 16:43:31 opensips /sbin/opensips[22222]: DBG:tm:set_timer: relative timeout is 4000000 Dec 5 16:43:31 opensips /sbin/opensips[22222]: DBG:tm:insert_timer_unsafe: [7]: 0xaf3edd20 (327600000) Dec 5 16:43:31 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : done Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_msg: SIP Request: Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_msg: method: <ACK> Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_msg: uri: <sip:00522375568@10.9.101.166:5060> Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_msg: version: <SIP/2.0> Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=2 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_via: end of header reached, state=5 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_headers: via found, flags=2 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_headers: this is the first via Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:receive_msg: After parse_msg... Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:receive_msg: preparing to run routing scripts... Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:sl:sl_filter_ACK: to late to be a local ACK! Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:siptrace:sip_trace: nothing to trace... Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=100 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_to_param: tag=155c340f586c28d0300cf5a6ccf90d99-de38 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_to: end of header reached, state=29 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_to: display={}, ruri={sip:00522375568@10.9.101.166:5060} Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: <To> [77]; uri=[sip:00522375568@10.9.101.166:5060] Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: to body [sip:00522375568@10.9.101.166:5060] Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:maxfwd:is_maxfwd_present: value = 70 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:uri:has_totag: totag found Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=200 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <ACK> Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: content_length=0 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:get_hdr_field: found end of header Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:rr:find_first_route: No Route headers found Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:rr:loose_route: There is no Route HF Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:parse_headers: flags=78 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: start searching: hash=58302, isACK=1 Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: proceeding to pre-RFC3261 transaction matching Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:tm:t_lookup_request: no transaction found Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:destroy_avp_list: destroying list (nil) Dec 5 16:43:31 opensips /sbin/opensips[22217]: DBG:core:receive_msg: cleaning up Dec 5 16:43:35 opensips /sbin/opensips[22222]: DBG:tm:utimer_routine: timer routine:7,tl=0xaf3edd20 next=(nil), timeout=327600000 Dec 5 16:43:35 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : reply resending (t=0xaf3edc58, SIP/2.0 4 ... ) Dec 5 16:43:35 opensips /sbin/opensips[22222]: DBG:tm:t_retransmit_reply: buf=0xb74345a0: SIP/2.0 4..., shmem=0xaf3efa90: SIP/2.0 4 Dec 5 16:43:35 opensips /sbin/opensips[22222]: DBG:tm:set_timer: relative timeout is 4000000 Dec 5 16:43:35 opensips /sbin/opensips[22222]: DBG:tm:insert_timer_unsafe: [7]: 0xaf3edd20 (331600000) Dec 5 16:43:35 opensips /sbin/opensips[22222]: DBG:tm:retransmission_handler: retransmission_handler : done Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_msg: SIP Request: Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_msg: method: <ACK> Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_msg: uri: <sip:00522375568@10.9.101.166:5060> Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_msg: version: <SIP/2.0> Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_headers: flags=2 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_via: end of header reached, state=5 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_headers: via found, flags=2 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_headers: this is the first via Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:receive_msg: After parse_msg... Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:receive_msg: preparing to run routing scripts... Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:sl:sl_filter_ACK: to late to be a local ACK! Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:siptrace:sip_trace: nothing to trace... Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_headers: flags=100 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_to_param: tag=155c340f586c28d0300cf5a6ccf90d99-de38 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_to: end of header reached, state=29 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_to: display={}, ruri={sip:00522375568@10.9.101.166:5060} Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: <To> [77]; uri=[sip:00522375568@10.9.101.166:5060] Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: to body [sip:00522375568@10.9.101.166:5060] Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:maxfwd:is_maxfwd_present: value = 70 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:uri:has_totag: totag found Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_headers: flags=200 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <ACK> Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: content_length=0 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:get_hdr_field: found end of header Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:rr:find_first_route: No Route headers found Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:rr:loose_route: There is no Route HF Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:parse_headers: flags=78 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:tm:t_lookup_request: start searching: hash=58302, isACK=1 Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:tm:t_lookup_request: proceeding to pre-RFC3261 transaction matching Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:tm:t_lookup_request: no transaction found Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:destroy_avp_list: destroying list (nil) Dec 5 16:43:35 opensips /sbin/opensips[22219]: DBG:core:receive_msg: cleaning up So, no USERNAME nor DOMAIN match... but the avp_table is filled up: opensipsctl avp list database engine 'MYSQL' loaded Control engine 'FIFO' loaded Query: SELECT uuid,username,domain,attribute,type,value FROM usr_preferences ; Dumping AVPs +------+---------------+------------------+-----------+------+-------+ | uuid | username | domain | attribute | type | value | +------+---------------+------------------+-----------+------+-------+ | | +390522375507 | 172.16.52.7:5061 | Linea-LW | 0 | y | +------+---------------+------------------+-----------+------+-------+ Can anyone help me? Thanks -- View this message in context: http://opensips-open-sip-server.1449251.n2.nabble.com/Modify-To-s-field-and-forward-tp7040781p7063562.html Sent from the OpenSIPS - Users mailing list archive at Nabble.com. _______________________________________________ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users