diff --git a/.vscode/launch.json b/.vscode/launch.json index 99fa42870..88030120e 100644 --- a/.vscode/launch.json +++ b/.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", } ] diff --git a/pyproject.toml b/pyproject.toml index cb2d5a40f..e64fe525f 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -19,6 +19,8 @@ dependencies = [ "pydantic", "ruamel.yaml", "IPython", + "loguru~=0.7", + "pygelf", ] dynamic = ["version"] license.file = "LICENSE" diff --git a/src/fastcs/attribute_io.py b/src/fastcs/attribute_io.py index e61f52c9e..3af563a16 100644 --- a/src/fastcs/attribute_io.py +++ b/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: diff --git a/src/fastcs/attributes.py b/src/fastcs/attributes.py index dce98bb81..a31a50584 100644 --- a/src/fastcs/attributes.py +++ b/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: diff --git a/src/fastcs/connections/ip_connection.py b/src/fastcs/connections/ip_connection.py index 9cd5e6f1b..12a0acee1 100644 --- 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 index 6f7b128b9..653745185 100755 --- a/src/fastcs/controller.py +++ b/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. diff --git a/src/fastcs/controller_api.py b/src/fastcs/controller_api.py index c5724000b..c0aae277f 100644 --- a/src/fastcs/controller_api.py +++ b/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())}])\ +""" diff --git a/src/fastcs/cs_methods.py b/src/fastcs/cs_methods.py index 824a2d1da..1c9c6751c 100644 --- 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 index ab7485c2b..09d022785 100644 --- 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 index d1ed2bcf1..12fade2bf 100755 --- a/src/fastcs/demo/controllers.py +++ b/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])) diff --git a/src/fastcs/launch.py b/src/fastcs/launch.py index 88cc9cb8d..4e41f1b59 100644 --- a/src/fastcs/launch.py +++ b/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 - ':'", + 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 diff --git a/src/fastcs/logging/__init__.py b/src/fastcs/logging/__init__.py new file mode 100644 index 000000000..0725cc538 --- /dev/null +++ b/src/fastcs/logging/__init__.py @@ -0,0 +1,113 @@ +import logging + +from loguru import logger as _logger + +from ._graylog import GraylogEndpoint as GraylogEndpoint +from ._graylog import GraylogEnvFields as GraylogEnvFields +from ._graylog import GraylogStaticFields as GraylogStaticFields +from ._graylog import parse_graylog_env_fields as parse_graylog_env_fields +from ._graylog import parse_graylog_static_fields as parse_graylog_static_fields +from ._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 ``_``. + +.. code-block:: python + + 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 + +.. code-block:: python + + from fastcs.logging import logger as _logger + + logger = _logger.bind(logger_name=__name__) + + +or to create a class logger with its name + +.. code-block:: python + + self.logger = _logger.bind(logger_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-confi 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_endpoint: GraylogEndpoint | None = None, + graylog_static_fields: GraylogStaticFields | None = None, + graylog_env_fields: GraylogEnvFields | None = None, +): + """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_endpoint: Endpoint for graylog logging - ':' + :param graylog_static_fields: Fields to add to graylog messages with static values + :param graylog_env_fields: Fields to add to graylog messages from env variables + + """ + global logger + + _configure_logger( + logger, level, graylog_endpoint, graylog_static_fields, graylog_env_fields + ) + + +# Configure logger with defaults - INFO level and disabled +configure_logging() + + +class _StdLoggingInterceptHandler(logging.Handler): + """A std logging handler to forward messages to loguru with nice formatting.""" + + def emit(self, record: logging.LogRecord): + logger.bind(logger_name=self.name).log(record.levelname, record.getMessage()) + + +def intercept_std_logger(logger_name: str): + """Intercept std logging messages from the given logger + + To find the correct ``logger_name`` for a message. Add a breakpoint in + ``logging.Logger.callHandlers``, debug and run until the log message appears as + ``record.msg``. The logger name will be in ``self.name``. + + :param logger_name: Name of the logger to intercept + + """ + handler = _StdLoggingInterceptHandler() + handler.set_name(logger_name) + + std_logger = logging.getLogger(logger_name) + std_logger.handlers = [handler] + std_logger.propagate = False diff --git a/src/fastcs/logging/_graylog.py b/src/fastcs/logging/_graylog.py new file mode 100644 index 000000000..719180022 --- /dev/null +++ b/src/fastcs/logging/_graylog.py @@ -0,0 +1,54 @@ +from dataclasses import dataclass +from typing import NewType + + +@dataclass +class GraylogEndpoint: + """Server and port for a graylog instance.""" + + host: str + port: int + + @classmethod + def parse_graylog_endpoint(cls, endpoint: str) -> "GraylogEndpoint": + try: + host, port = endpoint.split(":") + port = int(port) + except Exception as e: + raise ValueError( + "Invalid graylog endpoint. Expected ':'." + ) from e + + return cls(host, port) + + +GraylogEnvFields = NewType("GraylogEnvFields", dict[str, str]) +"""Fields to add to graylog messages from environment variables.""" + + +def parse_graylog_env_fields(comma_separated_fields: str) -> GraylogEnvFields: + try: + return GraylogEnvFields(_parse_graylog_env_fields(comma_separated_fields)) + except Exception as e: + raise ValueError( + "Failed to parse fields. Expected ':,...'" + ) from e + + +GraylogStaticFields = NewType("GraylogStaticFields", dict[str, str]) +"""Fields to add to graylog messages with static values.""" + + +def parse_graylog_static_fields(comma_separated_fields: str) -> GraylogStaticFields: + try: + return GraylogStaticFields(_parse_graylog_env_fields(comma_separated_fields)) + except Exception as e: + raise ValueError("Failed to parse fields. Expected ':,...'") from e + + +def _parse_graylog_env_fields(comma_separated_fields: str) -> dict[str, str]: + return { + field: env + for pair in comma_separated_fields.split(",") + for field, env in [pair.split(":")] + } diff --git a/src/fastcs/logging/_logging.py b/src/fastcs/logging/_logging.py new file mode 100644 index 000000000..1114a6dbd --- /dev/null +++ b/src/fastcs/logging/_logging.py @@ -0,0 +1,123 @@ +import getpass +import os +from enum import StrEnum +from logging import LogRecord +from typing import TYPE_CHECKING + +from prompt_toolkit.patch_stdout import StdoutProxy +from pygelf import GelfUdpHandler +from pygelf.gelf import SKIP_LIST + +from fastcs.logging._graylog import ( + GraylogEndpoint, + GraylogEnvFields, + GraylogStaticFields, +) + +if TYPE_CHECKING: + from loguru import Logger +else: + from typing import Any + + Logger = Any + + +def _configure_logger( + logger: Logger, + level: "LogLevel | None" = None, + graylog_endpoint: GraylogEndpoint | None = None, + graylog_static_fields: GraylogStaticFields | None = None, + graylog_env_fields: GraylogEnvFields | None = None, +): + logger.remove() + logger.add( + sink=StdoutProxy(raw=True), # type: ignore + colorize=True, + format=format_record, + level=level or "INFO", + ) + + if graylog_endpoint is not None: + static_fields = { + "app_name": "fastcs", + "username": getpass.getuser(), + "process_id": os.getpid(), + } + if graylog_static_fields is not None: + static_fields.update(graylog_static_fields) + + logger.add( + LoguruGelfUdpHandler( + graylog_endpoint.host, + graylog_endpoint.port, + # Include built-in file, line, module, function and logger_name fields + debug=True, + # Include these static fields + static_fields=static_fields, + # Include configured fields from environment + additional_env_fields=graylog_env_fields, + # Include fields added dynamically to log record (log statement kwargs) + include_extra_fields=True, + ), + format="{message}", + level="INFO", + ) + + if level is None: + logger.disable("fastcs") + else: + logger.enable("fastcs") + + +def format_record(record) -> str: + _time = record["time"].strftime("%Y-%m-%d %H:%M:%S.%f")[:-3] + _timezone = record["time"].strftime("%z") + time = f"{_time}{_timezone}" + + name = record["extra"].pop("logger_name", None) or record["name"] + + sep = ", " + if "extra" in record: + extras = [ + format_key_value(k, v) + for k, v in record["extra"].items() + if not k.startswith("_") + ] + extras = f"{sep.join(extras)}" + else: + extras = "" + + return f"""\ +[{time} {record["level"].name[0]}] \ +{record["message"]:<80} \ +[{name}] \ +{extras} +{{exception}}\ +""" + + +def format_key_value(k, v): + return f"{k}={v}" + + +class LogLevel(StrEnum): + TRACE = "TRACE" + DEBUG = "DEBUG" + INFO = "INFO" + WARNING = "WARNING" + ERROR = "ERROR" + CRITICAL = "CRITICAL" + + +class LoguruGelfUdpHandler(GelfUdpHandler): + def convert_record_to_gelf(self, record: LogRecord): + # Use full file path instead of file name + record.__dict__["filename"] = record.__dict__["pathname"] + + # Pull loguru extra fields into root of record for pygelf to include + extras = record.__dict__.pop("extra", {}) + for k, v in extras.items(): + if k not in SKIP_LIST and not k.startswith("_"): + record.__dict__[k] = v + + return super().convert_record_to_gelf(record) diff --git a/src/fastcs/tracer.py b/src/fastcs/tracer.py new file mode 100644 index 000000000..2b0ea2a67 --- /dev/null +++ b/src/fastcs/tracer.py @@ -0,0 +1,96 @@ +from collections import defaultdict +from typing import Any + +from fastcs.logging import logger + + +class Tracer: + """A mixin or standalone class for conditionally logging trace events. + + This can be used for verbose logging that is disabled by default and enabled on a + per-instance basis, with filtering based on specific key-value pairs on the event. + + Any instance of this class can enable tracing independently. Some key classes + inherit this class, such as ``Attributes``, and some modules have their own + ``Tracer``, such as ``fastcs.launch``. When enabled, any event logged from the + object, or from another ``Tracer`` that uses the object as the ``topic``, will be + logged. + + Note: The global logger level must be set to ``TRACE`` for the messages to be logged + + Example usage: + >>> controller.ramp_rate.enable_tracing() + >>> controller.ramp_rate.disable_tracing() + >>> controller.connection.enable_tracing() + >>> controller.connection.add_tracing_filter("query", "V?") + >>> controller.connection.remove_tracing_filter("query", "V?") + >>> controller.connection.disable_tracing() + + :param name: The name of the logger. Attached to log messages as ``logger_name``. + + """ + + def __init__(self, name: str | None = None): + self.__tracing_enabled: bool = False + self.__tracing_filters: dict[str, list[Any]] = defaultdict(list) + self.__logger_name = name if name is not None else self.__class__.__name__ + + def log_event(self, event: str, topic: "Tracer | None" = None, *args, **kwargs): + """Log an event only if tracing is enabled and the filter matches + + :param event: A message describing the event + :param topic: Another `Tracer` related to this event to enable it to be logged + :param args: Positional arguments for underlying logger + :param kwargs: Keyword arguments for underlying logger + + """ + if self.__tracing_enabled or (topic is not None and topic.__tracing_enabled): # noqa: SLF001 + if self.__tracing_filters: + for kwarg, values in self.__tracing_filters.items(): + if kwarg in kwargs and any(kwargs[kwarg] == v for v in values): + break + else: + return + + logger.trace(event, *args, logger_name=self.__logger_name, **kwargs) + + def enable_tracing(self): + """Enable trace logging for this object""" + self.__tracing_enabled = True + + def disable_tracing(self): + """Disable trace logging for this object""" + self.__tracing_enabled = False + + def add_tracing_filter(self, key: str, value: Any): + """Add a filter for trace log messages from this object + + To reduce trace messages further, a filter can be applied such that events must + have a key with a specific value for it to be logged. + + :param key: A new or existing key to filter on + :param value: An allowed value for the event to be logged + + """ + self.__tracing_filters[key].append(value) + + def remove_tracing_filter(self, key: str, value: Any): + """Remove a specific key-value pair from the filter + + :param key: An existing filter key + :param value: The allowed value to remove + + """ + if ( + key not in self.__tracing_filters + or value not in self.__tracing_filters[key] + ): + return + + self.__tracing_filters[key].remove(value) + if not self.__tracing_filters[key]: + self.__tracing_filters.pop(key) + + def clear_tracing_filters(self): + """Clear all filters and allow all messages to be logged (if enabled)""" + self.__tracing_filters.clear() diff --git a/src/fastcs/transport/epics/ca/ioc.py b/src/fastcs/transport/epics/ca/ioc.py index 45ac70277..45bfc96dc 100644 --- a/src/fastcs/transport/epics/ca/ioc.py +++ b/src/fastcs/transport/epics/ca/ioc.py @@ -8,7 +8,10 @@ from fastcs.attributes import AttrR, AttrRW, AttrW from fastcs.controller_api import ControllerAPI +from fastcs.cs_methods import Command from fastcs.datatypes import DataType, T +from fastcs.logging import logger as _fastcs_logger +from fastcs.tracer import Tracer from fastcs.transport.epics.ca.util import ( builder_callable_from_attribute, cast_from_epics_type, @@ -22,6 +25,10 @@ EPICS_MAX_NAME_LENGTH = 60 +tracer = Tracer(name=__name__) +logger = _fastcs_logger.bind(logger_name=__name__) + + class EpicsCAIOC: """A softioc which handles a controller. @@ -159,10 +166,14 @@ def _create_and_link_attribute_pvs( def _create_and_link_read_pv( pv_prefix: str, pv_name: str, attr_name: str, attribute: AttrR[T] ) -> None: + pv = f"{pv_prefix}:{pv_name}" + async def async_record_set(value: T): + tracer.log_event("PV set from attribute", topic=attribute, pv=pv, value=value) + record.set(cast_to_epics_type(attribute.datatype, value)) - record = _make_record(f"{pv_prefix}:{pv_name}", attribute) + record = _make_record(pv, attribute) _add_attr_pvi_info(record, pv_prefix, attr_name, "r") attribute.add_set_callback(async_record_set) @@ -197,12 +208,20 @@ def datatype_updater(datatype: DataType): def _create_and_link_write_pv( pv_prefix: str, pv_name: str, attr_name: str, attribute: AttrW[T] ) -> None: + pv = f"{pv_prefix}:{pv_name}" + async def on_update(value): + logger.info("PV put: {pv} = {value}", pv=pv, value=value) + await attribute.process_without_display_update( cast_from_epics_type(attribute.datatype, value) ) async def async_write_display(value: T): + tracer.log_event( + "PV setpoint set from attribute", topic=attribute, pv=pv, value=value + ) + record.set(cast_to_epics_type(attribute.datatype, value), process=False) record = _make_record( @@ -233,15 +252,19 @@ def _create_and_link_command_pvs( _pv_prefix, pv_name, attr_name, - method.fn, + method, ) def _create_and_link_command_pv( - pv_prefix: str, pv_name: str, attr_name: str, method: Callable + pv_prefix: str, pv_name: str, attr_name: str, method: Command ) -> None: + pv = f"{pv_prefix}:{pv_name}" + async def wrapped_method(_: Any): - await method() + tracer.log_event("Command PV put", topic=method, pv=pv) + + await method.fn() record = builder.Action( f"{pv_prefix}:{pv_name}", diff --git a/src/fastcs/transport/epics/ca/transport.py b/src/fastcs/transport/epics/ca/transport.py index 5ffccd75d..458b9da9e 100644 --- a/src/fastcs/transport/epics/ca/transport.py +++ b/src/fastcs/transport/epics/ca/transport.py @@ -5,6 +5,7 @@ from softioc import softioc from fastcs.controller_api import ControllerAPI +from fastcs.logging import logger as _fastcs_logger from fastcs.transport.epics.ca.ioc import EpicsCAIOC from fastcs.transport.epics.docs import EpicsDocs from fastcs.transport.epics.gui import EpicsGUI @@ -15,6 +16,8 @@ ) from fastcs.transport.transport import Transport +logger = _fastcs_logger.bind(logger_name=__name__) + @dataclass class EpicsCATransport(Transport): @@ -41,7 +44,7 @@ def create_gui(self) -> None: EpicsGUI(self._controller_api, self._pv_prefix).create_gui(self.gui) async def serve(self) -> None: - print(f"Running FastCS IOC: {self._pv_prefix}") + logger.info("Running IOC", pv_prefix=self._pv_prefix) self._ioc.run(self._loop) @property @@ -51,3 +54,6 @@ def context(self) -> dict[str, Any]: for command_name in softioc.command_names if command_name != "exit" } + + def __repr__(self): + return f"EpicsCATransport({self._pv_prefix})" diff --git a/src/fastcs/transport/epics/pva/transport.py b/src/fastcs/transport/epics/pva/transport.py index d89d3c52c..f5a69a000 100644 --- a/src/fastcs/transport/epics/pva/transport.py +++ b/src/fastcs/transport/epics/pva/transport.py @@ -2,6 +2,7 @@ from dataclasses import dataclass, field from fastcs.controller_api import ControllerAPI +from fastcs.logging import logger as _fastcs_logger from fastcs.transport.epics.docs import EpicsDocs from fastcs.transport.epics.gui import PvaEpicsGUI from fastcs.transport.epics.options import ( @@ -13,6 +14,8 @@ from .ioc import P4PIOC +logger = _fastcs_logger.bind(logger_name=__name__) + @dataclass class EpicsPVATransport(Transport): @@ -32,7 +35,7 @@ def initialise( self._ioc = P4PIOC(self.pva_ioc.pv_prefix, controller_api) async def serve(self) -> None: - print(f"Running FastCS IOC: {self._pv_prefix}") + logger.info("Running IOC", pv_prefix=self._pv_prefix) await self._ioc.run() def create_docs(self) -> None: @@ -40,3 +43,6 @@ def create_docs(self) -> None: def create_gui(self) -> None: PvaEpicsGUI(self._controller_api, self._pv_prefix).create_gui(self.gui) + + def __repr__(self): + return f"EpicsPVATransport({self._pv_prefix})" diff --git a/src/fastcs/transport/graphql/graphql.py b/src/fastcs/transport/graphql/graphql.py index c62eb7a72..dfa3ef242 100644 --- a/src/fastcs/transport/graphql/graphql.py +++ b/src/fastcs/transport/graphql/graphql.py @@ -10,6 +10,7 @@ from fastcs.attributes import AttrR, AttrRW, AttrW, T from fastcs.controller_api import ControllerAPI from fastcs.exceptions import FastCSError +from fastcs.logging import intercept_std_logger from .options import GraphQLServerOptions @@ -41,6 +42,10 @@ async def serve(self, options: GraphQLServerOptions | None = None) -> None: log_level=options.log_level, ) ) + intercept_std_logger("uvicorn.error") + intercept_std_logger("uvicorn.access") + intercept_std_logger("uvicorn.asgi") + await self._server.serve() diff --git a/src/fastcs/transport/graphql/transport.py b/src/fastcs/transport/graphql/transport.py index 5560ffa93..f469fe360 100644 --- a/src/fastcs/transport/graphql/transport.py +++ b/src/fastcs/transport/graphql/transport.py @@ -23,3 +23,6 @@ def initialise( async def serve(self) -> None: await self._server.serve(self.graphql) + + def __repr__(self) -> str: + return f"GraphQLTransport({self.graphql.host}:{self.graphql.port})" diff --git a/src/fastcs/transport/rest/rest.py b/src/fastcs/transport/rest/rest.py index db31247c5..ed45ddb57 100644 --- a/src/fastcs/transport/rest/rest.py +++ b/src/fastcs/transport/rest/rest.py @@ -8,6 +8,7 @@ from fastcs.attributes import AttrR, AttrRW, AttrW, T from fastcs.controller_api import ControllerAPI from fastcs.cs_methods import CommandCallback +from fastcs.logging import intercept_std_logger from .options import RestServerOptions from .util import ( @@ -44,6 +45,10 @@ async def serve(self, options: RestServerOptions | None): log_level=options.log_level, ) ) + intercept_std_logger("uvicorn.error") + intercept_std_logger("uvicorn.access") + intercept_std_logger("uvicorn.asgi") + await self._server.serve() diff --git a/src/fastcs/transport/rest/transport.py b/src/fastcs/transport/rest/transport.py index f17c860f7..d79e6c88b 100644 --- a/src/fastcs/transport/rest/transport.py +++ b/src/fastcs/transport/rest/transport.py @@ -23,3 +23,6 @@ def initialise( async def serve(self) -> None: await self._server.serve(self.rest) + + def __repr__(self) -> str: + return f"RestTransport({self.rest.host}:{self.rest.port})"