chore: Improve logging setup (#873)

Introduces a logging setup to centralize its configuration and removes
changes to the logging config from other places in the code base.

The logging config is called in the bases __init__ file to be as early
as possible applied. For sanic applications, it must also run for
workers and the main process. The configuration sets up logging by
default as follows:

- our code is logged at level INFO
- all third-party code is logged at level WARNING

What is "our" code is determined by the logger name: our loggers
should all be children of the renku_data_services logger. Using the
provided getLogger function makes sure this is the case.

The config can be adjusted using environment variables, as written in
`Config.from_env()`.

Author: eikek

bases/renku_data_services/data_api/__init__.py

@@ -1 +1,5 @@
 """Renku data service."""
+
+import renku_data_services.app_config.logging as logging
+
+logging.configure_logging()

bases/renku_data_services/data_api/main.py

@@ -8,14 +8,14 @@
 import sentry_sdk
 import uvloop
 from sanic import Request, Sanic
-from sanic.log import logger
 from sanic.response import BaseHTTPResponse
 from sanic.worker.loader import AppLoader
 from sentry_sdk.integrations.asyncio import AsyncioIntegration
 from sentry_sdk.integrations.grpc import GRPCIntegration
 from sentry_sdk.integrations.sanic import SanicIntegration, _context_enter, _context_exit, _set_transaction
 
 import renku_data_services.solr.entity_schema as entity_schema
+from renku_data_services.app_config.logging import configure_logging, getLogger
 from renku_data_services.authz.admin_sync import sync_admins_from_keycloak
 from renku_data_services.base_models.core import APIUser
 from renku_data_services.data_api.app import register_all_handlers
@@ -36,6 +36,9 @@
     import sentry_sdk._types
 
 
+logger = getLogger(__name__)
+
+
 async def _solr_reindex(app: Sanic) -> None:
     """Run a solr reindex of all data.
 
@@ -60,7 +63,7 @@ def solr_reindex(app_name: str) -> None:
 def create_app() -> Sanic:
     """Create a Sanic application."""
     dependency_manager = DependencyManager.from_env()
-    app = Sanic(dependency_manager.app_name)
+    app = Sanic(dependency_manager.app_name, configure_logging=False)
 
     if "COVERAGE_RUN" in environ:
         app.config.TOUCHUP = False
@@ -160,10 +163,18 @@ async def setup_rclone_validator(app: Sanic) -> None:
     @app.main_process_ready
     async def ready(app: Sanic) -> None:
         """Application ready event handler."""
-        logger.info("starting events background job.")
         if getattr(app.ctx, "solr_reindex", False):
+            logger.info("Starting solr reindex, as required by migrations.")
             app.manager.manage("SolrReindex", solr_reindex, {"app_name": app.name}, transient=True)
 
+    @app.before_server_start
+    async def logging_setup1(app: Sanic) -> None:
+        configure_logging()
+
+    @app.main_process_ready
+    async def logging_setup2(app: Sanic) -> None:
+        configure_logging()
+
     return app
 
 

bases/renku_data_services/data_tasks/__init__.py

@@ -1 +1,5 @@
 """Renku data service tasks."""
+
+import renku_data_services.app_config.logging as logging
+
+logging.configure_logging()

bases/renku_data_services/data_tasks/main.py

@@ -5,19 +5,13 @@
 
 import uvloop
 
+from renku_data_services.app_config.logging import getLogger
 from renku_data_services.data_tasks.dependencies import DependencyManager
 from renku_data_services.data_tasks.task_defs import all_tasks
 from renku_data_services.data_tasks.taskman import TaskDefininions, TaskManager
 from renku_data_services.data_tasks.tcp_handler import TcpHandler
 
-
-def configure_logging() -> None:
-    """Configures logging.
-
-    Log everything at level WARNING, except for our code that is set to INFO
-    """
-    logging.basicConfig(level=logging.WARNING, format="%(asctime)s %(name)s %(levelname)s %(message)s")
-    logging.getLogger("renku_data_services").setLevel(logging.INFO)
+logger = getLogger(__name__)
 
 
 async def log_tasks(logger: logging.Logger, tm: TaskManager, interval: int) -> None:
@@ -33,8 +27,6 @@ async def log_tasks(logger: logging.Logger, tm: TaskManager, interval: int) -> N
 async def main() -> None:
     """Data tasks entry point."""
     dm = DependencyManager.from_env()
-    configure_logging()
-    logger = logging.getLogger("renku_data_services.data_tasks.main")
     logger.info(f"Config: {dm.config}")
 
     tm = TaskManager(dm.config.max_retry_wait_seconds)

bases/renku_data_services/data_tasks/task_defs.py

@@ -1,7 +1,6 @@
 """The task definitions in form of coroutines."""
 
 import asyncio
-import logging
 
 from authzed.api.v1 import (
     Consistency,
@@ -20,6 +19,7 @@
 import renku_data_services.authz.admin_sync as admin_sync
 import renku_data_services.search.core as search_core
 from renku_data_services import errors
+from renku_data_services.app_config import logging
 from renku_data_services.authz.authz import ResourceType, _AuthzConverter, _Relation
 from renku_data_services.authz.models import Scope
 from renku_data_services.base_models.core import InternalServiceAdmin, ServiceAdminId
@@ -104,7 +104,7 @@ async def generate_user_namespaces(dm: DependencyManager) -> None:
 async def sync_user_namespaces(dm: DependencyManager) -> None:
     """Lists all user namespaces in the database and adds them to Authzed and the event queue."""
     user_namespaces = dm.group_repo._get_user_namespaces()
-    logging.info("Start syncing user namespaces to the authorization DB and message queue")
+    logger.info("Start syncing user namespaces to the authorization DB and message queue")
     num_authz: int = 0
     num_events: int = 0
     num_total: int = 0
@@ -124,14 +124,14 @@ async def sync_user_namespaces(dm: DependencyManager) -> None:
         except Exception as err:
             # NOTE: We do not rollback the authz changes here because it is OK if something is in Authz DB
             # but not in the message queue but not vice-versa.
-            logging.error(f"Failed to sync user namespace {user_namespace} because {err}")
+            logger.error(f"Failed to sync user namespace {user_namespace} because {err}")
             await tx.rollback()
         else:
             await tx.commit()
         finally:
             await session.close()
-    logging.info(f"Wrote authorization changes for {num_authz}/{num_total} user namespaces")
-    logging.info(f"Wrote to event queue database for {num_events}/{num_total} user namespaces")
+    logger.info(f"Wrote authorization changes for {num_authz}/{num_total} user namespaces")
+    logger.info(f"Wrote to event queue database for {num_events}/{num_total} user namespaces")
 
 
 async def bootstrap_user_namespaces(dm: DependencyManager) -> None:
@@ -152,7 +152,7 @@ async def bootstrap_user_namespaces(dm: DependencyManager) -> None:
                 if await anext(rels, None) is not None:
                     num_rels += 1
             if num_rels >= 5:
-                logging.info(
+                logger.info(
                     "Found at least 5 user namespace in the authorization database, "
                     "will not sync user namespaces to authorization."
                 )
@@ -183,12 +183,12 @@ async def fix_mismatched_project_namespace_ids(dm: DependencyManager) -> None:
                 )
             )
             async for rel in res:
-                logging.info(f"Checking project namespace - group relation {rel} for correct group ID")
+                logger.info(f"Checking project namespace - group relation {rel} for correct group ID")
                 project_id = rel.relationship.resource.object_id
                 try:
                     project = await dm.project_repo.get_project(api_user, project_id)
                 except errors.MissingResourceError:
-                    logging.info(f"Couldn't find project {project_id}, deleting relation")
+                    logger.info(f"Couldn't find project {project_id}, deleting relation")
                     await dm.authz.client.WriteRelationships(
                         WriteRelationshipsRequest(
                             updates=[
@@ -206,7 +206,7 @@ async def fix_mismatched_project_namespace_ids(dm: DependencyManager) -> None:
                 correct_group_id = project.namespace.underlying_resource_id
                 authzed_group_id = rel.relationship.subject.object.object_id
                 if authzed_group_id != correct_group_id:
-                    logging.info(
+                    logger.info(
                         f"The project namespace ID in Authzed {authzed_group_id} "
                         f"does not match the expected group ID {correct_group_id}, correcting it..."
                     )

bases/renku_data_services/data_tasks/taskman.py

@@ -3,7 +3,6 @@
 from __future__ import annotations
 
 import asyncio
-import logging
 import math
 import sys
 from asyncio.tasks import Task
@@ -12,6 +11,8 @@
 from datetime import datetime, timedelta
 from typing import Any, final
 
+from renku_data_services.app_config import logging
+
 logger = logging.getLogger(__name__)
 
 type TaskFactory = Callable[[], Coroutine[Any, Any, None]]

bases/renku_data_services/k8s_cache/__init__.py

@@ -1 +1,5 @@
 """Kubernetes Cache."""
+
+import renku_data_services.app_config.logging as logging
+
+logging.configure_logging()

bases/renku_data_services/k8s_cache/main.py

@@ -1,21 +1,22 @@
 """The entrypoint for the k8s cache service."""
 
 import asyncio
-import logging
 
 import kr8s
 
+from renku_data_services.app_config import logging
 from renku_data_services.k8s.models import Cluster, ClusterId
 from renku_data_services.k8s_cache.dependencies import DependencyManager
 from renku_data_services.k8s_watcher import K8sWatcher, k8s_object_handler
 from renku_data_services.notebooks.constants import AMALTHEA_SESSION_GVK, JUPYTER_SESSION_GVK
 from renku_data_services.session.constants import BUILD_RUN_GVK, TASK_RUN_GVK
 
+logger = logging.getLogger(__name__)
+
 
 async def main() -> None:
     """K8s cache entrypoint."""
 
-    logging.basicConfig(format="%(asctime)s %(levelname)s %(message)s", level=logging.INFO)
     dm = DependencyManager.from_env()
 
     kr8s_api = await kr8s.asyncio.api()
@@ -31,7 +32,7 @@ async def main() -> None:
         db_cache=dm.k8s_cache,
     )
     await watcher.start()
-    logging.info("started watching resources")
+    logger.info("started watching resources")
     # create file for liveness probe
     with open("/tmp/cache_ready", "w") as f:  # nosec B108
         f.write("ready")

bases/renku_data_services/secrets_storage_api/__init__.py

@@ -1 +1,5 @@
 """Secrets storage."""
+
+import renku_data_services.app_config.logging as logging
+
+logging.configure_logging()

bases/renku_data_services/secrets_storage_api/main.py

@@ -9,6 +9,7 @@
 from sanic import Sanic
 from sanic.worker.loader import AppLoader
 
+from renku_data_services.app_config import logging
 from renku_data_services.base_models.core import InternalServiceAdmin, ServiceAdminId
 from renku_data_services.secrets.core import rotate_encryption_keys
 from renku_data_services.secrets_storage_api.app import register_all_handlers
@@ -26,6 +27,11 @@ def create_app() -> Sanic:
     @app.main_process_start
     def main_process_start(app: Sanic) -> None:
         app.shared_ctx.rotation_lock = Lock()
+        logging.configure_logging()
+
+    @app.before_server_start
+    async def logging_setup1(app: Sanic) -> None:
+        logging.configure_logging()
 
     # Setup prometheus
     monitor(app, endpoint_type="url", multiprocess_mode="all", is_middleware=True).expose_endpoint()