[asterisk-bugs] [Asterisk 0014940]: Background application executed in post-Dial Application Macro terminates call

Mon Apr 20 19:26:43 CDT 2009

A NOTE has been added to this issue. 
====================================================================== 
http://bugs.digium.com/view.php?id=14940 
====================================================================== 
Reported By:                p_lindheimer
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   14940
Category:                   Applications/General
Reproducibility:            always
Severity:                   major
Priority:                   normal
Status:                     new
Asterisk Version:           1.4.24 
Regression:                 No 
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!): 177786 
Request Review:              
====================================================================== 
Date Submitted:             2009-04-20 11:37 CDT
Last Modified:              2009-04-20 19:26 CDT
====================================================================== 
Summary:                    Background application executed in post-Dial
Application Macro terminates call
Description: 
Note: I have not had access to a system to further isolate and run some
further tests yet but am providing some details of this issue as requested
on #asterisk-bugs channel. As a result, I can not conclusively say if this
is reproducible on a regular basis or if there are specific circumstances
that must be presented to create the problem.

This dialplan is from FreePBX 2.5 base.

This issue appears to have started at about Asterisk 1.4.24 where it was
first reported on the following two thread and then observed on a
customer's system who was running SVN r177786:

http://freepbx.org/forum/freepbx/users/call-confirmation-fails-after-asterisk-1-4-24-upgrade
http://freepbx.org/forum/freepbx/users/confirm-calls-hang-up

The crux of the issue is that macro-confirm is executed as a post dial
macro in a dialplan that would look something as follows:

Dial(Local/7365924 at from-internal/n,30,M(confirm^^^222)tTwWr))

The macro-confirm code is as follows:

[macro-confirm]
include => macro-confirm-custom
exten => s,1,Set(LOOPCOUNT=0)
exten => s,n,Set(__MACRO_RESULT=ABORT)
exten => s,n,Set(MSG1=${IF($["foo${ARG1}" !=
"foo"]?${ARG1}:"incoming-call-1-accept-2-decline")})
exten =>
s,n(start),Background(${MSG1},m,${CHANNEL(language)},macro-confirm)
exten => s,n,Read(INPUT,,1,,,4)
exten => s,n,GotoIf($[${LEN(${INPUT})} > 0]?${INPUT},1:t,1)
exten => 1,1,GotoIf($["${DB_EXISTS(RG/${ARG3}/${UNIQCHAN})}" =
"0"]?toolate,1)
exten => 1,n,dbDel(RG/${ARG3}/${UNIQCHAN})
exten => 1,n,dbDel(${BLKVM_OVERRIDE})
exten => 1,n,Set(__MACRO_RESULT=)
exten => 1,n(exitopt1),MacroExit()
exten => 2,1,Goto(noanswer,1)
exten => 3,1,SayDigits(${CALLCONFIRMCID})
exten => 3,n,GotoIf($["${DB_EXISTS(RG/${ARG3}/${UNIQCHAN})}" =
"0"]?toolate,1:s,start)
exten => t,1,GotoIf($["${DB_EXISTS(RG/${ARG3}/${UNIQCHAN})}" =
"0"]?toolate,1)
exten => t,n,Set(LOOPCOUNT=$[ ${LOOPCOUNT} + 1 ])
exten => t,n,GotoIf($[ ${LOOPCOUNT} < 5 ]?s,start:noanswer,1)
exten => _X,1,Background(invalid,m,${CHANNEL(language)},macro-confirm)
exten => _X,n,GotoIf($["${DB_EXISTS(RG/${ARG3}/${UNIQCHAN})}" =
"0"]?toolate,1)
exten => _X,n,Set(LOOPCOUNT=$[ ${LOOPCOUNT} + 1 ])
exten => _X,n,GotoIf($[ ${LOOPCOUNT} < 5 ]?s,start:noanswer,1)
exten => noanswer,1,Set(__MACRO_RESULT=ABORT)
exten => noanswer,n(exitnoanswer),MacroExit()
exten => toolate,1,Set(MSG2=${IF($["foo${ARG2}" !=
"foo"]?${ARG2}:"incoming-call-no-longer-avail")})
exten => toolate,n,Playback(${MSG2})
exten => toolate,n,Set(__MACRO_RESULT=ABORT)
exten => toolate,n(exittoolate),MacroExit()
exten => h,1,Macro(hangupcall,)

If the user presses a DTMF digit while the message is playing (typically
"1" to confirm and accept the call) then the call is failing with a log
file entry as shown below.

If they allow the message to play to completion, thus allowing the
dialplan to progress to the subsequent Read() application, then the
dialplan works as expected.

In one reported instance the log file reported the following:

[Apr 2 21:30:21] WARNING[12523] file.c: Unexpected control subclass '-1'
[Apr 2 21:30:27] DEBUG[12523] app_macro.c: Oooh, got something to jump out
with ('1')!
[Apr 2 21:30:27] DEBUG[12523] app_dial.c: Macro exited with status 49
[Apr 2 21:30:27] VERBOSE[12527] logger.c: -- Executing
[h at macro-dialout-trunk:1] Macro("Local/xxxxxxx at from-internal-182b,2",
"hangupcall|") in new stack

In another instance the following was reported:

[Apr 3 10:34:59] DEBUG[17927] app_macro.c: Oooh, got something to jump out
with ('1')!
[Apr 3 10:34:59] DEBUG[17927] app_dial.c: Macro exited with status 49
[Apr 3 10:34:59] DEBUG[17927] channel.c: Hanging up channel
'Local/xxxxxxx at from-internal-d163;1'
[Apr 3 10:34:59] DEBUG[17931] channel.c: Didn't get a frame from channel:
Local/xxxxxxx at from-internal-d163;2
[Apr 3 10:34:59] DEBUG[17931] channel.c: Bridge stops bridging channels
Local/xxxxxxx at from-internal-d163;2 and SIP/vitel-outbound-08632ed8

As can be seen for the dialplan, the background command is properly
directing back to the macro-confirm context. This dialplan has been working
flawlessly for 1-2 years on Asterisk 1.4 and it's variant on Asterisk 1.2
(the variant adjusting for Channel(language) that changed on 1.4).

======================================================================
Relationships       ID      Summary
----------------------------------------------------------------------
related to          0014011 [patch] Incorrect jump to extension
====================================================================== 

---------------------------------------------------------------------- 
 (0103512) tilghman (administrator) - 2009-04-20 19:26
 http://bugs.digium.com/view.php?id=14940#c103512 
---------------------------------------------------------------------- 
See related issue for the cause.  I have uploaded a patch, and testing
would be appreciated. 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2009-04-20 19:26 tilghman       Note Added: 0103512                          
======================================================================