Summary:	ASTERISK-06919: [patch] Macro does not fully execute when calling party disconnects
Reporter:	Ramon Peek-Fares (ramonpeek)	Labels:
Date Opened:	2006-06-28 10:36:00	Date Closed:	2007-02-07 12:20:39.000-0600
Priority:	Minor	Regression?	No
Status:	Closed/Complete	Components:	Core/Configuration
Versions:		Frequency of Occurrence
Related Issues:
Environment:		Attachments:	( 0) 20070126__bug7440.diff.txt ( 1) ConsoleTraceCalledPartyDisconnects-2.txt ( 2) ConsoleTraceCallingPartyDisconnects-2.txt
Description:	If your dialplan uses a macro to evaluate the hangup cause via the "h" extension and from this macro a second macro is called then this second macro is not fully executed in case the calling party disconnects. Only the first line of the second macro gets executed and then it just stops. ****** STEPS TO REPRODUCE ****** I used the following dialplan to recreate the problem; [test] exten = 100,1,Dial(SIP/100) exten = h,1,Macro(enddial,${DIALSTATUS}) exten = h,n,HangUp [macro-enddial] exten = s,1,NoOp(Macro-enddial: ${ARG1}) exten = s,n,NoOp(Evaluate the call after hangup) exten = s,n,Macro(test)  ; Call second macro exten = s,n,NoOp(end macro enddial) [macro-test] exten = s,1,NoOp(Test macro Line1) exten = s,2,NoOp(Test macro Line2) exten = s,3,NoOp(Test macro Line3) 1. Now dial from a SIP extension to extension 100 in context "test". 2. Answer the call at extension 100 3. Hangup the call at extension 100 (called party hangs up) 4. See the output, like it SHOULD be. 5. Redial extension 100 and answer but now disconnect at the calling party 6. See the output, notice that only the first line of macro "test" is executed?!?! ****** ADDITIONAL INFORMATION ****** Using Asterisk 1.2.9.1 with only SIP-clients, no TDM hardware. SIP clients in my case are Snom phones.
Comments:	By: Serge Vecher (serge-v) 2006-06-28 10:53:54 need tha console log for this, at high verbosity, please. Also, don't forget to set debug to 4 and have debug logged for console in logger.conf By: Ramon Peek-Fares (ramonpeek) 2006-06-29 02:13:58 Added Console Traces... (Note that instead of dialing SIP/100 like shown in dialplan example, I dialed extension SIP/537) "ConsoleTraceCalledPartyDisconnects.txt" 1. Call from SIP/511 to 100 (SIP/537) 2. Extension SIP/537 answers 3. Extension SIP/537 disconnects (CalledParty) 4. Result OK. "ConsoleTraceCallingPartyDisconnects.txt" 1. Call from SIP/511 to 100 (SIP/537) 2. Extensions SIP/537 answers 3. Extensions SIP/511 disconnects (CallingParty) 4. Result Faulty By: Serge Vecher (serge-v) 2006-06-29 08:46:01 ramonpeek: you forgot to enter "set verbose 4" -- that's what gives you high verbosity. Thanks. By: Ramon Peek-Fares (ramonpeek) 2006-07-04 05:02:41 Mmmm... strange I didn't get notified about the new posting... That's why my response is so slow... I'll create the new CLI traces right away... By: Ramon Peek-Fares (ramonpeek) 2006-07-05 07:33:14 Files uploaded as ConsoleTraceCalledPartyDisconnects-2 and ConsoleTraceCallingPartyDisconnects-2 Note: Traces made by setting "console => notice,warning,error,debug,verbose" in logger.conf and then on CLI: "set verbose 4" and "set debug 4". Then capture console output. By: Serge Vecher (serge-v) 2006-07-05 12:15:30 can you please post your macro as well? By: Ramon Peek-Fares (ramonpeek) 2006-07-06 03:10:59 Perhaps you overlooked.. It was already listed under "Steps to reproduce" in this ticket. By: Serge Vecher (serge-v) 2006-07-06 08:46:58 I see -- didn't have 'advanced view' turned on. The line of interest is this one: Jul  4 12:13:10 DEBUG[16322]: app_macro.c:245 macro_exec: Extension s, priority 1 returned normally even though call was hung up By: Serge Vecher (serge-v) 2006-09-01 14:07:00 murf: do you mind looking at this bug here? By: Steve Murphy (murf) 2006-09-01 15:50:13 Sorry, I guess we overlooked this one. This problem was solved in issue 7731. Unfortunately, the fix for this in 41239 is not yet in a 1.2.x release. You'll have to check out the 'trunk' of the 1.2 branch to get the fix. I guess I could have considered 7731 a dupicate of this bug, but in the end, it doesn't matter. By: Steve Murphy (murf) 2006-09-01 15:51:50 Hopefully, this fix will show up in the next 1.2 release, 1.2.9.2 or 1.2.10, or whatever. See 7731 for more gory details. By: Ramon Peek-Fares (ramonpeek) 2007-01-19 10:24:15.000-0600 The issue seemed solved, but I discovered it only works when the extension calling the macro is still the "h" extension. When for example the macro that was called by the "h" extension goes into another extension using for example the Goto function and this extension calls the second macro the problem reappears. I've written the following dialplan to reproduce the error; [test] exten = 100,1,Dial(SIP/100) exten = 200,1,Macro(enddial,NOJUMP) exten = h,1,Macro(enddial,JUMP) [macro-enddial] exten = s,1,NoOp(Macro-enddial called with argument ${ARG1}) exten = s,2,Macro(test); Call the second macro exten = s,3,GotoIf($[${ARG1} = JUMP]?test,200,1) [macro-test] exten = s,1,NoOp(Test macro Line1) exten = s,2,NoOp(Test macro Line2) exten = s,3,NoOp(Test macro Line3) Just call extension 100 in context test and see the difference between the calling party disconnecting or the called party disconnecting. By: Ramon Peek-Fares (ramonpeek) 2007-01-19 10:25:10.000-0600 Note: Now running Asterisk v1.2.13 And I'm using this bugnote instead of 7731 since it's to me more clearly described ;-) By: Ramon Peek-Fares (ramonpeek) 2007-01-22 02:45:01.000-0600 I've just tested this issue in Asterisk 1.4.0. The problem also occurs in this release! By: Steve Murphy (murf) 2007-01-22 07:49:30.000-0600 ramonpeek-- Remember that, as soon as you jump out of a macro, the macro ends and returns. This has confused more than one user! But it is documented. By: Steve Murphy (murf) 2007-01-23 13:39:41.000-0600 I'll have to assume that this issue is closed; the jump out of a macro will not be obeyed, it will merely cause the macro to return instead. If there's more to this issue, feel free to re-open it. You might get the effect you seek if you set some channel var to message the code outside the macro as to a special situation, and act accordingly--- the solution to your problem should exist. Try the #asterisk IRC channel, or the asterisk-users mailing list if you are stumped. By: Ramon Peek-Fares (ramonpeek) 2007-01-26 07:52:37.000-0600 I am aware that when jumping out of a macro the macro ends and returns. However the jump out of a macro to another extensions is allowed and should not result in not fully executing the newly called extension. The docs literly say: "If you Goto out of a Macro context, the Macro will terminate and control will be returned at the location of the Goto" That clearly states that the execution of extension 200 in my example dialplan should not stop as it does!! Please note that; The example dialplan that I've added works fine as long as the called party disconnects, but only fails when the calling party disconnects. This goes to show that this is not a problem with the way the dialplan is created but how the Macro application checks whether a call is still active or not. Please try out the sample dialplan and see for yourself. By: Tilghman Lesher (tilghman) 2007-01-26 10:25:24.000-0600 Okay, I think I understand the problem.  It's that Macro will only continue executing after hangup if it is called from an 'h' extension, and not when it is called from another Macro. Architecturally, this isn't easy to solve.  The problem is that since Macro hides old values on the callstack, they become inaccessible to search when calling Macro recursively.  Going forward, Gosub will have arguments in the version after 1.4, and this problem will be solved by using that set of applications. By: Tilghman Lesher (tilghman) 2007-01-26 10:48:39.000-0600 Okay, patch uploaded for test. By: Tilghman Lesher (tilghman) 2007-01-30 16:35:34.000-0600 You need to test this patch and report back results. By: Ramon Peek-Fares (ramonpeek) 2007-01-31 05:56:07.000-0600 Sorry... our spamfilter blocked mails from digium :-( Will start testing this new patch a.s.a.p By: Ramon Peek-Fares (ramonpeek) 2007-02-02 03:44:55.000-0600 The patch tested succesfull.... However I'll test it in other scenarios during the next 3 days to see whether there are unwanted side affects. I hope not.. Thanks a lot! By: Ramon Peek-Fares (ramonpeek) 2007-02-07 04:48:10.000-0600 I have tested the patch but still found a problem. I've discovered that the issue also occurs in other situations. I'm afraid we have been looking at the issue from the wrong point of view. I discovered that real problem description is: "If a macro is called from any extension other then the 'h' extension while the calling party has already disconnected the macro is not fully executed." So the problem doesn't only occur if a macro is called from another macro. Try this more simpeler dialplan; exten = 100,1,Gosub(playbackscript,play,1) exten = 100,n,Macro(test) exten = 100,n,Hangup [playbackscript] exten = play,1,Playback(tt-monkeys) exten = play,n,Return exten = h,1,Return [macro-test] exten = s,1,NoOp(Test macro Line1) exten = s,2,NoOp(Test macro Line2) exten = s,3,NoOp(Test macro Line3) Just dial 100 and disconnect while the playback is active and the problem will appear because the extension calling the macro 'test' is not the 'h' extension and the callingparty already disconnected. By: Tilghman Lesher (tilghman) 2007-02-07 07:54:23.000-0600 ramonpeek:  This is a completely invalid dialplan.  You are not permitted to call Return without a corresponding Gosub.  Just because you can write an invalid dialplan does not mean the dialplan should execute. By: Ramon Peek-Fares (ramonpeek) 2007-02-07 09:17:03.000-0600 Corydon76: The Gosub is command is given at priority 1 of extension 100. Then a Playback is started at priority 1 of extension 200 in context 'playbackscript'. If we do nothing we end up at the Return command at priority 2, however if we hangup during playback the 'h' extension is executed if available in the context 'playbackscript'. Since it is, it will call the Return command on priority 1 of the 'h' extension, resulting in returning to the original priority + 1 where the previous Gosub was called. And this is de Gosub command given at priority 1 of extension 100. So the call returns to priority 2 of extension 100. This ALL WORKS perfectly, but ONLY fails if we call a macro. I've checked all documentation I could find about Gosub, Return and the 'h' extension but nothing in these documents leads me to think that what I'm doing here is not allowed. Besides this.... it all works fine as long as we do not call a macro.. So I cannot think of anything that is wrong with this dialplan. If something is, please tell me where I can read about this? Or else if something is missing in the documentation we need to make sure it gets added. If this is really an invalid dialplan it's kinda strange that everything works fine as long as we do not use the macro command. And it makes you wonder if, when there are no docs about this, it would be useful to make sure it also works for the macro command? Don't get me wrong I'm not trying to be a pain in the ... ;-) I'll await your answer. P.S.: I've also converted the patch to work in v1.4.0 and it works just like in v1.2.9. Including the problem described in this last setup. By: Ramon Peek-Fares (ramonpeek) 2007-02-07 09:18:16.000-0600 Typo: extension '200' should have been 'play' By: Tilghman Lesher (tilghman) 2007-02-07 09:27:57.000-0600 ramonpeek:  but the Macro is not executing from the h extension, which means it validly exits.  A Macro called from the 'h' extension is the ONLY time a Macro will not exit after a Hangup event occurs.  It is therefore functioning properly. By: Tilghman Lesher (tilghman) 2007-02-07 09:35:58.000-0600 Committed, revisions 53354, 53355, 53356. By: Ramon Peek-Fares (ramonpeek) 2007-02-07 09:57:02.000-0600 Hold on! I was writing a reply since I have to disagree. But when I submitted the bugnote was already read_only causing my text to get lost. Give me some time to reply.. By: Ramon Peek-Fares (ramonpeek) 2007-02-07 10:12:35.000-0600 Corydon76: So you agree that the Return was not called without a Gosub.. But you state that "A Macro called from the 'h' extension is the ONLY time a Macro will not exit after a Hangup event occurs.". Only this is not entirely true since: * The macro is executed but only the first priority will execute. * The macro is executed fully if the called party disconnects instead of the calling party. ( Just replace Playback(tt-monkeys) with Dial(SIP/100) ) * The patch you have written actually fixes something which is conflicting with your statement. Since the second macro in the previous example is also NOT called from the 'h' extension, but called from the macro extension. Why fix that and not this?? * Maybe a bit being a pain in the ass, but this is also not documented and I never heard about this before. (Not even during my dCAP training) Again, I'm sorry but I really need to disagree with your statement. ;-) By: Leif Madsen (lmadsen) 2007-02-07 12:02:41.000-0600 I don't get what you are trying to do here. Why would you expect the dialplan to continue executing after a hangup unless you are parsing in the 'h' extension? This would be unexpected behaviour. By: Leif Madsen (lmadsen) 2007-02-07 12:08:27.000-0600 Further to your points: * The macro is executed but only the first priority will execute. This seems to be a bug. No priorities should execute after the 'h' extension calls Return(). * The macro is executed fully if the called party disconnects instead of the calling party. ( Just replace Playback(tt-monkeys) with Dial(SIP/100) ) That still seems like unexpected behaviour. * The patch you have written actually fixes something which is conflicting with your statement. Since the second macro in the previous example is also NOT called from the 'h' extension, but called from the macro extension. Again, this should not happen. Only that which happens in the 'h' extension should be executed, and no further dialplan execution should continue beyond the call to Return() from 'h'. By: Tilghman Lesher (tilghman) 2007-02-07 12:20:18.000-0600 I think blitzrage and I are in agreement.  This is clearly just abusing the dialplan.  Once you exit the 'h' extension after hangup, all bets are off as to behavior. If you're still interested in making a case for this, please join the #asterisk-bugs channel on freenode.net.  Do not reopen this bug without first discussing this with a bug marshal. By: Leif Madsen (lmadsen) 2007-02-07 12:20:39.000-0600 Yet again, I'm gonna reiterate what I believe "best practice" is going to dictate: You can not expect Asterisk to continue doing anything beyond the 'h' extension with any sort of expected results. You are calling the Return() application from 'h' after the hangup which you indicated you did during the Playback() application. Thus, Asterisk continues executing the dialplan only until an application is able to determine the channel is gone and should exit. Expected behaviour is to perform your post-hangup cleanup within' the 'h' extension. Do not leave the 'h' extension because Asterisk SHOULD NOT continue executing (even if it appears it does for part of a Macro() call, or whatnot). The last priority of all my 'h' extensions is Hangup() which guarentees Asterisk does not try to continue executing somewhere I would not expect it to. My opinion is that the bug of calling something like the following has been resolved. I don't see a valid reason why things in the dialplan should continue executing beyond the 'h' extension. exten => h,1,Macro(foo) [macro-foo] exten => s,1,Macro(bar) [macro-bar] exten => s,1,Verbose(1|My nested macro executed)