From 9d9ce454e530ffa6d906f2fe8180af0c23ed8a91 Mon Sep 17 00:00:00 2001 From: MartinRinas Date: Sat, 4 Jan 2025 20:26:21 +0000 Subject: [PATCH 1/5] add in-memory log handler to capture latest log cycle and keep last with warnings or errors --- packages/helpermodules/logger.py | 76 ++++++++++++++++++++++++++++++-- packages/main.py | 6 +++ 2 files changed, 78 insertions(+), 4 deletions(-) diff --git a/packages/helpermodules/logger.py b/packages/helpermodules/logger.py index 93fafcf7e5..bd97dd6601 100644 --- a/packages/helpermodules/logger.py +++ b/packages/helpermodules/logger.py @@ -6,6 +6,8 @@ import threading import typing_extensions import re +import io +import os FORMAT_STR_DETAILED = '%(asctime)s - {%(name)s:%(lineno)s} - {%(levelname)s:%(threadName)s} - %(message)s' FORMAT_STR_SHORT = '%(asctime)s - %(message)s' @@ -103,18 +105,67 @@ def filter_pos(name: str, record) -> bool: return False +class InMemoryLogHandler(logging.Handler): + def __init__(self, base_handler=None): + super().__init__() + self.base_handler = base_handler + self.log_stream = io.StringIO() + self.has_warning_or_error = False + + def emit(self, record): + if self.base_handler is None or self.base_handler.filter(record): + msg = self.format(record) + self.log_stream.write(msg + '\n') + if record.levelno >= logging.WARNING: + self.has_warning_or_error = True + + def get_logs(self): + return self.log_stream.getvalue() + + def clear(self): + self.log_stream = io.StringIO() + self.has_warning_or_error = False + + +def clear_in_memory_log_handlers() -> None: + global in_memory_log_handlers + for handler in in_memory_log_handlers.values(): + handler.clear() + + +def write_logs_to_files() -> None: + global in_memory_log_handlers + + for name, handler in in_memory_log_handlers.items(): + with open(os.path.join(RAMDISK_PATH, f'{name}.latest.log'), 'w') as f: + f.write(handler.get_logs()) + + # If any warning or error messages were logged, create a -warning copy + if handler.has_warning_or_error: + with open(os.path.join(RAMDISK_PATH, f'{name}.latest-warning.log'), 'w') as f: + f.write(handler.get_logs()) + + def setup_logging() -> None: def mb_to_bytes(megabytes: int) -> int: return megabytes * 1000000 - # Mehrere kleine Dateien verwenden, damit nicht zu viel verworfen wird, wenn die Datei voll ist. + + global in_memory_log_handlers + in_memory_log_handlers = {name: InMemoryLogHandler() for name in ["main", "internal_chargepoint"]} + # to do: add smarthome and soc to in_memory_log_handlers, needs updates in individual thread calls + + # Main logger main_file_handler = RotatingFileHandler(RAMDISK_PATH + 'main.log', maxBytes=mb_to_bytes(5.5), backupCount=4) main_file_handler.setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) main_file_handler.addFilter(RedactingFilter()) - logging.basicConfig(level=logging.DEBUG, handlers=[main_file_handler]) + in_memory_log_handlers["main"] = InMemoryLogHandler(main_file_handler) + in_memory_log_handlers["main"].setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) + logging.basicConfig(level=logging.DEBUG, handlers=[main_file_handler, in_memory_log_handlers["main"]]) logging.getLogger().handlers[0].addFilter(functools.partial(filter_neg, "soc")) logging.getLogger().handlers[0].addFilter(functools.partial(filter_neg, "Internal Chargepoint")) logging.getLogger().handlers[0].addFilter(functools.partial(filter_neg, "smarthome")) + # Chargelog logger chargelog_log = logging.getLogger("chargelog") chargelog_log.propagate = False chargelog_file_handler = RotatingFileHandler( @@ -123,6 +174,7 @@ def mb_to_bytes(megabytes: int) -> int: chargelog_file_handler.addFilter(RedactingFilter()) chargelog_log.addHandler(chargelog_file_handler) + # Data migration logger data_migration_log = logging.getLogger("data_migration") data_migration_log.propagate = False data_migration_file_handler = RotatingFileHandler( @@ -131,6 +183,7 @@ def mb_to_bytes(megabytes: int) -> int: data_migration_file_handler.addFilter(RedactingFilter()) data_migration_log.addHandler(data_migration_file_handler) + # MQTT logger mqtt_log = logging.getLogger("mqtt") mqtt_log.propagate = False mqtt_file_handler = RotatingFileHandler(RAMDISK_PATH + 'mqtt.log', maxBytes=mb_to_bytes(3), backupCount=1) @@ -138,32 +191,47 @@ def mb_to_bytes(megabytes: int) -> int: mqtt_file_handler.addFilter(RedactingFilter()) mqtt_log.addHandler(mqtt_file_handler) + # Smarthome logger smarthome_log_handler = RotatingFileHandler(RAMDISK_PATH + 'smarthome.log', maxBytes=mb_to_bytes(1), backupCount=1) smarthome_log_handler.setFormatter(logging.Formatter(FORMAT_STR_SHORT)) smarthome_log_handler.addFilter(functools.partial(filter_pos, "smarthome")) smarthome_log_handler.addFilter(RedactingFilter()) + # in_memory_log_handlers["smarthome"] = InMemoryLogHandler(smarthome_log_handler) + # in_memory_log_handlers["smarthome"].setFormatter(logging.Formatter(FORMAT_STR_SHORT)) logging.getLogger().addHandler(smarthome_log_handler) + # logging.getLogger().addHandler(in_memory_log_handlers["smarthome"]) + # SoC logger soc_log_handler = RotatingFileHandler(RAMDISK_PATH + 'soc.log', maxBytes=mb_to_bytes(2), backupCount=1) soc_log_handler.setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) soc_log_handler.addFilter(functools.partial(filter_pos, "soc")) soc_log_handler.addFilter(RedactingFilter()) + # in_memory_log_handlers["soc"] = InMemoryLogHandler(soc_log_handler) + # in_memory_log_handlers["soc"].setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) logging.getLogger().addHandler(soc_log_handler) + # logging.getLogger().addHandler(in_memory_log_handlers["soc"]) + # Internal chargepoint logger internal_chargepoint_log_handler = RotatingFileHandler(RAMDISK_PATH + 'internal_chargepoint.log', maxBytes=mb_to_bytes(1), backupCount=1) internal_chargepoint_log_handler.setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) internal_chargepoint_log_handler.addFilter(functools.partial(filter_pos, "Internal Chargepoint")) internal_chargepoint_log_handler.addFilter(RedactingFilter()) + in_memory_log_handlers["internal_chargepoint"] = InMemoryLogHandler(internal_chargepoint_log_handler) + in_memory_log_handlers["internal_chargepoint"].setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) logging.getLogger().addHandler(internal_chargepoint_log_handler) + logging.getLogger().addHandler(in_memory_log_handlers["internal_chargepoint"]) + # Urllib3 logger urllib3_log = logging.getLogger("urllib3.connectionpool") urllib3_log.propagate = True - urllib3_file_handler = RotatingFileHandler(RAMDISK_PATH + 'soc.log', maxBytes=mb_to_bytes(2), backupCount=1) + urllib3_file_handler = RotatingFileHandler(RAMDISK_PATH + 'urllib3.log', maxBytes=mb_to_bytes(2), backupCount=1) urllib3_file_handler.setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) urllib3_file_handler.addFilter(RedactingFilter()) - urllib3_file_handler.addFilter(functools.partial(filter_pos, "soc")) + urllib3_file_handler.addFilter(functools.partial(filter_pos, "urllib3")) + in_memory_log_handlers["urllib3"] = InMemoryLogHandler(urllib3_file_handler) + in_memory_log_handlers["urllib3"].setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) urllib3_log.addHandler(urllib3_file_handler) logging.getLogger("pymodbus").setLevel(logging.WARNING) diff --git a/packages/main.py b/packages/main.py index afa82ce914..aadaad89ef 100755 --- a/packages/main.py +++ b/packages/main.py @@ -66,10 +66,16 @@ def handler_with_control_interval(): self.interval_counter = 1 else: self.interval_counter = self.interval_counter + 1 + + # In-Memory Log-Handler zurücksetzen + logger.clear_in_memory_log_handlers() + log.info("# ***Start*** ") log.debug(f"Threads: {threading.enumerate()}") Pub().pub("openWB/set/system/time", timecheck.create_timestamp()) handler_with_control_interval() + logger.write_logs_to_files() + except KeyboardInterrupt: log.critical("Ausführung durch exit_after gestoppt: "+traceback.format_exc()) except Exception: From 9d9f0f2db5b0bcf645c07ce6b48a9801ff8892bb Mon Sep 17 00:00:00 2001 From: MartinRinas Date: Sat, 4 Jan 2025 21:00:05 +0000 Subject: [PATCH 2/5] specifcy log to be cleared and saved, add soc.log handling --- packages/helpermodules/logger.py | 45 +++++++++++++++++++++++--------- packages/main.py | 4 +-- packages/modules/update_soc.py | 4 +++ 3 files changed, 38 insertions(+), 15 deletions(-) diff --git a/packages/helpermodules/logger.py b/packages/helpermodules/logger.py index bd97dd6601..a2b9c5fdf1 100644 --- a/packages/helpermodules/logger.py +++ b/packages/helpermodules/logger.py @@ -127,24 +127,43 @@ def clear(self): self.has_warning_or_error = False -def clear_in_memory_log_handlers() -> None: +def clear_in_memory_log_handler(logger_name: str = None) -> None: global in_memory_log_handlers - for handler in in_memory_log_handlers.values(): - handler.clear() + if logger_name is None: + # Clear all in-memory log handlers + for handler in in_memory_log_handlers.values(): + handler.clear() + else: + # Clear specified in-memory log handler + if logger_name in in_memory_log_handlers: + in_memory_log_handlers[logger_name].clear() -def write_logs_to_files() -> None: +def write_logs_to_file(logger_name: str = None) -> None: global in_memory_log_handlers - for name, handler in in_memory_log_handlers.items(): - with open(os.path.join(RAMDISK_PATH, f'{name}.latest.log'), 'w') as f: - f.write(handler.get_logs()) + if logger_name is None: + # Write logs for all in-memory log handlers + for name, handler in in_memory_log_handlers.items(): + with open(os.path.join(RAMDISK_PATH, f'{name}.latest.log'), 'w') as f: + f.write(handler.get_logs()) - # If any warning or error messages were logged, create a -warning copy - if handler.has_warning_or_error: - with open(os.path.join(RAMDISK_PATH, f'{name}.latest-warning.log'), 'w') as f: + # If any warning or error messages were logged, create a -warning copy + if handler.has_warning_or_error: + with open(os.path.join(RAMDISK_PATH, f'{name}.latest-warning.log'), 'w') as f: + f.write(handler.get_logs()) + else: + # Write logs for specified in-memory log handler + if logger_name in in_memory_log_handlers: + handler = in_memory_log_handlers[logger_name] + with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest.log'), 'w') as f: f.write(handler.get_logs()) + # If any warning or error messages were logged, create a -warning copy + if handler.has_warning_or_error: + with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest-warning.log'), 'w') as f: + f.write(handler.get_logs()) + def setup_logging() -> None: def mb_to_bytes(megabytes: int) -> int: @@ -206,10 +225,10 @@ def mb_to_bytes(megabytes: int) -> int: soc_log_handler.setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) soc_log_handler.addFilter(functools.partial(filter_pos, "soc")) soc_log_handler.addFilter(RedactingFilter()) - # in_memory_log_handlers["soc"] = InMemoryLogHandler(soc_log_handler) - # in_memory_log_handlers["soc"].setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) + in_memory_log_handlers["soc"] = InMemoryLogHandler(soc_log_handler) + in_memory_log_handlers["soc"].setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) logging.getLogger().addHandler(soc_log_handler) - # logging.getLogger().addHandler(in_memory_log_handlers["soc"]) + logging.getLogger().addHandler(in_memory_log_handlers["soc"]) # Internal chargepoint logger internal_chargepoint_log_handler = RotatingFileHandler(RAMDISK_PATH + 'internal_chargepoint.log', diff --git a/packages/main.py b/packages/main.py index aadaad89ef..9a158b446d 100755 --- a/packages/main.py +++ b/packages/main.py @@ -68,13 +68,13 @@ def handler_with_control_interval(): self.interval_counter = self.interval_counter + 1 # In-Memory Log-Handler zurücksetzen - logger.clear_in_memory_log_handlers() + logger.clear_in_memory_log_handler("main") log.info("# ***Start*** ") log.debug(f"Threads: {threading.enumerate()}") Pub().pub("openWB/set/system/time", timecheck.create_timestamp()) handler_with_control_interval() - logger.write_logs_to_files() + logger.write_logs_to_file("main") except KeyboardInterrupt: log.critical("Ausführung durch exit_after gestoppt: "+traceback.format_exc()) diff --git a/packages/modules/update_soc.py b/packages/modules/update_soc.py index a81071ffb1..7c34a73672 100644 --- a/packages/modules/update_soc.py +++ b/packages/modules/update_soc.py @@ -13,6 +13,7 @@ from helpermodules.utils import joined_thread_handler from modules.common.abstract_vehicle import VehicleUpdateData from modules.utils import wait_for_module_update_completed +from helpermodules.logger import clear_in_memory_log_handler, write_logs_to_file log = logging.getLogger(__name__) @@ -31,14 +32,17 @@ def update(self) -> None: self.event_update_soc.clear() topic = "openWB/set/vehicle/set/vehicle_update_completed" try: + clear_in_memory_log_handler("soc") threads_update, threads_store = self._get_threads() joined_thread_handler(threads_update, 300) wait_for_module_update_completed(self.event_vehicle_update_completed, topic) # threads_store = self._filter_failed_store_threads(threads_store) joined_thread_handler(threads_store, data.data.general_data.data.control_interval/3) wait_for_module_update_completed(self.event_vehicle_update_completed, topic) + write_logs_to_file("soc") except Exception: log.exception("Fehler im update_soc-Modul") + write_logs_to_file("soc") def _get_threads(self) -> Tuple[List[Thread], List[Thread]]: threads_update, threads_store = [], [] From bcde2d47bd0b5291e459c4aa01e70249480408dd Mon Sep 17 00:00:00 2001 From: MartinRinas Date: Mon, 6 Jan 2025 19:31:09 +0000 Subject: [PATCH 3/5] skip writing to disk if there are no messages --- packages/helpermodules/logger.py | 32 ++++++++++++++++++-------------- 1 file changed, 18 insertions(+), 14 deletions(-) diff --git a/packages/helpermodules/logger.py b/packages/helpermodules/logger.py index a2b9c5fdf1..1f1cb29746 100644 --- a/packages/helpermodules/logger.py +++ b/packages/helpermodules/logger.py @@ -145,24 +145,28 @@ def write_logs_to_file(logger_name: str = None) -> None: if logger_name is None: # Write logs for all in-memory log handlers for name, handler in in_memory_log_handlers.items(): - with open(os.path.join(RAMDISK_PATH, f'{name}.latest.log'), 'w') as f: - f.write(handler.get_logs()) - - # If any warning or error messages were logged, create a -warning copy - if handler.has_warning_or_error: - with open(os.path.join(RAMDISK_PATH, f'{name}.latest-warning.log'), 'w') as f: - f.write(handler.get_logs()) + logs = handler.get_logs() + if logs: + with open(os.path.join(RAMDISK_PATH, f'{name}.latest.log'), 'w') as f: + f.write(logs) + + # If any warning or error messages were logged, create a -warning copy + if handler.has_warning_or_error: + with open(os.path.join(RAMDISK_PATH, f'{name}.latest-warning.log'), 'w') as f: + f.write(logs) else: # Write logs for specified in-memory log handler if logger_name in in_memory_log_handlers: handler = in_memory_log_handlers[logger_name] - with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest.log'), 'w') as f: - f.write(handler.get_logs()) - - # If any warning or error messages were logged, create a -warning copy - if handler.has_warning_or_error: - with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest-warning.log'), 'w') as f: - f.write(handler.get_logs()) + logs = handler.get_logs() + if logs: + with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest.log'), 'w') as f: + f.write(logs) + + # If any warning or error messages were logged, create a -warning copy + if handler.has_warning_or_error: + with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest-warning.log'), 'w') as f: + f.write(logs) def setup_logging() -> None: From 13cc7492a37970f7bbea9050411f2ac5b5d0b45b Mon Sep 17 00:00:00 2001 From: MartinRinas Date: Fri, 14 Mar 2025 20:32:29 +0000 Subject: [PATCH 4/5] keep last three logs, remove duplicate urllib logging --- packages/helpermodules/logger.py | 52 ++++++++++++++++++-------------- 1 file changed, 30 insertions(+), 22 deletions(-) diff --git a/packages/helpermodules/logger.py b/packages/helpermodules/logger.py index 1f1cb29746..0c75564b22 100644 --- a/packages/helpermodules/logger.py +++ b/packages/helpermodules/logger.py @@ -8,11 +8,13 @@ import re import io import os +import shutil FORMAT_STR_DETAILED = '%(asctime)s - {%(name)s:%(lineno)s} - {%(levelname)s:%(threadName)s} - %(message)s' FORMAT_STR_SHORT = '%(asctime)s - %(message)s' RAMDISK_PATH = str(Path(__file__).resolve().parents[2]) + '/ramdisk/' PERSISTENT_LOG_PATH = str(Path(__file__).resolve().parents[2]) + '/data/log/' +NUMBER_OF_LOGFILES = 3 KNOWN_SENSITIVE_FIELDS = [ 'password', 'secret', 'token', 'apikey', 'access_token', @@ -142,31 +144,47 @@ def clear_in_memory_log_handler(logger_name: str = None) -> None: def write_logs_to_file(logger_name: str = None) -> None: global in_memory_log_handlers + def rotate_logs(base_path: str, name: str): + # Rotate the log files + for i in range(NUMBER_OF_LOGFILES-1, 0, -1): + src = os.path.join(base_path, f'{name}.previous{i}.log') + dst = os.path.join(base_path, f'{name}.previous{i+1}.log') + if os.path.exists(src): + shutil.move(src, dst) + # Move the current log to previous1 + current_log = os.path.join(base_path, f'{name}.current.log') + if os.path.exists(current_log): + shutil.move(current_log, os.path.join(base_path, f'{name}.previous1.log')) + + def combine_logs(base_path: str, name: str): + latest_log_path = os.path.join(base_path, f'{name}.latest.log') + with open(latest_log_path, 'w') as latest_log: + for i in range(NUMBER_OF_LOGFILES-1, -1, -1): + log_file = os.path.join( + base_path, f'{name}.previous{i}.log') if i > 0 else os.path.join(base_path, f'{name}.current.log') + if os.path.exists(log_file): + with open(log_file, 'r') as f: + latest_log.write(f.read()) + if logger_name is None: # Write logs for all in-memory log handlers for name, handler in in_memory_log_handlers.items(): logs = handler.get_logs() if logs: - with open(os.path.join(RAMDISK_PATH, f'{name}.latest.log'), 'w') as f: + rotate_logs(RAMDISK_PATH, name) + with open(os.path.join(RAMDISK_PATH, f'{name}.current.log'), 'w') as f: f.write(logs) - - # If any warning or error messages were logged, create a -warning copy - if handler.has_warning_or_error: - with open(os.path.join(RAMDISK_PATH, f'{name}.latest-warning.log'), 'w') as f: - f.write(logs) + combine_logs(RAMDISK_PATH, name) else: # Write logs for specified in-memory log handler if logger_name in in_memory_log_handlers: handler = in_memory_log_handlers[logger_name] logs = handler.get_logs() if logs: - with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest.log'), 'w') as f: + rotate_logs(RAMDISK_PATH, logger_name) + with open(os.path.join(RAMDISK_PATH, f'{logger_name}.current.log'), 'w') as f: f.write(logs) - - # If any warning or error messages were logged, create a -warning copy - if handler.has_warning_or_error: - with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest-warning.log'), 'w') as f: - f.write(logs) + combine_logs(RAMDISK_PATH, logger_name) def setup_logging() -> None: @@ -219,10 +237,7 @@ def mb_to_bytes(megabytes: int) -> int: smarthome_log_handler.setFormatter(logging.Formatter(FORMAT_STR_SHORT)) smarthome_log_handler.addFilter(functools.partial(filter_pos, "smarthome")) smarthome_log_handler.addFilter(RedactingFilter()) - # in_memory_log_handlers["smarthome"] = InMemoryLogHandler(smarthome_log_handler) - # in_memory_log_handlers["smarthome"].setFormatter(logging.Formatter(FORMAT_STR_SHORT)) logging.getLogger().addHandler(smarthome_log_handler) - # logging.getLogger().addHandler(in_memory_log_handlers["smarthome"]) # SoC logger soc_log_handler = RotatingFileHandler(RAMDISK_PATH + 'soc.log', maxBytes=mb_to_bytes(2), backupCount=1) @@ -249,13 +264,6 @@ def mb_to_bytes(megabytes: int) -> int: # Urllib3 logger urllib3_log = logging.getLogger("urllib3.connectionpool") urllib3_log.propagate = True - urllib3_file_handler = RotatingFileHandler(RAMDISK_PATH + 'urllib3.log', maxBytes=mb_to_bytes(2), backupCount=1) - urllib3_file_handler.setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) - urllib3_file_handler.addFilter(RedactingFilter()) - urllib3_file_handler.addFilter(functools.partial(filter_pos, "urllib3")) - in_memory_log_handlers["urllib3"] = InMemoryLogHandler(urllib3_file_handler) - in_memory_log_handlers["urllib3"].setFormatter(logging.Formatter(FORMAT_STR_DETAILED)) - urllib3_log.addHandler(urllib3_file_handler) logging.getLogger("pymodbus").setLevel(logging.WARNING) logging.getLogger("uModbus").setLevel(logging.WARNING) From d69e8b9c5adc557b0ec6a04d6ef30e2e9d22f240 Mon Sep 17 00:00:00 2001 From: MartinRinas Date: Fri, 14 Mar 2025 20:57:09 +0000 Subject: [PATCH 5/5] add warning/error --- packages/helpermodules/logger.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/packages/helpermodules/logger.py b/packages/helpermodules/logger.py index 0c75564b22..834ed831cc 100644 --- a/packages/helpermodules/logger.py +++ b/packages/helpermodules/logger.py @@ -175,6 +175,12 @@ def combine_logs(base_path: str, name: str): with open(os.path.join(RAMDISK_PATH, f'{name}.current.log'), 'w') as f: f.write(logs) combine_logs(RAMDISK_PATH, name) + + # If any warning or error messages were logged, create a -warning copy + if handler.has_warning_or_error: + with open(os.path.join(RAMDISK_PATH, f'{name}.latest-warning.log'), 'w') as f: + f.write(logs) + else: # Write logs for specified in-memory log handler if logger_name in in_memory_log_handlers: @@ -186,6 +192,11 @@ def combine_logs(base_path: str, name: str): f.write(logs) combine_logs(RAMDISK_PATH, logger_name) + # If any warning or error messages were logged, create a -warning copy + if handler.has_warning_or_error: + with open(os.path.join(RAMDISK_PATH, f'{logger_name}.latest-warning.log'), 'w') as f: + f.write(logs) + def setup_logging() -> None: def mb_to_bytes(megabytes: int) -> int: