Keep log messages from last full run and last run with error or warnings (#2118)

* add in-memory log handler to capture latest log cycle and keep last with warnings or errors

* specifcy log to be cleared and saved, add soc.log handling

* skip writing to disk if there are no messages

* keep last three logs, remove duplicate urllib logging

* add warning/error

Author: MartinRinas

packages/helpermodules/logger.py

@@ -8,11 +8,15 @@
 import threading
 import typing_extensions
 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',
@@ -65,6 +69,7 @@ class RedactingFilter(logging.Filter):
     Args:
         name (str): The name of the filter.
     """
+
     def __init__(self, name: str = ''):
         super().__init__(name)
 
@@ -105,17 +110,114 @@ 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_handler(logger_name: str = None) -> None:
+    global in_memory_log_handlers
+    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_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:
+                rotate_logs(RAMDISK_PATH, name)
+                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:
+            handler = in_memory_log_handlers[logger_name]
+            logs = handler.get_logs()
+            if logs:
+                rotate_logs(RAMDISK_PATH, logger_name)
+                with open(os.path.join(RAMDISK_PATH, f'{logger_name}.current.log'), 'w') as f:
+                    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:
         return megabytes * 1000000
 
+    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
     log_queue = queue.Queue()
     queue_handler = logging.handlers.QueueHandler(log_queue)
     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=[queue_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=[queue_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"))
@@ -191,7 +293,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))
     logging.getLogger().addHandler(soc_queue_handler)
+    logging.getLogger().addHandler(in_memory_log_handlers["soc"])
     soc_listener = logging.handlers.QueueListener(soc_queue, soc_log_handler)
     soc_listener.start()
 
@@ -204,7 +309,10 @@ def mb_to_bytes(megabytes: int) -> int:
     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_queue_handler)
+    logging.getLogger().addHandler(in_memory_log_handlers["internal_chargepoint"])
     internal_chargepoint_listener = logging.handlers.QueueListener(internal_chargepoint_queue,
                                                                    internal_chargepoint_log_handler)
     internal_chargepoint_listener.start()

packages/main.py

@@ -154,6 +154,10 @@ 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_handler("main")
+
             log.info("# ***Start*** ")
             # log.debug(run_command.run_shell_command("top -b -n 1 | head -n 20"))
             # log.debug(f'Drosselung: {run_command.run_shell_command("if which vcgencmd >/dev/null; then vcgencmd get_throttled; else echo not found; fi")}')
@@ -162,6 +166,7 @@ def handler_with_control_interval():
                 return
             try:
                 handler_with_control_interval()
+                logger.write_logs_to_file("main")
             finally:
                 self.__release_lock("handler10Sec")
         except Exception:

packages/modules/update_soc.py

@@ -12,6 +12,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__)
 
@@ -30,14 +31,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 = [], []