Marcio, I will apply the patch on SVN, so that none else will be tricker by this.
For why it is not matching, post the debug logs related to the execution of the "do_routing()" function.
Regards, Bogdan On 05/05/2012 06:29 PM, Marcio Veloso Antunes wrote:
Bogdan, The patch showed that all routes were loaded (DBG:drouting:dr_load_routing_info: 50104 total records loaded from table dr_rules), thats ok. Now i don't know why OpenSIPS is not able to find the route i expected as my script is: ... xlog( "L_DBG", "TRACE: [R120] will do_routing( '$avp(dr_group_id)')"); if ( !do_routing( "$avp(dr_group_id)") ) { xlog( "L_DBG", "TRACE: [R120] No Rules matching the URI. GroupID: '$avp(dr_group_id)' From-Uri: $fu To-URI: $tu R-URI: $ru"); xlog( "L_ERR", "TRACE: [R120] No Rules matching the URI. GroupID: '$avp(dr_group_id)' From-Uri: $fu To-URI: $tu R-URI: $ru"); send_reply("503", "No Rules matching the URI"); exit; } else { ... I have this on debug: TRACE: [R120] will do_routing( '05') TRACE: [R120] No Rules matching the URI. GroupID: '05' From-Uri: sip:[email protected] To-URI: sip:[email protected];user=phone R-URI: sip:[email protected];user=phone And the load lines from logs, says that all 50104 rules i have were loaded: DBG:drouting:dr_load_routing_info: 50104 total records loaded from table dr_rules The lines that loaded the rule that should have been match: DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x822a50c,50094,0)=[93343] DBG:db_postgres:db_postgres_convert_rows: allocated 5 bytes for row_buf[0] at 0x8255e2c DBG:db_postgres:db_postgres_convert_rows: [50094][0] Column[ruleid]=[93343] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x822a50c,50094,1)=[05] DBG:db_postgres:db_postgres_convert_rows: allocated 2 bytes for row_buf[1] at 0x8255bac DBG:db_postgres:db_postgres_convert_rows: [50094][1] Column[groupid]=[05] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x822a50c,50094,2)=[5] DBG:db_postgres:db_postgres_convert_rows: allocated 1 bytes for row_buf[2] at 0x8255e7c DBG:db_postgres:db_postgres_convert_rows: [50094][2] Column[prefix]=[5] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x822a50c,50094,3)=[], zero len DBG:db_postgres:db_postgres_convert_rows: allocated 0 bytes for row_buf[3] at 0x8255db4 DBG:db_postgres:db_postgres_convert_rows: [50094][3] Column[timerec]=[] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x822a50c,50094,4)=[0] DBG:db_postgres:db_postgres_convert_rows: allocated 1 bytes for row_buf[4] at 0x8255c38 DBG:db_postgres:db_postgres_convert_rows: [50094][4] Column[priority]=[0] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x822a50c,50094,5)=[], zero len DBG:db_postgres:db_postgres_convert_rows: allocated 0 bytes for row_buf[5] at 0x8255ddc DBG:db_postgres:db_postgres_convert_rows: [50094][5] Column[routeid]=[] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x822a50c,50094,6)=[#7] DBG:db_postgres:db_postgres_convert_rows: allocated 2 bytes for row_buf[6] at 0x8255f80 DBG:db_postgres:db_postgres_convert_rows: [50094][6] Column[gwlist]=[#7] DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x822a50c,50094,7)=[], zero len DBG:db_postgres:db_postgres_convert_rows: allocated 0 bytes for row_buf[7] at 0x8255e04 DBG:db_postgres:db_postgres_convert_rows: [50094][7] Column[attrs]=[] DBG:db_postgres:db_postgres_str2val: converting INT [93343] DBG:db_postgres:db_postgres_str2val: converting STRING [05] DBG:db_postgres:db_postgres_str2val: converting STRING [5] DBG:db_postgres:db_postgres_str2val: converting STRING [] DBG:db_postgres:db_postgres_str2val: converting INT [0] DBG:db_postgres:db_postgres_str2val: converting STRING [] DBG:db_postgres:db_postgres_str2val: converting STRING [#7] DBG:db_postgres:db_postgres_str2val: converting STRING [] Please help me understand if i am missing something. Thanks in advance, Marcio Veloso Em sábado. 05/maio/2012, às 04:11:12, você escreveu:Hi Marcio, The issue is related to incomplete DBG logging - you see, the DR module loads the rules in chunks (and not all in the same time). And the debug you got reports only the size of the first chunk of rules. Just as an experiment, apply the attached patch - it has extra DBG logs to print the size for all chunks (you will get more "records found in dr_rules" for a single load) and to also print the final counting of rules that were validated and stored in memory. Regards, Bogdan On 05/04/2012 05:52 AM, Marcio Veloso Antunes wrote:Hi all! I am lost here. I think there is a problem on drouting module. I am using OpenSIPS 1.7.2 and my OpenSIPS cannot load the entire dr_rules table but it shows no Error. I have 50104 records in dr_rules table: SELECT count(*) from dr_rules; count ------- 50104 I have one big group id and 5 smaller ones with just 1 rule each. First i thought that memory could be the problem, so i lauched opensips with STARTOPTIONS="-u opensips -g opensips -m 256", but the problem still there. I've started opensips with fork=no and debug=7 to trace what was going wrong. My memory stats are: root@perseu:/var/log/opensips# opensipsctl fifo get_statistics free_size shmem:free_size = 239755320 root@perseu:/var/log/opensips# opensipsctl fifo get_statistics used_size shmem:used_size = 22432196 root@perseu:/var/log/opensips# opensipsctl fifo get_statistics real_used_size shmem:real_used_size = 28680136 root@perseu:/var/log/opensips# opensipsctl fifo get_statistics max_used_size shmem:max_used_size = 44551012 root@perseu:/var/log/opensips# opensipsctl fifo get_statistics fragments shmem:fragments = 260538 At debug file i found: DBG:drouting:dr_load_routing_info: 3278 records found in dr_rules So i have made a dr_reload (opensipsctl fifo dr_reload), and i found at debug file: DBG:drouting:dr_load_routing_info: 3275 records found in dr_rules So i issued again the dr_reload and now debug file shows: DBG:drouting:dr_load_routing_info: 3113 records found in dr_rules So i dive into the debug file to find that records found message, the lines around it is shown below: May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: allocated 0 bytes for row_buf[3] at 0x82ba2a0 May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: [3112][3] Column[timerec]=[] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x82284a4,3112,4)=[0] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: allocated 1 bytes for row_buf[4] at 0x82ba1dc May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: [3112][4] Column[priority]=[0] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x82284a4,3112,5)=[], zero len May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: allocated 0 bytes for row_buf[5] at 0x82ba28c May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: [3112][5] Column[routeid]=[] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: PQgetvalue(0x82284a4,3112,6)=[#2] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: allocated 2 bytes for row_buf[6] at 0x82ba25c May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: [3112][6] Column[gwlist]=[#2] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_str2val: converting INT [38154] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_str2val: converting STRING [0] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_str2val: converting STRING [55929998] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_str2val: converting STRING [] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_str2val: converting INT [0] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_str2val: converting STRING [] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_str2val: converting STRING [#2] May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: freeing row_buf[0] at 0x82ba248 May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: freeing row_buf[4] at 0x82ba1dc May 3 23:20:58 perseu opensips: DBG:db_postgres:db_postgres_convert_rows: freeing row buffer at 0x822d574 May 3 23:20:58 perseu opensips: DBG:drouting:dr_load_routing_info: 3113 records found in dr_rules May 3 23:20:58 perseu opensips: DBG:drouting:add_prefix: adding info 0xa7e5d1fc, 0 at: 0xa8c2afd4 (7) May 3 23:20:58 perseu opensips: DBG:drouting:add_prefix: adding info 0xa7e5d1bc, 0 at: 0xa8c2afe4 (8) May 3 23:20:58 perseu opensips: DBG:drouting:add_prefix: adding info 0xa8f8f890, 0 at: 0xa8c2aff4 (9) May 3 23:20:58 perseu opensips: DBG:drouting:add_prefix: adding info 0xa7e5cf64, 0 at: 0xa8c29f68 (1) May 3 23:20:58 perseu opensips: DBG:drouting:add_prefix: adding info 0xa7e5cf24, 1 at: 0xa8f8f938 (5) May 3 23:20:58 perseu opensips: DBG:drouting:add_prefix: adding info 0xa8c2b574, 0 at: 0xa8c29f78 (2) May 3 23:20:58 perseu opensips: DBG:drouting:add_prefix: adding info 0xa8c2b2c0, 0 at: 0xa8c29f88 (3) I think it is curious if not wrong it stops converting records, inform the numbers of rows found and then shows messages "add_prefix". Why the other 47000 records were not loaded? Please help, it is a production instalation. Marcio Veloso Antunes Tel.+55.11.3588.0802 Ext.106 Tel.+55.21.3005.3004 Ext.106 Cel. +55.21.8539.2949 _______________________________________________ Users mailing list [email protected] http://lists.opensips.org/cgi-bin/mailman/listinfo/users
-- Bogdan-Andrei Iancu OpenSIPS Founder and Developer http://www.opensips-solutions.com _______________________________________________ Users mailing list [email protected] http://lists.opensips.org/cgi-bin/mailman/listinfo/users
