Я правильно веду журнал с помощью модуля logging (logger.info, logger.debug...), и это записывается в файл.
Но в некоторых крайних случаях (внешние модули, неперехваченные исключения и т. д.) у меня иногда все еще пишутся ошибки в stderr.
Я записываю это в файл с:
import sys
sys.stdout, sys.stderr = open("stdout.log", "a+", buffering=1), open("stderr.log", "a+", buffering=1)
print("hello")
1/0
Это работает, но как также регистрировать дату и время перед каждой ошибкой?
Примечание. Я бы хотел не использовать logging для этой части, а использовать что-то более низкоуровневое.
Я также хочу избежать этого решения:
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
Потому что некоторые внешние модули могут переопределить это. Есть ли решение низкого уровня, например переопределение sys.stderr.print?
Вы можете использовать подход, описанный в этом рецепте поваренной книги, чтобы рассматривать регистратор как выходной поток, а затем перенаправлять sys.std{out,err} для регистрации записанных в них данных. Затем, конечно, вы можете настроить ведение журнала для использования любого формата, включая префикс даты и времени, обычным способом, используя, например. %(asctime)s в формате.
Для случайных читателей, если вы просто хотите «записать stderr в файл» - это не тот ответ, который вы ищете. Посмотрите на модуль logging Python; это лучший подход для большинства случаев использования. С частью «отказ от ответственности» более низкий подход к sys.std%s вполне возможен, но может быть довольно сложным. Следующий пример:
sys.stdout, sys.stderr = open(...)
из самого вопроса.std
заканчиваются новой строкой.#!/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()
Запуск этого кода выведет:
$ 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 =====
Распространение дочерних элементов явно не входит в сферу охвата этого вопроса. Тем не менее, изменение подхода не только позволяет собирать детские std%s в одни и те же файлы, но и упрощает отладку. Идея в том, чтобы писать на оригинал std%s, если возникнут проблемы. Следующее основано на этом ответе (спасибо, 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))
С указанными выше изменениями дочерние выходные данные также будут записаны в файлы. Например, если мы заменим 1/0 на subprocess.check_call(["ls", "/nosuch-dir"]), результат будет следующим:
$ 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 =====
Выходные данные дочерних элементов не будут иметь метку времени с их выходными данными (во многом как выходные данные ls в приведенном выше примере), однако это не только распространяется на дочерние элементы, но и помогает отладке (позволяя вернуться к исходным стандартным выходным данным). Например, простая опечатка в stdwriter будет видна, поскольку вывод возвращается к терминалу:
$ 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")
Могут быть лучшие (и более простые) подходы. Я вообще не исследовал возможность создания подклассов типов файлов. Единственное, что я вынес из этого, это то, что работа с методами вывода сообщений об ошибках делает «интересное» путешествие по отладке.
Отличный рецепт. Спасибо за то, что сделали пакет ведения журнала настолько полезным, насколько он есть.