DOSUBL Bug?

[jimbarbour]

 I *think* I've come across a bug with DOSUBL.  When I run the following code with CALL EXECUTE, it runs fine.

CALL  EXECUTE( '%NRSTR(%Main_Program_Macro(FileIn='  || strip(FileLiteral)  ||  ', Iteration='  ||  strip(Iteration)  ||  ');)' );

But when I run the same code with a DOSUBL, below, it gets a very odd error.  Now before you attribute this to the timing difference between the way CALL EXECUTE runs (after the DATA step finishes) vs DOSUBL (immediate execution), hear me out.  This appears to be a subtle bug, so read in detail.

rc = dosubl(%NRSTR('%Main_Program_Macro(FileIn=' || strip(FileLiteral) || ', Iteration=' ||  strip(Iteration) || ');'));

What is the nature of the bug?  Well first let me say I'm running EG 4.3 with an AIX server running SAS 9.3 (9.03.01M2P08152012).

I have a simple data step.  I either CALL EXECUTE or DOSUBL a Main_Program_Macro which consists of three DATA steps.  Each DATA step is followed by a PROC CONTENTS.  Just before each of my three DATA steps, I have the following code:

%LET  Debug=*;

Inside the DATA steps I can selectively control what code executes by putting a &Debug in front of it.  Normally the code won't run since the value of &Debug is an asterisk, but if I change the %LET statement to Debug=; the code will execute. Pretty standard stuff, right?

The PROC CONTENTS after the second of my three DATA steps inside my Main_Program_Macro looks like this:

&Debug	TITLE  "All F20_HLC Eq 1's";
&Debug	PROC CONTENTS 	DATA=&OutLib..All_F20_HLC_Eq_1	POSITION;
&Debug		SYSECHO "Contents All_F20_HLC_Eq_1";
&Debug	RUN  &Control_Value;
%&Debug.Check_SYSERR;

In other words, I don't normally run the PROC CONTENTS unless I'm doing some debugging.  

All is well (it doesn't execute) when I use CALL EXECUTE, but when I use DOSUBL, the PROC CONTENTS, bizarrely, executes.

I did a trace using PUT statements writing to the log.  The value of &Debug before the DATA step is '*'.   The value of &Debug within the DATA step is '*'.  The value after the data step appears to be null.  Why on earth would a macro variable lose it's value after crossing a step boundary?  Hunh?  And it works just fine with CALL EXECUTE.  This sure doesn't seem like a CALL EXECUTE vs. DOSUBL timing issue.  

From the log with a DOSUBL (with some extraneous lines deleted):

NOTE:  Start of Filters 01 Trace, Debug=*
SYMBOLGEN:  Macro variable DEBUG resolves to *
NOTE:  Inside of the Filters Data step non-debug 01 Trace, Debug=*
SYMBOLGEN:  Macro variable DEBUG resolves to *
SYMBOLGEN:  Macro variable DEBUG resolves to *
SYMBOLGEN:  Macro variable DEBUG resolves to *
SYMBOLGEN:  Macro variable DEBUG resolves to *
SYMBOLGEN:  Macro variable DEBUG resolves to *
SYMBOLGEN:  Macro variable DEBUG resolves to *
SYMBOLGEN:  Macro variable DEBUG resolves to *
SYMBOLGEN:  Macro variable DEBUG resolves to *
NOTE: There were 15000 observations read from the data set OUT.HELOC_EOD_FIELD01.
NOTE: The data set OUT.HELOC_EOD_FILTER01 has 15000 observations and 261 variables.
NOTE: Compressing data set OUT.HELOC_EOD_FILTER01 decreased size by 70.31 percent. 
      Compressed is 144 pages; un-compressed would require 485 pages.
NOTE: DATA statement used (Total process time):
      real time           0.34 seconds
      cpu time            0.22 seconds
      
NOTE:  End of Filters data step 01 Trace, Debug=

Do you see the very last note?  Suddenly, after the DATA step but before the PROC CONTENTS, the Debug macro variable has lost its value (when executed via DOSUBL).  It works absolutely stellarly with CALL EXECUTE.

Can anyone explain what is going on here or is this really a bug?

Jim

[Tom]

You be getting burned by this bug in DOSUBL() that causes corruption of global macro variables.

https://communities.sas.com/t5/Base-SAS-Programming/DOSUBL-scope-of-returned-macro-variables/td-p/13...

[jimbarbour]

Possibly, but I'm still in the code submitted by the DOSUBL. The value of the macro variable changes after one of the three data steps inside the Macro executed via DOSUBL. 

If I have time, I'll try to see if the value of the macro variable changes after each of the data steps. 

Jim 

[Quentin]

This sounds very odd.  Agree, if this is all happening within the DOSUBL() side-session, it would be different than the bug I described in the other thread.  That was about potential problems created when macro variables were returned to the main session.

Can you post a small demonstration example of code that replicates the problem?  That is, perhaps a %Main_Program_Macro which creates a macro variable, has a %PUT statement showing the value of the macro variable, runs a data step, and then another %PUT to show that the value of the macro variable has changed.  And also show the DOSUBL() invocation of this macro.   Include the log as well. 

If you can post sample code, I'm sure folks would be happy to try and replicate the problem.

And if you're lucky, if you start with a copy of your real code and try repeatedly cutting it down and simplifying it to make a suitable demonstration case, at one point you may see the problem disappear, providing a potential answer to the question (or at least a clue).

[jimbarbour]

Good idea..I was already stripping down the program which is how I discovered the point of failure. When I get back to the office on Monday, I'll try to strip out all but the essentials and post the code here.

It might be possible to create a quickie program from my verbal description in my original post if anyone were wanting not to wait until Monday.

I'm not certain, but I think that I might be creating a global macro variable named Debug in the autoexec code that runs when I open EG. The odd thing about that is that if so I would give it a default value of asterisk, so I have no idea how my local macro variable could be losing its value. I'll double check this on Monday.

Jim

[jimbarbour]

It's Monday and I'm back at work.  I wanted to look at the code SAS EG executes when I first open the application; see below.  I continue to be mystified.  The value assigned to &Debug when SEG opens is an asterisk.  If somehow the local vs. global macro variables were being confused with one another, I should come up with an asterisk either way; the global &Debug is set to asterisk and the local &Debug is set to asterisk.  How then is it coming up with no value at all when executed via a DOSUBL?  It works perfectly fine with a CALL EXECUTE.  

/** Initialize project/program flow control, program name, and debugging macro variables. **/
%LET  ReturnCode  	=	0;
%LET  Control_Value	=	;
%LET  Debug			=	*;
%LET  Program_Name  =	&_CLIENTTASKLABEL;		/** Available only when submitting from SAS Enterprise Guide. 	**/


/** Define SAS Auto Macro Library (for common macros). **/
OPTION  	SASAUTOS="/home/barbourj/macros/auto";

/** Enable the complied Macro option. **/
LIBNAME		CompMacs	"/home/barbourj/macros/auto/compiled";
OPTIONS		MSTORED		SASMSTORE=CompMacs;

Jim

[jimbarbour · Accepted solution]

Ah.  OK.  Got it.  This is weird, but I see what is happening.  Here is the code that causes the failure to retain values properly in a macro variable:

if mod(_n_,1000)=0 then
  		rc = dosubl(cats('SYSECHO "Filters N=',_n_,'";'));

If the above DOSUBL code exists in the DATA steps of the macro invoked by a prior DOSUBL, the macro variables "go crazy", toggling their values in an odd pattern (but it is a pattern; I'll say more about this in a minute).  In other words, if there is a DOSUBL embedded in code invoked by a DOSUBL, macro variable values appear to become unreliable.  Of course, keep in mind that I'm running EG 4.3 with an AIX server running SAS 9.3 (9.03.01M2P08152012).  Other instances of SAS/SAS EG may not display this behavior.

If someone has a moment, perhaps they could execute the below test program and see if they get the same results that I do.  Pay attention to the values of &Debug displayed before and after each of the DATA steps inside the Test_Macro as well as before and after the primary DATA step outside the Test_Macro. 

OPTIONS   noSYMBOLGEN  noSOURCE  noSOURCE2;

/* ---------------------------------------------------------------------------- */

%MACRO    Test_Macro;

%LET	Debug=;
%PUT    NOTE:  The value of Debug before the 1st Data step=&Debug;

DATA    _NULL_;
&Debug    PUT    "NOTE:  Executing 1st Debug Logic";
        PUT    "NOTE:  Executing 1st Regular Logic";
        PUT    "NOTE:  The value of Debug inside the 1st Data step=&Debug";
		_n_ = 1000;

		if mod(_n_,1000)=0 then
  		rc = dosubl(cats('SYSECHO "Filters N=',_n_,'";'));

RUN;

%PUT    NOTE:  The value of Debug after the 1st Data step=&Debug;

/* ---------------------------------------------------------------------------- */

%LET    Debug=*;
%PUT    NOTE:  The value of Debug before the 2nd Data step=&Debug;

DATA    _NULL_;
&Debug    PUT    "NOTE:  Executing 2nd Debug Logic";
        PUT    "NOTE:  Executing 2nd Regular Logic";
        PUT    "NOTE:  The value of Debug inside the 2nd Data step=&Debug";
		_n_ = 1000;

		if mod(_n_,1000)=0 then
  		rc = dosubl(cats('SYSECHO "Filters N=',_n_,'";'));

RUN;

%PUT    NOTE:  The value of Debug after the 2nd Data step=&Debug;

/* ---------------------------------------------------------------------------- */

%LET    Debug=*;
%PUT    NOTE:  The value of Debug before the 3rd Data step=&Debug;

DATA    _NULL_;
&Debug	PUT    "NOTE:  Executing 3rd Debug Logic";
        PUT    "NOTE:  Executing 3rd Regular Logic";
        PUT    "NOTE:  The value of Debug inside the 3rd Data step=&Debug";
		_n_ = 1000;

		if mod(_n_,1000)=0 then
  		rc = dosubl(cats('SYSECHO "Filters N=',_n_,'";'));
RUN;

%PUT    NOTE:  The value of Debug after the 3rd Data step=&Debug;

%MEND    Test_Macro;

/* ---------------------------------------------------------------------------- */

%PUT  NOTE-  ;
%PUT  NOTE-  ;
%PUT  NOTE:  __________________________________________________________________________________________________;
%PUT  NOTE-  ;
%PUT  NOTE-  ;

%LET    Debug=*; 
%PUT    		NOTE:  Starting primary execution.  The value of Debug=&Debug; 
%&Debug.PUT		NOTE-  Debugging Primary execution 1.  The value of Debug=&Debug; 

DATA  _NULL_;
&Debug	PUT "NOTE: Primary Debug Logic."; 
		PUT    	"NOTE:  The value of Debug before invoking macro, Debug=&Debug"; 
/*		CALL 	EXECUTE( '%NRSTR(%Test_Macro;)' ); */
        RC  =  	DOSUBL(%NRSTR('%Test_Macro;'));
		PUT    	"NOTE:  The value of Debug after invoking macro, Debug=&Debug"; 
        STOP;
RUN;

%PUT  NOTE:	Ending primary execution.  The value of Debug=&Debug; 

%PUT  NOTE-  ;
%PUT  NOTE-  ;
%PUT  NOTE:  __________________________________________________________________________________________________;
%PUT  NOTE-  ;
%PUT  NOTE-  ;

/* ---------------------------------------------------------------------------- */

Below is a screen shot of one of my runs.  I start the run with Debug=*.  I set the value of Debug to nothing before the first DATA Note however that the value of Debug has inexplicably changed to an asterisk after the completion of the first DATA step.  

In like manner, the value of Debug is an asterisk before the second DATA step, but Debug has no value after the second DATA step.

Similarly, in the third DATA step, the value again goes from asterisk to having no value.  This only occurs on runs where the "nested" DOSUBL executes.  Notice how I have a if mod(_n_,1000)=0 then statement before the nested DOSUBL.  If the DOSUBL doesn't execute, the macro variables retain their values in the normal fashion.  But set _n_ to 1000, and the macro variables start toggling back and forth in their odd pattern.  The pattern seems to be this:  The value of the macro variable appears to toggle back to a prior state upon the completion of a data step.  Note that even outside the Test_Macro, the value toggles yet again after the completion of the primary DATA step.

If anyone can reproduce these results, that would be helpful.  Please list what version of SAS you are running.  This bug may also be encountered with Display Manager, SAS web studio etc., but I have not experimented with those other variants of SAS at this juncture.

Jim

[Quentin]

Hi,

I haven't run your whole code, but I think it is related to the other thread about potential for macro variable collisions when using DOSUBL.  As I understand it, each time DOSUBL is called it needs to create the side session, import macro variables into it, and then at the end export macro variables back to the main session. 

Here is code inspired by your post:

%let macvar=GlobalValue;

%macro Test_Macro;
  %*macvar is NOT declared local!;
  %let macvar=InsideValue1;

  %put before dosubl #1;
  %put >>&macvar<<;
  %*put _user_;
  data _null_;
    rc = dosubl("");
  run;
  %put after dosubl #1;
  %put >>&macvar<<;
  %*put _user_;

  %let macvar=InsideValue2;
  %put before dosubl #2;
  %put >>&macvar<<;
  %*put _user_;
  data _null_;
    rc = dosubl("");
  run;
  %put after dosubl #2;
  %put >>&macvar<<;
  %*put _user_;

%mend ;

data _null_;
  rc=DOSUBL(%NRSTR('%Test_Macro;'));
run;

When I run this in 9.3 I get:

before dosubl #1
>>InsideValue1<<

after dosubl #1
>>GlobalValue<<

before dosubl #2
>>InsideValue2<<

after dosubl #2
>>GlobalValue<<

Which seems to show the sort of pattern you are seeing.  If you uncomment the %put _user_; statements, you will see that you end up sometimes with two macro variables in the same scope with the same name, which I think is part of the confusion:

before dosubl #1
>>InsideValue1<<
GLOBAL MACVAR InsideValue1
GLOBAL MACVAR GlobalValue

after dosubl #1
>>GlobalValue<<
TEST_MACRO MACVAR GlobalValue
GLOBAL MACVAR InsideValue1
GLOBAL MACVAR GlobalValue

before dosubl #2
>>InsideValue2<<
TEST_MACRO MACVAR InsideValue2
GLOBAL MACVAR InsideValue1
GLOBAL MACVAR GlobalValue

after dosubl #2
>>GlobalValue<<
TEST_MACRO MACVAR GlobalValue
GLOBAL MACVAR InsideValue1
GLOBAL MACVAR GlobalValue

[jimbarbour]

Interesting.

And, in my little Test_Macro program (see my post prior to this post), I tried two things.

1.  I changed the macro variable inside the Test_Macro to be %LOCAL.  Results are still screwy.  

2. I changed the macro variable inside the Test_Macro to an entirely different name, &Debug2.  Everything now works flawlessly.

So, it's interesting to me that, even when explicitly declared to be local, the use of &Debug causes problems with a DOSUBL that invokes another DOSUBL but using a different name for the macro variable does not.  Clearly, there's some kind of macro variable "confusion" or "collision" going on here.  This, as you say, most likely relates to that other reported problem with macro variable collisions with DOSUBL.

Also interesting is the fact the CALL EXECUTE does all this without batting an eye, even with the very same "inner" DOSUBL.  Likewise, the "outer" DOSUBL works just fine so long as the inner DOSUBL is not invoked.

Jim

[jimbarbour]

Interesting.  On a lark, I disconnected my SAS EG from our AIX server and ran local (on my PC) where I am running 9.03.01M1P11022011.  Everything ran just absolutely fine.  See first log below.  Yet when I connect to our AIX server where I am running a presumably newer version of SAS, 9.03.01M2P08152012 (based on the maintenance levels in bold), the macro variables get all fowled up, see second set log below.  It would appear that the bug that I've discovered is specific to a vary narrow range of SAS versions.

First log, SAS 9.03.01M1P11022011 (everything works fine)

NOTE:  __________________________________________________________________________________________________
     
     
NOTE:  Starting primary execution.  The value of Debug=*
       SYSVLONG4=9.03.01M1P11022011

NOTE:  The value of Debug before invoking macro, Debug=*
NOTE:  The value of Debug before the 1st Data step=
NOTE:  Executing 1st Debug Logic
NOTE:  Executing 1st Regular Logic
NOTE:  The value of Debug inside the 1st Data step=
NOTE: DATA statement used (Total process time):
      real time           0.74 seconds
      cpu time            0.03 seconds
      

NOTE:  The value of Debug after the 1st Data step=
NOTE:  The value of Debug before the 2nd Data step=*
NOTE:  Executing 2nd Regular Logic
NOTE:  The value of Debug inside the 2nd Data step=*
NOTE: DATA statement used (Total process time):
      real time           0.71 seconds
      cpu time            0.03 seconds
      

NOTE:  The value of Debug after the 2nd Data step=*
NOTE:  The value of Debug before the 3rd Data step=*
NOTE:  Executing 3rd Regular Logic
NOTE:  The value of Debug inside the 3rd Data step=*
NOTE: DATA statement used (Total process time):
      real time           0.73 seconds
      cpu time            0.03 seconds
      

NOTE:  The value of Debug after the 3rd Data step=*
NOTE: DATA statement used (Total process time):
      real time           3.10 seconds
      cpu time            0.12 seconds
      
NOTE:  The value of Debug after invoking macro, Debug=*

NOTE: Ending primary execution.  The value of Debug=*
     
     
NOTE:  __________________________________________________________________________________________________
     

Second log SAS 9.03.01M2P08152012 (macro variables get all fowled up)

NOTE:  __________________________________________________________________________________________________
     
     
NOTE:  Starting primary execution.  The value of Debug=*
       SYSVLONG4=9.03.01M2P08152012

NOTE:  The value of Debug before invoking macro, Debug=*
NOTE:  The value of Debug before the 1st Data step=
NOTE:  Executing 1st Debug Logic
NOTE:  Executing 1st Regular Logic
NOTE:  The value of Debug inside the 1st Data step=
NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds
      

NOTE:  The value of Debug after the 1st Data step=*
NOTE:  The value of Debug before the 2nd Data step=*
NOTE:  Executing 2nd Regular Logic
NOTE:  The value of Debug inside the 2nd Data step=*
NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds
      

NOTE:  The value of Debug after the 2nd Data step=
NOTE:  The value of Debug before the 3rd Data step=*
NOTE:  Executing 3rd Regular Logic
NOTE:  The value of Debug inside the 3rd Data step=*
NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds
      

NOTE:  The value of Debug after the 3rd Data step=
NOTE:  The value of Debug after invoking macro, Debug=*
NOTE: DATA statement used (Total process time):
      real time           0.05 seconds
      cpu time            0.01 seconds
      

NOTE: Ending primary execution.  The value of Debug=
     
     
NOTE:  __________________________________________________________________________________________________

Jim

[Quentin]

I would guess CALL EXECUTE avoids this problem because it's simply doing code generation, without all the magic of creating a separate side session to manage.

Note that the collision identified in the other thread has nothing to do with nested DOSUBL blocks.  Simply having a global variable and a local variable with the same name, and then invoking even a null DOSUBL block (creating the side-session and associated import/export of macro variables) will cause the collision.  e.g.:

%macro TestDoSubl(x=);
  %local rc;

  %put Before Dosubl: x=&x;

  data _null_;
    rc=dosubl("");
  run;

  %put After Dosubl: x=&x;

%mend TestDoSubl;

%let x=GlobalValue;
%TestDoSubl(x=LocalValue)

Returns:

121  %let x=GlobalValue;
122  %TestDoSubl(x=LocalValue)
Before Dosubl: x=LocalValue

NOTE: DATA statement used (Total process time):
      real time           0.31 seconds
      cpu time            0.06 seconds


After Dosubl: x=GlobalValue

[Quentin]

Thanks @data_null__, but I think the results are partly do to the way he calls %Test_Macro:

data _null_;
  rc=DOSUBL(%NRSTR('%Test_Macro;'));
run;

When I tried on  9.04.01M0P061913 I got the same results as 9.3.  But honestly, I haven't thought this version of the problem through, just feels the same as the other one.

[data_null__]

---

@Quentin wrote:

Thanks @data_null__, but I think the results are partly do to the way he calls %Test_Macro:

data _null_;
  rc=DOSUBL(%NRSTR('%Test_Macro;'));
run;

When I tried on  9.04.01M0P061913 I got the same results as 9.3.  But honestly, I haven't thought this version of the problem through, just feels the same as the other one.

---

Duh!  Sorry I completly missed the part where you call the macro with DOSUBL.  I will test again but I expect the same result as you show.

[jimbarbour]

I've tried submitting both of the below, and I didn't see any difference in results:

RC = DOSUBL('%Test_Macro;'); 
RC = DOSUBL(%NRSTR('%Test_Macro;'));

CALL EXECUTE on the other hand has no problems at all.  DOSUBL only has problems if another DOSUBL is executed within the code invoked by the first DOSUBL.

I have not tried RUN_MACRO.

Jim