#553 dialplan results not consistent

trunk
closed-fixed
Liviu Chircu
modules (454)
5
2014-08-21
2012-08-15
Richard Revels
No

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@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@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@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@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@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@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 |
+----+------+-----+----------+----------------------------------+-----------+--------------------------+----------+----------+-------------+

Discussion

  • Richard Revels
    Richard Revels
    2012-08-15

    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

     
  • Richard Revels
    Richard Revels
    2012-08-15

    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}

     
  • Richard Revels
    Richard Revels
    2012-08-15

    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

     
  • Richard Revels
    Richard Revels
    2012-08-16

    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.

     
  • Richard Revels
    Richard Revels
    2012-08-16

    rework translate function.

     
    Attachments
  • Hello Richard,

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

    Regards,
    Vlad

     
  • 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@trunking1 opensips-1.8-trunk]# opensipsctl fifo dp_translate 30 sip:19198788990@sip.bandwidth.com
    Output:: +19198788990
    ATTRIBUTES:: domesticno+
    [root@trunking1 opensips-1.8-trunk]# opensipsctl fifo dp_reload
    [root@trunking1 opensips-1.8-trunk]# opensipsctl fifo dp_translate 30 sip:19198788990@sip.bandwidth.com
    404 No information available for dpid

     
  • 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

     
  • trunk

     
  • Richard Revels
    Richard Revels
    2012-08-30

    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

     
    • assigned_to: nobody --> liviuchircu
     
  • Hi Richard,

    There was a fixing on trunk for this - could you please update from SVN trunk and see if everything ok now?

    Thanks and regards,
    Bogdan

     
  • Richard Revels
    Richard Revels
    2012-09-18

    It appears the dialplan reload MI command now works as expected. There are other things not working as expected now though. Is work still going on in the module code? If not, I will open another tracker as the original issue this was opened for appears resolved.

     
  • The work over the modules was completed, so if you have any other issues, open other tickets, I will close this one.

    Thanks,
    Bogdan

     
    • status: open --> closed-fixed