Refactor logging mechanism for kuksa-client

docs/cli.md

@@ -48,6 +48,29 @@ If you wish to connect to a VISS server e.g. `kuksa-val-server` (not using TLS),
 kuksa-client ws://127.0.0.1:8090
 ```
 
+## Logging
+
+The log level of `kuksa-client` can be set using the LOG_LEVEL environment variable. The following levels are supported
+
+* `error`
+* `warning`
+* `info` (default)
+* `debug`
+
+
+To set the log level to DEBUG
+
+```console
+$ LOG_LEVEL=debug kuksa-client
+```
+
+It is possible to control log level in detail.
+The example below sets log level to DEBUG, but for asyncio INFO.
+
+```console
+$ LOG_LEVEL=debug,asyncio=info kuksa-client
+```
+
 ## TLS with databroker
 
 KUKSA Client uses TLS to connect to Databroker when the schema part of the server URI is `grpcs`.

kuksa-client/kuksa_client/__main__.py

@@ -41,13 +41,11 @@
 
 from kuksa_client import KuksaClientThread
 from kuksa_client import _metadata
+from kuksa_client.kuksa_logger import KuksaLogger
 
 scriptDir = os.path.dirname(os.path.realpath(__file__))
 
 DEFAULT_KUKSA_ADDRESS = os.environ.get("KUKSA_ADDRESS", "grpc://127.0.0.1:55555")
-DEFAULT_LOGGING_CONFIG = os.environ.get(
-    "LOGGING_CONFIG", os.path.join(scriptDir, "logging.ini")
-)
 DEFAULT_TOKEN_OR_TOKENFILE = os.environ.get("TOKEN_OR_TOKENFILE", None)
 DEFAULT_CERTIFICATE = os.environ.get("CERTIFICATE", None)
 DEFAULT_KEYFILE = os.environ.get("KEYFILE", None)
@@ -667,6 +665,10 @@ def do_version(self, _args):
 # Main Function
 
 def main():
+
+    kuksa_logger = KuksaLogger()
+    kuksa_logger.init_logging()
+
     parser = argparse.ArgumentParser()
     parser.add_argument(
         "server",
@@ -675,11 +677,6 @@ def main():
         Supported protocols: [grpc, grpcs, ws, wss]. Example: {DEFAULT_KUKSA_ADDRESS}",
         default=DEFAULT_KUKSA_ADDRESS,
     )
-    parser.add_argument(
-        "--logging-config",
-        default=DEFAULT_LOGGING_CONFIG,
-        help="Path to logging configuration file",
-    )
     parser.add_argument(
         "--token_or_tokenfile",
         default=DEFAULT_TOKEN_OR_TOKENFILE,
@@ -716,8 +713,6 @@ def main():
 
     args = parser.parse_args()
 
-    logging.config.fileConfig(args.logging_config)
-
     clientApp = TestClient(
         args.server,
         token_or_tokenfile=args.token_or_tokenfile,

kuksa-client/kuksa_client/_metadata.py

@@ -18,6 +18,9 @@
 # SPDX-License-Identifier: Apache-2.0
 ########################################################################
 
+
+import logging
+
 __all__ = (
     "__title__",
     "__summary__",
@@ -56,5 +59,5 @@
     __license__ = metadata["license"]
 
 except importlib_metadata.PackageNotFoundError as e:
-    print(e)
-    print("skip configuring metadata")
+    logger = logging.getLogger(__name__)
+    logger.info("skip configuring metadata", e)

kuksa-client/kuksa_client/cli_backend/grpc.py

@@ -28,6 +28,7 @@
 from typing import Optional
 import uuid
 import os
+import logging
 
 from kuksa_client import cli_backend
 import kuksa_client.grpc
@@ -36,9 +37,15 @@
 from kuksa.val.v1 import types_pb2
 
 
+logger = logging.getLogger(__name__)
+
+
 def callback_wrapper(callback: Callable[[str], None]) -> Callable[[Iterable[EntryUpdate]], None]:
     def wrapper(updates: Iterable[EntryUpdate]) -> None:
-        callback(json.dumps([update.to_dict() for update in updates], cls=DatabrokerEncoder))
+        try:
+            callback(json.dumps([update.to_dict() for update in updates], cls=DatabrokerEncoder))
+        except Exception as e:
+            logger.error("Callback could not be executed", e)
     return wrapper
 
 
@@ -93,7 +100,7 @@ def connection_established(self) -> bool:
     def stop(self):
         self.disconnect()
         self.run = False
-        print("gRPC channel disconnected.")
+        logger.info("gRPC channel disconnected.")
 
     # Function to implement fetching of metadata
     def getMetaData(self, path: str, timeout=5):
@@ -264,14 +271,14 @@ async def _grpcHandler(self, vss_client: kuksa_client.grpc.aio.VSSClient):
 
     # Update VSS Tree Entry
     def updateVSSTree(self, jsonStr, timeout=5):
-        print("Command not supported by KUKSA Databroker or KUKSA gRPC!")
+        logger.warning("Command not supported by KUKSA Databroker or KUKSA gRPC!")
 
     # Main loop for handling gRPC communication
     async def mainLoop(self):
         if self.insecure:
 
             async with kuksa_client.grpc.aio.VSSClient(self.serverIP, self.serverPort, token=self.token) as vss_client:
-                print("gRPC channel connected.")
+                logger.info("gRPC channel connected.")
                 await self._grpcHandler(vss_client)
         else:
             async with kuksa_client.grpc.aio.VSSClient(
@@ -283,5 +290,5 @@ async def mainLoop(self):
                 tls_server_name=self.tls_server_name,
                 token=self.token
             ) as vss_client:
-                print("Secure gRPC channel connected.")
+                logger.info("Secure gRPC channel connected.")
                 await self._grpcHandler(vss_client)

kuksa-client/kuksa_client/cli_backend/ws.py

@@ -26,11 +26,14 @@
 import ssl
 import time
 import uuid
+import logging
 
 import websockets
 
 from kuksa_client import cli_backend
 
+logger = logging.getLogger(__name__)
+
 
 class Backend(cli_backend.Backend):
     def __init__(self, config):
@@ -58,7 +61,7 @@ async def _receiver_handler(self, webSocket):
                         self.subscriptionCallbacks[resJson["subscriptionId"]](
                             message)
                     except Exception as e:  # pylint: disable=broad-except
-                        print(e)
+                        logger.warning("Receiver Handler exception", e)
 
     async def _sender_handler(self, webSocket):
         while self.run:
@@ -68,7 +71,7 @@ async def _sender_handler(self, webSocket):
             except queue.Empty:
                 await asyncio.sleep(0.01)
             except Exception as e:  # pylint: disable=broad-except
-                print(e)
+                logger.warning("Sender Handler exception", e)
                 return
 
     async def _msgHandler(self, webSocket):
@@ -113,7 +116,7 @@ def _sendReceiveMsg(self, req, timeout):
     def stop(self):
         self.ws_connection_established = False
         self.run = False
-        print("Server disconnected.")
+        logger.info("Server disconnected.")
 
     def disconnect(self, _):
         self.stop()
@@ -302,7 +305,7 @@ async def connect(self, _=None):
             # If using your own certificates make sure that name is included or use tls_server_name work-around
             context.check_hostname = True
             try:
-                print("connect to wss://"+self.serverIP+":"+str(self.serverPort))
+                logger.info("connect to wss://"+self.serverIP+":"+str(self.serverPort))
                 args = {
                     "uri": "wss://"+self.serverIP+":"+str(self.serverPort),
                     "ssl": context,
@@ -316,22 +319,22 @@ async def connect(self, _=None):
 
                 async with websockets.connect(**args) as ws:
                     self.subprotocol = ws.subprotocol
-                    print(f"Websocket connected. Negotiated subprotocol {self.subprotocol}")
+                    logger.info(f"Websocket connected. Negotiated subprotocol {self.subprotocol}")
                     await self._msgHandler(ws)
             except OSError as e:
-                print("Disconnected!! " + str(e))
+                logger.warning("Disconnected!!", e)
         else:
             try:
                 uri = "ws://"+self.serverIP+":"+str(self.serverPort)
-                print(f"connect to {uri}")
+                logger.info("connect to %s", uri)
                 async with websockets.connect(uri, subprotocols=subprotocols) as ws:
                     self.subprotocol = ws.subprotocol
                     if self.subprotocol == "VISSv2":
-                        print("subprotocol matches condition")
-                    print(f"Websocket connected. Negotiated subprotocol {self.subprotocol}")
+                        logger.info("subprotocol matches condition")
+                    logger.info("Websocket connected. Negotiated subprotocol %s", self.subprotocol)
                     await self._msgHandler(ws)
             except OSError as e:
-                print("Disconnected!! " + str(e))
+                logger.warning("Disconnected!!", e)
 
     # Main loop for handling websocket communication
     async def mainLoop(self):

kuksa-client/kuksa_client/grpc/__init__.py

@@ -16,6 +16,7 @@
 # SPDX-License-Identifier: Apache-2.0
 ########################################################################
 
+from __future__ import absolute_import
 import contextlib
 import dataclasses
 import datetime

kuksa-client/kuksa_client/kuksa_logger/__init__.py

@@ -0,0 +1,121 @@
+# /********************************************************************************
+# * Copyright (c) 2024 Contributors to the Eclipse Foundation
+# *
+# * See the NOTICE file(s) distributed with this work for additional
+# * information regarding copyright ownership.
+# *
+# * This program and the accompanying materials are made available under the
+# * terms of the Apache License 2.0 which is available at
+# * http://www.apache.org/licenses/LICENSE-2.0
+# *
+# * SPDX-License-Identifier: Apache-2.0
+# ********************************************************************************/
+
+# This file contains a logger that could be useful for clients using kuksa-python-sdk
+
+import logging
+import sys
+import os
+
+
+class KuksaLogger:
+    def init_logging(self):
+        # Example
+        #
+        # Set log level to debug
+        #   LOG_LEVEL=debug kuksa-client
+        #
+        # Set log level to INFO, but for dbcfeederlib.databrokerclientwrapper set it to DEBUG
+        #   LOG_LEVEL=info,dbcfeederlib.databrokerclientwrapper=debug kuksa-client
+        #
+        #
+
+        loglevels = self.parse_env_log(os.environ.get("LOG_LEVEL"))
+
+        # set root loglevel etc
+        self.init_root_logging(loglevels["root"])
+
+        # set loglevels for other loggers
+        for logger, level in loglevels.items():
+            if logger != "root":
+                logging.getLogger(logger).setLevel(level)
+
+    def init_root_logging(self, loglevel):
+        """Set up console logger"""
+        # create console handler and set level to debug. This just means that it can show DEBUG messages.
+        # What actually is shown is controlled by logging configuration
+        console_logger = logging.StreamHandler()
+        console_logger.setLevel(logging.DEBUG)
+
+        # create formatter
+        if sys.stdout.isatty():
+            formatter = ColorFormatter()
+        else:
+            formatter = logging.Formatter(
+                fmt="%(asctime)s %(levelname)s %(name)s: %(message)s"
+            )
+
+        # add formatter to console_logger
+        console_logger.setFormatter(formatter)
+
+        # add console_logger as a global handler
+        root_logger = logging.getLogger()
+        root_logger.setLevel(loglevel)
+        root_logger.addHandler(console_logger)
+
+    def parse_env_log(self, env_log, default=logging.INFO):
+        def parse_level(specified_level, default=default):
+            if isinstance(specified_level, str):
+                if specified_level.lower() in [
+                    "debug",
+                    "info",
+                    "warn",
+                    "warning",
+                    "error",
+                    "critical",
+                                               ]:
+                    return specified_level.upper()
+                raise ValueError(f"could not parse '{specified_level}' as a log level")
+            return default
+
+        parsed_loglevels = {}
+
+        if env_log is not None:
+            log_specs = env_log.split(",")
+            for log_spec in log_specs:
+                spec_parts = log_spec.split("=")
+                if len(spec_parts) == 1:
+                    # This is a root level spec
+                    if "root" in parsed_loglevels:
+                        raise ValueError("multiple root loglevels specified")
+                    parsed_loglevels["root"] = parse_level(spec_parts[0])
+                if len(spec_parts) == 2:
+                    logger_name = spec_parts[0]
+                    logger_level = spec_parts[1]
+                    parsed_loglevels[logger_name] = parse_level(logger_level)
+
+        if "root" not in parsed_loglevels:
+            parsed_loglevels["root"] = default
+
+        return parsed_loglevels
+
+
+class ColorFormatter(logging.Formatter):
+    """Color formatter that can be used for terminals"""
+    FORMAT = "{time} {{loglevel}} {logger} {msg}".format(
+        time="\x1b[2m%(asctime)s\x1b[0m",  # grey
+        logger="\x1b[2m%(name)s:\x1b[0m",  # grey
+        msg="%(message)s",
+    )
+    FORMATS = {
+        logging.DEBUG: FORMAT.format(loglevel="\x1b[34mDEBUG\x1b[0m"),  # blue
+        logging.INFO: FORMAT.format(loglevel="\x1b[32mINFO\x1b[0m"),  # green
+        logging.WARNING: FORMAT.format(loglevel="\x1b[33mWARNING\x1b[0m"),  # yellow
+        logging.ERROR: FORMAT.format(loglevel="\x1b[31mERROR\x1b[0m"),  # red
+        logging.CRITICAL: FORMAT.format(loglevel="\x1b[31mCRITICAL\x1b[0m"),  # red
+    }
+
+    def format(self, record):
+        log_fmt = self.FORMATS.get(record.levelno)
+        formatter = logging.Formatter(log_fmt)
+        return formatter.format(record)