Merge pull request #299 from willcl-ark/tidy-up-logging

Author: willcl-ark

src/logging_config/config.json

@@ -0,0 +1,61 @@
+{
+  "version": 1,
+  "disable_existing_loggers": false,
+  "formatters": {
+    "simple": {
+      "format": " %(asctime)s - %(levelname)s - %(message)s",
+      "datefmt": "%Y-%m-%dT%H:%M:%S%z"
+    },
+    "detailed": {
+      "format": " %(asctime)s - %(levelname)s - [%(module)s|L%(lineno)d] - %(message)s",
+      "datefmt": "%Y-%m-%dT%H:%M:%S%z"
+    }
+  },
+  "filters": {
+    "no_errors": {
+      "()": "warnet.utils.NonErrorFilter"
+    }
+  },
+  "handlers": {
+    "stdout": {
+      "class": "logging.StreamHandler",
+      "level": "DEBUG",
+      "formatter": "simple",
+      "filters": ["no_errors"],
+      "stream": "ext://sys.stdout"
+    },
+    "stderr": {
+      "class": "logging.StreamHandler",
+      "level": "WARNING",
+      "formatter": "simple",
+      "stream": "ext://sys.stderr"
+    },
+    "file": {
+      "class": "logging.handlers.RotatingFileHandler",
+      "level": "DEBUG",
+      "formatter": "detailed",
+      "filename": "warnet.log",
+      "maxBytes": 16000000,
+      "backupCount": 3
+    }
+  },
+  "loggers": {
+    "root": {
+      "level": "DEBUG",
+      "handlers": [
+        "stdout",
+        "stderr",
+        "file"
+      ]
+    },
+    "urllib3.connectionpool": {
+        "level": "WARNING",
+        "propagate": 1
+    },
+
+    "kubernetes.client.rest": {
+        "level": "WARNING",
+        "propagate": 1
+    }
+  }
+}

src/warnet/server.py

@@ -1,6 +1,8 @@
 import argparse
 import base64
+import json
 import logging
+import logging.config
 import os
 import pkgutil
 import platform
@@ -14,8 +16,6 @@
 import traceback
 from datetime import datetime
 from io import BytesIO
-from logging import StreamHandler
-from logging.handlers import RotatingFileHandler
 from pathlib import Path
 
 import jsonschema
@@ -35,6 +35,7 @@
 
 WARNET_SERVER_PORT = 9276
 CONFIG_DIR_ALREADY_EXISTS = 32001
+LOGGING_CONFIG_PATH = Path("src/logging_config/config.json")
 
 
 class Server:
@@ -60,12 +61,10 @@ def __init__(self, backend):
         self.jsonrpc = JSONRPC(self.app, "/api")
 
         self.log_file_path = os.path.join(self.basedir, "warnet.log")
-        self.logger: logging.Logger
         self.setup_global_exception_handler()
         self.setup_logging()
         self.setup_rpc()
         self.logger.info("Started server")
-        self.app.add_url_rule("/-/healthy", view_func=self.healthy)
 
         # register a well known /-/healthy endpoint for liveness tests
         # we regard warnet as healthy if the http server is up
@@ -101,30 +100,23 @@ def healthy(self):
         return "warnet is healthy"
 
     def setup_logging(self):
-        # Ensure the directory exists
         os.makedirs(os.path.dirname(self.log_file_path), exist_ok=True)
 
-        # Configure root logger
-        logging.basicConfig(
-            level=logging.DEBUG,
-            handlers=[
-                RotatingFileHandler(
-                    self.log_file_path, maxBytes=16_000_000, backupCount=3, delay=True
-                ),
-                StreamHandler(sys.stdout),
-            ],
-            format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
-        )
-        # Disable urllib3.connectionpool logging
-        logging.getLogger("urllib3.connectionpool").setLevel(logging.CRITICAL)
+        with open(LOGGING_CONFIG_PATH) as f:
+            logging_config = json.load(f)
+
+        # Update log file path
+        logging_config["handlers"]["file"]["filename"] = str(self.log_file_path)
+
+        # Apply the config
+        logging.config.dictConfig(logging_config)
+
         self.logger = logging.getLogger("warnet")
         self.logger.info("Logging started")
 
-        if self.backend == "k8s":
-            # if using k8s as a backend, tone the logging down
-            logging.getLogger("kubernetes.client.rest").setLevel(logging.WARNING)
-
         def log_request():
+            if "healthy" in request.path:
+                return # No need to log all these
             if not request.path.startswith("/api/"):
                 self.logger.debug(request.path)
             else:
@@ -439,7 +431,7 @@ def thread_start(wn):
                 wn.apply_network_conditions()
                 wn.wait_for_health()
                 self.logger.info(
-                    f"Resumed warnet named '{network}' from config dir {wn.config_dir}"
+                    f"Successfully resumed warnet named '{network}' from config dir {wn.config_dir}"
                 )
             except Exception as e:
                 trace = traceback.format_exc()
@@ -472,6 +464,7 @@ def thread_start(wn, lock: threading.Lock):
                     wn.warnet_up()
                     wn.wait_for_health()
                     wn.apply_network_conditions()
+                    self.logger.info("Warnet started successfully")
                 except Exception as e:
                     trace = traceback.format_exc()
                     self.logger.error(f"Unhandled exception starting warnet: {e}\n{trace}")

src/warnet/tank.py

@@ -62,12 +62,13 @@ def _parse_version(self):
 
     def parse_graph_node(self, node):
         # Dynamically parse properties based on the schema
+        graph_properties = {}
         for property, specs in self.warnet.node_schema["properties"].items():
             value = node.get(property, specs.get("default"))
             if property == "version":
                 self._parse_version()
             setattr(self, property, value)
-            logger.debug(f"{property}={value}")
+            graph_properties[property] = value
 
         if self.version and self.image:
             raise Exception(
@@ -83,7 +84,8 @@ def parse_graph_node(self, node):
 
         self.config_dir = self.warnet.config_dir / str(self.suffix)
         self.config_dir.mkdir(parents=True, exist_ok=True)
-        logger.debug(f"{self=:}")
+
+        logger.debug(f"Parsed graph node: {self.index} with attributes: {[f'{key}={value}' for key, value in graph_properties.items()]}")
 
     @classmethod
     def from_graph_node(cls, index, warnet, tank=None):

src/warnet/utils.py

@@ -36,6 +36,12 @@
 NODE_SCHEMA_PATH = SCHEMA / "node_schema.json"
 
 
+class NonErrorFilter(logging.Filter):
+
+    def filter(self, record: logging.LogRecord) -> bool | logging.LogRecord:
+        return record.levelno <= logging.INFO
+
+
 def exponential_backoff(max_retries=5, base_delay=1, max_delay=32):
     """
     A decorator for exponential backoff.