topic Re: verbose logging when called via call execute in SAS Programming

verbose logging when called via call execute

noffer — Fri, 09 Feb 2024 16:03:30 GMT

I have 2 calls to macros that call out to a proc http

Call 1 (called once):

 %sbscrbr_get_jwt_token(&svcurl.,&svcuser.,&svcpwd.);

... works fine, no excessive logging

Call 2 (called many times in worker processes):

 data work_dir.thread_part&threadId.;
   /* do stuff */

         /**** INSERT NORMAL DATA STEP CODE HERE ****/
         call execute('%nrstr(%consent_post2(token='||strip(token)||', consUrl='||strip(cons_url)||' , jsonBody='||strip(json_body)||'));');
   run;

... which results in filling the logs with all sorts of detail about the parameters. I recall there was an options setting that can supress this. I know that I did it once before, but maybe someone recalls what to set to suppress these messages? Its helpful for debugging, but when running `10-100k posts, I think the program spends more time spitting things out to the logs than it does processing data.

Re: proc http verbose logging when called via call execute

SASJedi — Fri, 09 Feb 2024 15:52:07 GMT

Set DEBUG LEVEL=0. See https://go.documentation.sas.com/doc/en/pgmsascdc/default/proc/n0i2ek87s12e7mn1h2q3h0mywkl1.htm

Re: verbose logging when called via call execute

noffer — Fri, 09 Feb 2024 16:09:07 GMT

Messages aren't coming from the proc http, its just dumping the params passed into the macro. That was my first pass. Sorry, I should have noted. I updated the subject as the actual "proc http" not really logging anything else other than the response code, which is fine

Re: verbose logging when called via call execute

Quentin — Fri, 09 Feb 2024 17:52:16 GMT

I'm lost. CALL EXECUTE doesn't have anything special to do with logging, or verbosity of logging. Its job is to generate code.

In this case, it should generate one macro call for each iteration of the DATA step, so you should see lines that say CALL EXECUTE generated the line:

%consent_post2(token=..,consUrl=...,jsonBody=...)

Is that what you want to avoid?

There are ways to turn off writing messages to the log. For example you can use PROC PRINTTO to send the log to a file, or maybe even to nul. But generally IMHO turning off logging is a bad idea. Cuz even if you believe your code is working, you can't know without seeing the log.

Maybe you could post a log snippet of the messages you're trying to avoid?

It's also possible that there is something in the macro definition that is flooding your log. If you just call %consent_post2(token=..,consUrl=...,jsonBody=...) once, without using CALL EXECUTE, does that flood your log?

Re: verbose logging when called via call execute

noffer — Fri, 09 Feb 2024 19:34:54 GMT

Thank you for your reply. Here's a bit of the log:

NOTE: 201 Created
NOTE: PROCEDURE HTTP used (Total process time):
      real time           1.81 seconds
      cpu time            0.01 seconds


11        + %consent_post2
12       
+(token=2048charactertoken,
consUrl="https://someurl" ,
20        + jsonBody='{"definition": "stuff","isGranted": true}');

NOTE: 201 Created
NOTE: PROCEDURE HTTP used (Total process time):
      real time           1.43 seconds
      cpu time            0.01 seconds

As you can see, one variable is 8 lines long, and probably should never be logged (JWT token). Fine with printing the 201's to the log, and even the name of the macro, but posting the parameter values is what I'm trying to get away from. I'll keep tinkering as I'm hearing what you're saying in that the cal execute working as it's supposed to. I know I've solved this once, so I'll post back if I figure it out.

Re: verbose logging when called via call execute

Tom — Fri, 09 Feb 2024 20:22:52 GMT

So I THINK what you are saying is that you are pushing a really long string to CALL EXECUTE() and you don't want to see it all echoed back in the line with the + at the front that CALL EXECUTE() generates.

One way to avoid that is to put the long string into a macro variable and then pass the reference to the macro variable to CALL EXECUTE() but wrap it in %NRSTR() so only the reference is shown, not the value. (Or course that kind of defeats the purpose of having a LOG in the first place.).

Note you will need to make a different macro variable for each observation since the lines pushed to CALL EXECUTE() do not run until after the step that pushed them.

Example:

1    data _null_;
2      set sashelp.class(obs=3);
3      call execute(catx(' ','%nrstr(%put',name,');'));
4    run;

NOTE: There were 3 observations read from the data set SASHELP.CLASS.
NOTE: DATA statement used (Total process time):
      real time           0.01 seconds
      cpu time            0.01 seconds


NOTE: CALL EXECUTE generated line.
1   + %put Alfred ;
Alfred
2   + %put Alice ;
Alice
3   + %put Barbara ;
Barbara
5
6    data _null_;
7      set sashelp.class(obs=3);
8      call symputx(cats('n',_n_),name);
9      call execute(cats('%nrstr(%put &n',_n_,');'));
10   run;

NOTE: There were 3 observations read from the data set SASHELP.CLASS.
NOTE: DATA statement used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds


NOTE: CALL EXECUTE generated line.
1   + %put &n1;
Alfred
2   + %put &n2;
Alice
3   + %put &n3;
Barbara

Re: verbose logging when called via call execute

Quentin — Fri, 09 Feb 2024 20:58:30 GMT

There are systems options that will turn off writing to the log, e.g. options NOSOURCE NONOTES; or as I mentioned even more drastic using PROC PRINTTO.

That is one way that some people solve this problem. Personally, these methods scare me, because the log file is a critical artifact from the SAS run. I'd be shocked if writing the log lines for 1,000 PROC HTTP calls was slowing things down more than the 1,000 PROC HTTP calls. And if you're batch submitting a program, than all those log lines are being written to disk pretty quickly. I guess with some IDE's its possible for the log to 'fill up' or be slow transferring from server to your client.

But even in those settings, I 've never chosen to turn off my log. Even when I have "production code" that I "know works." I don't even like it when EG or another SAS IDE turns off the log temporarily in the wrapper code it generates.

Re: verbose logging when called via call execute

noffer — Fri, 09 Feb 2024 21:11:48 GMT

Thanks for your thoughtful reply, and of course I just found where I'd done it before:

options nosource;

... just before my data step and I still get the Notes printed from the macro execution.