Add logging framework and Tracer

.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/attribute_io.py

@@ -3,9 +3,10 @@
 from fastcs.attribute_io_ref import AttributeIORef, AttributeIORefT
 from fastcs.attributes import AttrR, AttrRW
 from fastcs.datatypes import T
+from fastcs.tracer import Tracer
 
 
-class AttributeIO(Generic[T, AttributeIORefT]):
+class AttributeIO(Generic[T, AttributeIORefT], Tracer):
     ref_type = AttributeIORef
 
     def __init_subclass__(cls) -> None:

src/fastcs/attributes.py

@@ -4,14 +4,21 @@
 from collections.abc import Callable
 from typing import Generic
 
-from .attribute_io_ref import AttributeIORefT
-from .datatypes import ATTRIBUTE_TYPES, AttrSetCallback, AttrUpdateCallback, DataType, T
+from fastcs.attribute_io_ref import AttributeIORefT
+from fastcs.datatypes import (
+    ATTRIBUTE_TYPES,
+    AttrSetCallback,
+    AttrUpdateCallback,
+    DataType,
+    T,
+)
+from fastcs.tracer import Tracer
 
 ONCE = float("inf")
 """Special value to indicate that an attribute should be updated once on start up."""
 
 
-class Attribute(Generic[T, AttributeIORefT]):
+class Attribute(Generic[T, AttributeIORefT], Tracer):
     """Base FastCS attribute.
 
     Instances of this class added to a ``Controller`` will be used by the FastCS class.
@@ -24,6 +31,8 @@ def __init__(
         group: str | None = 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}"
@@ -73,6 +82,9 @@ def update_datatype(self, datatype: DataType[T]) -> None:
         for callback in self._update_datatype_callbacks:
             callback(datatype)
 
+    def __repr__(self):
+        return f"{self.__class__.__name__}({self._datatype})"
+
 
 class AttrR(Attribute[T, AttributeIORefT]):
     """A read-only ``Attribute``."""
@@ -101,6 +113,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._on_set_callbacks is not None:

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

@@ -9,9 +9,10 @@
 from fastcs.attribute_io_ref import AttributeIORefT
 from fastcs.attributes import Attribute, AttrR, AttrRW, AttrW
 from fastcs.datatypes import T
+from fastcs.tracer import Tracer
 
 
-class BaseController:
+class BaseController(Tracer):
     """Base class for controller."""
 
     #: Attributes passed from the device at runtime.
@@ -25,6 +26,8 @@ def __init__(
         description: str | None = None,
         ios: Sequence[AttributeIO[T, AttributeIORefT]] | None = None,
     ) -> None:
+        super().__init__()
+
         if (
             description is not None
         ):  # Use the argument over the one class defined description.
@@ -182,6 +185,11 @@ def register_sub_controller(self, name: str, sub_controller: Controller):
     def get_sub_controllers(self) -> dict[str, Controller]:
         return self.__sub_controller_tree
 
+    def __repr__(self):
+        return f"""\
+{type(self).__name__}({self.path}, {list(self.__sub_controller_tree.keys())})\
+"""
+
 
 class Controller(BaseController):
     """Top-level controller for a device.

src/fastcs/controller_api.py

@@ -29,3 +29,8 @@ def walk_api(self) -> Iterator["ControllerAPI"]:
         yield self
         for api in self.sub_apis.values():
             yield from api.walk_api()
+
+    def __repr__(self):
+        return f"""\
+ControllerAPI(path={self.path}, sub_apis=[{", ".join(self.sub_apis.keys())}])\
+"""

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

@@ -33,6 +33,10 @@ class TemperatureControllerAttributeIORef(AttributeIORef):
     name: str
     update_period: float | None = 0.2
 
+    def __post_init__(self):
+        # Call __init__ of non-dataclass parent
+        super().__init__()
+
 
 class TemperatureControllerAttributeIO(
     AttributeIO[NumberT, TemperatureControllerAttributeIORef]
@@ -44,17 +48,22 @@ def __init__(self, connection: IPConnection, suffix: str):
     async def send(
         self, attr: AttrW[NumberT, TemperatureControllerAttributeIORef], value: NumberT
     ) -> None:
-        await self._connection.send_command(
-            f"{attr.io_ref.name}{self.suffix}={attr.dtype(value)}\r\n"
-        )
+        command = f"{attr.io_ref.name}{self.suffix}={attr.dtype(value)}"
+        await self._connection.send_command(f"{command}\r\n")
+        self.log_event("Send command for attribute", topic=attr, command=command)
 
     async def update(
         self, attr: AttrR[NumberT, TemperatureControllerAttributeIORef]
     ) -> None:
-        response = await self._connection.send_query(
-            f"{attr.io_ref.name}{self.suffix}?\r\n"
-        )
+        query = f"{attr.io_ref.name}{self.suffix}?"
+        response = await self._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))
 
@@ -93,10 +102,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

@@ -15,6 +15,17 @@
 
 from fastcs import __version__
 from fastcs.attribute_io_ref import AttributeIORef
+from fastcs.logging import (
+    GraylogEndpoint,
+    GraylogEnvFields,
+    GraylogStaticFields,
+    LogLevel,
+    configure_logging,
+    parse_graylog_env_fields,
+    parse_graylog_static_fields,
+)
+from fastcs.logging import logger as _fastcs_logger
+from fastcs.tracer import Tracer
 from fastcs.transport.epics.ca.transport import EpicsCATransport
 from fastcs.transport.epics.pva.transport import EpicsPVATransport
 from fastcs.transport.graphql.transport import GraphQLTransport
@@ -39,6 +50,9 @@
     | GraphQLTransport
 ]
 
+tracer = Tracer(name=__name__)
+logger = _fastcs_logger.bind(logger_name=__name__)
+
 
 class FastCS:
     """For launching a controller with given transport(s) and keeping
@@ -149,6 +163,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:
@@ -237,9 +257,10 @@ def _add_attribute_updater_tasks(
 def _create_updater_callback(attribute: AttrR[T]):
     async def callback():
         try:
+            tracer.log_event("Call attribute updater", topic=attribute)
             await attribute.update()
-        except Exception as e:
-            print(f"Update loop in {attribute} stopped:\n{e.__class__.__name__}: {e}")
+        except Exception:
+            logger.opt(exception=True).error("Update loop failed", attribute=attribute)
             raise
 
     return callback
@@ -381,10 +402,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