[OpenSIPS-Users] dr_rules does not load all DB records
Bogdan-Andrei Iancu
bogdan at opensips.org
Tue May 8 13:47:13 CEST 2012
Marcio,
debug=4 should do it . Search for "do_routing:" string in the logs. And
be sure you are calling the function :)
Regards,
Bogdan
On 05/07/2012 03:58 PM, Marcio Veloso Antunes wrote:
> Bogdan,
>
> What level of debug is necessary to show do_routing function debug? I am
> using level 7 but i could not find any debug at all. I was the first thing i've
> looked for.
>
> Thanks again,
>
> Em segunda-feira. 07/maio/2012, às 08:55:45, Bogdan-Andrei Iancu escreveu:
>> 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