Add logging framework and Tracer

Author: GDYendell

.vscode/launch.json

@@ -39,7 +39,14 @@
             "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-endpoint",
+                // "graylog-log-target.diamond.ac.uk:12201",
+            ],
             "console": "integratedTerminal",
         }
     ]

pyproject.toml

@@ -19,6 +19,8 @@ dependencies = [
     "pydantic",
     "ruamel.yaml",
     "IPython",
+    "loguru~=0.7",
+    "pygelf",
 ]
 dynamic = ["version"]
 license.file = "LICENSE"

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:

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(logger_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

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:

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.

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)

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

src/fastcs/demo/controllers.py

@@ -30,6 +30,10 @@ class TemperatureControllerHandler(AttrHandlerRW):
     update_period: float | None = 0.2
     _controller: TemperatureController | TemperatureRampController | None = None
 
+    def __post_init__(self):
+        # Call __init__ of non-dataclass parent
+        super().__init__()
+
     async def initialise(self, controller: BaseController):
         assert isinstance(controller, TemperatureController | TemperatureRampController)
         self._controller = controller
@@ -42,15 +46,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 +97,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]))
 
 

src/fastcs/launch.py

@@ -13,6 +13,16 @@
 from ruamel.yaml import YAML
 
 from fastcs import __version__
+from fastcs.logging import (
+    GraylogEndpoint,
+    GraylogEnvFields,
+    GraylogStaticFields,
+    LogLevel,
+    configure_logging,
+    logger,
+    parse_graylog_env_fields,
+    parse_graylog_static_fields,
+)
 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 +96,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 +215,39 @@ def run(
                 help=f"A yaml file matching the {controller_class.__name__} schema"
             ),
         ],
+        log_level: Annotated[
+            Optional[LogLevel],  # noqa: UP045
+            typer.Option(),
+        ] = None,
+        graylog_endpoint: Annotated[
+            Optional[GraylogEndpoint],  # noqa: UP045
+            typer.Option(
+                help="Endpoint for graylog logging - '<host>:<port>'",
+                parser=GraylogEndpoint.parse_graylog_endpoint,
+            ),
+        ] = None,
+        graylog_static_fields: Annotated[
+            Optional[GraylogStaticFields],  # noqa: UP045
+            typer.Option(
+                help="Fields to add to graylog messages with static values",
+                parser=parse_graylog_static_fields,
+            ),
+        ] = None,
+        graylog_env_fields: Annotated[
+            Optional[GraylogEnvFields],  # noqa: UP045
+            typer.Option(
+                help="Fields to add to graylog messages from environment variables",
+                parser=parse_graylog_env_fields,
+            ),
+        ] = None,
     ):
         """
         Start the controller
         """
+        configure_logging(
+            log_level, graylog_endpoint, graylog_static_fields, graylog_env_fields
+        )
+
         controller_class = ctx.obj.controller_class
         fastcs_options = ctx.obj.fastcs_options