Add logging framework and Tracer

GDYendell · GDYendell · commit c29fc3d34fc9 · 2025-10-01T12:09:57.000Z
diff --git a/.vscode/launch.json b/.vscode/launch.json
@@ -39,7 +39,13 @@
             "request": "launch",
             "justMyCode": false,
             "module": "fastcs.demo",
-            "args": ["run", "${workspaceFolder:FastCS}/src/fastcs/demo/controller.yaml"],
+            "args": [
+                "run",
+                "${workspaceFolder:FastCS}/src/fastcs/demo/controller.yaml",
+                "--log-level",
+                "TRACE",
+                // "--graylog"
+            ],
             "console": "integratedTerminal",
         }
     ]
diff --git a/pyproject.toml b/pyproject.toml
@@ -32,6 +32,7 @@ requires-python = ">=3.11"
 [project.optional-dependencies]
 dev = [
     "copier",
+    "loguru~=0.7",
     "myst-parser",
     "pipdeptree",
     "pre-commit",
diff --git a/src/fastcs/attributes.py b/src/fastcs/attributes.py
@@ -6,6 +6,7 @@
 from typing import Any, Generic
 
 import fastcs
+from fastcs.tracer import Tracer
 
 from .datatypes import ATTRIBUTE_TYPES, AttrCallback, DataType, T
 
@@ -21,7 +22,7 @@ class AttrMode(Enum):
     READ_WRITE = 3
 
 
-class _BaseAttrHandler:
+class _BaseAttrHandler(Tracer):
     async def initialise(self, controller: fastcs.controller.BaseController) -> None:
         pass
 
@@ -62,7 +63,7 @@ async def update(self, attr: AttrR) -> None:
         raise RuntimeError("SimpleHandler cannot update")
 
 
-class Attribute(Generic[T]):
+class Attribute(Generic[T], Tracer):
     """Base FastCS attribute.
 
     Instances of this class added to a ``Controller`` will be used by the backend.
@@ -76,6 +77,8 @@ def __init__(
         handler: Any = None,
         description: str | None = None,
     ) -> None:
+        super().__init__()
+
         assert issubclass(datatype.dtype, ATTRIBUTE_TYPES), (
             f"Attr type must be one of {ATTRIBUTE_TYPES}, "
             "received type {datatype.dtype}"
@@ -155,6 +158,8 @@ def get(self) -> T:
         return self._value
 
     async def set(self, value: T) -> None:
+        self.log_event("Attribute set", attribute=self, value=value)
+
         self._value = self._datatype.validate(value)
 
         if self._update_callbacks is not None:
diff --git a/src/fastcs/backend.py b/src/fastcs/backend.py
@@ -4,13 +4,18 @@
 
 from fastcs.cs_methods import Command, Put, Scan
 from fastcs.datatypes import T
+from fastcs.logging import logger as _fastcs_logger
+from fastcs.tracer import Tracer
 
 from .attributes import ONCE, AttrHandlerR, AttrHandlerW, AttrR, AttrW
 from .controller import BaseController, Controller
 from .controller_api import ControllerAPI
 from .exceptions import FastCSError
 from .util import validate_hinted_attributes
 
+tracer = Tracer(name=__name__)
+logger = _fastcs_logger.bind(name=__name__)
+
 
 class Backend:
     """For keeping track of tasks during FastCS serving."""
@@ -153,9 +158,14 @@ def _create_updater_callback(attribute: AttrR[T]):
 
     async def callback():
         try:
+            tracer.log_event("Call attribute updater", topic=attribute)
             await updater.update(attribute)
-        except Exception as e:
-            print(f"Update loop in {updater} stopped:\n{e.__class__.__name__}: {e}")
+        except Exception:
+            logger.opt(exception=True).error(
+                "Update loop failed",
+                updater=updater,
+                attribute=attribute,
+            )
             raise
 
     return callback
diff --git a/src/fastcs/connections/ip_connection.py b/src/fastcs/connections/ip_connection.py
@@ -1,6 +1,8 @@
 import asyncio
 from dataclasses import dataclass
 
+from fastcs.tracer import Tracer
+
 
 class DisconnectedError(Exception):
     """Raised if the ip connection is disconnected."""
@@ -44,10 +46,11 @@ async def close(self):
         await self.writer.wait_closed()
 
 
-class IPConnection:
+class IPConnection(Tracer):
     """For connecting to an ip using a `StreamConnection`."""
 
     def __init__(self):
+        super().__init__()
         self.__connection = None
 
     @property
@@ -61,14 +64,20 @@ async def connect(self, settings: IPConnectionSettings):
         reader, writer = await asyncio.open_connection(settings.ip, settings.port)
         self.__connection = StreamConnection(reader, writer)
 
-    async def send_command(self, message) -> None:
+    async def send_command(self, message: str) -> None:
         async with self._connection as connection:
             await connection.send_message(message)
 
-    async def send_query(self, message) -> str:
+    async def send_query(self, message: str) -> str:
         async with self._connection as connection:
             await connection.send_message(message)
-            return await connection.receive_response()
+            response = await connection.receive_response()
+            self.log_event(
+                "Received query response",
+                query=message.strip(),
+                response=response.strip(),
+            )
+            return response
 
     async def close(self):
         async with self._connection as connection:
diff --git a/src/fastcs/controller.py b/src/fastcs/controller.py
@@ -5,9 +5,10 @@
 from typing import get_type_hints
 
 from fastcs.attributes import Attribute
+from fastcs.tracer import Tracer
 
 
-class BaseController:
+class BaseController(Tracer):
     """Base class for controller."""
 
     #: Attributes passed from the device at runtime.
@@ -18,6 +19,8 @@ class BaseController:
     def __init__(
         self, path: list[str] | None = None, description: str | None = None
     ) -> None:
+        super().__init__()
+
         if (
             description is not None
         ):  # Use the argument over the one class defined description.
diff --git a/src/fastcs/cs_methods.py b/src/fastcs/cs_methods.py
@@ -5,6 +5,7 @@
 from typing import Any, Generic, TypeVar
 
 from fastcs.controller import BaseController
+from fastcs.tracer import Tracer
 
 from .exceptions import FastCSError
 
@@ -31,10 +32,12 @@
 )
 
 
-class Method(Generic[Controller_T]):
+class Method(Generic[Controller_T], Tracer):
     """Generic base class for all FastCS Controller methods."""
 
     def __init__(self, fn: MethodCallback, *, group: str | None = None) -> None:
+        super().__init__()
+
         self._docstring = getdoc(fn)
 
         sig = signature(fn, eval_str=True)
diff --git a/src/fastcs/demo/controller.yaml b/src/fastcs/demo/controller.yaml
@@ -10,7 +10,7 @@ transport:
       port: 8083
       log_level: info
   - ca_ioc:
-      pv_prefix: DEMO
+      pv_prefix: GARYDEMO
     gui:
       title: Temperature Controller Demo
       output_path: ./demo.bob
diff --git a/src/fastcs/demo/controllers.py b/src/fastcs/demo/controllers.py
@@ -30,6 +30,9 @@ class TemperatureControllerHandler(AttrHandlerRW):
     update_period: float | None = 0.2
     _controller: TemperatureController | TemperatureRampController | None = None
 
+    def __post_init__(self):
+        super().__init__()
+
     async def initialise(self, controller: BaseController):
         assert isinstance(controller, TemperatureController | TemperatureRampController)
         self._controller = controller
@@ -42,15 +45,21 @@ def controller(self) -> TemperatureController | TemperatureRampController:
         return self._controller
 
     async def put(self, attr: AttrW, value: Any) -> None:
-        await self.controller.connection.send_command(
-            f"{self.name}{self.controller.suffix}={attr.dtype(value)}\r\n"
-        )
+        command = f"{self.name}{self.controller.suffix}={attr.dtype(value)}"
+
+        await self.controller.connection.send_command(f"{command}\r\n")
+        self.log_event("Put request for attribute", topic=attr, command=command)
 
     async def update(self, attr: AttrR) -> None:
-        response = await self.controller.connection.send_query(
-            f"{self.name}{self.controller.suffix}?\r\n"
-        )
+        query = f"{self.name}{self.controller.suffix}?"
+        response = await self.controller.connection.send_query(f"{query}\r\n")
         response = response.strip("\r\n")
+        self.log_event(
+            "Query for attribute",
+            topic=attr,
+            query=query,
+            response=response,
+        )
 
         await attr.set(attr.dtype(response))
 
@@ -87,10 +96,17 @@ async def close(self) -> None:
 
     @scan(0.1)
     async def update_voltages(self):
+        query = "V?"
         voltages = json.loads(
-            (await self.connection.send_query("V?\r\n")).strip("\r\n")
+            (await self.connection.send_query(f"{query}\r\n")).strip("\r\n")
         )
         for index, controller in enumerate(self._ramp_controllers):
+            self.log_event(
+                "Update voltages",
+                topic=controller.voltage,
+                query=query,
+                response=voltages,
+            )
             await controller.voltage.set(float(voltages[index]))
 
 
diff --git a/src/fastcs/launch.py b/src/fastcs/launch.py
@@ -13,6 +13,7 @@
 from ruamel.yaml import YAML
 
 from fastcs import __version__
+from fastcs.logging import LogLevel, configure_logging, logger
 from fastcs.transport.epics.ca.transport import EpicsCATransport
 from fastcs.transport.epics.pva.transport import EpicsPVATransport
 from fastcs.transport.graphql.transport import GraphQLTransport
@@ -86,6 +87,12 @@ async def serve(self) -> None:
 
         coros.append(self._interactive_shell(context))
 
+        logger.info(
+            "Starting FastCS",
+            controller=self._controller,
+            transports=f"[{', '.join(str(t) for t in self._transports)}]",
+        )
+
         try:
             await asyncio.gather(*coros)
         except asyncio.CancelledError:
@@ -199,10 +206,23 @@ def run(
                 help=f"A yaml file matching the {controller_class.__name__} schema"
             ),
         ],
+        log_level: Annotated[
+            Optional[LogLevel],  # noqa: UP045
+            typer.Option(),
+        ] = None,
+        graylog: Annotated[
+            bool,
+            typer.Option(
+                "--graylog",
+                help="Enable graylog logging",
+            ),
+        ] = False,
     ):
         """
         Start the controller
         """
+        configure_logging(log_level, graylog)
+
         controller_class = ctx.obj.controller_class
         fastcs_options = ctx.obj.fastcs_options
 
diff --git a/src/fastcs/logging/__init__.py b/src/fastcs/logging/__init__.py
@@ -0,0 +1,70 @@
+from loguru import logger as _logger
+
+from fastcs.logging._logging import LogLevel, _configure_logger
+
+logger = _logger.bind(logger_name="fastcs")
+"""FastCS logger
+
+This is a singleton logger instance to be used throughout the library and in specific
+drivers. This logger uses `loguru` as underlying logging library, which enables much
+simpler configuration as well as structured logging.
+
+Keyword arguments to log statments will be attached as extra fields on the log record.
+These fields are displayed separately in the console output and can used for filtering
+and metrics in graylog.
+
+It is best to keep the message short and use extra fields for additional information for
+messages to be formatted nicely in the console. To add kwargs to format the message
+without them appearing as extra fields, prepend the key with `_`.
+
+```
+from fastcs.logging import logger
+
+logger.info("PV put: {pv} = {value}", pv=pv, value=value)
+```
+
+By default messages will be logged with the name `fastcs`. Within different modules and
+classes it can be useful to override this name. This can be done with the `bind` method.
+To create a module logger with its name
+
+```
+from fastcs.logging import logger as _logger
+
+logger = _logger.bind(name=__name__)
+```
+
+or to create a class logger with its name
+
+```
+self.logger = _logger.bind(name=__class__.__name__)
+```
+
+As standard `loguru` supports `trace` level monitoring, but it should not be used in
+fastcs. Instead there is a `Tracer` class for verbose logging with fine-grained controls
+that can be enabled by the user at runtime.
+
+Use `configure_logging` to re-configure the logger at runtime. For more advanced
+controls, configure the `logger` singleton directly.
+
+See the `loguru` docs for more information: https://loguru.readthedocs.io
+"""
+
+
+def configure_logging(level: LogLevel | None = None, graylog: bool = False):
+    """Configure FastCS logger
+
+    This function can be called at any time to
+      - Change the console log level
+      - Enable/disable graylog logging
+
+    :param level: Log level to set
+    :param graylog: Enable graylog logging
+
+    """
+    global logger
+
+    _configure_logger(logger, level, graylog)
+
+
+# Configure logger with defaults - INFO level and disabled
+configure_logging()
diff --git a/src/fastcs/logging/_logging.py b/src/fastcs/logging/_logging.py
diff --git a/src/fastcs/tracer.py b/src/fastcs/tracer.py
diff --git a/src/fastcs/transport/epics/ca/ioc.py b/src/fastcs/transport/epics/ca/ioc.py
