fix: WIP logging

docker-compose.yaml

@@ -3,7 +3,7 @@
 
 name: "${USER}-cm-service"
 services:
-  init-db:
+  migratedb:
     profiles:
       - full
       - server
@@ -46,13 +46,13 @@ services:
     networks:
       - cmservice
     depends_on:
-      init-db:
+      migratedb:
         condition: service_completed_successfully
 
   cmworker:
     profiles:
       - full
-      - worker
+      - daemon
     build:
       context: .
       dockerfile: docker/Dockerfile
@@ -66,7 +66,7 @@ services:
     networks:
       - cmservice
     depends_on:
-      init-db:
+      migratedb:
         condition: service_completed_successfully
 
   postgresql:

src/lsst/cmservice/common/daemon.py

@@ -1,37 +1,42 @@
 from datetime import datetime, timedelta
 
-import structlog
 from sqlalchemy.ext.asyncio import async_scoped_session
 from sqlalchemy.future import select
 
+from ..common.logging import LOGGER
 from ..config import config
 from ..db.queue import Queue
 from ..db.script import Script
 
-logger = structlog.get_logger(__name__)
+logger = LOGGER.bind(module=__name__)
 
 
 async def daemon_iteration(session: async_scoped_session) -> None:
     iteration_start = datetime.now()
     queue_entries = await session.execute(select(Queue).where(Queue.time_next_check < iteration_start))
+    logger.debug("Daemon Iteration: %s", iteration_start)
 
     # TODO: should the daemon check any campaigns with a state == prepared that
     #       do not have queues? Queue creation should not be a manual step.
     queue_entry: Queue
     for (queue_entry,) in queue_entries:
-        queued_node = await queue_entry.get_node(session)
-        if (
-            queued_node.status.is_processable_script()
-            if isinstance(queued_node, Script)
-            else queued_node.status.is_processable_element()
-        ):
-            logger.info(f"Processing queue_entry {queued_node.fullname}")
-            await queue_entry.process_node(session)
-            sleep_time = await queue_entry.node_sleep_time(session)
-        else:
-            # Put this entry to sleep for a while
-            sleep_time = config.daemon.processing_interval
-        time_next_check = iteration_start + timedelta(seconds=sleep_time)
-        queue_entry.time_next_check = time_next_check
-        logger.info(f"Next check for {queued_node.fullname} at {time_next_check}")
+        try:
+            queued_node = await queue_entry.get_node(session)
+            if (
+                queued_node.status.is_processable_script()
+                if isinstance(queued_node, Script)
+                else queued_node.status.is_processable_element()
+            ):
+                logger.info("Processing queue_entry %s", queued_node.fullname)
+                await queue_entry.process_node(session)
+                sleep_time = await queue_entry.node_sleep_time(session)
+            else:
+                # Put this entry to sleep for a while
+                sleep_time = config.daemon.processing_interval
+            time_next_check = iteration_start + timedelta(seconds=sleep_time)
+            queue_entry.time_next_check = time_next_check
+            logger.info(f"Next check for {queued_node.fullname} at {time_next_check}")
+        except Exception:
+            logger.exception()
+            continue
     await session.commit()

src/lsst/cmservice/common/logging.py

@@ -0,0 +1,10 @@
+"""Provide a common application root logger."""
+
+import structlog
+from safir.logging import configure_logging
+
+from ..config import config
+
+configure_logging(profile=config.logging.profile, log_level=config.logging.level, name=config.logging.handle)
+
+LOGGER = structlog.get_logger(config.logging.handle)

src/lsst/cmservice/config.py

@@ -272,6 +272,11 @@ class AsgiConfiguration(BaseModel):
 class LoggingConfiguration(BaseModel):
     """Configuration for the application's logging facility."""
 
+    handle: str = Field(
+        default="cm-service",
+        title="Handle or name of the root logger",
+    )
+
     level: str = Field(
         default="INFO",
         title="Log level of the application's logger",

src/lsst/cmservice/daemon.py

@@ -2,20 +2,21 @@
 from collections.abc import AsyncGenerator
 from contextlib import asynccontextmanager
 
-import structlog
 import uvicorn
 from anyio import current_time, sleep_until
 from fastapi import FastAPI
 from safir.database import create_async_session, create_database_engine
-from safir.logging import configure_logging, configure_uvicorn_logging
+from safir.logging import configure_uvicorn_logging
 
 from . import __version__
 from .common.daemon import daemon_iteration
+from .common.logging import LOGGER
 from .config import config
 from .routers.healthz import health_router
 
 configure_uvicorn_logging(config.logging.level)
-configure_logging(profile=config.logging.profile, log_level=config.logging.level, name=__name__)
+
+logger = LOGGER.bind(module=__name__)
 
 
 @asynccontextmanager
@@ -34,7 +35,6 @@ async def main_loop() -> None:
     With a database session, perform a single daemon interation and then sleep
     until the next daemon appointment.
     """
-    logger = structlog.get_logger(__name__)
     engine = create_database_engine(config.db.url, config.db.password)
     sleep_time = config.daemon.processing_interval
 

src/lsst/cmservice/db/handler.py

@@ -10,13 +10,16 @@
 
 from ..common.enums import StatusEnum
 from ..common.errors import CMBadHandlerTypeError
+from ..common.logging import LOGGER
 from ..common.utils import add_sys_path
 
 if TYPE_CHECKING:
     from .element import ElementMixin
     from .node import NodeMixin
     from .script import Script
 
+logger = LOGGER.bind(module=__name__)
+
 
 class Handler:
     """Base class to handle callbacks generated by particular

src/lsst/cmservice/db/node.py

@@ -15,6 +15,7 @@
     CMResolveCollectionsError,
     test_type_and_raise,
 )
+from ..common.logging import LOGGER
 from ..config import config
 from .handler import Handler
 from .row import RowMixin
@@ -25,6 +26,8 @@
     from .campaign import Campaign
     from .element import ElementMixin
 
+logger = LOGGER.bind(module=__name__)
+
 
 class NodeMixin(RowMixin):
     """Mixin class to define common features of database rows
@@ -734,6 +737,7 @@ async def process(
             Status of the processing
         """
         handler = await self.get_handler(session)
+        logger.debug("Processing node with handler %s", handler.get_handler_class_name())
         return await handler.process(session, self, **kwargs)
 
     async def run_check(

src/lsst/cmservice/db/queue.py

@@ -10,6 +10,7 @@
 
 from ..common.enums import LevelEnum
 from ..common.errors import CMBadEnumError, CMMissingFullnameError
+from ..common.logging import LOGGER
 from .base import Base
 from .campaign import Campaign
 from .group import Group
@@ -18,6 +19,8 @@
 from .script import Script
 from .step import Step
 
+logger = LOGGER.bind(module=__name__)
+
 
 class Queue(Base, NodeMixin):
     """Database table to implement processing queue"""
@@ -214,9 +217,11 @@ async def process_node(
         node = await self.get_node(session)
 
         if node.level == LevelEnum.script:
+            logger.debug("Processing a %s", node.level)
             if not node.status.is_processable_script():
                 return False
         if not node.status.is_processable_element():
+            logger.debug("Node %s is not processable", node.name)
             return False
 
         process_kwargs: dict = {}

src/lsst/cmservice/handlers/scripts.py

@@ -16,12 +16,15 @@
 )
 from ..common.enums import LevelEnum, ScriptMethodEnum, StatusEnum
 from ..common.errors import CMBadExecutionMethodError, CMMissingScriptInputError, test_type_and_raise
+from ..common.logging import LOGGER
 from ..config import config
 from ..db.element import ElementMixin
 from ..db.script import Script
 from ..db.step import Step
 from .script_handler import ScriptHandler
 
+logger = LOGGER.bind(module=__name__)
+
 
 class NullScriptHandler(ScriptHandler):
     """A no-op script, mostly for testing"""