From f812e0c22ad802849a5a9e0cb2fdff5a0eaef75c Mon Sep 17 00:00:00 2001 From: Sven Eberth Date: Mon, 26 Feb 2024 22:32:35 +0100 Subject: [PATCH] Started to refactor the logger and use no longer the default logger --- src/viur/core/__init__.py | 17 ++++++++++------- src/viur/core/logging.py | 28 ++++++++++++++++++++-------- src/viur/core/request.py | 31 +++++++++++++++++-------------- 3 files changed, 47 insertions(+), 29 deletions(-) diff --git a/src/viur/core/__init__.py b/src/viur/core/__init__.py index 47e508662..64168bca8 100644 --- a/src/viur/core/__init__.py +++ b/src/viur/core/__init__.py @@ -50,10 +50,13 @@ TaskHandler, callDeferred, retry_n_times, runStartupTasks) # noinspection PyUnresolvedReferences -from viur.core import logging as viurLogging # unused import, must exist, initializes request logging +from viur.core import logging as viur_logging # unused import, must exist, initializes request logging import logging # this import has to stay here, see #571 +logger = viur_logging.LOGGER.getChild(__name__) + + __all__ = [ # basics from this __init__ "setDefaultLanguage", @@ -100,7 +103,7 @@ def load_indexes_from_file() -> dict[str, list]: indexes_dict.setdefault(index["kind"], []).append(index) except FileNotFoundError: - logging.warning("index.yaml not found") + logger.warning("index.yaml not found") return {} return indexes_dict @@ -232,7 +235,7 @@ def buildApp(modules: ModuleType | object, renderers: ModuleType | object, defau # This might be useful for debugging, please keep it for now. if conf.debug.trace: import pprint - logging.debug(pprint.pformat(resolver)) + logger.debug(pprint.pformat(resolver)) return root @@ -271,7 +274,7 @@ def setup(modules: ModuleType | object, render: ModuleType | object = None, de "ViUR just started a new Instance with call tracing enabled! This might log sensitive information!" ) except Exception as exc: # OverQuota, whatever - logging.exception(exc) + logger.exception(exc) # Ensure that our Content Security Policy Header Cache gets build from viur.core import securityheaders securityheaders._rebuildCspHeaderCache() @@ -301,11 +304,11 @@ def setup(modules: ModuleType | object, render: ModuleType | object = None, de from viur.core import db key = db.Key("viur-conf", "viur-conf") if not (obj := db.Get(key)): # create a new "viur-conf"? - logging.info("Creating new viur-conf") + logger.info("Creating new viur-conf") obj = db.Entity(key) if "hmacKey" not in obj: # create a new hmacKey - logging.info("Creating new hmacKey") + logger.info("Creating new hmacKey") obj["hmacKey"] = utils.string.random(length=20) db.Put(obj) @@ -358,7 +361,7 @@ def __getattr__(attr: str) -> object: func = entry[1] msg = f"@{attr} was replaced by @{entry[0]}" warnings.warn(msg, DeprecationWarning, stacklevel=2) - logging.warning(msg, stacklevel=2) + logger.warning(msg, stacklevel=2) return func return super(__import__(__name__).__class__).__getattr__(attr) diff --git a/src/viur/core/logging.py b/src/viur/core/logging.py index 93930312d..365c7c73c 100644 --- a/src/viur/core/logging.py +++ b/src/viur/core/logging.py @@ -97,6 +97,8 @@ def colorize(level: str, text: str) -> str: def format(self, record: logging.LogRecord) -> str: # truncate the pathname + # print(f"{record = }") + # print(f"{vars(record) = }") if "/deploy" in record.pathname: pathname = record.pathname.split("/deploy/")[1] else: @@ -111,6 +113,7 @@ def format(self, record: logging.LogRecord) -> str: pathname = "/".join(parts) record.pathname = pathname + record.name = record.name.removeprefix(f"{LOGGER.name}.").removesuffix(f'.{record.filename.split(".", 1)[0]}') # Select colorization mode match (os.getenv(f"VIUR_LOGGING_COLORIZATION") or "FULL").upper(): @@ -140,17 +143,21 @@ def format(self, record: logging.LogRecord) -> str: } ) +# logger = logging.getLogger("viur.shop").getChild(__name__) +LOGGER = logging.getLogger(conf.instance.project_id)#.getChild("viur.core") +LOGGER.setLevel(logging.DEBUG) +# logger.propagate = False + logger = logging.getLogger() -logger.setLevel(logging.DEBUG) # Calling getLogger(name) ensures that any placeholder loggers held by loggerDict are fully initialized # (https://stackoverflow.com/a/53250066) -for name, level in { - k: v.getEffectiveLevel() - for k, v in logging.root.manager.loggerDict.items() - if isinstance(v, logging.Logger) -}.items(): - logging.getLogger(name).setLevel(level) +# for name, level in { +# k: v.getEffectiveLevel() +# for k, v in logging.root.manager.loggerDict.items() +# if isinstance(v, logging.Logger) +# }.items(): +# logging.getLogger(name).setLevel(level) # Remove any existing handler from logger for handler in logger.handlers[:]: @@ -170,7 +177,12 @@ def format(self, record: logging.LogRecord) -> str: else: # Use ViURLocalFormatter for local debug message formatting - formatter = ViURLocalFormatter(f"[%(asctime)s] %(pathname)s:%(lineno)d [%(levelname)s] %(message)s") + # formatter = ViURLocalFormatter(f"[%(asctime)s] %(pathname)s|%(name)s|%(module)s:%(lineno)d [%(levelname)s] %(message)s") + formatter = ViURLocalFormatter(f"[%(asctime)s] %(name)s %(filename)s:%(lineno)d [%(levelname)s] %(message)s") sh = logging.StreamHandler() sh.setFormatter(formatter) logger.addHandler(sh) + + +print(f"{logger.handlers = }") +print(f"{logger = }") diff --git a/src/viur/core/request.py b/src/viur/core/request.py index 82e19320c..8db28e17f 100644 --- a/src/viur/core/request.py +++ b/src/viur/core/request.py @@ -24,9 +24,12 @@ from viur.core.logging import client as loggingClient, requestLogger, requestLoggingRessource from viur.core.securityheaders import extendCsp from viur.core.tasks import _appengineServiceIPs +from viur.core.logging import LOGGER TEMPLATE_STYLE_KEY = "style" +logger = LOGGER.getChild(__name__) + class RequestValidator(ABC): """ @@ -150,7 +153,7 @@ def isDevServer(self) -> bool: import warnings msg = "Use of `isDevServer` is deprecated; Use `conf.instance.is_dev_server` instead!" warnings.warn(msg, DeprecationWarning, stacklevel=2) - logging.warning(msg) + logger.warning(msg) return conf.instance.is_dev_server def _select_language(self, path: str) -> str: @@ -205,7 +208,7 @@ def _select_language(self, path: str) -> str: def _process(self): if self.method not in ("get", "post", "head"): - logging.error(f"{self.method=} not supported") + logger.error(f"{self.method=} not supported") return if self.request.headers.get("X-AppEngine-TaskName", None) is not None: # Check if we run in the appengine @@ -218,7 +221,7 @@ def _process(self): # Check if we should process or abort the request for validator, reqValidatorResult in [(x, x.validate(self)) for x in self.requestValidators]: if reqValidatorResult is not None: - logging.warning(f"Request rejected by validator {validator.name}") + logger.warning(f"Request rejected by validator {validator.name}") statusCode, statusStr, statusDescr = reqValidatorResult self.response.status = f"{statusCode} {statusStr}" self.response.write(statusDescr) @@ -299,7 +302,7 @@ def _process(self): except errors.Redirect as e: if conf.debug.trace_exceptions: - logging.warning("""conf.debug.trace_exceptions is set, won't handle this exception""") + logger.warning("""conf.debug.trace_exceptions is set, won't handle this exception""") raise self.response.status = f"{e.status} {e.name}" url = e.url @@ -309,27 +312,27 @@ def _process(self): except Exception as e: if conf.debug.trace_exceptions: - logging.warning("""conf.debug.trace_exceptions is set, won't handle this exception""") + logger.warning("""conf.debug.trace_exceptions is set, won't handle this exception""") raise self.response.body = b"" if isinstance(e, errors.HTTPException): - logging.info(f"[{e.status}] {e.name}: {e.descr}", exc_info=conf.debug.trace) + logger.info(f"[{e.status}] {e.name}: {e.descr}", exc_info=conf.debug.trace) self.response.status = f"{e.status} {e.name}" # Set machine-readable x-viur-error response header in case there is an exception description. if e.descr: self.response.headers["x-viur-error"] = e.descr.replace("\n", "") else: self.response.status = 500 - logging.error("ViUR has caught an unhandled exception!") - logging.exception(e) + logger.error("ViUR has caught an unhandled exception!") + logger.exception(e) res = None if conf.error_handler: try: res = conf.error_handler(e) except Exception as newE: - logging.error("viur.error_handler failed!") - logging.exception(newE) + logger.error("viur.error_handler failed!") + logger.exception(newE) res = None if not res: descr = "The server encountered an unexpected error and is unable to process your request." @@ -417,11 +420,11 @@ def _process(self): while self.pendingTasks: task = self.pendingTasks.pop() - logging.debug(f"Deferred task emulation, executing {task=}") + logger.debug(f"Deferred task emulation, executing {task=}") try: task() except Exception: # noqa - logging.exception(f"Deferred Task emulation {task} failed") + logger.exception(f"Deferred Task emulation {task} failed") def _route(self, path: str) -> None: """ @@ -532,7 +535,7 @@ def _route(self, path: str) -> None: if self.request.headers.get("X-Viur-Disable-Cache"): # No cache requested, check if the current user is allowed to do so if (user := current.user.get()) and "root" in user["access"]: - logging.debug("Caching disabled by X-Viur-Disable-Cache header") + logger.debug("Caching disabled by X-Viur-Disable-Cache header") self.disableCache = True # Destill context as self.context, if available @@ -546,7 +549,7 @@ def _route(self, path: str) -> None: if ((self.internalRequest and conf.debug.trace_internal_call_routing) or conf.debug.trace_external_call_routing): - logging.debug( + logger.debug( f"Calling {caller._func!r} with args={self.args!r}, {kwargs=} within context={self.context!r}" )