[OpenSIPS-Users] dr_rules does not load all DB records
Bogdan-Andrei Iancu
bogdan at opensips.org
Mon May 7 13:55:45 CEST 2012
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:02130053004 at tecnologiaip.com.br To-URI:
> sip:0000502185392949 at sip2.tecnologiaip.com.br;user=phone R-URI: sip:552185392949 at sip2.tecnologiaip.com.br;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 at perseu:/var/log/opensips# opensipsctl fifo get_statistics free_size
>>> shmem:free_size = 239755320
>>> root at perseu:/var/log/opensips# opensipsctl fifo get_statistics used_size
>>> shmem:used_size = 22432196
>>> root at perseu:/var/log/opensips# opensipsctl fifo get_statistics
>>> real_used_size shmem:real_used_size = 28680136
>>> root at perseu:/var/log/opensips# opensipsctl fifo get_statistics
>>> max_used_size shmem:max_used_size = 44551012
>>> root at 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
>>> Users at lists.opensips.org
>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
--
Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
http://www.opensips-solutions.com
More information about the Users
mailing list