subprocess.Popen communicate() writes to console, but not to log file

Question

I have the following line in a Python script that runs a separate Python script from within the original script:

subprocess.Popen("'/MyExternalPythonScript.py' " + theArgumentToPassToPythonScript, shell=True).communicate()

Using the above line, any print() statements found in the separate Python file do appear in the console of the main Python script.

However, these statements are not reflected in the .txt file log that the script writes to.

Does anyone know how to fix this, so that the .txt file exactly reflects the true console text of the main Python script?

This is the method I am using to save the console as a .txt file, in real time:

import sys
class Logger(object):
    def __init__(self):
        self.terminal = sys.stdout
        self.log = open("/ScriptLog.txt", "w", 0)
    def write(self, message):
        self.terminal.write(message)
        self.log.write(message)


sys.stdout = Logger()

I am not necessarily attached to this method. I am interested in any method that will achieve what I've detailed.

You can `self.log.flush()` after every write. Essentially Python will wait to write to the file until it has enough data in the buffer, or the file handle is closed (for instance when the application stops). — Willem Van Onsem, Dec 27 '17 at 23:10
I just tried inserting `self.log.flush()` after `self.log.write(message)`. Doing this did not change anything. The .txt file still does not contain the `print` text from the external script. — Crickets, Dec 27 '17 at 23:23
Hold on, this script is rather dangerous. Furthermore your program nowhere prints the argument at all. So I guess this is only the shell itself that prints the argument. — Willem Van Onsem, Dec 27 '17 at 23:25
In `write`, open the file an write to it instead of using reference to an open file as an instance attribute. Dues that work. — wwii, Dec 27 '17 at 23:41
Using string concatenation to form shell commands is a substantial security risk -- if someone puts `$(rm -rf ~)` somewhere in an argument you're amending to the string, you're in a world of hurt. If you care about security and reliability, avoid `shell=True`. (Unwanted globbing poses risks even when inputs aren't deliberately malicious: I once was present when code tried to delete a file created by code with a bug that dumped random garbage from memory into a name; that garbage happened to have a whitespace-surrounded `*`, and multiple TB of backups were lost). — Charles Duffy, Dec 28 '17 at 00:40

score 1 · Answer 1 · answered Dec 27 '17 at 23:58

Do you really need subprocess.Popen's communicate() method? It looks like you just want the output. That's what subprocess.check_output() is for.

If you use that, you can use the built-in logging module for "tee"-ing the output stream to multiple destinations.

import logging
import subprocess
import sys

EXTERNAL_SCRIPT_PATH = '/path/to/talker.py'
LOG_FILE_PATH = '/path/to/debug.log'

logger = logging.getLogger('')
logger.setLevel(logging.INFO)

# Log to screen
console_logger = logging.StreamHandler(sys.stdout)
logger.addHandler(console_logger)

# Log to file
file_logger = logging.FileHandler(LOG_FILE_PATH)
logger.addHandler(file_logger)

# Driver script output
logger.info('Calling external script')

# External script output
logger.info(
    subprocess.check_output(EXTERNAL_SCRIPT_PATH, shell=True)
)

# More driver script output
logger.info('Finished calling external script')

As always, be careful with shell=True. If you can write the call as subprocess.check_output(['/path/to/script.py', 'arg1', 'arg2']), do so!

Savir · Accepted Answer · 2017-12-28T00:51:08.920

Keep in mind that subprocess spawns a new process, and doesn't really communicate with the parent process (they're pretty much independent entities). Despite its name, the communicate method is just a way of sending/receiving data from the parent process to the child process (simulate that the user input something on the terminal, for instance)

In order to know where to write the output, subprocess uses numbers (file identifiers or file numbers). When subprocess spawns a process, the child process only knows that the standard output is the file identified in the O.S. as 7 (to say a number) but that's pretty much it. The subprocess will independently query the operative system with something like "Hey! What is file number 7? Give it to me, I have something to write in it." (understanding what a C fork does is quite helpful here)

Basically, the spawned subprocess doesn't understand your Logger class. It just knows it has to write its stuff to a file: a file which is uniquely identified within the O.S with a number and that unless otherwise specified, that number corresponds with the file descriptor of the standard output (but as explained in the case #2 below, you can change it if you want)

So you have several "solutions"...

Clone (tee) stdout to a file, so when something is written to stdout, the operative system ALSO writes it to your file (this is really not Python-related... it's OS related):

import os
import tempfile
import subprocess

file_log = os.path.join(tempfile.gettempdir(), 'foo.txt')
p = subprocess.Popen("python ./run_something.py | tee %s" % file_log, shell=True)
p.wait()

Choose whether to write to terminal OR to the file using the fileno() function of each. For instance, to write only to the file:

import os
import tempfile
import subprocess

file_log = os.path.join(tempfile.gettempdir(), 'foo.txt')
with open(file_log, 'w') as f:
    p = subprocess.Popen("python ./run_something.py", shell=True, stdout=f.fileno())
    p.wait()

What I personally find "safer" (I don't feel confortable overwriting sys.stdout): Just let the command run and store its output into a variable and pick it up later (in the parent process):

import os
import tempfile
import subprocess

p = subprocess.Popen("python ./run_something.py", shell=True, stdout=subprocess.PIPE)
p.wait()
contents = p.stdout.read()
# Whatever the output of Subprocess was is now stored in 'contents'
# Let's write it to file:
file_log = os.path.join(tempfile.gettempdir(), 'foo.txt')
with open(file_log, 'w') as f:
    f.write(contents)

This way, you can also do a print(contents) somewhere in your code to output whatever the subprocess "said" to the terminal.

For example purposes, the script "./run_something.py" is just this:

print("Foo1")
print("Foo2")
print("Foo3")

I ended up going with Solution #3. It works great. I can simply `print(contents)`, and the .txt log then reflects the `contents`. I appreciate the detailed answer. — Crickets, Dec 28 '17 at 04:19
Sure... And yeah, to me it was very important to understand that _processes_ (threads are something different) basically can only communicate with each other through files (in one shape or another, but in the end, files, after all) It's like having two completely separate "things" that both use a common file to "talk" (call it queue, call it buffer... same idea): process-1 writes to a file and process-2 reads from it, and many other variations, but the files are pretty much the only thing that can "link" processes together — Savir, Dec 28 '17 at 05:13

subprocess.Popen communicate() writes to console, but not to log file

2 Answers2