scrambled output from a child process run from subprocess

Question

I'm using the following code to run another python script. The problem I'm facing is that the output of that script is coming out in an unorderly manner. While running it from the command line, I get the correct output i.e. :

some output here
Editing xml file and saving changes
Uploading xml file back..

While running the script using subprocess, am getting some of the output in reverse order:

correct output till here
Uploading xml file back..
Editing xml file and saving changes

The script is executing without errors and making the right changes. So I think the culprit might be the code that is calling the child script, but I can't find the problem:

    cmd = "child_script.py"
    proc = subprocess.Popen(cmd.split(), stdout=subprocess.PIPE,stderr=subprocess.STDOUT)
    (fout ,ferr) = ( proc.stdout, proc.stderr )
    print "Going inside while - loop"
    while True:
        line = proc.stdout.readline()
        print line
        fo.write(line)
        try : 
            err = ferr.readline()
            fe.write(err)
        except Exception, e:
            pass
        if not line:
            pass
            break

[EDIT]: fo and fe are file handles to output and error logs. Also the script is being run on Windows.Sorry for missing these details.

Also you have a "break" command just bellow a "pass" statement - this program will run in an inifnite loop. Why the "while" voodoo at all? simply do "for line in proc.stdout". Also, you are not using the "fout, ferr" variables. For which You would not need the parentheses as well. — jsbueno, Feb 28 '11 at 11:42
The other thing you need to clarify is where the correct and incorrect output that you quote at the beginning is coming from - is that in one of the log files that you're writing to via `fe` and `fo` or must it come from the `print` statement? — Mark Longair, Mar 01 '11 at 08:50
@Mark - it is coming from subprocess.PIPE which gets it from the print statement of the child script. — fixxxer, Mar 01 '11 at 08:56
@jsbeuno: Incorporated your suggestions. Should I update the questions as well? — fixxxer, Mar 01 '11 at 09:47

score 4 · Accepted Answer · edited May 23 '17 at 10:29

4

There are a few problems with the part of the script you've quoted, I'm afraid:

As mentioned in detly's comment, what are fo and fe? Presumably those are objects to which you're writing the output of the child process? (Update: you indicate that these are both for writing output logs.)
There's an indentation error on line 3. (Update: I've fixed that in the original post.)
You're specifying stderr=subprocess.STDOUT, so: (a) ferr will always be None in your loop and (b) due to buffering, standard output and error may be mixed in an unpredictable way. However, it looks from your code as if you actually want to deal with standard output and standard error separately, so perhaps try stderr=subprocess.PIPE instead.

It would be a good idea to rewrite your loop as jsbueno suggests:

from subprocess import Popen, PIPE
proc = Popen(["child_script.py"], stdout=PIPE, stderr=PIPE)
fout, ferr = proc.stdout, proc.stderr
for line in fout:
    print(line.rstrip())
    fo.write(line)
for line in ferr:
    fe.write(line)

... or to reduce it even further, since it seems that the aim is essentially that you just want to write the standard output and standard error from the child process to fo and fe, just do:

proc = subprocess.Popen(["child_script.py"], stdout=fo, stderr=fe)

If you still see the output lines swapped in the file that fo is writing to, then we can only assume that there is some way in which this can happen in the child script. e.g. is the child script multi-threaded? Is one of the lines printed via a callback from another function?

edited May 23 '17 at 10:29

Community

1
1

answered Feb 28 '11 at 09:13

Mark Longair

446,582
72
411
327

point 1: Edited the question. sorry about missing that. point 2: Please ignore that. point 3: Will try that! – fixxxer Feb 28 '11 at 09:24
@fixxxer: I hope that helps. The other question is whether the child process is writing each of the two lines that you see swapped around to stdout or stderr... – Mark Longair Feb 28 '11 at 09:54
Maybe you would want to write out and err logs in your child script instead? That way you get rid of the responsibility of dealing with output in the parent script (at least if it's as simple in your question). – aknuds1 Feb 28 '11 at 10:14
@mark - using stderr = subprocess.PIPE did not help. And, no they are not being swapped to stdout and stderr either. – fixxxer Mar 01 '11 at 08:37
@fixxxer: so are both those lines being written to stdout? That's not clear to me. – Mark Longair Mar 01 '11 at 08:38
@aknuds1: But is it possible to write and read from the same output log file with different file handles, simultaneously? I thought because of file locks this won't be possible and hence posted this. – fixxxer Mar 01 '11 at 08:41
@Mark: Yes both are being written to stdout. No errors occurred so stderr is empty. – fixxxer Mar 01 '11 at 08:54
@fixxxer: well, I've updated my answer and added a couple of suggested ways that you could rewrite the calling code, but I can only assume that the problem is in the child script unless this is some strange Python-on-Windows problem. – Mark Longair Mar 01 '11 at 09:31
@fixxxer: I don't see why you would need to write to and read from the output and error log files at the same time? Can't the child processes write to log files created by itself? The point is to move the log writing out of the parent. – aknuds1 Mar 01 '11 at 09:42
@Mark: Can we get the child_script.py to write the output to a file and simultaneously read it from the parent script? Thanks for taking the time to improve the answer. @jsbeuno's suggestion have already been incorporated. – fixxxer Mar 01 '11 at 09:45
@aknuds1: Since the parent script is a GUI and the output of the child_script.py needs to be shown to the user - thats why. To clarify: the child script writes the log and the parent script reads it; parent script does no logging in this scenario. – fixxxer Mar 01 '11 at 09:51
1

@fixxxer: once the log file created by the child exists, you could use the generator in [this answer](http://stackoverflow.com/questions/1475950/tail-f-in-python-with-no-time-sleep/1476006#1476006) to continually read new data from the log file – Mark Longair Mar 01 '11 at 10:01
@Mark - Lovely! Exactly what I started out for. Thanks! – fixxxer Mar 01 '11 at 10:24
@Mark - Observation :- This give me the same scrambled output: "python child_script.py Argument1 > outputlog.txt". While, "python child_script.py Argument1" output that is print to the command window is fine. – fixxxer Mar 02 '11 at 14:08
@fixxxer: In that case I think you should probably start a new question with more details about what goes on in child_script.py and that puzzle. (I asked about whether it was multi-threaded in my answer, which might explain that behaviour.) – Mark Longair Mar 02 '11 at 14:53
@mark : http://stackoverflow.com/questions/5177068/unorderly-output-when-python-script-output-is-redirected-to-file-via-command-line – fixxxer Mar 03 '11 at 05:39

score 2 · Answer 2 · edited Mar 01 '11 at 09:40

Most of the times I've seen order of output differ based on execution, some output was sent to the C standard IO streams stdin, and some output was sent to stderr. The buffering characteristics of stdout and stderr vary depending upon if they are connected to a terminal, pipes, files, etc:

NOTES
   The stream stderr is unbuffered.  The stream stdout is
   line-buffered when it points to a terminal.  Partial lines
   will not appear until fflush(3) or exit(3) is called, or a
   newline is printed.  This can produce unexpected results,
   especially with debugging output.  The buffering mode of
   the standard streams (or any other stream) can be changed
   using the setbuf(3) or setvbuf(3) call.  Note that in case
   stdin is associated with a terminal, there may also be
   input buffering in the terminal driver, entirely unrelated
   to stdio buffering.  (Indeed, normally terminal input is
   line buffered in the kernel.)  This kernel input handling
   can be modified using calls like tcsetattr(3); see also
   stty(1), and termios(3).

So perhaps you should configure both stdout and stderr to go to the same source, so the same buffering will be applied to both streams.

Also, some programs open the terminal directly open("/dev/tty",...) (mostly so they can read passwords), so comparing terminal output with pipe output isn't always going to work.

Further, if your program is mixing direct write(2) calls with standard IO calls, the order of output can be different based on the different buffering choices.

I hope one of these is right :) let me know which, if any.

sarnold, By this:"Further, if your program is mixing direct write(2) calls with standard IO calls, the order of output can be different based on the different buffering choices.", do you mean that I should move the file-writes for after the while loop? — fixxxer, Feb 28 '11 at 09:30
@fixxxer, the problem with mixing `write(2)` with standard IO would be in `child_script.py`. — sarnold, Feb 28 '11 at 09:37

scrambled output from a child process run from subprocess

2 Answers2