[Home]

Summary:ASTERISK-19143: Core dump when adding dialplan extension
Reporter:Steven Wheeler (swheeler)Labels:
Date Opened:2011-12-30 12:15:06.000-0600Date Closed:2015-03-13 21:06:32
Priority:MajorRegression?
Status:Closed/CompleteComponents:Core/Configuration
Versions:1.8.7.2 1.8.8.0 Frequency of
Occurrence		Frequent
Related
Issues:
is duplicated byASTERISK-24444 PBX: Crash when generating extension for pattern matching hint
Environment:CentOS 5.5Attachments:( 0) 32s.patch
( 1) backtrace.txt
( 2) backtrace-20120305-1136.txt
( 3) backtrace-20120305-1138.txt
( 4) full_debug.log
( 5) full.log
Description:asterisk -rx "dialplan add extension steventest2-swheeler,hint,SIP/steventest2-swheeler_softphone&Custom:unavailable into blf replace

Executing this command will occasionally cause asterisk to segfault.  From what I can tell in the back trace the issue seems to be related to logging the message "Found duplicate exten. Had %s found %s".  Please see the attached back trace and debug logs for more information.
Comments:By: Steven Wheeler (swheeler) 2011-12-30 12:16:24.901-0600

Output of gdb 'bt full' and 'thread apply all bt'.
By: Steven Wheeler (swheeler) 2011-12-30 12:17:33.725-0600

Asterisk logging output.
By: Steven Wheeler (swheeler) 2011-12-30 12:22:32.369-0600

Asterisk logging output with debug enabled.
By: Stefan Schmidt (schmidts) 2012-01-02 08:54:06.303-0600

why do you call asterisk -rx to change the dialplan in this case? IMHO what you are looking for is the DEVSTATE function?

i am not sure if this really would help in that case but i also tried to reproduce this problem with 1.8 svn version and i didnt get it to crash.

but using system(asterisk -rx... doesnt sounds like a good idea to me at all.
you will see a lot of deadlocks and crashes when you do it like this.

By: Steven Wheeler (swheeler) 2012-01-10 09:29:50.239-0600

Sorry for the delayed response I was out on vacation last week.  We use asterisk -rx because we actually need to change which devices are included in the hint as the "real-time" lookup is not really done in real-time.  What we are trying to accomplish is BLF for hot desking users which can be assigned multiple devices and can change dynamically.  As far as I know the DEVSTATE function doesn't allow you to change which devices are included in the hint.  It just lets you check the state of a device or set a custom state.

I would love to get away from using asterisk -rx to change the hints as I agree it is a horrible hack.  However, we couldn't find any other way to do it with the current real-time hint limitations.
By: Steven Wheeler (swheeler) 2012-01-12 11:03:07.547-0600

We have now seen this a few times in our production system as well.  It appears to crash only if someone is watching the console with asterisk -r.
By: Sébastien Couture (sysreq) 2012-03-05 11:52:44.383-0600

I've experienced the same issue twice this morning, on 1.8.8.2.

I'm using dynamic hints and it seems that issue arises when a phone tries to subscribe to a hint that contains characters other than numbers (in my case, parentheses).

Consider the following hint:

[hinthint]

exten => _X.,hint,SIP/${EXTEN}

A phone tries to subscribe to something like '1(60)', which triggers the matching pattern a creates an extension by the same name in the user's default subscribe context at priority -1. That, in turn, in confirmed by the following:

-- Added extension '1(60)' priority -1 to hinthint

The crash doesn't happen right away. Either the same user or another one needs to try to subscribe to the same bogus hint multiple times for it to happen. After a couple of those, Asterisk segfaults:

[Mar  5 11:38:35] WARNING[12489] pbx.c: Found duplicate exten. Had 1(60) found 1(60)
[Mar  5 11:38:35] WARNING[12489] pbx.c: Unable to register extension '1(60)', priority -1 in 'hinthint', already in use

Hope this helps. I'll attach the two backtraces from this morning.

Thanks.
By: Sébastien Couture (sysreq) 2012-03-05 11:58:15.254-0600

Oh, I forgot to mention. I'm pretty sure my specific case has to do with the bogus characters given in the device part of the hint and can most likely be avoided by using something like FILTER(0-9,${EXTEN}) to only allow for numbers to be used.

That'll be my first step in trying to avoid the crashes until the bug is resolved.
By: alexr1 (alexr1) 2014-07-06 19:06:40.518-0500

I'm experiencing this problem on a production system running 1.8.24.0 which was released over a year after this issue was opened.

Is it worth trying a newer version? How are others getting around this issue? I see there's no resolution to this issue or this related issue: ASTERISK-19711

In my case, it's from dynamic hints:
{noformat}
exten => _X.,hint,${IF($[${EXTEN:0:2} = 83]?SIP/${EXTEN}:Custom:83-${EXTEN})}
{noformat}
(If they are trying to subscribe to anything beginning with 83, then it's a SIP device, otherwise it's a custom device).

Doesn't appear to be related to special characters.

Crash 1.
{noformat}
[2014-07-07 09:24:03] VERBOSE[1886] pbx.c:     -- Added extension '04XXXX680' priority -1 to pbx-outgoing-83
[2014-07-07 09:24:03] VERBOSE[1886] pbx.c:     -- Added extension '04XXXX151' priority -1 to pbx-outgoing-83
[2014-07-07 09:24:03] WARNING[1886] pbx.c: Found duplicate exten. Had 04XXXX0151 found 04XXXX0151
[2014-07-07 09:24:03] WARNING[1886] pbx.c: Unable to register extension '04XXXX0151' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:04] VERBOSE[1886] pbx.c:     -- Added extension '04XXXX8489' priority -1 to pbx-outgoing-83
[2014-07-07 09:24:04] VERBOSE[1886] pbx.c:     -- Added extension '04XXXX9689' priority -1 to pbx-outgoing-83
[2014-07-07 09:24:04] VERBOSE[1886] pbx.c:     -- Added extension '02XXXX6769' priority -1 to pbx-outgoing-83
[2014-07-07 09:24:04] WARNING[1886] pbx.c: Found duplicate exten. Had 02XXXX6769 found 02XXXX6769
[2014-07-07 09:24:04] WARNING[1886] pbx.c: Unable to register extension '02XXXX6769' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:04] VERBOSE[1886] pbx.c:     -- Added extension '04XXXX1997' priority -1 to pbx-outgoing-83
--end of log--
{noformat}



Crash 2.
{noformat}
[2014-07-07 09:24:23] WARNING[8800] pbx.c: Found duplicate exten. Had 04XXXX3311 found 04XXXX3311
[2014-07-07 09:24:23] WARNING[8800] pbx.c: Unable to register extension '04XXXX3311' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:23] WARNING[8800] pbx.c: Found duplicate exten. Had 04XXXX8015 found 04XXXX8015
[2014-07-07 09:24:23] WARNING[8800] pbx.c: Unable to register extension '04XXXX8015' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:23] WARNING[8800] pbx.c: Found duplicate exten. Had (null) found 02XXXX1879
[2014-07-07 09:24:23] WARNING[8800] pbx.c: Unable to register extension '02XXXX1879' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:23] WARNING[8800] pbx.c: Found duplicate exten. Had 02XXXX1879 found 02XXXX1879
[2014-07-07 09:24:23] WARNING[8800] pbx.c: Unable to register extension '02XXXX1879' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:24] WARNING[8800] pbx.c: Found duplicate exten. Had (null) found 04XXXX9956
[2014-07-07 09:24:24] WARNING[8800] pbx.c: Unable to register extension '04XXXX9956' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:24] WARNING[8800] pbx.c: Found duplicate exten. Had 04XXXX9956 found 04XXXX9956
[2014-07-07 09:24:24] WARNING[8800] pbx.c: Unable to register extension '04XXXX9956' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:24] WARNING[8800] pbx.c: Found duplicate exten. Had (null) found 04XXXX3311
[2014-07-07 09:24:24] WARNING[8800] pbx.c: Unable to register extension '04XXXX3311' priority -1 in 'pbx-outgoing-83', already in use
[2014-07-07 09:24:24] WARNING[8800] pbx.c: Found duplicate exten. Had 04XXXX3311 found 04XXXX3311
[2014-07-07 09:24:24] WARNING[8800] pbx.c: Unable to register extension '04XXXX3311' priority -1 in 'pbx-outgoing-83', already in use
--end of log--
{noformat}

By: alexr1 (alexr1) 2014-07-07 19:54:09.175-0500

Upgraded to Asterisk 11 (latest version Asterisk 11.10.2). Issue is STILL present - should I be creating a new issue about this?

Bounty posted to asterisk-dev mailing list.
By: Richard Mudgett (rmudgett) 2014-07-08 12:45:25.341-0500

No. Don't create a new issue just because the version is different.  It will only get closed as a duplicate.
By: Russell Bryant (russell) 2014-07-08 20:07:27.829-0500

@alexr1: Can you post a backtrace of your crash?  I'd like to see something against the latest code, as a lot has changed since these original backtraces.
By: cloos (cloos) 2014-07-10 10:51:40.623-0500

A core dump also would be helpful, to see what the pointers point at.
By: alexr1 (alexr1) 2014-07-20 04:39:17.054-0500

If you look at the backtraces you can see an encoded space: %20 in the SIP URI (from the SUBSCRIBE request).

In issue ASTERISK-19711
{noformat}
readbuf = "SUBSCRIBE sip:418-766-2000%20x4696@64.254.249.114:5060 SIP/2.0.....
{noformat}

In this issue ASTERISK-19143:
{noformat}
readbuf = "SUBSCRIBE sip:1%20(35%20)@64.254.249.110:5060 SIP/2.0......
{noformat}

I can reproduce this issue in the latest 1.8 or 11 when you try and subscribe multiple times to an extension containing %20. It may not happen instantly, but it will happen after multiple subscribes. 1.8 seemed to crash with a trailing %20, but 11 only crashed after I prefixed the extension with %20.. despite showing corruption: pbx.c:2402 add_exten_to_pattern_tree: Found duplicate exten. Had b¡Æ)

I used the following subscriptions to trigger the crash:
{noformat}
%2002112
02113%20
%2002114
{noformat}

With this hint:
{noformat}
exten => _X.,hint,${IF($[${EXTEN:0:2} = 02]?SIP/${EXTEN}:Custom:02-${EXTEN})}
{noformat}

Over to you - bounty still available to the first person to patch :)
By: cloos (cloos) 2014-07-26 23:51:38.870-0500

The segv only occurs when there is a space in the extension string.

It looks like at some point a struct ast_exten.exten string gets stored w/o a trailing NULL.

When __ast_str_helper() tries to determine how long the resulting string will be, it calls vnsprintf which follows the unterminated "string" data past the end of allocation, causing a SEGV.

(At least a missing NULL is the most likely reason; changing the %s to %p, to see the address of the char*s, showed reasonable values. So it isn’t that the va itself is outside of allocated memory.)

pbx.c has this warning in pbx_builtin_setvar():

“Please avoid unnecessary spaces on variables as it may lead to unexpected results”

Since the segv only occurred when a new exten with a space duplicated an existing, one of the functions which skips spaces must fail to include a proper termination, a race allows the terminator to get overwritten or something should be setting the deleted flag, but fails to do so.

(I hope I edited that correctly; this *tiny* text box is most painful.)
By: cloos (cloos) 2014-07-29 12:37:51.096-0500

Limiting the accepted length of the arguments to the "%s" formats should prevent vsnprintf(3) from searching for the end of the strings, and therefor should prevent the SEGV.

This patch proposes a limit of thirty-two characters.

By: alexr1 (alexr1) 2014-08-05 10:08:22.215-0500

Unfortunately the patch does not solve the issue (on 1.8, unsure about 11), however your earlier solution (by email) to replace the %s with %p does work - so I'm happy to stick with that for now.

I moved back to 1.8.24 on the production system for various reasons and it seems that there is not always a valid pointer... (In Ast 11, there did seem to be a valid pointer all the time, but I didn't do extensive testing after it stopped crashing)

{noformat}
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:2230 add_exten_to_pattern_tree: Found duplicate exten. Had (nil) found 0x7f5d9ce8daa8
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:8576 add_priority: Unable to register extension '02111' priority -1 in 'pbx-outgoing-02', already in use
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:2230 add_exten_to_pattern_tree: Found duplicate exten. Had 0x7f5d9ce69900 found 0x7f5d9ce25878
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:8576 add_priority: Unable to register extension '02111' priority -1 in 'pbx-outgoing-02', already in use
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:2230 add_exten_to_pattern_tree: Found duplicate exten. Had 0x7f5d9cf8e460 found 0x7f5d9d2105d8
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:8576 add_priority: Unable to register extension '02115' priority -1 in 'pbx-outgoing-02', already in use
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:2230 add_exten_to_pattern_tree: Found duplicate exten. Had 0x7f5d9c719f20 found 0x7f5d9cea05b8
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:8576 add_priority: Unable to register extension '02115' priority -1 in 'pbx-outgoing-02', already in use
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:2230 add_exten_to_pattern_tree: Found duplicate exten. Had (nil) found 0x7f5d9cf7a798
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:8576 add_priority: Unable to register extension '02113' priority -1 in 'pbx-outgoing-02', already in use
[2014-08-06 00:54:18] WARNING[12763]: pbx.c:2230 add_exten_to_pattern_tree: Found duplicate exten. Had 0x7f5d9cd891f0 found 0x7f5d9cf1f298
{noformat}