submit() hangs with STDIO on Linux in certain situations

Describe the bug This is a follow-up of #443. I just stumbled across it now. Sorry for not noticing before.

To reproduce The following is a minimal working example that will hang forever when using STDIO on Linux:

import saspy

sas = saspy.SASsession()
sas.submit("%macro cancel; %abort cancel; %mend; %cancel")

Expected behavior The program above terminates in an instant.

Analysis I have not yet figured out why it hangs.

Thank you very much, that helps indeed.

I now fixed the problem by breaking the loop in lines 831-964 in sasiostdio.py as soon as logf contains the error message "ERROR: Execution canceled by an %ABORT CANCEL statement.". Maybe killing the SAS process in this situation would also be a good idea?

Yes, for that case, there's no way for me to detect that SAS isn't going to send over any output, so I'm stuck waiting on output that will never come. SAS doesn't terminate on it's own in this case, or I would catch that and return with a failure. So, hitting attn, ctl-c, break, whatever it's called in the interface you're using, will drive my attn handler and then you can terminate the session. I don't have a better way to deal with this specific (un-useful, won't work, will only make SAS unusable) case. Kinda have to fall back to simply:, 'don't submit that statement, no good can come of it.'


>>> sas.submit("%macro cancel; %abort cancel; %mend; %cancel")
^CException caught!
Processing interrupt
Attn handler Query is

Select:
  C. Cancel the dialog
  T. Terminate the SAS System

Please enter your Response: t
Secondary Query is:

Press
  Y to terminate this SAS session,
  N to continue.

Please enter your Response: y
{'ABORT': True, 'LOG': 'SAS process has terminated unexpectedly. Pid State= (21069, 512)', 'LST': ''}
>>> sas
Access Method         = STDIO
SAS Config name       = tdi
SAS Config file       = /opt/tom/github/saspy/saspy/sascfg_personal.py
WORK Path             = /usr/tmp/SAS_work35A40000524D_tom64-5/
SAS Version           = 9.04.01M7P08052020
SASPy Version         = 4.2.0
Teach me SAS          = False
Batch                 = False
Results               = Pandas
SAS Session Encoding  = utf-8
Python Encoding value = utf_8
SAS process Pid value = None

>>>

Thank you very much for the further explanations!

I believe the issue should be fixable, even if somewhat clumsily. See my pull request #449.

There might even be a way that does not involve killing the SAS process such that subsequent calls to submit() are possible. Namely, starting sas -stdio in a terminal one can hit Ctrl+D after an abort cancel to recover a working SAS session.

But for me a fix similar to the one proposed in #449 would be sufficient.

Hey, so regarding the idea of looking for 'abort cancel' (or whatever string) in the log, I really shy away from trying to search for strings in the log and try to do anything 'overt' (? can't think of the right word; anything that could be the wrong thing to do if it didn't really happen to be the case I was trying to find). So terminating SAS because you see a string in the log isn't something I'm going to code up. This goes right back to the other issue w/ the warnings module and looking for ERROR in the log. I really didn't like that, but, simply issuing a warning (which you can disable easily), didn't change the behavior of the system (like killing the SAS process cuz you saw something that seemed like a problem). And, like you mentioned, and I've been trying to diagnose, when running in other languages, these strings may be localized, so then you're missing those cases (I do see my catch all being able to work in that case, BTW). So for instance (where abort cancel hangs I see this in the log):

(Pdb) print(log.decode(self.sascfg.encoding))

21   ods listing close;ods html5 (id=saspy_internal) file=stdout options(bitmap_mode='inline') device=svg style=HTMLBlue; ods
21 ! graphics on / outputfmt=png;
NOTE: 正在写入 HTML5(SASPY_INTERNAL) Body（主体）文件: STDOUT
22   ;*';*";*/;
23   %macro cancel; %abort cancel; %mend; %cancel
ERROR: 已通过 %ABORT CANCEL 语句取消执行。
(Pdb)

Well,

      self.cancel_messages = [
         b"ERROR: Execution canceled by an %ABORT CANCEL",
         b"ERROR: Execution terminated by an ABORT CANCEL"
      ]

isn't gonna cut it for this. Then you can back down to finding ERROR and looking for ABORT xxx in the same line, but that is just starting to get a bit down in the weeds, especially for a one time case that can never be something that will be a useful thing to submit. So I kinda go to the answer for those kind of problems as being: don't submit 'abort cancel!' It'll never get you anything useful. Sometimes documenting things that can never work is the better way than trying to hack some kind of quasi check and an 'overt' reaction. If there's a clean way to catch and handle it, then, sure, I'm all in!

This isn't in anyway trying to keep from addressing all of these various things you're looking into. I only want to make SASPy better and more solid too, so don't get me wrong here. But, especially w/ the STDIO access method I invented, there's no API that this uses, it's really just 'dumb' interface, where I (in code) try to handle all of the idiosyncrasies that we have (the SAS system) with SAS havening no idea it's not a human at a terminal interacting with it. The attention handling is a good example of that; it will never be 100% correct, but I try to do the best I can in code to make it useful. To that case specifically, here's that 'catch all' I was talking about. The words in the log for SELECT and PRESS are localized, so I just display what was in the lst and let you provide whatever response it happened to say (I have no idea what it asked),:

Access Method         = STDIO
SAS Config name       = tdi
SAS Config file       = /r/sanyo.unx.sas.com/vol/vol810/u81/sastpw/.config/saspy/sascfg_personal.py
WORK Path             = /usr/tmp/SAS_workC92700007F6F_tom64-5/
SAS Version           = 9.04.01M7P08052020
SASPy Version         = 4.1.0
Teach me SAS          = False
Batch                 = False
Results               = Pandas
SAS Session Encoding  = euc-cn
Python Encoding value = gb2312
SAS process Pid value = 32623

>>> code = '''data a; {}; run;'''.format(100 * 'x=99999999;output;z=sleep(1,1);\n')
>>> ll = sas.submit(code,results='text')
^CException caught!
******************No 'Select' or 'Press' found. Here's what was found.
Processing interrupt
Attn handler Query is

选择:
  1. 暂停 DATA 步/PROC: DATASTEP
  C. 取消对话框
  T. 终止 SAS 系统
?响应无效，请重试。
选择:
  1. 暂停 DATA 步/PROC: DATASTEP
  C. 取消对话框
  T. 终止 SAS 系统
?
Please enter your Response: or N/A only if there are no choices: 1
******************No 'Select' or 'Press' found. Here's what was found.
Processing interrupt
Attn handler Query is

按
  Y 中断 DATA 步或 PROC 步，
  N 继续。
?
Please enter your Response: or N/A only if there are no choices: y
Exception ignored, continuing to process...

/usr/lib/python3.5/site-packages/saspy/sasiostdio.py:970: UserWarning: Noticed 'ERROR:' in LOG, you ought to take a look and see if there was a problem
  warnings.warn("Noticed 'ERROR:' in LOG, you ought to take a look and see if there was a problem")
>>> 

# then in an english session to see what that really said

>>> import saspy; sas = saspy.SASsession(cfgname='tdi'); sas
SAS Connection established. Subprocess id is 342

Access Method         = STDIO
SAS Config name       = tdi
SAS Config file       = /r/sanyo.unx.sas.com/vol/vol810/u81/sastpw/.config/saspy/sascfg_personal.py
WORK Path             = /usr/tmp/SAS_work5DC900000156_tom64-5/
SAS Version           = 9.04.01M7P08052020
SASPy Version         = 4.1.0
Teach me SAS          = False
Batch                 = False
Results               = Pandas
SAS Session Encoding  = utf-8
Python Encoding value = utf_8
SAS process Pid value = 342

>>> code = '''data a; {}; run;'''.format(1000 * 'x=99999999;output;z=sleep(1,1);\n')
>>> ll = sas.submit(code,results='text')
^CException caught!
Processing interrupt
Attn handler Query is

Select:
  1. Halt DATA step/PROC: DATASTEP
  C. Cancel the dialog
  T. Terminate the SAS System

Please enter your Response: 1
Secondary Query is:

Press
  Y to halt DATA step/proc,
  N to continue.

Please enter your Response: y
Exception handled :)

/usr/lib/python3.5/site-packages/saspy/sasiostdio.py:970: UserWarning: Noticed 'ERROR:' in LOG, you ought to take a look and see if there was a problem
  warnings.warn("Noticed 'ERROR:' in LOG, you ought to take a look and see if there was a problem")
>>> print(ll['LOG'])

21
22   data a; x=99999999;output;z=sleep(1,1);
23   x=99999999;output;z=sleep(1,1);
24   x=99999999;output;z=sleep(1,1);
25   x=99999999;output;z=sleep(1,1);
[...]
1020  x=99999999;output;z=sleep(1,1);
1021  x=99999999;output;z=sleep(1,1);
1022  ; run;
ERROR: User asked for termination
NOTE: The SAS System stopped processing this step because of errors.
WARNING: The data set WORK.A may be incomplete.  When this step was stopped there were 1 observations and 2 variables.
NOTE: DATA statement used (Total process time):
      real time           4.31 seconds
      cpu time            0.17 seconds

BTW, still looking in to all of the other things; more to come!

Thanks! Tom

Thanks again for all the effort you put in this detailed answer! I definitely agree with you that terminating (or merely "canceling" the current submit) on seeing a string is not a nice thing to do. So it's fine for me if it's not implemented or if it's made an option:

SAS_config_options = {
    "cancel_messages": [
       "^ERROR: Execution .* %ABORT CANCEL",
       "^ERROR: Execution .* ABORT CANCEL"
    ]
}

Concerning:

especially for a one time case that can never be something that will be a useful thing to submit. So I kinda go to the answer for those kind of problems as being: don't submit 'abort cancel!' It'll never get you anything useful.

I totally understand your point and it really depends on what saspy is intended to be used for. Actually, I was using it to write a python script that let's the user run arbitrary SAS files (whose contents I don't want to control). One of those submitted files contained a conditional %abort cancel statement which caused my program to hang while consuming all CPU power. So you see, the problem is not completely artificial. But maybe it would indeed be a better idea to run the scripts directly via sas in this situation. The reason I didn't do it is that I liked the idea that with saspy it's very easy to write a python script that runs both on our server and locally.

Hey @saspyrate I've been looking into all of this, including the PR. And, yes, I concur that I should catch this at least to keep from just spinning at 100% CPU till you kill the process. For the other access methods I wrote, which have API's, this particular case doesn't cause this problem. It's only with STDIO, so even though it's a runtime error to submit this in this case, I ought to catch it and fail. I have seen the ctl-d in interactive mode (which is what I'm running SAS in also) kinda work, but the same thing didn't work in my case. I will try out a little more today to see if I can get that to work; it would make it behave like in the other access methods, but no guarantee sine it's not exactly the same, so I may not be able to force SAS to do what I want there.

Anyway, didn't want you to think I wasn't on this. Just juggling a few things but still looking into these various issues. Checking out the other, using the thread and queue, like I had to do for windows clients to be able to use this access method. That seems reasonable at a glance. Just nee to test it out and put it through it's paces too, since it's a pervasive change, even if it seems straight forward.

Thanks! Tom

Hi Tom, I think I (almost) solved the problem using the CTRL-D functionality (i.e. sending an EOT character). I proceeded as follows:

Analyze each line of the SAS log while reading it.
If a line matches ERROR: .* %?ABORT CANCEL.* (or whatever appropriately localized regular expression specified by the user in the configuration), take it as a hint that the submit might have been canceled.
We then check whether there really was a cancelation. To do this, send an %abort cancel so that the submit is now canceled for sure. This is necessary because writing an EOT in interactive mode seems to terminate the SAS session unless there was a cancelation. Now we can send an EOT to recover the SAS session.

The only problem here is that in the unlikely situation that we canceled the session even though no prior cancelation occurred (i.e. the user for some reason wrote ^ERROR: .* %?ABORT CANCEL.*$ into the log), we cannot return completely to the previous state. Namely, the read-only macro variables SYSERR and SYSERRORTEXT will probably have changed their value.

Should it be possible to send an EOT without canceling, we could of course also get rid of this last problem. But even if we can't, I think the solution is better than the status quo and closer to how cancelations are handled for the other access methods. If it still seems too dangerous, we can disable it by default and make it a configurable option.

Here's a proof of concept: saspyrate/sas_stdio

The class SASsession in _sasstdio.py implements a minimalistic analogy of your logic for Linux. Instead of writing directly to stdin of the SAS process, I use the file descriptor for the master returned by os.forkpty(). Then it's easy to send the EOT character.

I hope the code in test.py works as is after replacing /path/to/sas with the path of the SAS executable.

I've been looking at this and trying it out, as well as just trying to get anything (submit EOT, use other signals, ...) to get the session back usable from my own code as well, but I can't (and the code you provided didn't) ever get the SAS session usable again. Your code doesn't hang, but it doesn't make SAS ever work again with anything that's submitted after submitting the abort cancel.

>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
INFO: submit finished
>>>>>>>>>> LOG >>>>>>>>>>
9    proc print data=sashelp.cars(obs=1);run;
NOTE: There were 1 observations read from the data set SASHELP.CARS.
NOTE: The PROCEDURE PRINT printed page 4.
NOTE: PROCEDURE PRINT used (Total process time):
      real time           0.00 seconds
      cpu time            0.00 seconds

<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
                                                           The SAS System                          10:02 Tuesday, April 12, 2022   4

                                  Drive                   Engine                                 MPG_
      Obs Make  Model Type Origin Train     MSRP  Invoice  Size  Cylinders Horsepower MPG_City Highway Weight Wheelbase Length

        1 Acura  MDX  SUV   Asia   All   $36,945  $33,337   3.5      6         265       17       23    4451     106      189
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("data _null_; abort cancel; run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
data _null_; abort cancel; run;
<<<<<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>> LOG >>>>>>>>>>

<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> >>> >>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>

My guess is that it only works if there's a physical terminal involved, but I'd have to go try to find the host code that's implementing this, somewhere in the bowels of base SAS and see if I can tell what the difference is. Though, that wouldn't change anything. W/out being able to actually get SAS back usable, catching this and terminating it, instead of spinning, is the best case. It's just not a valid statement to execute in this configuration.

I can put a simple check in the loop to catch this and terminate, that's only a few lines of code and works just fine. Though I would make that an option, as it's not necessary 99% of the time because submitting this will never actually work right in this particular configuration (as of now w/ everything I've tried). So even catching this and killing the process didn't fix anything; you just have to go change that statement in the SAS program to get that program to run successfully. This begs the question (I haven't mentioned yet) about looking for this statement in the source before submitting it; and doing something about it. That sounds like a cop-out to me though, as opposed to me handling it in my code; but as I can't actually make it work, so far, it's just me trying to find the statement and kill the process, after submitting it, so you do have to. But again, that doesn't solve anything.

Do you actually have some case where SAS get's beck into a usable state (not running it yourself in a terminal, but from Python? I can't get it to work again regardless of what I've tried; including the your project.

For me it worked so far in all test cases - not just in an interactive python session. But, given that the SAS process is created as a fork, the way python is started on my machine might be responsible for this.

Does my program work on your machine if you artificially execute SAS from a shell? For instance like so:

sas = sas_stdio.SASsession(sascmd=["/usr/bin/sh", "-c", "/path/to/sas -stdio"])

When I find time somewhere in the next couple of days, I'll try to cook up a solution that avoids os.forkpty.

UPDATE: Maybe there's something else wrong with my program. I would have expected that it should either hang or should output the info SAS not running before the LOG:

<<<<<<<<<<<<<<<<<<<<<<<<<
INFO: SAS not running
>>>>>>>>>> LOG >>>>>>>>>>

Could you perhaps rerun the statement submit_verbosely("data _null_; abort cancel; run;") after changing logging.INFO to logging.DEBUG in my code? Do you get more output then?

Just to be sure: When running SAS on its own with -stdio in a terminal, pressing Ctrl+D after an abort cancel recovers the session for you, too. Right?

Yes, I see that when running SAS in an actual terminal, ctl-D will happen to get the session back after an abort cancel. But I've yet to see that in any case where I'm running it via SASPy, where there's not actually a terminal, even though I'm running SAS using the same options to start it. Sorry for how ling this is gonna be, but I've run your code w/ DEBUG log level and here's the results. BTW, asis it just hangs in the select.select. I had to change the timeout from None to something; I set it to 0.1 since that's what you have otherwise. Here's some tests with this (and ctl-d doesn't work here either).


Default case where submit has timeout None  (hangs)
---------------------------------------------------

Python 3.9.5 (default, Jul 28 2021, 14:19:56)
[GCC 4.4.7 20120313 (Red Hat 4.4.7-23)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging
import sas_stdio

logging.basicConfig(level=logging.DEBUG, format="%(levelname)s: %(message)s")
path = '/tdi/mva-v940m7/usrlibsas/laxno.20w34.20200805.weekly/SASFoundation/9.4/bin/sas_en'
sas = sas_stdio.SASsession(sascmd=[path, "-stdio"])
>>> >>> >>> >>> >>> 

DEBUG: write b'\n%put 0e831b8c59cb88d1;\n'
DEBUG: read 132 bytes b'1                                                          The SAS System                           ...'
DEBUG: handle log line b''
DEBUG: read 292 bytes b'\n\nNOTE: Unable to open SASUSER.REGSTRY. WORK.REGSTRY will be opened instead.\nNOTE: All registry chan...'
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b'NOTE: Unable to open SASUSER.REGSTRY. WORK.REGSTRY will be opened instead.'
DEBUG: handle log line b'NOTE: All registry changes will be lost at the end of the session.'
DEBUG: handle log line b''
DEBUG: handle log line b'WARNING: Unable to copy SASUSER registry to WORK registry. Because of this, you will not see registry customizations during this '
DEBUG: handle partial log line b'         session.'
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b'         session.'
DEBUG: handle partial log line b''
DEBUG: read 74 bytes b'NOTE: Unable to open SASUSER.PROFILE. WORK.PROFILE will be opened instead....'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 65 bytes b'NOTE: All profile changes will be lost at the end of the session....'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 63 bytes b'NOTE: Copyright (c) 2016 by SAS Institute Inc., Cary, NC, USA. ...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 47 bytes b'NOTE: SAS (r) Proprietary Software 9.4 (TS1M7) ...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 45 bytes b'      Licensed to SAS Institute Inc., Site 1....'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 91 bytes b'NOTE: This session is executing on the Linux 2.6.32-754.11.1.el6.x86_64 (LIN X64) platform....'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 26 bytes b'NOTE: Analytical products:...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 6 bytes b'      ...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 19 bytes b'      SAS/STAT 15.2...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 18 bytes b'      SAS/ETS 15.2...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 17 bytes b'      SAS/OR 15.2...'
DEBUG: handle log line b''
DEBUG: read 189 bytes b'\n      SAS/IML 15.2\n      SAS/QC 15.2\n\nNOTE: Additional host information:\n\n Linux LIN X64 2.6.32-754...'
DEBUG: handle log line b''
DEBUG: handle log line b'      SAS/IML 15.2'
DEBUG: handle log line b'      SAS/QC 15.2'
DEBUG: handle log line b''
DEBUG: handle log line b'NOTE: Additional host information:'
DEBUG: handle log line b''
DEBUG: handle log line b' Linux LIN X64 2.6.32-754.11.1.el6.x86_64 #1 SMP Tue Feb 26 15:38:56 UTC 2019 x86_64 CentOS release 6.10 (Final) '
DEBUG: handle partial log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 698 bytes b'You are running SAS 9. Some SAS 8 files will be automatically converted \nby the V9 engine; others ar...'
DEBUG: handle log line b'You are running SAS 9. Some SAS 8 files will be automatically converted '
DEBUG: handle log line b'by the V9 engine; others are incompatible.  Please see '
DEBUG: handle log line b'http://support.sas.com/rnd/migration/planning/platform/64bit.html'
DEBUG: handle log line b''
DEBUG: handle log line b'PROC MIGRATE will preserve current SAS file attributes and is '
DEBUG: handle log line b'recommended for converting all your SAS libraries from any '
DEBUG: handle log line b'SAS 8 release to SAS 9.  For details and examples, please see'
DEBUG: handle log line b'http://support.sas.com/rnd/migration/index.html'
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b'This message is contained in the SAS news file, and is presented upon'
DEBUG: handle log line b'initialization.  Edit the file "news" in the "misc/base" directory to'
DEBUG: handle log line b'display site-specific news and information in the program log.'
DEBUG: handle log line b'The command line option "-nonews" will prevent this display.'
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 30 bytes b'NOTE: SAS initialization used:...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 38 bytes b'      real time           0.24 seconds...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 38 bytes b'      cpu time            0.12 seconds...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 6 bytes b'      ...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 5 bytes b'1    ...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 27 bytes b'2    %put 0e831b8c59cb88d1;...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 16 bytes b'0e831b8c59cb88d1...'
DEBUG: handle log line b''

^CTraceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/net/sanyo.unx.sas.com/vol/vol810/u81/sastpw/sas_stdio-master/sas_stdio.py", line 33, in __init__
    self.initial_results = self.submit(b"")
  File "/net/sanyo.unx.sas.com/vol/vol810/u81/sastpw/sas_stdio-master/sas_stdio.py", line 48, in submit
    while select.select(rfds, [], [], timeout)[0]:
KeyboardInterrupt
>>>

Not default case where submit has timeout 0.1 instead of None
-------------------------------------------------------------

Python 3.9.5 (default, Jul 28 2021, 14:19:56)
[GCC 4.4.7 20120313 (Red Hat 4.4.7-23)] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging
import sas_stdio

logging.basicConfig(level=logging.DEBUG, format="%(levelname)s: %(message)s")
path = '/tdi/mva-v940m7/usrlibsas/laxno.20w34.20200805.weekly/SASFoundation/9.4/bin/sas_en'
sas = sas_stdio.SASsession(sascmd=[path, "-stdio"])
>>> >>> >>> >>> >>> 

DEBUG: write b'\n%put 0e831b8c59cb88d1;\n'

>>> sas
<sas_stdio.SASsession object at 0x7f51ef55ffd0>
>>>
>>> def submit_verbosely(code):
...     print("\n" + 25*"=" + "\n" + 10*">" + " CODE " + 10*">" + "\n" + code + "\n" + 25*"<")
...     res = sas.submit(code.encode())
...     for x in ["LOG", "LST"]:
...         print(10*">" + f" {x} " + 10*">" + res[x].decode() + "\n" + 25*"<" + "\n" + 25*"=")

... >>>
>>>
>>> submit_verbosely(
    "options nosource;"
)... ...

=========================
>>>>>>>>>> CODE >>>>>>>>>>
options nosource;
<<<<<<<<<<<<<<<<<<<<<<<<<
DEBUG: write b'options nosource;\n%put 0e831b8c59cb88d1;\n'
DEBUG: read 1964 bytes b'1                                                          The SAS System                           ...'
DEBUG: handle log line b'1                                                          The SAS System                             11:41 Thursday, April 14, 2022'
DEBUG: handle log line b''
DEBUG: handle log line b'NOTE: Unable to open SASUSER.REGSTRY. WORK.REGSTRY will be opened instead.'
DEBUG: handle log line b'NOTE: All registry changes will be lost at the end of the session.'
DEBUG: handle log line b''
DEBUG: handle log line b'WARNING: Unable to copy SASUSER registry to WORK registry. Because of this, you will not see registry customizations during this '
DEBUG: handle log line b'         session.'
DEBUG: handle log line b'NOTE: Unable to open SASUSER.PROFILE. WORK.PROFILE will be opened instead.'
DEBUG: handle log line b'NOTE: All profile changes will be lost at the end of the session.'
DEBUG: handle log line b'NOTE: Copyright (c) 2016 by SAS Institute Inc., Cary, NC, USA. '
DEBUG: handle log line b'NOTE: SAS (r) Proprietary Software 9.4 (TS1M7) '
DEBUG: handle log line b'      Licensed to SAS Institute Inc., Site 1.'
DEBUG: handle log line b'NOTE: This session is executing on the Linux 2.6.32-754.11.1.el6.x86_64 (LIN X64) platform.'
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b'NOTE: Analytical products:'
DEBUG: handle log line b'      '
DEBUG: handle log line b'      SAS/STAT 15.2'
DEBUG: handle log line b'      SAS/ETS 15.2'
DEBUG: handle log line b'      SAS/OR 15.2'
DEBUG: handle log line b'      SAS/IML 15.2'
DEBUG: handle log line b'      SAS/QC 15.2'
DEBUG: handle log line b''
DEBUG: handle log line b'NOTE: Additional host information:'
DEBUG: handle log line b''
DEBUG: handle log line b' Linux LIN X64 2.6.32-754.11.1.el6.x86_64 #1 SMP Tue Feb 26 15:38:56 UTC 2019 x86_64 CentOS release 6.10 (Final) '
DEBUG: handle log line b''
DEBUG: handle log line b'You are running SAS 9. Some SAS 8 files will be automatically converted '
DEBUG: handle log line b'by the V9 engine; others are incompatible.  Please see '
DEBUG: handle log line b'http://support.sas.com/rnd/migration/planning/platform/64bit.html'
DEBUG: handle log line b''
DEBUG: handle log line b'PROC MIGRATE will preserve current SAS file attributes and is '
DEBUG: handle log line b'recommended for converting all your SAS libraries from any '
DEBUG: handle log line b'SAS 8 release to SAS 9.  For details and examples, please see'
DEBUG: handle log line b'http://support.sas.com/rnd/migration/index.html'
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b'This message is contained in the SAS news file, and is presented upon'
DEBUG: handle log line b'initialization.  Edit the file "news" in the "misc/base" directory to'
DEBUG: handle log line b'display site-specific news and information in the program log.'
DEBUG: handle log line b'The command line option "-nonews" will prevent this display.'
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b''
DEBUG: handle log line b'NOTE: SAS initialization used:'
DEBUG: handle log line b'      real time           0.25 seconds'
DEBUG: handle log line b'      cpu time            0.10 seconds'
DEBUG: handle log line b'      '
DEBUG: handle log line b'1    '
DEBUG: handle log line b'2    %put 0e831b8c59cb88d1;'
INFO: submit finished
DEBUG: handle partial log line b'0e831b8c59cb88d1'
DEBUG: read 40 bytes b'\n3    options nosource;\n0e831b8c59cb88d1...'
DEBUG: handle log line b'0e831b8c59cb88d1'
DEBUG: handle log line b'3    options nosource;'
DEBUG: handle partial log line b'0e831b8c59cb88d1'
>>>>>>>>>> LOG >>>>>>>>>>1                                                          The SAS System                             11:41 Thursday, April 14, 2022

NOTE: Unable to open SASUSER.REGSTRY. WORK.REGSTRY will be opened instead.
NOTE: All registry changes will be lost at the end of the session.

WARNING: Unable to copy SASUSER registry to WORK registry. Because of this, you will not see registry customizations during this
         session.
NOTE: Unable to open SASUSER.PROFILE. WORK.PROFILE will be opened instead.
NOTE: All profile changes will be lost at the end of the session.
NOTE: Copyright (c) 2016 by SAS Institute Inc., Cary, NC, USA.
NOTE: SAS (r) Proprietary Software 9.4 (TS1M7)
      Licensed to SAS Institute Inc., Site 1.
NOTE: This session is executing on the Linux 2.6.32-754.11.1.el6.x86_64 (LIN X64) platform.

NOTE: Analytical products:

      SAS/STAT 15.2
      SAS/ETS 15.2
      SAS/OR 15.2
      SAS/IML 15.2
      SAS/QC 15.2

NOTE: Additional host information:

 Linux LIN X64 2.6.32-754.11.1.el6.x86_64 #1 SMP Tue Feb 26 15:38:56 UTC 2019 x86_64 CentOS release 6.10 (Final)

You are running SAS 9. Some SAS 8 files will be automatically converted
by the V9 engine; others are incompatible.  Please see
http://support.sas.com/rnd/migration/planning/platform/64bit.html

PROC MIGRATE will preserve current SAS file attributes and is
recommended for converting all your SAS libraries from any
SAS 8 release to SAS 9.  For details and examples, please see
http://support.sas.com/rnd/migration/index.html

This message is contained in the SAS news file, and is presented upon
initialization.  Edit the file "news" in the "misc/base" directory to
display site-specific news and information in the program log.
The command line option "-nonews" will prevent this display.

NOTE: SAS initialization used:
      real time           0.25 seconds
      cpu time            0.10 seconds

1
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely('')

=========================
>>>>>>>>>> CODE >>>>>>>>>>

<<<<<<<<<<<<<<<<<<<<<<<<<
DEBUG: write b'\n%put 0e831b8c59cb88d1;\n'
DEBUG: read 17 bytes b'\n0e831b8c59cb88d1...'
DEBUG: handle log line b''
DEBUG: handle partial log line b'0e831b8c59cb88d1'
INFO: submit finished
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
DEBUG: write b'proc print data=sashelp.cars(obs=1);run;\n%put 0e831b8c59cb88d1;\n'
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("data _null_; abort cancel; run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
data _null_; abort cancel; run;
<<<<<<<<<<<<<<<<<<<<<<<<<
DEBUG: write b'data _null_; abort cancel; run;\n%put 0e831b8c59cb88d1;\n'
DEBUG: read 397 bytes b'\nNOTE: There were 1 observations read from the data set SASHELP.CARS.\nNOTE: The PROCEDURE PRINT prin...'
DEBUG: handle log line b''
DEBUG: handle log line b'NOTE: There were 1 observations read from the data set SASHELP.CARS.'
DEBUG: handle log line b'NOTE: The PROCEDURE PRINT printed page 1.'
DEBUG: handle log line b'NOTE: PROCEDURE PRINT used (Total process time):'
DEBUG: handle log line b'      real time           0.12 seconds'
DEBUG: handle log line b'\x0c2                                                          The SAS System                             11:41 Thursday, April 14, 2022'
DEBUG: handle log line b''
DEBUG: handle log line b'      cpu time            0.10 seconds'
DEBUG: handle log line b'      '
DEBUG: handle partial log line b'0e831b8c59cb88d1'
INFO: submit finished
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b'0e831b8c59cb88d1'
DEBUG: handle partial log line b''
DEBUG: read 77 bytes b'ERROR: Execution terminated by an ABORT CANCEL statement at line 9 column 14....'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 15 bytes b'_ERROR_=1 _N_=1...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 47 bytes b'NOTE: DATA statement used (Total process time):...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 38 bytes b'      real time           0.01 seconds...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 38 bytes b'      cpu time            0.01 seconds...'
DEBUG: handle log line b''
DEBUG: read 1 bytes b'\n...'
DEBUG: handle log line b''
DEBUG: handle partial log line b''
DEBUG: read 6 bytes b'      ...'
DEBUG: handle log line b''
>>>>>>>>>> LOG >>>>>>>>>>
NOTE: There were 1 observations read from the data set SASHELP.CARS.
NOTE: The PROCEDURE PRINT printed page 1.
NOTE: PROCEDURE PRINT used (Total process time):
      real time           0.12 seconds
2                                                          The SAS System                             11:41 Thursday, April 14, 2022

      cpu time            0.10 seconds

<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>                                                           The SAS System                         11:41 Thursday, April 14, 2022   1

                                  Drive                   Engine                                 MPG_
      Obs Make  Model Type Origin Train     MSRP  Invoice  Size  Cylinders Horsepower MPG_City Highway Weight Wheelbase Length

        1 Acura  MDX  SUV   Asia   All   $36,945  $33,337   3.5      6         265       17       23    4451     106      189
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
DEBUG: write b'proc print data=sashelp.cars(obs=1);run;\n%put 0e831b8c59cb88d1;\n'
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
DEBUG: write b'proc print data=sashelp.cars(obs=1);run;\n%put 0e831b8c59cb88d1;\n'
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
DEBUG: write b'proc print data=sashelp.cars(obs=1);run;\n%put 0e831b8c59cb88d1;\n'
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>> submit_verbosely("proc print data=sashelp.cars(obs=1);run;")

=========================
>>>>>>>>>> CODE >>>>>>>>>>
proc print data=sashelp.cars(obs=1);run;
<<<<<<<<<<<<<<<<<<<<<<<<<
DEBUG: write b'proc print data=sashelp.cars(obs=1);run;\n%put 0e831b8c59cb88d1;\n'
>>>>>>>>>> LOG >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>>>>>>>> LST >>>>>>>>>>
<<<<<<<<<<<<<<<<<<<<<<<<<
=========================
>>>

BTW, asis it just hangs in the select.select. I had to change the timeout from None to something; I set it to 0.1 since that's what you have otherwise. Here's some tests with this (and ctl-d doesn't work here either).

OK, this explains the unexpected output I mentioned in one of my last posts.

Unfortunately, I hadn't time to further look into this until now. Feel free to close the issue any time if you think it's not important enough to be fixed.

Well, I haven't found a way to actually fix it. The ctl-D that happens to work if you are really in a terminal running SAS, doesn't work with the STDIO access method. So, I have no fix for this one case; it works ok for all of the interfaces that have an API, but this is just a consequence of STDIO being an API-less 'contrived' interface. The only thing I've see so far is to just check for the tell tale message (the last thing that will ever show up in the log) that it's done because of the abort, and just terminate the session then, as opposed to the user having to hit ctl-C and terminate it. So, I can add that in, but that's all I've seen that can be done, so far.

I'm going to close this since I have no fix for this behavior of SAS in this one access method. The ctl-D doesn't work in this case and preemptively killing the SAS process out from saspy based upon seeing certain words in the log isn't really a fix and I don't like that anyway. If I can ever figure out an actual way to fix this, I'm all for it. But I've got nothing. Tom

sassoftware / saspy

submit() hangs with STDIO on Linux in certain situations #447