Started to refactor the logger and use no longer the default logger

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)

src/viur/core/logging.py

@@ -97,6 +97,8 @@
 
     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 @@
                 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 @@
     }
 )
 
+# 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 @@
 
 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 = }")

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}"
             )