logging overhaul

.gitignore

@@ -6,7 +6,7 @@ TODO*
 test.py
 .DS_Store
 .idea
-old_*.py
+*_old.py
 *.rdb
 #
 # Github Default from https://github.com/martinohanlon/flightlight/issues/1

hyperglass/api/__init__.py

@@ -1,4 +1,6 @@
 """hyperglass API."""
+# Standard Library
+import logging
 
 # Third Party
 from litestar import Litestar
@@ -33,21 +35,28 @@
     root_schema_site="elements",
 )
 
+HANDLERS = [
+    device,
+    devices,
+    queries,
+    info,
+    query,
+]
 
-app = Litestar(
-    route_handlers=[
-        device,
-        devices,
-        queries,
-        info,
-        query,
+if not STATE.settings.disable_ui:
+    HANDLERS = [
+        *HANDLERS,
         create_static_files_router(
             path="/images", directories=[IMAGES_DIR], name="images", include_in_schema=False
         ),
         create_static_files_router(
             path="/", directories=[UI_DIR], name="ui", html_mode=True, include_in_schema=False
         ),
-    ],
+    ]
+
+
+app = Litestar(
+    route_handlers=HANDLERS,
     exception_handlers={
         HTTPException: http_handler,
         HyperglassError: app_handler,

hyperglass/api/error_handlers.py

@@ -2,6 +2,7 @@
 
 # Third Party
 from litestar import Request, Response
+from litestar.exceptions import ValidationException
 
 # Project
 from hyperglass.log import log
@@ -18,9 +19,7 @@
 def default_handler(request: Request, exc: BaseException) -> Response:
     """Handle uncaught errors."""
     state = use_state()
-    log.critical(
-        "{method} {path} {detail!s}", method=request.method, path=request.url.path, detail=exc
-    )
+    log.bind(method=request.method, path=request.url.path, detail=str(exc)).critical("Error")
     return Response(
         {"output": state.params.messages.general, "level": "danger", "keywords": []},
         status_code=500,
@@ -29,9 +28,7 @@ def default_handler(request: Request, exc: BaseException) -> Response:
 
 def http_handler(request: Request, exc: BaseException) -> Response:
     """Handle web server errors."""
-    log.critical(
-        "{method} {path} {detail}", method=request.method, path=request.url.path, detail=exc.detail
-    )
+    log.bind(method=request.method, path=request.url.path, detail=exc.detail).critical("HTTP Error")
     return Response(
         {"output": exc.detail, "level": "danger", "keywords": []},
         status_code=exc.status_code,
@@ -40,23 +37,20 @@ def http_handler(request: Request, exc: BaseException) -> Response:
 
 def app_handler(request: Request, exc: BaseException) -> Response:
     """Handle application errors."""
-    log.critical(
-        "{method} {path} {detail}", method=request.method, path=request.url.path, detail=exc.message
+    log.bind(method=request.method, path=request.url.path, detail=exc.message).critical(
+        "hyperglass Error"
     )
     return Response(
         {"output": exc.message, "level": exc.level, "keywords": exc.keywords},
         status_code=exc.status_code,
     )
 
 
-def validation_handler(request: Request, exc: BaseException) -> Response:
+def validation_handler(request: Request, exc: ValidationException) -> Response:
     """Handle Pydantic validation errors raised by FastAPI."""
     error = exc.errors()[0]
-    log.critical(
-        "{method} {path} {detail}",
-        method=request.method,
-        path=request.url.path,
-        detail=error["msg"],
+    log.bind(method=request.method, path=request.url.path, detail=error["msg"]).critical(
+        "Validation Error"
     )
     return Response(
         {"output": error["msg"], "level": "error", "keywords": error["loc"]},

hyperglass/api/routes.py

@@ -73,15 +73,17 @@ async def query(_state: HyperglassState, request: Request, data: Query) -> Query
     # each command output value is unique.
     cache_key = f"hyperglass.query.{data.digest()}"
 
-    log.info("{!r} starting query execution", data)
+    _log = log.bind(query=data.summary())
+
+    _log.info("Starting query execution")
 
     cache_response = cache.get_map(cache_key, "output")
     json_output = False
     cached = False
     runtime = 65535
 
     if cache_response:
-        log.debug("{!r} cache hit (cache key {!r})", data, cache_key)
+        _log.bind(cache_key=cache_key).debug("Cache hit")
 
         # If a cached response exists, reset the expiration time.
         cache.expire(cache_key, expire_in=_state.params.cache.timeout)
@@ -91,7 +93,7 @@ async def query(_state: HyperglassState, request: Request, data: Query) -> Query
         timestamp = cache.get_map(cache_key, "timestamp")
 
     elif not cache_response:
-        log.debug("{!r} cache miss (cache key {!r})", data, cache_key)
+        _log.bind(cache_key=cache_key).debug("Cache miss")
 
         timestamp = data.timestamp
 
@@ -109,7 +111,7 @@ async def query(_state: HyperglassState, request: Request, data: Query) -> Query
 
         endtime = time.time()
         elapsedtime = round(endtime - starttime, 4)
-        log.debug("{!r} runtime: {!s} seconds", data, elapsedtime)
+        _log.debug("Runtime: {!s} seconds", elapsedtime)
 
         if output is None:
             raise HyperglassError(message=_state.params.messages.general, alert="danger")
@@ -125,7 +127,7 @@ async def query(_state: HyperglassState, request: Request, data: Query) -> Query
         cache.set_map_item(cache_key, "timestamp", timestamp)
         cache.expire(cache_key, expire_in=_state.params.cache.timeout)
 
-        log.debug("{!r} cached for {!s} seconds", data, _state.params.cache.timeout)
+        _log.bind(cache_timeout=_state.params.cache.timeout).debug("Response cached")
 
         runtime = int(round(elapsedtime, 0))
 
@@ -137,8 +139,7 @@ async def query(_state: HyperglassState, request: Request, data: Query) -> Query
 
     if json_output:
         response_format = "application/json"
-
-    log.success("{!r} execution completed", data)
+    _log.info("Execution completed")
 
     response = {
         "output": cache_response,

hyperglass/api/tasks.py

@@ -65,4 +65,6 @@ async def send_webhook(
                     }
                 )
     except Exception as err:
-        log.error("Error sending webhook to {}: {!s}", params.logging.http.provider, err)
+        log.bind(destination=params.logging.http.provider, error=str(err)).error(
+            "Failed to send webhook"
+        )

hyperglass/compat/_sshtunnel.py

@@ -217,19 +217,11 @@ def _redirect(self, chan):
                 data = self.request.recv(1024)
                 if not data:
                     break
-                self.logger.trace(
-                    ">>> OUT {0} send to {1}: {2} >>>".format(
-                        self.info, self.remote_address, hexlify(data)
-                    ),
-                )
                 chan.sendall(data)
             if chan in rqst:  # else
                 if not chan.recv_ready():
                     break
                 data = chan.recv(1024)
-                self.logger.trace(
-                    "<<< IN {0} recv: {1} <<<".format(self.info, hexlify(data)),
-                )
                 self.request.sendall(data)
 
     def handle(self):
@@ -249,24 +241,21 @@ def handle(self):
             chan = None
         if chan is None:
             msg = "{0} to {1} was rejected by the SSH server".format(self.info, self.remote_address)
-            self.logger.trace(msg)
             raise HandlerSSHTunnelForwarderError(msg)
 
-        self.logger.trace("{0} connected".format(self.info))
         try:
             self._redirect(chan)
         except socket.error:
             # Sometimes a RST is sent and a socket error is raised, treat this
             # exception. It was seen that a 3way FIN is processed later on, so
             # no need to make an ordered close of the connection here or raise
             # the exception beyond this point...
-            self.logger.trace("{0} sending RST".format(self.info))
-        except Exception as e:
-            self.logger.trace("{0} error: {1}".format(self.info, repr(e)))
+            pass
+        except Exception:
+            pass
         finally:
             chan.close()
             self.request.close()
-            self.logger.trace("{0} connection closed.".format(self.info))
 
 
 class _ForwardServer(socketserver.TCPServer):  # Not Threading
@@ -283,10 +272,7 @@ def __init__(self, *args, **kwargs):
 
     def handle_error(self, request, client_address):
         (exc_class, exc, tb) = sys.exc_info()
-        self.logger.error(
-            "Could not establish connection from {0} to remote " "side of the tunnel",
-            request.getsockname(),
-        )
+        self.logger.bind(source=request.getsockname()).error("Could not establish connection to remote side of the tunnel")
         self.tunnel_ok.put(False)
 
     @property
@@ -814,16 +800,13 @@ def __init__(
 
         check_host(self.ssh_host)
         check_port(self.ssh_port)
-
-        self.logger.info(
-            "Connecting to gateway: {h}:{p} as user '{u}', timeout {t}",
-            h=self.ssh_host,
-            p=self.ssh_port,
-            u=self.ssh_username,
-            t=self.gateway_timeout,
-        )
-
-        self.logger.debug("Concurrent connections allowed: {0}", self._threaded)
+        self.logger.bind(
+            host=self.ssh_host,
+            port=self.ssh_port,
+            username=self.ssh_username,
+            timeout=self.gateway_timeout,
+        ).info("Connecting to gateway")
+        self.logger.bind(count=self._threaded).debug("Concurrent connections allowed")
 
     @staticmethod
     def _read_ssh_config(
@@ -1154,8 +1137,7 @@ def _check_tunnel(self, _srv) -> None:
         if self.skip_tunnel_checkup:
             self.tunnel_is_up[_srv.local_address] = True
             return
-
-        self.logger.info("Checking tunnel to: {a}", a=_srv.remote_address)
+        self.logger.debug("Checking tunnel", address=_srv.remote_address)
 
         if isinstance(_srv.local_address, str):  # UNIX stream
             s = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
@@ -1171,13 +1153,13 @@ def _check_tunnel(self, _srv) -> None:
             )
             s.connect(connect_to)
             self.tunnel_is_up[_srv.local_address] = _srv.tunnel_ok.get(timeout=TUNNEL_TIMEOUT * 1.1)
-            self.logger.debug("Tunnel to {0} is DOWN".format(_srv.remote_address))
+            self.logger.bind(status="DOWN", address=_srv.remote_address).debug("Tunnel Status")
         except socket.error:
-            self.logger.debug("Tunnel to {0} is DOWN".format(_srv.remote_address))
+            self.logger.bind(status="DOWN", address=_srv.remote_address).debug("Tunnel Status")
             self.tunnel_is_up[_srv.local_address] = False
 
         except queue.Empty:
-            self.logger.debug("Tunnel to {0} is UP".format(_srv.remote_address))
+            self.logger.bind(status="UP", address=_srv.remote_address).debug("Tunnel Status")
             self.tunnel_is_up[_srv.local_address] = True
         finally:
             s.close()

hyperglass/configuration/load.py

@@ -63,7 +63,7 @@ def load_dsl(path: Path, *, empty_allowed: bool) -> LoadedConfig:
             raise ConfigError(
                 "'{!s}' exists, but it is empty and is required to start hyperglass.".format(path),
             )
-    log.debug("Loaded configuration from {!s}", path)
+    log.bind(path=path).debug("Loaded configuration")
     return data or {}
 
 
@@ -101,7 +101,7 @@ def load_python(path: Path, *, empty_allowed: bool) -> LoadedConfig:
     if data is None and empty_allowed is False:
         raise ConfigError(f"'{path!s} exists', but variable or function 'main' is an invalid type")
 
-    log.debug("Loaded configuration from {!s}", path)
+    log.bind(path=path).debug("Loaded configuration")
     return data or {}
 
 

hyperglass/configuration/validate.py

@@ -4,7 +4,7 @@
 from pydantic import ValidationError
 
 # Project
-from hyperglass.log import log, enable_file_logging, enable_syslog_logging
+from hyperglass.log import log
 from hyperglass.settings import Settings
 from hyperglass.models.ui import UIParameters
 from hyperglass.models.directive import Directive, Directives
@@ -31,7 +31,7 @@ def init_files() -> None:
         path = Settings.app_path / directory
         if not path.exists():
             path.mkdir(parents=True)
-            log.debug("Created directory {!s}", path)
+            log.debug("Created directory", path=path)
 
 
 def init_params() -> "Params":
@@ -40,20 +40,20 @@ def init_params() -> "Params":
     # Map imported user configuration to expected schema.
     params = Params(**user_config)
 
-    # Set up file logging once configuration parameters are initialized.
-    enable_file_logging(
-        log_directory=params.logging.directory,
-        log_format=params.logging.format,
-        log_max_size=params.logging.max_size,
-        debug=Settings.debug,
-    )
+    # # Set up file logging once configuration parameters are initialized.
+    # enable_file_logging(
+    #     log_directory=params.logging.directory,
+    #     log_format=params.logging.format,
+    #     log_max_size=params.logging.max_size,
+    #     debug=Settings.debug,
+    # )
 
     # Set up syslog logging if enabled.
-    if params.logging.syslog is not None and params.logging.syslog.enable:
-        enable_syslog_logging(
-            syslog_host=params.logging.syslog.host,
-            syslog_port=params.logging.syslog.port,
-        )
+    # if params.logging.syslog is not None and params.logging.syslog.enable:
+    #     enable_syslog_logging(
+    #         syslog_host=params.logging.syslog.host,
+    #         syslog_port=params.logging.syslog.port,
+    #     )
 
     if params.logging.http is not None and params.logging.http.enable:
         log.debug("HTTP logging is enabled")
@@ -103,7 +103,7 @@ def init_devices() -> "Devices":
         raise ConfigError("No devices are defined in devices file")
 
     devices = Devices(*items)
-    log.debug("Initialized devices {!r}", devices)
+    log.debug("Initialized devices", devices=devices)
 
     return devices