I do proper logging with the logging module (logger.info, logger.debug...) and this gets written to a file.
But in some corner cases (external modules, uncaught exceptions, etc.), I sometimes still have errors written to stderr.
I log this to a file with:
import sys
sys.stdout, sys.stderr = open("stdout.log", "a+", buffering=1), open("stderr.log", "a+", buffering=1)
print("hello")
1/0
It works, but how to also have the datetime logged before each error?
Note: I'd like to avoid to use logging for this part, but something more low level.
I also want to avoid this solution:
def exc_handler(ex_cls, ex, tb):
with open('mylog.log', 'a') as f:
dt = time.strftime('%Y-%m-%d %H:%M:%S')
f.write(f"{dt}\n")
traceback.print_tb(tb, file=f)
f.write(f"{dt}\n")
sys.excepthook = exc_handler
because some external modules might override this. Is there a low level solution like overriding sys.stderr.print?
For the benefit of random readers, if you are simply looking to "log stderr to file" - this is not the answer you are looking for. Look at python's logging module; that is the best approach for most use-cases.
With the "disclaimer" part over-with, a lower-level approach to sys.std%s is very possible, but might be quite tricky. The following example:
sys.stdout, sys.stderr = open(...) approach from the question itself.stdwrites end with a newline.#!/usr/bin/env python
import sys
import os
import datetime
import time
import subprocess
from types import MethodType
def get_timestamp_prefix():
return f"{datetime.datetime.now()!s}: "
def stdwriter(self, msg, *args, **kwargs):
tstamp_prefix = get_timestamp_prefix()
if self._last_write_ended_with_newline:
# Add current timestamp if we're starting a new line
self._orig_write(tstamp_prefix)
self._last_write_ended_with_newline = msg.endswith('\n')
if msg.endswith('\n'):
# Avoid associating current timestamp to next error message
self._orig_write(f"\n{tstamp_prefix}".join(msg.split('\n')[:-1]))
self._orig_write("\n")
else:
self._orig_write(f"\n{tstamp_prefix}".join(msg.split('\n')))
def setup_std_files():
sys.stdout, sys.stderr = open("stdout.log", "a+", buffering=1), open("stderr.log", "a+", buffering=1)
for stream_name in ("stdout", "stderr"):
sys_stream = getattr(sys, stream_name)
setattr(sys_stream, "_last_write_ended_with_newline", True)
setattr(sys_stream, "_orig_write", getattr(sys_stream, "write"))
setattr(sys_stream, "write", MethodType(stdwriter, sys_stream))
def print_some_stuff():
print("hello")
print("world")
print("and..,", end=" ")
time.sleep(2.5)
# demonstrating "single" (close enough) timestamp until a newline is encountered
print("whazzzuppp?")
print("this line's timestamp should be ~2.5 seconds ahead of 'and.., whazzzuppp'")
def run_some_failing_stuff():
try:
1/0
except (ZeroDivisionError, subprocess.CalledProcessError) as e:
print(f"Exception handling: {e!r}") # to STDOUT
raise e # to STDERR (only after `finally:`)
else:
print("This should never happen")
finally:
print("Getting outta' here..") # to STDOUT
if __name__ == "__main__":
setup_std_files()
print_some_stuff()
run_some_failing_stuff()
Running this code will output:
$ rm *.log; ./pyerr_division.py ; for f in *.log; do echo "====== $f ====="; cat $f; echo "====== end ====="; done
====== stderr.log =====
2023-01-14 06:59:02.852233: Traceback (most recent call last):
2023-01-14 06:59:02.852386: File "/private/tmp/std_files/./pyerr_division.py", line 63, in <module>
2023-01-14 06:59:02.853152: run_some_failing_stuff()
2023-01-14 06:59:02.853192: File "/private/tmp/std_files/./pyerr_division.py", line 53, in run_some_failing_stuff
2023-01-14 06:59:02.853294: raise e # to STDERR (only after `finally:`)
2023-01-14 06:59:02.853330: File "/private/tmp/std_files/./pyerr_division.py", line 50, in run_some_failing_stuff
2023-01-14 06:59:02.853451: 1/0
2023-01-14 06:59:02.853501: ZeroDivisionError: division by zero
====== end =====
====== stdout.log =====
2023-01-14 06:59:00.346447: hello
2023-01-14 06:59:00.346502: world
2023-01-14 06:59:00.346518: and.., whazzzuppp?
2023-01-14 06:59:02.851982: this line's timestamp should be ~2.5 seconds ahead of 'and.., whazzzuppp'
2023-01-14 06:59:02.852039: Exception handling: ZeroDivisionError('division by zero')
2023-01-14 06:59:02.852077: Getting outta' here..
====== end =====
Child propagation is not explicitly in-scope for this question. Still, changing the approach not only allows to collect children's std%s to the same files, but also provides for easier debugging. The idea is to write to the original std%s if problems occur.
The following is based on this answer (thanks user48..2):
def failsafe_stdwriter(self, *args, **kwargs):
try:
self.stdwriter(*args, **kwargs)
except BaseException as be:
try:
self._orig_file.write(*args, **kwargs)
self._orig_file.write(f"\nFAILED WRITING WITH TIMESTAMP: {be!r}\n")
except Exception:
pass
raise be
def setup_std_files():
# sys.stdout, sys.stderr = open("stdout.log", "a+", buffering=1), open("stderr.log", "a+", buffering=1)
for stream_name in ("stdout", "stderr"):
sys_stream = getattr(sys, stream_name)
f = open(f"{stream_name}.log", "a+")
sys_stream_dup = os.dup(sys_stream.fileno())
setattr(sys_stream, "_orig_file", open(sys_stream_dup, "w"))
os.dup2(f.fileno(), sys_stream.fileno())
setattr(sys_stream, "_last_write_ended_with_newline", True)
setattr(sys_stream, "_orig_write", getattr(sys_stream, "write"))
setattr(sys_stream, "write", MethodType(stdwriter, sys_stream))
setattr(sys_stream, "stdwriter", MethodType(stdwriter, sys_stream))
setattr(sys_stream, "write", MethodType(failsafe_stdwriter, sys_stream))
With the above changes, child outputs will also be written to the files. For example, if we replace 1/0 with subprocess.check_call(["ls", "/nosuch-dir"]), the output will be as follows:
$ rm *.log; ./pyerr_subprocess.py ; for f in *.log; do echo "====== $f ====="; cat $f; echo "====== end ====="; done
====== stderr.log =====
ls: /nosuch-dir: No such file or directory
2023-01-14 08:22:41.945919: Traceback (most recent call last):
2023-01-14 08:22:41.945954: File "/private/tmp/std_files/./pyerr_subprocess.py", line 80, in <module>
2023-01-14 08:22:41.946193: run_some_failing_stuff()
2023-01-14 08:22:41.946232: File "/private/tmp/std_files/./pyerr_subprocess.py", line 71, in run_some_failing_stuff
2023-01-14 08:22:41.946339: raise e # to STDERR (only after `finally:`)
2023-01-14 08:22:41.946370: File "/private/tmp/std_files/./pyerr_subprocess.py", line 68, in run_some_failing_stuff
2023-01-14 08:22:41.946463: subprocess.check_call(["ls", "/nosuch-dir"])
2023-01-14 08:22:41.946494: File "/Library/Developer/CommandLineTools/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/subprocess.py", line 373, in check_call
2023-01-14 08:22:41.946740: raise CalledProcessError(retcode, cmd)
2023-01-14 08:22:41.946774: subprocess.CalledProcessError: Command '['ls', '/nosuch-dir']' returned non-zero exit status 1.
====== end =====
====== stdout.log =====
2023-01-14 08:22:39.428945: hello
2023-01-14 08:22:39.428998: world
2023-01-14 08:22:39.429013: and.., whazzzuppp?
2023-01-14 08:22:41.931855: this line's timestamp should be ~2.5 seconds ahead of 'and.., whazzzuppp'
2023-01-14 08:22:41.945638: Exception handling: CalledProcessError(1, ['ls', '/nosuch-dir'])
2023-01-14 08:22:41.945774: Getting outta' here..
====== end =====
Children's output will not have a timestamp with their output (much like ls's output in the above example), however this not only propagates to children, but also helps debugging (by allowing to fall-back to the original standard outputs). For example, a simple typo in stdwriter would be visible, as the output falls-back to the terminal:
$ rm *.log; ./pyerr_subprocess.py ; for f in *.log; do echo "====== $f ====="; cat $f; echo "====== end ====="; done
hello
FAILED WRITING WITH TIMESTAMP: NameError("name 'get_tamestamp_prefix' is not defined")
There might be better (and simpler) approaches. I did not explore the option of subclassing file types at all. The one thing I take away from this is - tinkering with error message output methods, makes for an "interesting" debug journey.