python logging with subprocesses: get ordered output as it appears on screen also on log file

Question

I have a python script (script1.py) which generates sub processes as follows:

print 'This is the main script'
status=os.system(command)

Now I execute the script and redirect the stdoutput like this:

python script1.py > log.txt

The file log.txt contains first the output of the subprocess command (called using os.system) and only after the string 'This is the main script'. I would expect the opposite order!

If I use subprocess instead of os.system the situation is still the same:

print 'This is the main script'
p=subprocess.Popen(command,shell=True, stdout=None, stderr=subprocess.STDOUT)
status=p.returncode

So how can I redirect the stdoutput to a file and make sure that all subprocesses write in that file in the proper order? Note that if I do not redirect the standard output, the order of the log messages is correct (as it appears on the screen)!

UPDATE

This fixes my problem (as described here):

sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 0)

Alternatively one can also force the printed content to be flushed:

sys.stdout.flush()

however, I think this is not ideal as it should be done after each print command. So I used the first approach which has also the advantage that I can examine the logs in real time, without waiting that the computation ends before writing to file the buffered output.

Answer 1

Use the logging module. Print is not reliable for this. Example:

import logging
rootLogger = logging.getLogger()

proc = subprocess.Popen(["cat", "/etc/services"], stdout=subprocess.PIPE, shell=True)
(out, err) = proc.communicate()
logger.INFO('This is the main script. Here\'s the program output:')
logger.INFO(out)