[OpenSIPS-Devel] [ opensips-Bugs-3557901 ] dialplan results not consistent

SourceForge.net noreply at sourceforge.net
Thu Aug 30 02:13:13 CEST 2012


Bugs item #3557901, was opened at 2012-08-15 06:01
Message generated for change (Comment added) made by rrevels
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3557901&group_id=232389

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: trunk
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Richard Revels (rrevels)
Assigned to: Nobody/Anonymous (nobody)
Summary: dialplan results not consistent

Initial Comment:
When opensips is first loaded and a dialplan lookup function is called the result is different than after a MI dialplan reload command is issued and the same lookup is done.  The results also don't match my expectations in either case but that may be me not keeping up with changes in the regex parser.  So, anyway, this is what I'm seeing in my logs when calling +19198788990

On initial proxy load:

Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: Doing dialplan lookup in route fix ruri 
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:dp_translate_f: dpid is 30
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:dp_get_svalue: searching 14 
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:dp_translate_f: input is sip:+19198788990 at X.XX.XX.XX
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:translate: regex operator testing
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:test_match: test_match:[0] sip:+19198788990 at X.XX.XX.XX
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:translate: found a matching rule 0x2b0c6e160b80: pr 100, match_exp .*
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:translate: the rule's attrs are restrc
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:translate: the copied attributes are: restrc
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:test_match: test_match:[0] sip:+19198788990 at X.XX.XX.XX
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:rule_translate: simply replace the string, subst_comp 0x2b0c6e160a50, n_escapes 0
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: DBG:dialplan:dp_translate_f: input sip:+19198788990 at X.XX.XX.XX with dpid 30 => output invalid
Aug 15 12:45:49 trunking1 /usr/local/sbin/opensips[15244]: Got destination type of restrc from dialplan and set destination to invalid 


After MI reload dialplan issued:

Aug 15 12:48:18 trunking1 /usr/local/sbin/opensips[15247]: Doing dialplan lookup in route fix ruri 
Aug 15 12:48:18 trunking1 /usr/local/sbin/opensips[15247]: DBG:dialplan:dp_translate_f: dpid is 30
Aug 15 12:48:18 trunking1 /usr/local/sbin/opensips[15247]: DBG:dialplan:dp_get_svalue: searching 14 
Aug 15 12:48:18 trunking1 /usr/local/sbin/opensips[15247]: DBG:dialplan:dp_translate_f: input is sip:+19198788990 at X.XX.XX.XX
Aug 15 12:48:18 trunking1 /usr/local/sbin/opensips[15247]: DBG:dialplan:dp_translate_f: no information available for dpid 30
Aug 15 12:48:18 trunking1 /usr/local/sbin/opensips[15247]: Did not get indication of match in dialplan call with sip:+19198788990 at X.XX.XX.XX 

I'm sure this will paste badly but here are the rules I'm using for this lookup:

+----+------+-----+----------+----------------------------------+-----------+--------------------------+----------+----------+-------------+
| id | dpid | pr  | match_op | match_exp                        | match_len | subst_exp                | repl_exp | disabled | attrs       |
+----+------+-----+----------+----------------------------------+-----------+--------------------------+----------+----------+-------------+
| 31 |   30 |  40 |        1 | sip:011.*                        |         0 | (011)(.*)@.*             | +\2      |        0 | intl        | 
| 19 |   30 |  49 |        1 | sip:([1]?...5551212|411|1411)@.* |         0 | .*                       | +1411    |        0 | information | 
| 10 |   30 |  50 |        1 | sip:(\+1888|1888|888)[0-9]{7}@.* |         0 | (\+?[1]?)([2-9][0-9]{9}) | +1\2     |        0 | tollfree    | 
| 18 |   30 |  50 |        1 | sip:(\+1800|1800|800)[0-9]{7}@.* |         0 | (\+?[1]?)([2-9][0-9]{9}) | +1\2     |        0 | tollfree    | 
| 13 |   30 |  50 |        1 | sip:(\+1866|1866|866)[0-9]{7}@.* |         0 | (\+?[1]?)([2-9][0-9]{9}) | +1\2     |        0 | tollfree    | 
| 14 |   30 |  50 |        1 | sip:(\+1877|1877|877)[0-9]{7}@.* |         0 | (\+?[1]?)([2-9][0-9]{9}) | +1\2     |        0 | tollfree    | 
| 42 |   30 |  50 |        1 | sip:(\+1911|1911|911)@.*         |         0 | (\+?[1]?)(911)           | +1\2     |        0 | emergency   | 
| 17 |   30 |  99 |        1 | sip:\+1[2-9][0-9]{9}@.*          |         0 | (\+?[1]?)([2-9][0-9]{9}) | +1\2     |        0 | domestic    | 
| 16 |   30 |  99 |        1 | sip:([1])?([2-9][0-9]{9})@.*     |         0 | (\+?[1]?)([2-9][0-9]{9}) | +1\2     |        0 | domesticno+ | 
| 25 |   30 | 100 |        1 | .*                               |         0 | .*                       | invalid  |        0 | restrc      | 
+----+------+-----+----------+----------------------------------+-----------+--------------------------+----------+----------+-------------+




----------------------------------------------------------------------

>Comment By: Richard Revels (rrevels)
Date: 2012-08-29 17:13

Message:
I bumped up the logging again and issued a dialplan reload command.  The
table(s) are being loaded and then all rules, old and new, are being
deleted.  I'll spend some quality time on this tomorrow.


Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 1 next (nil)
to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 40 next (nil)
to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 49 next (nil)
to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 50 next (nil)
to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 50 next (nil)
to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 50 next (nil)
to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 50 next (nil)
to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 50 next (nil)
to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 100 next
(nil) to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 0 pr 100 next
(nil) to the index with 0 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:add_rule2hash: added the rule id 30 index 10 pr 101 next
(nil) to the index with 10 len
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 101
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 101
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 1
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 40
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 49
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 100
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 100
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 100
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 100
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 50
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 49
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 40
Aug 29 20:48:44 trunking1 /usr/local/sbin/opensips[9352]:
ERROR:dialplan:destroy_rule: destroying rule with priority 1


----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2012-08-28 11:48

Message:
trunk



----------------------------------------------------------------------

Comment By: Vladut-Stefan Paiu (vladut-paiu)
Date: 2012-08-28 11:42

Message:
Hello,

Are you using trunk, or the main 1.8 branch ?
Asking because there have recently been some additions on the dialplan
module in trunk, so that might have had some side effects :)

Regards,
Vlad

----------------------------------------------------------------------

Comment By: Nobody/Anonymous (nobody)
Date: 2012-08-28 11:34

Message:
I am running revision 9214.

Thank you for reminding me.  I never did go back and look at what is
causing the problem with dialplan reload via the MI interface.



[root at trunking1 opensips-1.8-trunk]# opensipsctl fifo dp_translate 30
sip:19198788990 at sip.bandwidth.com
Output:: +19198788990
ATTRIBUTES:: domesticno+
[root at trunking1 opensips-1.8-trunk]# opensipsctl fifo dp_reload
[root at trunking1 opensips-1.8-trunk]# opensipsctl fifo dp_translate 30
sip:19198788990 at sip.bandwidth.com
404 No information available for dpid




----------------------------------------------------------------------

Comment By: Vladut-Stefan Paiu (vladut-paiu)
Date: 2012-08-28 09:52

Message:
Hello Richard,

What OpenSIPS version are you currently using, that's causing your issues
?

Regards,
Vlad

----------------------------------------------------------------------

Comment By: Richard Revels (rrevels)
Date: 2012-08-15 19:39

Message:
I couldn't figure out how the translate function was supposed to work so I
rewrote it.  I'll upload a patch tomorrow.  I didn't look at the reload
problem.

----------------------------------------------------------------------

Comment By: Richard Revels (rrevels)
Date: 2012-08-15 11:00

Message:
Well, the loading process seems fine.  Through the end of the database
stuff anyway.  Guess I'll try looking at the lookup stuff a little closer.

Breakpoint 1, dp_load_db (dp_table=0x2aaab11408a8) at dp_db.c:279
279		destroy_hash(&dp_table->hash[dp_table->crt_index]);
(gdb) p *dp_table->hash[1]->next
$1 = {dp_id = 30, first_index = 0x2aaab1142930, next = 0x2aaab1142528}
(gdb) p *dp_table->hash[1]->next->next
$2 = {dp_id = 30, first_index = 0x2aaab1142558, next = 0x2aaab1142230}
(gdb) p *dp_table->hash[1]->next->next->next
$3 = {dp_id = 30, first_index = 0x2aaab1142260, next = 0x2aaab1141ed8}
(gdb) p *dp_table->hash[1]->next->next->next->next
$4 = {dp_id = 30, first_index = 0x2aaab1141f08, next = 0x2aaab1141af8}
(gdb) p *dp_table->hash[1]->next->next->next->next->first_index
$5 = {len = 0, first_rule = 0x2aaab1141d90, last_rule = 0x2aaab1141d90,
next = 0x0}
(gdb) p
*dp_table->hash[1]->next->next->next->next->first_index->first_rule
$6 = {dpid = 30, pr = 50, matchop = 1, matchlen = 0, match_exp = {s =
0x2aaab1141e18 "sip:(\\+1877|1877|877)[0-9]{7}@.*", len = 32}, subst_exp =
{s = 0x2aaab1141e58 "(\\+?[1]?)([2-9][0-9]{9})", len = 24}, 
  repl_exp = {s = 0x2aaab1141e90 "+1\\2", len = 4}, match_comp =
0x2aaab1141b60, subst_comp = 0x2aaab1141c08, repl_comp = 0x2aaab1141cb8,
attrs = {s = 0x2aaab1141eb0 "tollfree", len = 8}, next = 0x0}
(gdb) next
281		dp_table->crt_index = dp_table->next_index;
(gdb) next
284		lock_stop_write( dp_table->ref_lock );
(gdb) next
286		list_hash(dp_table->hash[dp_table->crt_index], dp_table->ref_lock);
(gdb) p
*dp_table->hash[1]->next->next->next->next->first_index->first_rule
$7 = {dpid = 30, pr = 50, matchop = 1, matchlen = 0, match_exp = {s =
0x2aaab1141e18 "sip:(\\+1877|1877|877)[0-9]{7}@.*", len = 32}, subst_exp =
{s = 0x2aaab1141e58 "(\\+?[1]?)([2-9][0-9]{9})", len = 24}, 
  repl_exp = {s = 0x2aaab1141e90 "+1\\2", len = 4}, match_comp =
0x2aaab1141b60, subst_comp = 0x2aaab1141c08, repl_comp = 0x2aaab1141cb8,
attrs = {s = 0x2aaab1141eb0 "tollfree", len = 8}, next = 0x0}
(gdb) cont



----------------------------------------------------------------------

Comment By: Richard Revels (rrevels)
Date: 2012-08-15 09:47

Message:
It kinda looks like loading the dialplan rules is just broke.  When I step
through the translate function in dp_repl.c the next pointer in both rulep
and indexp is set to null on the first time through the loop which causes
only the first rule to be looked at.


Breakpoint 1, translate (msg=0x2b059394fb68, input=...,
output=0x7fff6f7ee9c0, idp=0x2b0599ef3c70, attrs=0x7fff6f7ee9b0) at
dp_repl.c:304
warning: Source file is more recent than executable.
304		for(rulep=indexp->first_rule; rulep!=NULL; rulep= rulep->next){
(gdb) next
305			LM_DBG("testing rule input --> comparasion %.*s --> %s\n", input.len,
input.s, rulep->match_comp);
(gdb) p *rulep
$1 = {dpid = 30, pr = 101, matchop = 1, matchlen = 0, match_exp = {s =
0x2b0599ef3bb8 "sip:([1])?([2-9][0-9]{9,})@.*", len = 29}, subst_exp = {s =
0x2b0599ef3bf0 "(\\+?[1]?)([2-9][0-9]{9})", len = 24}, 
  repl_exp = {s = 0x2b0599ef3c28 "+1\\2", len = 4}, match_comp =
0x2b0599ef38f0, subst_comp = 0x2b0599ef39a8, repl_comp = 0x2b0599ef3a58,
attrs = {s = 0x2b0599ef3c48 "domesticno+", len = 11}, next = 0x0}
(gdb) p *indexp
$2 = {len = 0, first_rule = 0x2b0599ef3b30, last_rule = 0x2b0599ef3b30,
next = 0x0}


----------------------------------------------------------------------

Comment By: Richard Revels (rrevels)
Date: 2012-08-15 06:28

Message:
Oh, by the way, this is also in my logs and looks like a few too many
entries for the number of records I have:


Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 100
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 40
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 49
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 99
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 99
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 100
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 99
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 99
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 50
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 49
Aug 15 12:48:11 trunking1 /usr/local/sbin/opensips[15237]:
DBG:dialplan:destroy_rule: destroying rule with priority 40


----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=3557901&group_id=232389



More information about the Devel mailing list