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:[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
