From 3c0b2895df4fb19a82565f6b89641d64bb07dfac Mon Sep 17 00:00:00 2001 From: Erik Jaegervall Date: Wed, 8 May 2024 16:10:51 +0200 Subject: [PATCH] Refactor logging mechanism for kuksa-client Keep print only for things that can be printed in CLI Adapt config to method used by other providers Fixes #25 --- docs/cli.md | 23 ++++ kuksa-client/kuksa_client/__main__.py | 15 +-- kuksa-client/kuksa_client/_metadata.py | 7 +- kuksa-client/kuksa_client/cli_backend/grpc.py | 17 ++- kuksa-client/kuksa_client/cli_backend/ws.py | 23 ++-- kuksa-client/kuksa_client/grpc/__init__.py | 1 + .../kuksa_client/kuksa_logger/__init__.py | 121 ++++++++++++++++++ kuksa-client/kuksa_client/logging.ini | 23 ---- 8 files changed, 180 insertions(+), 50 deletions(-) create mode 100644 kuksa-client/kuksa_client/kuksa_logger/__init__.py delete mode 100644 kuksa-client/kuksa_client/logging.ini diff --git a/docs/cli.md b/docs/cli.md index c1f6c8a..1e3f22a 100644 --- a/docs/cli.md +++ b/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`. diff --git a/kuksa-client/kuksa_client/__main__.py b/kuksa-client/kuksa_client/__main__.py index 2f76afe..e0fac36 100755 --- a/kuksa-client/kuksa_client/__main__.py +++ b/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, diff --git a/kuksa-client/kuksa_client/_metadata.py b/kuksa-client/kuksa_client/_metadata.py index 3560041..84dcf76 100644 --- a/kuksa-client/kuksa_client/_metadata.py +++ b/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) diff --git a/kuksa-client/kuksa_client/cli_backend/grpc.py b/kuksa-client/kuksa_client/cli_backend/grpc.py index 564baad..15a0ce7 100644 --- a/kuksa-client/kuksa_client/cli_backend/grpc.py +++ b/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) diff --git a/kuksa-client/kuksa_client/cli_backend/ws.py b/kuksa-client/kuksa_client/cli_backend/ws.py index df94254..effd204 100644 --- a/kuksa-client/kuksa_client/cli_backend/ws.py +++ b/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): diff --git a/kuksa-client/kuksa_client/grpc/__init__.py b/kuksa-client/kuksa_client/grpc/__init__.py index f2f569f..492f326 100644 --- a/kuksa-client/kuksa_client/grpc/__init__.py +++ b/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 diff --git a/kuksa-client/kuksa_client/kuksa_logger/__init__.py b/kuksa-client/kuksa_client/kuksa_logger/__init__.py new file mode 100644 index 0000000..8f9ffac --- /dev/null +++ b/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) diff --git a/kuksa-client/kuksa_client/logging.ini b/kuksa-client/kuksa_client/logging.ini deleted file mode 100644 index 302b705..0000000 --- a/kuksa-client/kuksa_client/logging.ini +++ /dev/null @@ -1,23 +0,0 @@ -[loggers] -keys=root - -[handlers] -keys=consoleHandler - -[formatters] -keys=simpleFormatter - -[logger_root] -; Set level to DEBUG for extra debugging information -level=INFO -handlers=consoleHandler - -[handler_consoleHandler] -class=StreamHandler -level=DEBUG -formatter=simpleFormatter -args=(sys.stdout,) - -[formatter_simpleFormatter] -format=%(levelname)s %(asctime)s %(name)s %(message)s -datefmt=