diff --git a/docs/snippets/static14.py b/docs/snippets/static14.py index 2e1824eab..fb794b199 100644 --- a/docs/snippets/static14.py +++ b/docs/snippets/static14.py @@ -10,13 +10,11 @@ from fastcs.controllers import Controller from fastcs.datatypes import Enum, Float, Int, String from fastcs.launch import FastCS -from fastcs.logging import bind_logger, configure_logging +from fastcs.logging import configure_logging, logger from fastcs.methods import command, scan from fastcs.transports.epics import EpicsGUIOptions, EpicsIOCOptions from fastcs.transports.epics.ca import EpicsCATransport -logger = bind_logger(__name__) - NumberT = TypeVar("NumberT", int, float) @@ -33,8 +31,6 @@ class TemperatureControllerAttributeIO( def __init__(self, connection: IPConnection, suffix: str = ""): super().__init__() - self.logger = bind_logger(__class__.__name__) - self._connection = connection self._suffix = suffix @@ -49,7 +45,7 @@ async def send( ) -> None: command = f"{attr.io_ref.name}{self._suffix}={attr.dtype(value)}" - self.logger.info("Sending attribute value", command=command, attribute=attr) + logger.info("Sending attribute value", command=command, attribute=attr) await self._connection.send_command(f"{command}\r\n") diff --git a/docs/snippets/static15.py b/docs/snippets/static15.py index 4df6934c2..0246d2cb0 100644 --- a/docs/snippets/static15.py +++ b/docs/snippets/static15.py @@ -10,13 +10,11 @@ from fastcs.controllers import Controller from fastcs.datatypes import Enum, Float, Int, String from fastcs.launch import FastCS -from fastcs.logging import LogLevel, bind_logger, configure_logging +from fastcs.logging import LogLevel, configure_logging, logger from fastcs.methods import command, scan from fastcs.transports.epics import EpicsGUIOptions, EpicsIOCOptions from fastcs.transports.epics.ca import EpicsCATransport -logger = bind_logger(__name__) - NumberT = TypeVar("NumberT", int, float) @@ -33,8 +31,6 @@ class TemperatureControllerAttributeIO( def __init__(self, connection: IPConnection, suffix: str = ""): super().__init__() - self.logger = bind_logger(__class__.__name__) - self._connection = connection self._suffix = suffix @@ -52,7 +48,7 @@ async def send( ) -> None: command = f"{attr.io_ref.name}{self._suffix}={attr.dtype(value)}" - self.logger.info("Sending attribute value", command=command, attribute=attr) + logger.info("Sending attribute value", command=command, attribute=attr) await self._connection.send_command(f"{command}\r\n") diff --git a/docs/tutorials/static-drivers.md b/docs/tutorials/static-drivers.md index 09c0a975a..31c345922 100644 --- a/docs/tutorials/static-drivers.md +++ b/docs/tutorials/static-drivers.md @@ -409,10 +409,8 @@ DEMO:R1:Enabled_RBV Off FastCS has convenient logging support to provide status and metrics from the application. To enable logging from the core framework call `configure_logging` with no -arguments (the default logging level is INFO). To log messages from a driver, either -import the singleton `logger` directly, or to provide more context to the message, call -`bind_logger` with a name (usually either the name of the module or the name of the -class). +arguments (the default logging level is INFO). To log messages from a driver, import the +singleton `logger` directly. Create a module-level logger to log status of the application start up. Create a class logger for `TemperatureControllerAttributeIO` to log the commands it sends. @@ -421,7 +419,7 @@ logger for `TemperatureControllerAttributeIO` to log the commands it sends. :class: dropdown, hint :::{literalinclude} /snippets/static14.py -:emphasize-lines: 15,20-21,53-55,116,123 +:emphasize-lines: 13,48,110,117 ::: :::: @@ -434,7 +432,7 @@ Try setting a PV and check the console for the log message it prints. A similar log message could be added for the update method of the IO, but this would be very verbose. For this use case FastCS provides the `Tracer` class, which is inherited -by `AttributeIO`, among other core FastCS classes. This adds a enables logging `TRACE` +by `AttributeIO`, among other core FastCS classes. This enables the logging of `TRACE` level log messages that are disabled by default, but can be enabled at runtime. Update the `send` method of the IO to log a message showing the query that was sent and @@ -446,13 +444,14 @@ visible. :class: dropdown, hint :::{literalinclude} /snippets/static15.py -:emphasize-lines: 15,47-49,119 +:emphasize-lines: 13,49-51,120 ::: :::: Enable tracing on the `power` attribute by calling `enable_tracing` and then enable a -ramp so that the value updates. Check the console to see the messages. Call `disable_tracing` to disable the log messages for `power. +ramp so that the value updates. Check the console to see the messages. Call +`disable_tracing` to disable the log messages for `power`. ``` In [1]: controller.power.enable_tracing() @@ -472,7 +471,7 @@ In [1]: controller.power.enable_tracing() In [2]: controller.power.disable_tracing() ``` -These log messages includes other trace loggers that log messages with `power` as the +These log messages include other trace loggers that log messages with `power` as the `topic`, so they also appear automatically, so the log messages show changes to the attribute throughout the stack: the query to the device and its response, the value the attribute is set to, and the value that the PV in the EPICS CA transport is set to. @@ -484,7 +483,7 @@ The `Tracer` can also be used as a module-level instance for use in free functio ```python from fastcs.tracer import Tracer -tracer = Tracer(__name__) +tracer = Tracer() def handle_attribute(attr): tracer.log_event("Handling attribute", topic=attr) diff --git a/src/fastcs/attributes/attr_r.py b/src/fastcs/attributes/attr_r.py index 59a2f227a..95a9fa383 100644 --- a/src/fastcs/attributes/attr_r.py +++ b/src/fastcs/attributes/attr_r.py @@ -8,10 +8,7 @@ from fastcs.attributes.attribute_io_ref import AttributeIORefT from fastcs.attributes.util import AttrValuePredicate, PredicateEvent from fastcs.datatypes import DataType, DType_T -from fastcs.logging import bind_logger - -logger = bind_logger(logger_name=__name__) - +from fastcs.logging import logger AttrIOUpdateCallback = Callable[["AttrR[DType_T, Any]"], Awaitable[None]] """An AttributeIO callback that takes an AttrR and updates its value""" diff --git a/src/fastcs/attributes/attr_rw.py b/src/fastcs/attributes/attr_rw.py index deff02783..5f0c2edbd 100644 --- a/src/fastcs/attributes/attr_rw.py +++ b/src/fastcs/attributes/attr_rw.py @@ -3,9 +3,6 @@ from fastcs.attributes.attribute import AttributeAccessMode from fastcs.attributes.attribute_io_ref import AttributeIORefT from fastcs.datatypes import DataType, DType_T -from fastcs.logging import bind_logger - -logger = bind_logger(logger_name=__name__) class AttrRW(AttrR[DType_T, AttributeIORefT], AttrW[DType_T, AttributeIORefT]): diff --git a/src/fastcs/attributes/attr_w.py b/src/fastcs/attributes/attr_w.py index 4532364a5..fa2b3d894 100644 --- a/src/fastcs/attributes/attr_w.py +++ b/src/fastcs/attributes/attr_w.py @@ -5,10 +5,7 @@ from fastcs.attributes.attribute import Attribute, AttributeAccessMode from fastcs.attributes.attribute_io_ref import AttributeIORefT from fastcs.datatypes import DataType, DType_T -from fastcs.logging import bind_logger - -logger = bind_logger(logger_name=__name__) - +from fastcs.logging import logger AttrOnPutCallback = Callable[["AttrW[DType_T, Any]", DType_T], Awaitable[None]] """Callbacks to be called when the setpoint of an attribute is changed""" diff --git a/src/fastcs/attributes/attribute.py b/src/fastcs/attributes/attribute.py index ae6e3852d..ca4955b53 100644 --- a/src/fastcs/attributes/attribute.py +++ b/src/fastcs/attributes/attribute.py @@ -4,11 +4,8 @@ from fastcs.attributes.attribute_io_ref import AttributeIORefT from fastcs.datatypes import DataType, DType, DType_T -from fastcs.logging import bind_logger from fastcs.tracer import Tracer -logger = bind_logger(logger_name=__name__) - AttributeAccessMode = Literal["r", "w", "rw"] diff --git a/src/fastcs/control_system.py b/src/fastcs/control_system.py index cae16b77d..b1a6ea6cd 100644 --- a/src/fastcs/control_system.py +++ b/src/fastcs/control_system.py @@ -8,13 +8,12 @@ from IPython.terminal.embed import InteractiveShellEmbed from fastcs.controllers import BaseController, Controller -from fastcs.logging import bind_logger +from fastcs.logging import logger from fastcs.methods import ScanCallback from fastcs.tracer import Tracer from fastcs.transports import ControllerAPI, Transport -tracer = Tracer(name=__name__) -logger = bind_logger(logger_name=__name__) +tracer = Tracer() class FastCS: diff --git a/src/fastcs/controllers/base_controller.py b/src/fastcs/controllers/base_controller.py index 0e5fc1de0..472573526 100755 --- a/src/fastcs/controllers/base_controller.py +++ b/src/fastcs/controllers/base_controller.py @@ -6,12 +6,10 @@ from typing import _GenericAlias, get_args, get_origin, get_type_hints # type: ignore from fastcs.attributes import AnyAttributeIO, Attribute, AttrR, AttrW, HintedAttribute -from fastcs.logging import bind_logger +from fastcs.logging import logger from fastcs.methods import Command, Scan, UnboundCommand, UnboundScan from fastcs.tracer import Tracer -logger = bind_logger(logger_name=__name__) - class BaseController(Tracer): """Base class for controllers diff --git a/src/fastcs/logging/__init__.py b/src/fastcs/logging/__init__.py index ba11b087e..d47a268fd 100644 --- a/src/fastcs/logging/__init__.py +++ b/src/fastcs/logging/__init__.py @@ -7,7 +7,7 @@ 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 Logger, LogLevel, _configure_logger +from ._logging import LogLevel, _configure_logger logger = _logger.bind(logger_name="fastcs") """FastCS logger @@ -21,8 +21,7 @@ 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 ``_``. +messages to be formatted nicely in the console. .. code-block:: python @@ -30,24 +29,22 @@ 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 +To add kwargs to format the message without them appearing as extra fields, prepend the +key with ``_``. + +By default messages will be logged with the name ``fastcs``. Within a driver it may be +useful to set a distinct logger name. This can be done with the ``bind`` method. To +create a new logger with the the name of the driver, use the following in a logging.py +module and use it throughout the package instead of the fastcs logger: .. 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__) + logger = _logger.bind(logger_name="fastcs-driver") 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 +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 @@ -57,18 +54,6 @@ """ -def bind_logger(logger_name: str) -> Logger: - """Create a wrapper of the singleton fastcs logger with the given name bound - - The name will be displayed in all log messages from the returned wrapper. - - See the docstring for ``fastcs.logging.logger`` for more information. - - """ - - return logger.bind(logger_name=logger_name) - - def configure_logging( level: LogLevel = LogLevel.INFO, graylog_endpoint: GraylogEndpoint | None = None, @@ -94,10 +79,6 @@ def configure_logging( ) -# Configure logger with defaults - INFO level and disabled -_configure_logger(logger) - - class _StdLoggingInterceptHandler(logging.Handler): """A std logging handler to forward messages to loguru with nice formatting.""" diff --git a/src/fastcs/logging/_logging.py b/src/fastcs/logging/_logging.py index a4358426b..c62d7a608 100644 --- a/src/fastcs/logging/_logging.py +++ b/src/fastcs/logging/_logging.py @@ -90,6 +90,7 @@ def format_record(record) -> str: time = f"{_time}{_timezone}" name = record["extra"].pop("logger_name", None) or record["name"] + message_pad = max(0, 100 - len(name)) sep = ", " if "extra" in record: @@ -108,8 +109,8 @@ def format_record(record) -> str: return f"""\ [{time} {record["level"].name[0]}] \ -{record["message"]:<80} \ -[{name}] \ +{record["message"]:<{message_pad}} \ +{name} [{record["file"].path}:{record["line"]}] \ {extras} {{exception}}\ """ diff --git a/src/fastcs/methods/command.py b/src/fastcs/methods/command.py index 87d0e0b1d..5259e4b64 100644 --- a/src/fastcs/methods/command.py +++ b/src/fastcs/methods/command.py @@ -2,13 +2,12 @@ from types import MethodType from typing import TYPE_CHECKING -from fastcs.logging import bind_logger +from fastcs.logging import logger from fastcs.methods.method import Controller_T, Method if TYPE_CHECKING: from fastcs.controllers import BaseController # noqa: F401 -logger = bind_logger(logger_name=__name__) UnboundCommandCallback = Callable[[Controller_T], Coroutine[None, None, None]] """A Command callback that is unbound and must be called with a `Controller` instance""" diff --git a/src/fastcs/methods/scan.py b/src/fastcs/methods/scan.py index a20b7e944..5701e79df 100644 --- a/src/fastcs/methods/scan.py +++ b/src/fastcs/methods/scan.py @@ -2,13 +2,12 @@ from types import MethodType from typing import TYPE_CHECKING -from fastcs.logging import bind_logger +from fastcs.logging import logger from fastcs.methods.method import Controller_T, Method if TYPE_CHECKING: from fastcs.controllers import BaseController # noqa: F401 -logger = bind_logger(logger_name=__name__) UnboundScanCallback = Callable[[Controller_T], Coroutine[None, None, None]] """A Scan callback that is unbound and must be called with a `Controller` instance""" diff --git a/src/fastcs/tracer.py b/src/fastcs/tracer.py index 6a5a8cca6..a62f93c8a 100644 --- a/src/fastcs/tracer.py +++ b/src/fastcs/tracer.py @@ -1,7 +1,10 @@ from collections import defaultdict from typing import Any -from fastcs.logging import logger +from fastcs.logging import logger as _logger + +# Pass depth so that reported line number in log messages is `log_event` call site +logger = _logger.opt(depth=1) class Tracer: @@ -16,9 +19,9 @@ class Tracer: 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 + Note: The logger level must be set to ``TRACE`` for the messages to be logged - Example usage: + Example usage in interactive shell: .. code-block:: python controller.ramp_rate.enable_tracing() @@ -27,23 +30,20 @@ class Tracer: 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): + def __init__(self): 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 + Args: + event: A message describing the event + topic: Another `Tracer` related to this event to enable it to be logged + args: Positional arguments for underlying logger + kwargs: Keyword arguments for underlying logger """ if self.__tracing_enabled or (topic is not None and topic.__tracing_enabled): # noqa: SLF001 @@ -54,7 +54,7 @@ def log_event(self, event: str, topic: "Tracer | None" = None, *args, **kwargs): else: return - logger.trace(event, *args, logger_name=self.__logger_name, **kwargs) + logger.trace(event, *args, **kwargs) def enable_tracing(self): """Enable trace logging for this object""" diff --git a/src/fastcs/transports/controller_api.py b/src/fastcs/transports/controller_api.py index 3a13fae0a..b41d8ad34 100644 --- a/src/fastcs/transports/controller_api.py +++ b/src/fastcs/transports/controller_api.py @@ -4,14 +4,9 @@ from dataclasses import dataclass, field from fastcs.attributes import Attribute, AttributeIORef, AttrR -from fastcs.logging import bind_logger from fastcs.methods import Command, Scan, ScanCallback -from fastcs.tracer import Tracer from fastcs.util import ONCE -tracer = Tracer(name=__name__) -logger = bind_logger(logger_name=__name__) - @dataclass class ControllerAPI: diff --git a/src/fastcs/transports/epics/ca/ioc.py b/src/fastcs/transports/epics/ca/ioc.py index 8c21bd1b0..e8e94d7a3 100644 --- a/src/fastcs/transports/epics/ca/ioc.py +++ b/src/fastcs/transports/epics/ca/ioc.py @@ -7,7 +7,7 @@ from fastcs.attributes import AttrR, AttrRW, AttrW from fastcs.datatypes import DType_T, Waveform -from fastcs.logging import bind_logger +from fastcs.logging import logger from fastcs.methods import Command from fastcs.tracer import Tracer from fastcs.transports.controller_api import ControllerAPI @@ -23,8 +23,7 @@ EPICS_MAX_NAME_LENGTH = 60 -tracer = Tracer(name=__name__) -logger = bind_logger(logger_name=__name__) +tracer = Tracer() class EpicsCAIOC: diff --git a/src/fastcs/transports/epics/ca/transport.py b/src/fastcs/transports/epics/ca/transport.py index a4e507a5f..08ac3aebf 100644 --- a/src/fastcs/transports/epics/ca/transport.py +++ b/src/fastcs/transports/epics/ca/transport.py @@ -4,7 +4,7 @@ from softioc import softioc -from fastcs.logging import bind_logger +from fastcs.logging import logger from fastcs.transports.controller_api import ControllerAPI from fastcs.transports.epics import ( EpicsDocsOptions, @@ -16,8 +16,6 @@ from fastcs.transports.epics.gui import EpicsGUI from fastcs.transports.transport import Transport -logger = bind_logger(logger_name=__name__) - @dataclass class EpicsCATransport(Transport): diff --git a/src/fastcs/transports/epics/gui.py b/src/fastcs/transports/epics/gui.py index 0e650cf2b..98e2f9984 100644 --- a/src/fastcs/transports/epics/gui.py +++ b/src/fastcs/transports/epics/gui.py @@ -32,14 +32,12 @@ String, Waveform, ) -from fastcs.logging import bind_logger +from fastcs.logging import logger from fastcs.methods import Command from fastcs.transports.controller_api import ControllerAPI from fastcs.transports.epics.options import EpicsGUIFormat, EpicsGUIOptions from fastcs.util import snake_to_pascal -logger = bind_logger(logger_name=__name__) - class EpicsGUI: """For creating gui in the EPICS transports.""" diff --git a/src/fastcs/transports/epics/pva/_pv_handlers.py b/src/fastcs/transports/epics/pva/_pv_handlers.py index 099a9c334..5ba819f98 100644 --- a/src/fastcs/transports/epics/pva/_pv_handlers.py +++ b/src/fastcs/transports/epics/pva/_pv_handlers.py @@ -21,7 +21,7 @@ p4p_timestamp_now, ) -tracer = Tracer(name=__name__) +tracer = Tracer() class WritePvHandler: diff --git a/src/fastcs/transports/epics/pva/transport.py b/src/fastcs/transports/epics/pva/transport.py index 1ccc8042d..14854dea7 100644 --- a/src/fastcs/transports/epics/pva/transport.py +++ b/src/fastcs/transports/epics/pva/transport.py @@ -1,7 +1,7 @@ import asyncio from dataclasses import dataclass, field -from fastcs.logging import bind_logger +from fastcs.logging import logger from fastcs.transports.controller_api import ControllerAPI from fastcs.transports.epics import ( EpicsDocsOptions, @@ -14,8 +14,6 @@ from .ioc import P4PIOC -logger = bind_logger(logger_name=__name__) - @dataclass class EpicsPVATransport(Transport):