[OpenSIPS-Users] dr_rules does not load all DB records

Marcio Veloso Antunes mveloso at tecnologiaip.com.br
Tue May 8 17:31:02 CEST 2012


Bogdan,

  I have found an error message (error level, not debug) that says:

ERROR:drouting:do_routing: failed to get group id

  But i am calling do_routing, passing the string "05" through $avp(dr_group_id) as you can see in the script section below:

...
  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");
...

The log generated confirms that:

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:0000502126434378 at sip2.tecnologiaip.com.br:5061;user=phone R-URI: 
sip:552126434378 at sip2.tecnologiaip.com.br:5061;user=phone

Am i doing something wrong or it is really odd?

Marcio Veloso


Em terça-feira. 08/maio/2012, às 10:14:09, Marcio Veloso Antunes escreveu:
> Bogdan,
> 
>   The only messages i have in the log that have 'do_routing' are listed
> below. I am sure the function is being called.
> 
> May  5 12:04:11 perseu opensips: DBG:core:find_cmd_export_t: found
> <do_routing>(1) in module drouting
> [/usr/local/opensips/lib/opensips/modules/]
> May  5 12:04:11 perseu opensips: DBG:core:fix_actions: fixing do_routing,
> line 1145 May  5 12:07:48 perseu opensips: TRACE: [R120] will do_routing(
> '05') May  5 12:08:10 perseu opensips: TRACE: [R120] will do_routing(
> '05')
> 
>   Do you think i should downgrade from 1.7.2 to some other version?
> 
>   Thanks,
>   Marcio
> 
> Em terça-feira. 08/maio/2012, às 08:47:13, Bogdan-Andrei Iancu escreveu:
> > 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

-- 
  Atenciosamente,

  Marcio Veloso Antunes
  Tel.+55.11.3588.0802 Ext.106
  Tel.+55.21.3005.3004 Ext.106
  Cel. +55.21.8539.2949



More information about the Users mailing list