[Home]

Summary:ASTERISK-14733: [patch] Unable to carry over application map functions from 1.4.24 to 1.4.26
Reporter:Ron Byer (ronb)Labels:
Date Opened:2009-08-28 11:44:52Date Closed:2011-06-07 14:08:20
Priority:MinorRegression?Yes
Status:Closed/CompleteComponents:Resources/res_features
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) ast1.4.24.log
( 1) ast1.4.26.log
( 2) confs.tar
( 3) features-debug1.diff
( 4) full
( 5) stripped-confs.tar
Description:I am having a problem with applicationmaps/features in 1.4.26 that I wasn't having in 1.4.24.1 Possibly something changed, or there is a configuration problem but if that's the case, I haven't been able to see it.

Below I will document the relevant parts of the dialplan, as well as log output from the two versions of asterisk.  

What works in 1.4.24:
applicationmap function *75
automon (*8)
blindxfer (#)

What doesn't appear to work in 1.4.26:
all of the above.

extensions.conf:
[macro-stdexten]
exten = s,1,Set(__DYNAMIC_FEATURES=apps#automon)
exten = s,2,Set(DYNAMIC_FEATURES=apps#automon)
exten = s,3,Set(_DYNAMIC_FEATURES=apps#automon)
exten = s,4,GotoIf($["${FOLLOWME_${ARG1}}" = "1"]?7:5)
exten = s,5,Dial(${ARG2},${RINGTIME},${DIALOPTIONS})
exten = s,6,Goto(s-${DIALSTATUS},1)
exten = s,7,Macro(stdexten-followme,${ARG1},${ARG2})
exten = s-NOANSWER,1,Voicemail(${ARG1},u)
exten = s-NOANSWER,2,Goto(default,s,1)
exten = s-BUSY,1,Voicemail(${ARG1},b)
exten = s-BUSY,2,Goto(default,s,1)
exten = _s-.,1,Goto(s-NOANSWER,1)
exten = a,1,VoicemailMain(${ARG1})


[macro-apprecord]
exten => s,1,GotoIf($["${XAD}" = "0" | "${XAD}" = ""]?startrec:stoprec)
exten => s,n(startrec),Set(XAD=1)
exten => s,n,Set(FILENAME=/tmp/MON-${CALLERID(number)})
exten => s,n,NoOp(Filename is ${FILENAME})
exten => s,n,Monitor(wav,${FILENAME},m)
exten => s,n,MacroExit
exten => s,n(stoprec),StopMonitor
exten => s,n,Set(XAD=0)
exten => s,n,MacroExit
========================================

features.conf:

featuredigittimeout = 2000      ; Max time (ms) between digits for

[featuremap]
automon => *78
blindxfer => #
atxfer => *2

[applicationmap]
apps = *75,caller,Macro,apprecord



****** ADDITIONAL INFORMATION ******

running on astlinux svn 2613 (same for both asterisk 1.4.24 and 1.4.26)
net5501

I have CLI output and DTMF logs for both sessions.

Comments:By: Ron Byer (ronb) 2009-08-28 12:02:23

The 2 debug output attachments show:
clean restart of asterisk, entry into CLI (show version number)
reload res_features.so (show app applicationmap getting registered)
call bridge, with DYNAMIC_FEATURES being set.
2 attempts to invoke *75 (1.4.24 case turns it on/off).
attempt to transfer call using single '#'

in the 1.4.26 case. I ran the sequence twice. The first case the DTMF output complained mildly that the DTMF time was 60 ms, which was shorter than the desired 80 ms. I ran it again with longer DTMF tones.
By: Ron Byer (ronb) 2009-08-28 12:06:07

I debated putting the severity as 'block', since it would appear that I can happily use a prior version 1.4.24, leaving this as a minor issue.

However, as I understand it, there was a backport on local channel DIAL function "/n' to 1.4.26 which I am hoping to take advantage of for a customer feature request. Given that I've already promised these feature, I labelled it as block.

Let me know if you need anything else.
By: judd (judd) 2009-09-08 00:52:36

Hi,

We are experiencing a similar issue.  We use an applicationmap to fire a macro when '*0' is pressed.  On asterisk 1.4.25.1 this would work fine when either the caller or callee dialled it.  However since upgrading to version 1.4.26.2 the following occurs:

As background the topology used here is SIP IP phones connect to a server running asterisk which registers to an external service via IAX.

- Call in to SIP phone via IAX trunk, caller dials '*0'. applicationmap not fired
- Call in to SIP phone via IAX trunk, callee dials '*0'. applicationmap not fired
- Call out from SIP phone through IAX trunk, caller dials '*0'. applicationmap fires correctly
- Call out from SIP phone through IAX trunk, callee dials '*0'. applicationmap fires correctly

Please let me know what further details I can provide for assistance.

Thank you.
By: judd (judd) 2009-09-08 01:58:32

Please disregard the note above.  This was due to user error on my part.  I apologise for any inconvenience caused.
By: Matthew Nicholson (mnicholson) 2009-09-28 09:48:59

I was unable to reproduce this with svn 1.4 branch rev 220288 or with 1.4.26.  Can you provide more information on reproducing this bug?

I tested by configuring the applicationmap you posted in your report and a similar extensions.conf.  I then bridged a call and successfully activated the feature by dialing *75 multiple times.
By: Ron Byer (ronb) 2009-09-28 12:28:30

I created a new log file with the dialplan and cli output in it, but then realized I had already sent that and it presents nothing new.

In both cases (1.4.24 and 1.4.26) the application registers.
==================================
sk3*CLI> reload res_features.so

sk3*CLI>
The 'reload' command is deprecated and will be removed in a future release. Please use 'module reload' instead.
   -- Reloading module 'res_features.so' (Call Features Resource)
 == Parsing '/etc/asterisk/features.conf': Found
 == Registered Feature 'apps'
 == Mapping Feature 'apps' to app 'Macro(apprecord)' with code '*75'
   -- Added extension '700' priority 1 to parkedcalls
======================================================
The 1.4.24 DTMF log shows the incoming DTMF codes for *75, followed by the succesfull connection to the app
=======================================================
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF begin '*' received on SIP/120-081c7bc8
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF begin passthrough '*' on SIP/120-081c7bc8
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF end '*' received on SIP/120-081c7bc8, duration 60 ms
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF end accepted with begin '*' on SIP/120-081c7bc8
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF end '*' has duration 60 but want minimum 80, emulating on SIP/120-081c7bc8
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF end emulation of '*' queued on SIP/120-081c7bc8
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF begin '7' received on SIP/120-081c7bc8
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF begin passthrough '7' on SIP/120-081c7bc8
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF end '7' received on SIP/120-081c7bc8, duration 80 ms
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF end accepted with begin '7' on SIP/120-081c7bc8
[Aug 28 12:49:09] DTMF[18765] channel.c: DTMF end passthrough '7' on SIP/120-081c7bc8
[Aug 28 12:49:10] DTMF[18765] channel.c: DTMF begin '5' received on SIP/120-081c7bc8
[Aug 28 12:49:10] DTMF[18765] channel.c: DTMF begin passthrough '5' on SIP/120-081c7bc8
[Aug 28 12:49:10] DTMF[18765] channel.c: DTMF end '5' received on SIP/120-081c7bc8, duration 80 ms
[Aug 28 12:49:10] DTMF[18765] channel.c: DTMF end accepted with begin '5' on SIP/120-081c7bc8
[Aug 28 12:49:10] DTMF[18765] channel.c: DTMF end passthrough '5' on SIP/120-081c7bc8
[Aug 28 12:49:10] VERBOSE[18765] logger.c:     --  Feature Found: apps exten: apps
[Aug 28 12:49:10] VERBOSE[18765] logger.c:     -- Executing [s@macro-apprecord:1] GotoIf("SIP/120-081c7bc8", "1?startrec:stoprec") in new stack
======================================================

In the 1.4.26 case, I see the DTMF codes the same way, but no connection to the app following. In this case, I tried the "#" to transfer the call after it was evident that there was application following.

==================================================================
[Aug 28 12:53:07] VERBOSE[18822] logger.c:     -- SIP/120-081c3638 answered SIP/freehold-sk3-081c7c48
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF begin '*' received on SIP/120-081c3638
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF begin passthrough '*' on SIP/120-081c3638
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF end '*' received on SIP/120-081c3638, duration 80 ms
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF end accepted with begin '*' on SIP/120-081c3638
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF end passthrough '*' on SIP/120-081c3638
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF begin '7' received on SIP/120-081c3638
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF begin passthrough '7' on SIP/120-081c3638
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF end '7' received on SIP/120-081c3638, duration 60 ms
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF end accepted with begin '7' on SIP/120-081c3638
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF end '7' has duration 60 but want minimum 80, emulating on SIP/120-081c3638
[Aug 28 12:53:10] DTMF[18822] channel.c: DTMF end emulation of '7' queued on SIP/120-081c3638
[Aug 28 12:53:11] DTMF[18822] channel.c: DTMF begin '5' received on SIP/120-081c3638
[Aug 28 12:53:11] DTMF[18822] channel.c: DTMF begin passthrough '5' on SIP/120-081c3638
[Aug 28 12:53:11] DTMF[18822] channel.c: DTMF end '5' received on SIP/120-081c3638, duration 80 ms
[Aug 28 12:53:11] DTMF[18822] channel.c: DTMF end accepted with begin '5' on SIP/120-081c3638
[Aug 28 12:53:11] DTMF[18822] channel.c: DTMF end passthrough '5' on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF begin '*' received on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF begin passthrough '*' on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end '*' received on SIP/120-081c3638, duration 60 ms
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end accepted with begin '*' on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end '*' has duration 60 but want minimum 80, emulating on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end emulation of '*' queued on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF begin '7' received on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF begin passthrough '7' on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end '7' received on SIP/120-081c3638, duration 80 ms
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end accepted with begin '7' on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end passthrough '7' on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF begin '5' received on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF begin passthrough '5' on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end '5' received on SIP/120-081c3638, duration 80 ms
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end accepted with begin '5' on SIP/120-081c3638
[Aug 28 12:53:13] DTMF[18822] channel.c: DTMF end passthrough '5' on SIP/120-081c3638
[Aug 28 12:53:15] DTMF[18822] channel.c: DTMF begin '#' received on SIP/120-081c3638
[Aug 28 12:53:15] DTMF[18822] channel.c: DTMF begin passthrough '#' on SIP/120-081c3638
[Aug 28 12:53:15] DTMF[18822] channel.c: DTMF end '#' received on SIP/120-081c3638, duration 60 ms
[Aug 28 12:53:15] DTMF[18822] channel.c: DTMF end accepted with begin '#' on SIP/120-081c3638
[Aug 28 12:53:15] DTMF[18822] channel.c: DTMF end '#' has duration 60 but want minimum 80, emulating on SIP/120-081c3638
[Aug 28 12:53:15] DTMF[18822] channel.c: DTMF end emulation of '#' queued on SIP/120-081c3638
[Aug 28 12:53:21] VERBOSE[18822] logger.c:   == Spawn extension (macro-stdexten, s, 5) exited non-zero on 'SIP/freehold-sk3-081c7c48' in macro 'std
===================================================================


My method of testing is that using the same configuration files on the same machine, I simply switch between asterisk versions (as well as chan_dahdi which has  a symbol dependency), restart asterisk, and bridge a call. In the 1.4.24 case, the app function works as expected. In the 1.4.26 case, there is no response to the key sequence (*75), nor to a simple # for transfer.  I can switch back and forth and the problem stays with the version (1.4.26).

This is running on astlinux, but it is a complete version of asterisk that I have built myself.

please suggest what additional information I can provide :: additional log output,conf file tarball ? whatever I can do to help get past thing efficiently
I'll do.

Thanks.
By: Ron Byer (ronb) 2009-09-28 12:33:58

I noticed that the 1.4.26 DTMF sequence I used had the digittimeout complaints. here is the same sequence without the digittimeout complaints.
=========================================
[Aug 28 12:54:46] VERBOSE[18824] logger.c:     -- SIP/120-081c7c48 answered SIP/freehold-sk3-081a6798
[Aug 28 12:54:48] DTMF[18824] channel.c: DTMF begin '*' received on SIP/120-081c7c48
[Aug 28 12:54:48] DTMF[18824] channel.c: DTMF begin passthrough '*' on SIP/120-081c7c48
[Aug 28 12:54:48] DTMF[18824] channel.c: DTMF end '*' received on SIP/120-081c7c48, duration 220 ms
[Aug 28 12:54:48] DTMF[18824] channel.c: DTMF end accepted with begin '*' on SIP/120-081c7c48
[Aug 28 12:54:48] DTMF[18824] channel.c: DTMF end passthrough '*' on SIP/120-081c7c48
[Aug 28 12:54:48] DTMF[18824] channel.c: DTMF begin '7' received on SIP/120-081c7c48
[Aug 28 12:54:48] DTMF[18824] channel.c: DTMF begin passthrough '7' on SIP/120-081c7c48
[Aug 28 12:54:49] DTMF[18824] channel.c: DTMF end '7' received on SIP/120-081c7c48, duration 220 ms
[Aug 28 12:54:49] DTMF[18824] channel.c: DTMF end accepted with begin '7' on SIP/120-081c7c48
[Aug 28 12:54:49] DTMF[18824] channel.c: DTMF end passthrough '7' on SIP/120-081c7c48
[Aug 28 12:54:49] DTMF[18824] channel.c: DTMF begin '5' received on SIP/120-081c7c48
[Aug 28 12:54:49] DTMF[18824] channel.c: DTMF begin passthrough '5' on SIP/120-081c7c48
[Aug 28 12:54:49] DTMF[18824] channel.c: DTMF end '5' received on SIP/120-081c7c48, duration 100 ms
[Aug 28 12:54:49] DTMF[18824] channel.c: DTMF end accepted with begin '5' on SIP/120-081c7c48
[Aug 28 12:54:49] DTMF[18824] channel.c: DTMF end passthrough '5' on SIP/120-081c7c48
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF begin '*' received on SIP/120-081c7c48
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF begin passthrough '*' on SIP/120-081c7c48
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF end '*' received on SIP/120-081c7c48, duration 240 ms
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF end accepted with begin '*' on SIP/120-081c7c48
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF end passthrough '*' on SIP/120-081c7c48
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF begin '7' received on SIP/120-081c7c48
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF begin passthrough '7' on SIP/120-081c7c48
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF end '7' received on SIP/120-081c7c48, duration 180 ms
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF end accepted with begin '7' on SIP/120-081c7c48
[Aug 28 12:54:52] DTMF[18824] channel.c: DTMF end passthrough '7' on SIP/120-081c7c48
[Aug 28 12:54:53] DTMF[18824] channel.c: DTMF begin '5' received on SIP/120-081c7c48
[Aug 28 12:54:53] DTMF[18824] channel.c: DTMF begin passthrough '5' on SIP/120-081c7c48
[Aug 28 12:54:53] DTMF[18824] channel.c: DTMF end '5' received on SIP/120-081c7c48, duration 240 ms
[Aug 28 12:54:53] DTMF[18824] channel.c: DTMF end accepted with begin '5' on SIP/120-081c7c48
[Aug 28 12:54:53] DTMF[18824] channel.c: DTMF end passthrough '5' on SIP/120-081c7c48
[Aug 28 12:54:56] DTMF[18824] channel.c: DTMF begin '#' received on SIP/120-081c7c48
[Aug 28 12:54:56] DTMF[18824] channel.c: DTMF begin passthrough '#' on SIP/120-081c7c48
[Aug 28 12:54:57] DTMF[18824] channel.c: DTMF end '#' received on SIP/120-081c7c48, duration 260 ms
[Aug 28 12:54:57] DTMF[18824] channel.c: DTMF end accepted with begin '#' on SIP/120-081c7c48
[Aug 28 12:54:57] DTMF[18824] channel.c: DTMF end passthrough '#' on SIP/120-081c7c48
[Aug 28 12:55:01] VERBOSE[18824] logger.c:   == Spawn extension (macro-stdexten, s, 5) exited non-zero on 'SIP/freehold-sk3-081a6798' in macro 'stdexten'
==========================================================
By: Matthew Nicholson (mnicholson) 2009-09-28 12:40:10

Please try testing this with a minimal set of configs.  Use the default settings for everything except features.conf, sip.conf, and extensions.conf and see if you can still reproduce the bug.  This should help narrow down exactly what the problem is.
By: Ron Byer (ronb) 2009-10-05 17:04:58

This took longer than it should have, but I have tested this problem with minimal configs, namely extensions.conf, users.conf, features.conf. Sip.conf wasn't modified at all. Results were the same as previously reported.

I'm attached the conf files. I've include tarfiles of both full confs and ones with comments/blanklines stripped. Not sure which is more useful.


By: Ron Byer (ronb) 2009-10-05 17:08:07

I didn't include any additional logs or CLI output, since they *appeared* identical (famous latest words). If you think the log output from these runs are useful, I can rerun pretty easily. will save this configuration.
By: Matthew Nicholson (mnicholson) 2009-10-09 13:55:34

I am going to attempt to reproduce this using a subset of your configs.  Thanks for following up on this.
By: Matthew Nicholson (mnicholson) 2009-10-09 15:30:30

I was not able to reproduce this.  On Monday, I will upload a patch designed to provide additional debugging information that should help to locate the problem.
By: Matthew Nicholson (mnicholson) 2009-10-12 09:57:56

Please test with the patch I just uploaded with debug level set to 3 and post your results.  I am interested in NOTICE messages that should be generated while the patch is applied..
By: Ron Byer (ronb) 2009-10-12 15:29:11

I attached a log file with the additional logging... but it's a formality. It works now, and with a little digging I've found my own problem.

Recent version upgrades have neglected to update res_features (at least.. I will look for more victims next). The upgrade to 1.4.26 neglected to update res_features, which stay pre-1.4.26. So, while I thought I was isolating it to a version problem, I wasn't.

===========================
sh-3.2# strings res_features.so | grep Revision
$Revision: 211596 $
sh-3.2# strings res_features.so.save | grep Revision
$Revision: 179840 $
sh-3.2#
===========================

I should have seen this sooner. Many thanks for your help and patience, and my apologies.

Ron
By: Matthew Nicholson (mnicholson) 2009-10-12 15:32:12

Glad to hear it is working for you now :)  Do you have any idea why it was failing to update res_features?
By: Ron Byer (ronb) 2009-10-12 15:52:26

I don't know yet. An entire disk image gets rolled up as part of a build and is then ready to deliver and boot from.  However, it won't take long to find now.

Thanks again.