[Home]

Summary:ASTERISK-19205: Most Unique pattern matching broken when trailing "-" is part of extension
Reporter:Philippe Lindheimer (p_lindheimer)Labels:
Date Opened:2012-01-17 00:19:01.000-0600Date Closed:2012-11-27 17:50:45.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/PBX
Versions:1.8.7.2 Frequency of
Occurrence		Constant
Related
Issues:
is caused byASTERISK-13218 Extensions configuration is not being sorted correctly
is related toASTERISK-16121 [patch] strange extension pattern matching
Environment:Attachments:
Description:The following FreePBX bug has some information. The crux is as follows. FreePBX uses some dialplan where extension patterns take on a format that might look like: "_RG-10111-." for a pattern. The crux of the issue is given two similar patterns, one always expect Asterisk to do the "most specific match". It appears starting with 1.6.2 something in Asterisk changed the behavior if that trailing "-" is left off. Tests were done on 1.4.32 where Asterisk seemed to work properly, and on 1.6.2.21 and 1.8.7.2 where it works improperly.

The following is a simple dialplan context that can be used to demonstrate the error:

{noformat}
[from-internal]
exten => 1112,1,Goto(tst-parse,s,1)

[tst-parse]
exten => s,1,Noop(Running Parse Priority Text)
exten => s,n,Dial(Local/RG-10111-99999@tst-parse)
exten => s,n,Dial(Local/RG-20111-99999@tst-parse)
exten => s,n,Hangup
exten => h,1,Hangup
exten => _RG-10111-.,1,Noop(IN 10111, this is CORRECT)
exten => _RG-101-.,1,Noop(IN 101, this is WRONG)
exten => _RG-20111.,1,Noop(IN 20111, this is CORRECT)
exten => _RG-201.,1,Noop(IN 201, this is WRONG)
{noformat}

In this example, you dial "1112" to trigger teh context. Note the difference in the two sets of target dialplan, in one case there is a trailing "\-" and in the other case there is not. One wold expect both cases to execute the instruction that results in the "CORRECT" more specific match however leaving off the trailing "\-" is required for this to happen and if not, the wrong dialplan is executed.

The results from 1.4 show proper execution:
{noformat}
-- Executing [1112@from-internal:1] Goto("SIP/7001-000005bf", "tst-parse|s|1") in new stack
   -- Goto (tst-parse,s,1)
   -- Executing [s@tst-parse:1] NoOp("SIP/7001-000005bf", "Running Parse Priority Text") in new stack
   -- Executing [s@tst-parse:2] Dial("SIP/7001-000005bf", "Local/RG-10111-99999@tst-parse") in new stack
   -- Called RG-10111-99999@tst-parse
   -- Executing [RG-10111-99999@tst-parse:1] NoOp("Local/RG-10111-99999@tst-parse-8d8c,2", "IN 10111| this is CORRECT") in new stack
 == Auto fallthrough, channel 'Local/RG-10111-99999@tst-parse-8d8c,2' status is 'UNKNOWN'
   -- Executing [h@tst-parse:1] Hangup("Local/RG-10111-99999@tst-parse-8d8c,2", "") in new stack
 == Spawn extension (tst-parse, h, 1) exited non-zero on 'Local/RG-10111-99999@tst-parse-8d8c,2'
 == Everyone is busy/congested at this time (1:0/0/1)
   -- Executing [s@tst-parse:3] Dial("SIP/7001-000005bf", "Local/RG-20111-99999@tst-parse") in new stack
   -- Called RG-20111-99999@tst-parse
   -- Executing [RG-20111-99999@tst-parse:1] NoOp("Local/RG-20111-99999@tst-parse-6a9b,2", "IN 20111| this is CORRECT") in new stack
 == Auto fallthrough, channel 'Local/RG-20111-99999@tst-parse-6a9b,2' status is 'UNKNOWN'
   -- Executing [h@tst-parse:1] Hangup("Local/RG-20111-99999@tst-parse-6a9b,2", "") in new stack
 == Spawn extension (tst-parse, h, 1) exited non-zero on 'Local/RG-20111-99999@tst-parse-6a9b,2'
 == Everyone is busy/congested at this time (1:0/0/1)
   -- Executing [s@tst-parse:4] Hangup("SIP/7001-000005bf", "") in new stack
 == Spawn extension (tst-parse, s, 4) exited non-zero on 'SIP/7001-000005bf'
   -- Executing [h@tst-parse:1] Hangup("SIP/7001-000005bf", "") in new stack
 == Spawn extension (tst-parse, h, 1) exited non-zero on 'SIP/7001-000005bf'
{noformat}

The results from 1.8 show improper execution, the same was seen on 1.6.2:
{noformat}
   -- Executing [1112@from-internal:1] Goto("SIP/700-000003ac", "tst-parse,s,1") in new stack
   -- Goto (tst-parse,s,1)
   -- Executing [s@tst-parse:1] NoOp("SIP/700-000003ac", "Running Parse Priority Text") in new stack
   -- Executing [s@tst-parse:2] Dial("SIP/700-000003ac", "Local/RG-10111-99999@tst-parse") in new stack
   -- Called Local/RG-10111-99999@tst-parse
   -- Executing [RG-10111-99999@tst-parse:1] NoOp("Local/RG-10111-99999@tst-parse-6114;2", "IN 101, this is WRONG") in new stack
   -- Auto fallthrough, channel 'Local/RG-10111-99999@tst-parse-6114;2' status is 'UNKNOWN'
   -- Executing [h@tst-parse:1] Hangup("Local/RG-10111-99999@tst-parse-6114;2", "") in new stack
 == Spawn extension (tst-parse, h, 1) exited non-zero on 'Local/RG-10111-99999@tst-parse-6114;2'
   -- No one is available to answer at this time (1:0/0/0)
   -- Executing [s@tst-parse:3] Dial("SIP/700-000003ac", "Local/RG-20111-99999@tst-parse") in new stack
   -- Called Local/RG-20111-99999@tst-parse
   -- Executing [RG-20111-99999@tst-parse:1] NoOp("Local/RG-20111-99999@tst-parse-19bc;2", "IN 20111, this is CORRECT") in new stack
   -- Auto fallthrough, channel 'Local/RG-20111-99999@tst-parse-19bc;2' status is 'UNKNOWN'
   -- Executing [h@tst-parse:1] Hangup("Local/RG-20111-99999@tst-parse-19bc;2", "") in new stack
{noformat}

In the case of FreePBX, this breaks functionality when in the event that someone were to have two phone extensions configured with 101 and 10111. The following ticket with FreePBX references this issue:

http://www.freepbx.org/trac/ticket/5521
Comments:By: Richard Mudgett (rmudgett) 2012-01-17 10:46:00.811-0600

The fix for ASTERISK-18909 may have also fixed this issue.
By: Matt Jordan (mjordan) 2012-09-25 16:58:42.184-0500

This was likely fixed by r347811.  Can you confirm if this is still a problem?
By: Matt Jordan (mjordan) 2012-10-17 09:10:57.710-0500

Suspended due to lack of activity. Please request a bug marshal in #asterisk-bugs on the IRC network irc.freenode.net to reopen the issue should you have the additional information requested.  Further information can be found at http://www.asterisk.org/developers/bug-guidelines


By: Birger "WIMPy" Harzenetter (wimpy) 2012-11-05 22:01:04.430-0600

I just hit a similar issue on the current TRUNK version.

Here are 6 test calls. The first half with a pattern of _foo-! and the second half with _foo.
Both trying to Goto foo-1, foo-2 and foo- in that order.

{noformat}
exten => start,1,Answer()
exten => start,n,Read(x,,1)
exten => start,n,Verbose(0,Goto(foo-${x},1))
exten => start,n,Goto(foo-${x},1)
exten => foo-1,1,Verbose(0,hit foo-1)
exten => _foo-!,1,Verbose(0,hit _foo-! / ${EXTEN})
{noformat}

{noformat}
[2012-11-06 04:43:36]     -- Executing [start@ssmmc:1] Answer("lcr/121", "") in new stack
[2012-11-06 04:43:36]     -- Executing [start@ssmmc:2] Read("lcr/121", "x,,1") in new stack
[2012-11-06 04:43:36]     -- Accepting a maximum of 1 digits.
[2012-11-06 04:43:41]     -- User entered '1'
[2012-11-06 04:43:41]     -- Executing [start@ssmmc:3] Verbose("lcr/121", "0,Goto(foo-1,1)") in new stack
[2012-11-06 04:43:41] Goto(foo-1,1)
[2012-11-06 04:43:41]     -- Executing [start@ssmmc:4] Goto("lcr/121", "foo-1,1") in new stack
[2012-11-06 04:43:41]     -- Goto (ssmmc,foo-1,1)
[2012-11-06 04:43:41]     -- Executing [foo-1@ssmmc:1] Verbose("lcr/121", "0,hit foo-1") in new stack
[2012-11-06 04:43:41] hit foo-1
{noformat}

{noformat}
[2012-11-06 04:43:48]     -- Executing [start@ssmmc:1] Answer("lcr/122", "") in new stack
[2012-11-06 04:43:48]     -- Executing [start@ssmmc:2] Read("lcr/122", "x,,1") in new stack
[2012-11-06 04:43:48]     -- Accepting a maximum of 1 digits.
[2012-11-06 04:43:49]     -- User entered '2'
[2012-11-06 04:43:49]     -- Executing [start@ssmmc:3] Verbose("lcr/122", "0,Goto(foo-2,1)") in new stack
[2012-11-06 04:43:49] Goto(foo-2,1)
[2012-11-06 04:43:49]     -- Executing [start@ssmmc:4] Goto("lcr/122", "foo-2,1") in new stack
[2012-11-06 04:43:49]     -- Goto (ssmmc,foo-2,1)
[2012-11-06 04:43:49]     -- Executing [foo-2@ssmmc:1] Verbose("lcr/122", "0,hit _foo-! / foo-2") in new stack
[2012-11-06 04:43:49] hit _foo-! / foo-2
{noformat}

{noformat}
[2012-11-06 04:43:54]     -- Executing [start@ssmmc:1] Answer("lcr/123", "") in new stack
[2012-11-06 04:43:54]     -- Executing [start@ssmmc:2] Read("lcr/123", "x,,1") in new stack
[2012-11-06 04:43:54]     -- Accepting a maximum of 1 digits.
[2012-11-06 04:43:55]     -- User entered nothing.
[2012-11-06 04:43:55]     -- Executing [start@ssmmc:3] Verbose("lcr/123", "0,Goto(foo-,1)") in new stack
[2012-11-06 04:43:55] Goto(foo-,1)
[2012-11-06 04:43:55]     -- Executing [start@ssmmc:4] Goto("lcr/123", "foo-,1") in new stack
[2012-11-06 04:43:55]     -- Goto (ssmmc,foo-,1)
[2012-11-06 04:43:55] WARNING[626][C-00000089]: pbx.c:6161 __ast_pbx_run: Channel 'lcr/123' sent to invalid extension but no invalid handler: context,exten,priority=ssmmc,foo-,1
{noformat}


{noformat}
exten => start,1,Answer()
exten => start,n,Read(x,,1)
exten => start,n,Verbose(0,Goto(foo-${x},1))
exten => start,n,Goto(foo-${x},1)
exten => foo-1,1,Verbose(0,hit foo-1)
exten => _foo.,1,Verbose(0,hit _foo. / ${EXTEN})
{noformat}

{noformat}
[2012-11-06 04:46:08]     -- Executing [start@ssmmc:1] Answer("lcr/124", "") in new stack
[2012-11-06 04:46:08]     -- Executing [start@ssmmc:2] Read("lcr/124", "x,,1") in new stack
[2012-11-06 04:46:08]     -- Accepting a maximum of 1 digits.
[2012-11-06 04:46:09]     -- User entered '1'
[2012-11-06 04:46:09]     -- Executing [start@ssmmc:3] Verbose("lcr/124", "0,Goto(foo-1,1)") in new stack
[2012-11-06 04:46:09] Goto(foo-1,1)
[2012-11-06 04:46:09]     -- Executing [start@ssmmc:4] Goto("lcr/124", "foo-1,1") in new stack
[2012-11-06 04:46:09]     -- Goto (ssmmc,foo-1,1)
[2012-11-06 04:46:09]     -- Executing [foo-1@ssmmc:1] Verbose("lcr/124", "0,hit foo-1") in new stack
[2012-11-06 04:46:09] hit foo-1
{noformat}

{noformat}
[2012-11-06 04:46:11]     -- Executing [start@ssmmc:1] Answer("lcr/125", "") in new stack
[2012-11-06 04:46:11]     -- Executing [start@ssmmc:2] Read("lcr/125", "x,,1") in new stack
[2012-11-06 04:46:11]     -- Accepting a maximum of 1 digits.
[2012-11-06 04:46:13]     -- User entered '2'
[2012-11-06 04:46:13]     -- Executing [start@ssmmc:3] Verbose("lcr/125", "0,Goto(foo-2,1)") in new stack
[2012-11-06 04:46:13] Goto(foo-2,1)
[2012-11-06 04:46:13]     -- Executing [start@ssmmc:4] Goto("lcr/125", "foo-2,1") in new stack
[2012-11-06 04:46:13]     -- Goto (ssmmc,foo-2,1)
[2012-11-06 04:46:13]     -- Executing [foo-2@ssmmc:1] Verbose("lcr/125", "0,hit _foo. / foo-2") in new stack
[2012-11-06 04:46:13] hit _foo. / foo-2
{noformat}

{noformat}
[2012-11-06 04:46:15]     -- Executing [start@ssmmc:1] Answer("lcr/126", "") in new stack
[2012-11-06 04:46:15]     -- Executing [start@ssmmc:2] Read("lcr/126", "x,,1") in new stack
[2012-11-06 04:46:15]     -- Accepting a maximum of 1 digits.
[2012-11-06 04:46:16]     -- User entered nothing.
[2012-11-06 04:46:16]     -- Executing [start@ssmmc:3] Verbose("lcr/126", "0,Goto(foo-,1)") in new stack
[2012-11-06 04:46:16] Goto(foo-,1)
[2012-11-06 04:46:16]     -- Executing [start@ssmmc:4] Goto("lcr/126", "foo-,1") in new stack
[2012-11-06 04:46:16]     -- Goto (ssmmc,foo-,1)
[2012-11-06 04:46:16] WARNING[1976][C-0000008c]: pbx.c:6161 __ast_pbx_run: Channel 'lcr/126' sent to invalid extension but no invalid handler: context,exten,priority=ssmmc,foo-,1
{noformat}


In the last example the trailing - is only in the Goto, not in the extension pattern so there seems to be something more to it.

By: Richard Mudgett (rmudgett) 2012-11-19 16:41:58.577-0600

Birger
The last test is invalid because the '-' characters are treated as nonexistent.
goto(foo-,1) is the same as goto(foo,1) which cannot match "_foo.".

By: Richard Mudgett (rmudgett) 2012-11-19 16:42:52.565-0600

See reviewboard:
https://reviewboard.asterisk.org/r/2201/
By: Birger "WIMPy" Harzenetter (wimpy) 2012-11-20 17:17:31.136-0600

I found the same information about "-" being ignored in ASTERISK-16121 but I cannot find any documentation on that special behavior, neither in the wiki (
https://wiki.asterisk.org/wiki/display/AST/Contexts%2C+Extensions%2C+and+Priorities
https://wiki.asterisk.org/wiki/display/AST/Pattern+Matching
) nor in the sample config.
That comes as a little surprise as this "feature" may have unexpected side-effects.

BUT: Even if that's the expected behavior, it doesn't change the expected outcome of the 6 tests I did.
The last one should still match.

By: Richard Mudgett (rmudgett) 2012-11-20 18:26:06.042-0600

{quote}
goto(foo-,1) is the same as goto(foo,1) which cannot match "_foo.".
{quote}

The last one cannot match since '.' matches *one* or more digits and that trailing '-' does not count.
By: Richard Mudgett (rmudgett) 2012-11-20 19:04:24.771-0600

Asterisk has been skipping '\-' chars in patterns and the extens to match with patterns since at least Asterisk v1.2.  It just has not been very consistent about ignoring the '\-' characters as shown by this issue.
By: Birger "WIMPy" Harzenetter (wimpy) 2012-11-20 23:09:40.514-0600

Oh, yes. Now I see the issue. I was just thinking about unintended matches not the other way round.

I really don't want to know how may hours I spent fiddling around in the dialplan in the past years because it didn't work as expected (by me) because of surprise features like this or the wildcards also working lower case.