How to duplicate sys.stdout to a log file?

Viewed 125045

Edit: Since it appears that there's either no solution, or I'm doing something so non-standard that nobody knows - I'll revise my question to also ask: What is the best way to accomplish logging when a python app is making a lot of system calls?

My app has two modes. In interactive mode, I want all output to go to the screen as well as to a log file, including output from any system calls. In daemon mode, all output goes to the log. Daemon mode works great using os.dup2(). I can't find a way to "tee" all output to a log in interactive mode, without modifying each and every system call.


In other words, I want the functionality of the command line 'tee' for any output generated by a python app, including system call output.

To clarify:

To redirect all output I do something like this, and it works great:

# open our log file
so = se = open("%s.log" % self.name, 'w', 0)

# re-open stdout without buffering
sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 0)

# redirect stdout and stderr to the log file opened above
os.dup2(so.fileno(), sys.stdout.fileno())
os.dup2(se.fileno(), sys.stderr.fileno())

The nice thing about this is that it requires no special print calls from the rest of the code. The code also runs some shell commands, so it's nice not having to deal with each of their output individually as well.

Simply, I want to do the same, except duplicating instead of redirecting.

At first thought, I thought that simply reversing the dup2's should work. Why doesn't it? Here's my test:

import os, sys

### my broken solution:
so = se = open("a.log", 'w', 0)
sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 0)

os.dup2(sys.stdout.fileno(), so.fileno())
os.dup2(sys.stderr.fileno(), se.fileno())
###

print("foo bar")

os.spawnve("P_WAIT", "/bin/ls", ["/bin/ls"], {})
os.execve("/bin/ls", ["/bin/ls"], os.environ)

The file "a.log" should be identical to what was displayed on the screen.

19 Answers

I had this same issue before and found this snippet very useful:

class Tee(object):
    def __init__(self, name, mode):
        self.file = open(name, mode)
        self.stdout = sys.stdout
        sys.stdout = self
    def __del__(self):
        sys.stdout = self.stdout
        self.file.close()
    def write(self, data):
        self.file.write(data)
        self.stdout.write(data)
    def flush(self):
        self.file.flush()

from: http://mail.python.org/pipermail/python-list/2007-May/438106.html

The print statement will call the write() method of any object you assign to sys.stdout.

I would spin up a small class to write to two places at once...

import sys

class Logger(object):
    def __init__(self):
        self.terminal = sys.stdout
        self.log = open("log.dat", "a")

    def write(self, message):
        self.terminal.write(message)
        self.log.write(message)  

sys.stdout = Logger()

Now the print statement will both echo to the screen and append to your log file:

# prints "1 2" to <stdout> AND log.dat
print "%d %d" % (1,2)

This is obviously quick-and-dirty. Some notes:

  • You probably ought to parametize the log filename.
  • You should probably revert sys.stdout to <stdout> if you won't be logging for the duration of the program.
  • You may want the ability to write to multiple log files at once, or handle different log levels, etc.

These are all straightforward enough that I'm comfortable leaving them as exercises for the reader. The key insight here is that print just calls a "file-like object" that's assigned to sys.stdout.

What you really want is logging module from standard library. Create a logger and attach two handlers, one would be writing to a file and the other to stdout or stderr.

See Logging to multiple destinations for details

Since you're comfortable spawning external processes from your code, you could use tee itself. I don't know of any Unix system calls that do exactly what tee does.

# Note this version was written circa Python 2.6, see below for
# an updated 3.3+-compatible version.
import subprocess, os, sys

# Unbuffer output (this ensures the output is in the correct order)
sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 0)

tee = subprocess.Popen(["tee", "log.txt"], stdin=subprocess.PIPE)
os.dup2(tee.stdin.fileno(), sys.stdout.fileno())
os.dup2(tee.stdin.fileno(), sys.stderr.fileno())

print "\nstdout"
print >>sys.stderr, "stderr"
os.spawnve("P_WAIT", "/bin/ls", ["/bin/ls"], {})
os.execve("/bin/ls", ["/bin/ls"], os.environ)

You could also emulate tee using the multiprocessing package (or use processing if you're using Python 2.5 or earlier).

Update

Here is a Python 3.3+-compatible version:

import subprocess, os, sys

tee = subprocess.Popen(["tee", "log.txt"], stdin=subprocess.PIPE)
# Cause tee's stdin to get a copy of our stdin/stdout (as well as that
# of any child processes we spawn)
os.dup2(tee.stdin.fileno(), sys.stdout.fileno())
os.dup2(tee.stdin.fileno(), sys.stderr.fileno())

# The flush flag is needed to guarantee these lines are written before
# the two spawned /bin/ls processes emit any output
print("\nstdout", flush=True)
print("stderr", file=sys.stderr, flush=True)

# These child processes' stdin/stdout are 
os.spawnve("P_WAIT", "/bin/ls", ["/bin/ls"], {})
os.execve("/bin/ls", ["/bin/ls"], os.environ)

As described elsewhere, perhaps the best solution is to use the logging module directly:

import logging

logging.basicConfig(level=logging.DEBUG, filename='mylog.log')
logging.info('this should to write to the log file')

However, there are some (rare) occasions where you really want to redirect stdout. I had this situation when I was extending django's runserver command which uses print: I didn't want to hack the django source but needed the print statements to go to a file.

This is a way of redirecting stdout and stderr away from the shell using the logging module:

import logging, sys

class LogFile(object):
    """File-like object to log text using the `logging` module."""

    def __init__(self, name=None):
        self.logger = logging.getLogger(name)

    def write(self, msg, level=logging.INFO):
        self.logger.log(level, msg)

    def flush(self):
        for handler in self.logger.handlers:
            handler.flush()

logging.basicConfig(level=logging.DEBUG, filename='mylog.log')

# Redirect stdout and stderr
sys.stdout = LogFile('stdout')
sys.stderr = LogFile('stderr')

print 'this should to write to the log file'

You should only use this LogFile implementation if you really cannot use the logging module directly.

(Ah, just re-read your question and see that this doesn't quite apply.)

Here is a sample program that makes uses the python logging module. This logging module has been in all versions since 2.3. In this sample the logging is configurable by command line options.

In quite mode it will only log to a file, in normal mode it will log to both a file and the console.

import os
import sys
import logging
from optparse import OptionParser

def initialize_logging(options):
    """ Log information based upon users options"""

    logger = logging.getLogger('project')
    formatter = logging.Formatter('%(asctime)s %(levelname)s\t%(message)s')
    level = logging.__dict__.get(options.loglevel.upper(),logging.DEBUG)
    logger.setLevel(level)

    # Output logging information to screen
    if not options.quiet:
        hdlr = logging.StreamHandler(sys.stderr)
        hdlr.setFormatter(formatter)
        logger.addHandler(hdlr)

    # Output logging information to file
    logfile = os.path.join(options.logdir, "project.log")
    if options.clean and os.path.isfile(logfile):
        os.remove(logfile)
    hdlr2 = logging.FileHandler(logfile)
    hdlr2.setFormatter(formatter)
    logger.addHandler(hdlr2)

    return logger

def main(argv=None):
    if argv is None:
        argv = sys.argv[1:]

    # Setup command line options
    parser = OptionParser("usage: %prog [options]")
    parser.add_option("-l", "--logdir", dest="logdir", default=".", help="log DIRECTORY (default ./)")
    parser.add_option("-v", "--loglevel", dest="loglevel", default="debug", help="logging level (debug, info, error)")
    parser.add_option("-q", "--quiet", action="store_true", dest="quiet", help="do not log to console")
    parser.add_option("-c", "--clean", dest="clean", action="store_true", default=False, help="remove old log file")

    # Process command line options
    (options, args) = parser.parse_args(argv)

    # Setup logger format and output locations
    logger = initialize_logging(options)

    # Examples
    logger.error("This is an error message.")
    logger.info("This is an info message.")
    logger.debug("This is a debug message.")

if __name__ == "__main__":
    sys.exit(main())

I've been using Jacob Gabrielson's accepted solution for about 1 year, but now the inevitable has happened and one of my users wants this on Windows. Looking at the other proposed answers, I think most of these answers fail at capturing the outputs of spawned processes (as bolded by the original poster); I think the only way to do this is to do os.dup2(). I think I've figured out how to answer the original poster's exact question, and without using the Unix-specific tool tee: I can now capture all outputs of my Python program, including any spawned shell commands. This works on Windows, Mac and Linux. The code is as follows:

import os, sys, threading, platform

class StreamCapture:
    def __init__(self,stream,writer,echo=True,monkeypatch=None):
        self.active = True
        self.writer = writer
        self.stream = stream
        self.fd = stream.fileno()
        self.echo = echo
        (r,w) = os.pipe()
        self.pipe_read_fd = r
        self.pipe_write_fd = w
        self.dup_fd = os.dup(self.fd)
        os.dup2(w,self.fd)
        self.monkeypatch = monkeypatch if monkeypatch is not None else platform.system()=='Windows'
        if self.monkeypatch:
            self.oldwrite = stream.write
            stream.write = lambda z: os.write(self.fd,z.encode() if type(z)==str else z)
        t = threading.Thread(target=self.printer)
        self.thread = t
        t.start()
    def printer(self):
        while True:
            data = os.read(self.pipe_read_fd,100000)
            if(len(data)==0):
                self.writer.close()
                os.close(self.dup_fd)
                os.close(self.pipe_read_fd)
                return
            self.writer.write(data)
            if self.echo:
                os.write(self.dup_fd,data)
    def close(self):
        if not self.active:
            return
        self.active = False
        self.stream.flush()
        if self.monkeypatch:
            self.stream.write = self.oldwrite
        os.dup2(self.dup_fd,self.fd)
        os.close(self.pipe_write_fd)
    def __enter__(self):
        return self
    def __exit__(self,a,b,c):
        self.close()

You use it like this (notice the hard case that other solutions, apart from Jacob Gabrielson's, fail to capture):

print("This does not get saved to the log file")
with StreamCapture(sys.stdout,open('logfile.txt','wb')):
        os.write(sys.stdout.fileno(),b"Hello, captured world!\n")
        os.system('echo Hello from the shell')     # Hard case
        print("More capturing")
print("This also does not get saved to the log file")

This is not a short-and-sweet answer, but I tried to keep it succinct, and it's as simple as I could make it. It's complicated for the following reasons:

  1. Since I cannot use tee, I have to somehow perform the task of tee from within my Python process. It was not clear to me that there was a portable way of fork()ing and communicating with an os.pipe() (this states it's hard to share filedescriptors with forked processes in Windows) so I decided to use threading.

  2. In Windows, sys.stdout and sys.stderr really don't appreciate when their underlying fileno() get rerouted through an os.pipe() via os.dup2(). The Python interpreter crashes immediately after the first print(...) command.

  3. On Windows only, to solve the interpreter crashes, I monkeypatch sys.stdout.write = ... by setting it to a new function that simply calls to os.write(...). By default, I only do this when Windows is detected. Because I monkeypatch, I'm hoping this will reach all cached references to sys.stdout. I chose this monkeypatching approach instead of allocating a brand new stream, e.g. sys.stdout=..., because I was concerned that copies of the old sys.stdout would remain cached in various parts of the interpreter, but I guessed that sys.stdout.write was less likely to have been directly cached.

  4. If you daemonize the thread that processes the output of the pipe, then that thread gets killed as soon as the main thread completes, but this does not guarantee that all outputs have been written to the log file. It's actually necessary to not daemonize those helper threads and to let them gracefully terminate themselves when the pipes are closed.

I'm actually not entirely sure that I got all the corner cases right -- threaded code that interacts with delicate OS features is scary to write. Nevertheless, it passed my tests thus far. Because it's kind of hairy, I've made a PyPI package:

pip install streamcapture

The Github is here.

If you wish to log all output to a file AND output it to a text file then you can do the following. It's a bit hacky but it works:

import logging
debug = input("Debug or not")
if debug == "1":
    logging.basicConfig(level=logging.DEBUG, filename='./OUT.txt')
    old_print = print
    def print(string):
        old_print(string)
        logging.info(string)
print("OMG it works!")

EDIT: Note that this does not log errors unless you redirect sys.stderr to sys.stdout

EDIT2: A second issue is that you have to pass 1 argument unlike with the builtin function.

EDIT3: See the code before to write stdin and stdout to console and file with stderr only going to file

import logging, sys
debug = input("Debug or not")
if debug == "1":
    old_input = input
    sys.stderr.write = logging.info
    def input(string=""):
        string_in = old_input(string)
        logging.info("STRING IN " + string_in)
        return string_in
    logging.basicConfig(level=logging.DEBUG, filename='./OUT.txt')
    old_print = print
    def print(string="", string2=""):
        old_print(string, string2)
        logging.info(string)
        logging.info(string2)
print("OMG")
b = input()
print(a) ## Deliberate error for testing

You can also add stderr as well, based on shx2's answer above using class multifile :

class Log(object):

    def __init__(self, path_log, mode="w", encoding="utf-8"):
        h = open(path_log, mode, encoding=encoding)
        sys.stdout = multifile([ sys.stdout, h ])
        sys.stderr = multifile([ sys.stderr, h ])

    def __enter__(self):
        """ Necessary if called by with (or with... as) """
        return self     # only necessary if "as"

    def __exit__(self, type, value, tb):
        """ Necessary if call by with """
        pass

    def __del__(self):
        if sys is not None:
            # restoring
            sys.stdout = sys.__stdout__
            sys.stderr = sys.__stderr__

log = Log("test.txt")
print("line 1")
print("line 2", file=sys.stderr)
del log
print("line 3 only on screen")

Here's a context manager that temporarily duplicates stdout to a file. It's an improvement in my view because it resets sys.stdout & closes the file even when exceptions occur, and the syntax is indicative of an invisible change in the background. Expaneded on John T's solution.

class DuplicateStdout:
    def __init__(self, path):
        self.stdout = sys.stdout
        self.path = path
        self.f = None
    
    def write(self, s):
        self.stdout.write(s)
        self.f.write(s)

    def __enter__(self):
        self.f = open(self.path, "w")
        sys.stdout = self
    
    def __exit__(self, *args):
        sys.stdout = self.stdout
        self.f.close()

Example usage:

with DuplicateStdout("foo.log"):
    print("Hey") # also in foo.log

print("There") # not in foo.log
Related