Formatting when redirecting stderr and stdout to logger

Question

In some cases I need to monkey-patch stderr and stdout to redirect them to logging. I'm using the solutions from How to redirect stdout and stderr to logger in Python. This code nearly works:

import logging, sys

logging.basicConfig(filename='test.log', format='%(asctime)s %(levelname)s %(message)s', datefmt='%H:%M:%S')
log = logging.getLogger('foobar')

class LoggerWriter:
    def __init__(self, level):
        self.level = level
        self.linebuf = ''
    def write(self, buf):
        for line in buf.rstrip().splitlines():
           self.level(line.rstrip())
    def flush(self):
        pass

sys.stdout = LoggerWriter(log.warning)
sys.stderr = LoggerWriter(log.error)

print("hello")

blablabla  # to trigger an error

but the ouput is not as desired, for example the traceback is split in too many lines. Why? How to improve the formatting?

07:37:02 WARNING hello
07:37:02 ERROR Traceback (most recent call last):
07:37:02 ERROR   File "D:\test.py", line 21, in <module>
07:37:02 ERROR blablabla  # to trigger an error
07:37:02 ERROR NameError
07:37:02 ERROR :
07:37:02 ERROR name 'blablabla' is not defined

How to avoid the the 3 separate lines (that should be 1 line)? Or better: the traceback should be logged in one logging call.

Note: I don't want to use traceback + sys.excepthook (I already used this in another case), here in my application, I really need stderr/stdout patching.

Answer 1

The problem is that in the process of outputting the exception traceback to stdout/stderr, the structure (the fact that it's an exception traceback) has been lost - it's just a set of random lines of text, as far as the logger is concerned.

To overcome this, you'd have to buffer the text in LoggerWriter and process it later: e.g. you could look for a line containing Traceback (most recent call last): to start buffering - but as exception text doesn't have a trailer, it would be hard to know when the last line of exception text was seen.

Update: Why are there three lines for the NameError? To address this specific point, it's down to the vagaries of buffering, which is down to a combination of the OS and the process that is doing the output. Each call to write is sent as a separate line to the log, and that might not be a whole line. If the NameError is sent as three separate writes to an output stream - something like the following pseudocode:

out_stream.write(exception.type)
out_stream.write(':')
out_stream.write(exception.message)

then that could result in what you see as three separate lines.