From c5e1c8e3d84aea172d6164fa4beee0950b4b68cb Mon Sep 17 00:00:00 2001 From: Yan Date: Mon, 21 Sep 2026 15:45:58 +0200 Subject: [PATCH 1/7] implement scoped logger --- docs/examples/logging/logging_example.ipynb | 101 +++++++++ src/qcodes/instrument/instrument_base.py | 65 +++++- src/qcodes/instrument/ip_to_visa.py | 2 +- src/qcodes/instrument/visa.py | 2 +- tests/test_logger.py | 234 ++++++++++++++++++++ 5 files changed, 400 insertions(+), 4 deletions(-) diff --git a/docs/examples/logging/logging_example.ipynb b/docs/examples/logging/logging_example.ipynb index 819d5fb5a51e..35beb597c4f7 100644 --- a/docs/examples/logging/logging_example.ipynb +++ b/docs/examples/logging/logging_example.ipynb @@ -333,6 +333,107 @@ " driver.cartesian((0, 0, 1))" ] }, + { + "cell_type": "markdown", + "metadata": {}, + "source": [ + "## One logger per instrument\n", + "By default all instruments share a single logger, named `qcodes.instrument.instrument_base` (and `...instrument_base.com.visa` for the VISA communication). This means that calling `setLevel`, `addHandler` or setting `propagate` on `instrument.log.logger` affects every other instrument in the process as well.\n", + "\n", + "A driver can opt in to a logger of its own by setting `default_logger_scope` to `\"instrument\"`. This can be done on the driver class, which also works for drivers you do not control:" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "class ScopedAMIModel430(AMIModel430):\n", + " default_logger_scope = \"instrument\"\n", + "\n", + "\n", + "mag_w = ScopedAMIModel430(\n", + " \"w\", address=\"GPIB::4::INSTR\", pyvisa_sim_file=\"AMI430.yaml\", terminator=\"\\n\"\n", + ")\n", + "\n", + "print(mag_w.log.logger.name)\n", + "print(mag_w.switch_heater.log.logger.name)\n", + "print(mag_x.log.logger.name)" + ] + }, + { + "cell_type": "markdown", + "metadata": {}, + "source": [ + "The logger name is built from the driver class followed by the instrument's `name_parts`, so scoped loggers mirror the instrument hierarchy: a submodule logger is a child of its instrument's logger, which is a child of a per-driver-class logger, which is a child of the shared logger. Any level configured on `qcodes.instrument.instrument_base`, for instance via `logger_levels` in `qcodesrc.json`, is therefore still inherited.\n", + "\n", + "The scope is looked up on the root instrument when the instrument is created, so it has to be set before instantiating the driver and applies to the whole instrument.\n", + "\n", + "The level of a single instrument can now be changed without affecting any other instrument:" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "mag_w.log.logger.setLevel(logging.DEBUG)\n", + "\n", + "print(logging.getLevelName(mag_w.log.logger.getEffectiveLevel()))\n", + "print(logging.getLevelName(mag_x.log.logger.getEffectiveLevel()))" + ] + }, + { + "cell_type": "markdown", + "metadata": {}, + "source": [ + "Because there is a node per driver class, you can also raise the level for *every* instrument of a driver at once, which is typically what you want while developing or debugging that driver. This works for instruments that do not exist yet, so it can equally well be put in the `logger_levels` section of `qcodesrc.json`:" + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "logging.getLogger(\"qcodes.instrument.instrument_base.ScopedAMIModel430\").setLevel(\n", + " logging.DEBUG\n", + ")\n", + "\n", + "mag_v = ScopedAMIModel430(\n", + " \"v\", address=\"GPIB::2::INSTR\", pyvisa_sim_file=\"AMI430.yaml\", terminator=\"\\n\"\n", + ")\n", + "\n", + "# both instruments of this driver are now at DEBUG, mag_x is untouched\n", + "for inst in (mag_w, mag_v):\n", + " print(inst.name, logging.getLevelName(inst.log.logger.getEffectiveLevel()))\n", + "print(mag_x.name, logging.getLevelName(mag_x.log.logger.getEffectiveLevel()))" + ] + }, + { + "cell_type": "markdown", + "metadata": {}, + "source": [ + "Two things are worth keeping in mind:\n", + "\n", + "* QCoDeS attaches its console and file handlers to the **root** logger and those handlers have their own levels. Lowering the level of an instrument logger to `DEBUG` only becomes visible if the handler level lets the record through, so combine it with `console_level` or `handler_level` as shown above.\n", + "* Setting `instrument.log.logger.propagate = False` silences that instrument everywhere, including in the QCoDeS log file.\n", + "\n", + "Note also that parameters log through the logger of their *root* instrument, so messages from a channel parameter appear on the root instrument's logger rather than on the channel's own logger." + ] + }, + { + "cell_type": "code", + "execution_count": null, + "metadata": {}, + "outputs": [], + "source": [ + "mag_w.close()\n", + "mag_v.close()" + ] + }, { "cell_type": "markdown", "metadata": {}, diff --git a/src/qcodes/instrument/instrument_base.py b/src/qcodes/instrument/instrument_base.py index 733bfa0ecb6c..2a3522ae1c71 100644 --- a/src/qcodes/instrument/instrument_base.py +++ b/src/qcodes/instrument/instrument_base.py @@ -5,7 +5,7 @@ import collections.abc import logging import warnings -from typing import TYPE_CHECKING, Any, ClassVar, cast +from typing import TYPE_CHECKING, Any, ClassVar, Literal, cast import numpy as np from typing_extensions import TypedDict, TypeVar, deprecated @@ -37,6 +37,21 @@ "TSubmodule", bound="InstrumentModule | ChannelTuple", default="InstrumentModule" ) +LoggerScope = Literal["shared", "instrument"] +""" +Naming scope used for the logger behind :attr:`InstrumentBase.log` (and +:attr:`~qcodes.instrument.VisaInstrument.visa_log`). + +``"shared"`` + All instruments share a single logger. +``"instrument"`` + Each instrument gets its own logger, named after the class of its + ``root_instrument`` followed by its ``name_parts``. This creates one logger + per driver class, one per instrument and one per submodule, each a child of + the previous one, so a level configured on any of them applies to + everything below it. +""" + class InstrumentBaseKWArgs(TypedDict): """ @@ -71,6 +86,28 @@ class InstrumentBase(MetadatableWithName, DelegateAttributes): """ + default_logger_scope: LoggerScope = "shared" + """ + Logger naming scope used for :attr:`log` (and + :attr:`~qcodes.instrument.VisaInstrument.visa_log`). + + By default all instruments share a single logger. Set this to + ``"instrument"`` on a driver class to give each of its instruments a logger + of its own, so that log levels and handlers can be configured per + instrument:: + + >>> MyDriver.default_logger_scope = "instrument" + + The resulting loggers are named + ``qcodes.instrument.instrument_base..``, so a + level can be set for a whole driver class, a single instrument, or a single + submodule. + + The scope is looked up on the :meth:`root_instrument` while the instrument + is created, so it applies to the whole instrument including its submodules, + and changing it afterwards has no effect on existing instruments. + """ + def __init__( self, name: str, @@ -118,9 +155,33 @@ def __init__( # This is needed for snapshot method to work self._meta_attrs = ["name", "label"] - self.log: InstrumentLoggerAdapter = get_instrument_logger(self, __name__) + self.log: InstrumentLoggerAdapter = get_instrument_logger( + self, self._logger_name(__name__) + ) self.log.debug("Created instrument: %s", self.full_name) + def _logger_name(self, base: str) -> str: + """ + Name of the logger to use, derived from ``base`` according to the + logger scope of the :meth:`root_instrument`. + + Under the ``"instrument"`` scope the name is built from the class of + the :meth:`root_instrument` followed by :meth:`name_parts`, e.g. + ``.MyDriver.myinst.ChanA``. That gives one node per driver class, + one per instrument and one per submodule, so a level can be configured + for a whole driver, a single instrument, or a single channel, and each + is inherited by everything below it. + + Args: + base: Name of the shared logger that this instrument would use if + no scope was configured. + + """ + root = self.root_instrument + if root.default_logger_scope == "instrument": + return ".".join((base, type(root).__name__, *self.name_parts)) + return base + @property def label(self) -> str: """ diff --git a/src/qcodes/instrument/ip_to_visa.py b/src/qcodes/instrument/ip_to_visa.py index 67d61acb421b..47ef12da7695 100644 --- a/src/qcodes/instrument/ip_to_visa.py +++ b/src/qcodes/instrument/ip_to_visa.py @@ -57,7 +57,7 @@ def __init__( newkwargs = {kw: val for (kw, val) in kwargs.items() if kw not in ipkwargs} Instrument.__init__(self, name, **newkwargs) - self.visa_log = get_instrument_logger(self, VISA_LOGGER) + self.visa_log = get_instrument_logger(self, self._logger_name(VISA_LOGGER)) ################################################## # __init__ of VisaInstrument diff --git a/src/qcodes/instrument/visa.py b/src/qcodes/instrument/visa.py index e14b43b173be..7f7169bd9d0e 100644 --- a/src/qcodes/instrument/visa.py +++ b/src/qcodes/instrument/visa.py @@ -167,7 +167,7 @@ def __init__( timeout = self.default_timeout super().__init__(name, **kwargs) - self.visa_log = get_instrument_logger(self, VISA_LOGGER) + self.visa_log = get_instrument_logger(self, self._logger_name(VISA_LOGGER)) self.timeout: Parameter[float | None, Self] = self.add_parameter( "timeout", diff --git a/tests/test_logger.py b/tests/test_logger.py index cacfdc5d594c..24afdd70fbb4 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -14,7 +14,12 @@ import qcodes as qc from qcodes import logger from qcodes.instrument import Instrument +from qcodes.instrument.visa import VISA_LOGGER from qcodes.instrument_drivers.american_magnetics import AMIModel430, AMIModel4303D +from qcodes.instrument_drivers.mock_instruments import ( + DummyChannelInstrument, + DummyInstrument, +) from qcodes.instrument_drivers.tektronix import TektronixAWG5208 from qcodes.logger.log_analysis import capture_dataframe from tests.drivers.test_lakeshore_372 import LakeshoreModel372Mock @@ -22,10 +27,15 @@ if TYPE_CHECKING: from collections.abc import Callable, Generator + from qcodes.instrument.instrument_base import LoggerScope + TEST_LOG_MESSAGE = "test log message" NUM_PYTEST_LOGGERS = 4 +SHARED_INSTRUMENT_LOGGER_NAME = "qcodes.instrument.instrument_base" +SHARED_VISA_LOGGER_NAME = VISA_LOGGER + _LOGGER = logging.getLogger(__name__) @@ -351,3 +361,227 @@ def test_get_level_code_with_invalid_type() -> None: """Only str and int can be converted to a logging level code.""" with pytest.raises(RuntimeError, match="get_level_code: Cannot to convert level"): logger.get_level_code(1.5) # type: ignore[arg-type] + + +class ScopedDummyInstrument(DummyInstrument): + """Dummy instrument that opts in to a per instrument logger.""" + + default_logger_scope: "LoggerScope" = "instrument" + + +class ScopedDummyChannelInstrument(DummyChannelInstrument): + """Instrument with channels that opts in to a per instrument logger.""" + + default_logger_scope: "LoggerScope" = "instrument" + + +class ScopedAMIModel430(AMIModel430): + """VISA instrument that opts in to a per instrument logger.""" + + default_logger_scope: "LoggerScope" = "instrument" + + +@pytest.fixture(name="restore_shared_logger_levels", autouse=True) +def _restore_shared_logger_levels() -> "Generator[None, None, None]": + """ + Restore the level of the shared loggers and of every logger below them. + + Scoped loggers stay in the logging registry for the lifetime of the + process, so a level set by one test would otherwise leak into the next. + """ + roots = (SHARED_INSTRUMENT_LOGGER_NAME, SHARED_VISA_LOGGER_NAME) + + def scoped_loggers() -> list[logging.Logger]: + return [ + logging.getLogger(name) + for name in (*roots, *logging.Logger.manager.loggerDict) + if any(name == root or name.startswith(f"{root}.") for root in roots) + ] + + levels = {logger_.name: logger_.level for logger_ in scoped_loggers()} + yield + for logger_ in scoped_loggers(): + logger_.setLevel(levels.get(logger_.name, logging.NOTSET)) + + +def test_default_logger_scope_is_shared() -> None: + """By default all instruments keep sharing a single logger.""" + inst_a = DummyInstrument("shared_scope_a") + inst_b = DummyInstrument("shared_scope_b") + + assert inst_a.log.logger.name == SHARED_INSTRUMENT_LOGGER_NAME + assert inst_a.log.logger is inst_b.log.logger + + +def test_instrument_scope_gives_one_logger_per_instrument() -> None: + inst_a = ScopedDummyInstrument("instrument_scope_a") + inst_b = ScopedDummyInstrument("instrument_scope_b") + + assert ( + inst_a.log.logger.name + == f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument.instrument_scope_a" + ) + assert ( + inst_b.log.logger.name + == f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument.instrument_scope_b" + ) + assert inst_a.log.logger is not inst_b.log.logger + + +def test_instrument_scope_isolates_logger_level() -> None: + """Changing the level of one scoped logger must not affect any other.""" + shared_logger = logging.getLogger(SHARED_INSTRUMENT_LOGGER_NAME) + shared_level = shared_logger.level + + inst_a = ScopedDummyInstrument("level_isolation_a") + inst_b = ScopedDummyInstrument("level_isolation_b") + inst_a.log.logger.setLevel(logging.DEBUG) + + assert inst_a.log.logger.level == logging.DEBUG + assert inst_b.log.logger.level == logging.NOTSET + assert shared_logger.level == shared_level + + +def test_scoped_logger_inherits_level_from_shared_logger() -> None: + """Opting in must not disconnect an instrument from existing configuration.""" + logging.getLogger(SHARED_INSTRUMENT_LOGGER_NAME).setLevel(logging.ERROR) + + inst = ScopedDummyInstrument("level_inheritance") + + assert inst.log.logger.level == logging.NOTSET + assert inst.log.logger.getEffectiveLevel() == logging.ERROR + + +def test_level_can_be_set_for_a_whole_driver_class() -> None: + """ + A level configured on the driver class node applies to every instrument of + that driver, including ones created afterwards, and not to other drivers. + """ + class_logger = logging.getLogger( + f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument" + ) + class_logger.setLevel(logging.DEBUG) + + # created only after the level was configured + inst_a = ScopedDummyInstrument("class_level_a") + inst_b = ScopedDummyInstrument("class_level_b") + other = ScopedDummyChannelInstrument("class_level_other") + + assert inst_a.log.logger.getEffectiveLevel() == logging.DEBUG + assert inst_b.log.logger.getEffectiveLevel() == logging.DEBUG + assert other.log.logger.getEffectiveLevel() != logging.DEBUG + + +def test_driver_class_level_applies_to_submodules() -> None: + class_logger = logging.getLogger( + f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyChannelInstrument" + ) + class_logger.setLevel(logging.DEBUG) + + inst = ScopedDummyChannelInstrument("class_level_channels") + channel = inst.submodules["A"] + + assert channel.log.logger.getEffectiveLevel() == logging.DEBUG # type: ignore[union-attr] + + +def test_instrument_level_overrides_driver_class_level() -> None: + """The per instrument node must stay more specific than the class node.""" + logging.getLogger( + f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument" + ).setLevel(logging.ERROR) + + inst_a = ScopedDummyInstrument("override_a") + inst_b = ScopedDummyInstrument("override_b") + inst_a.log.logger.setLevel(logging.DEBUG) + + assert inst_a.log.logger.getEffectiveLevel() == logging.DEBUG + assert inst_b.log.logger.getEffectiveLevel() == logging.ERROR + + +def test_scoped_logger_keeps_instrument_extra_info(caplog: LogCaptureFixture) -> None: + """Records must keep the info that ``filter_instrument`` relies on.""" + inst = ScopedDummyInstrument("extra_info") + + with caplog.at_level(logging.INFO): + inst.log.info(TEST_LOG_MESSAGE) + + record = caplog.records[-1] + assert record.name == inst.log.logger.name + assert record.__dict__["instrument_name"] == "extra_info" + assert record.__dict__["instrument_type"] == "ScopedDummyInstrument" + + +def test_scoped_logger_is_filterable_by_instrument() -> None: + inst = ScopedDummyInstrument("filterable") + other = ScopedDummyInstrument("not_filterable") + + with ( + logger.LogCapture(level=logging.DEBUG) as logs, + logger.filter_instrument(inst, handler=logs.string_handler), + ): + inst.log.info(TEST_LOG_MESSAGE) + other.log.info(TEST_LOG_MESSAGE) + + assert "[filterable(ScopedDummyInstrument)]" in logs.value + assert "[not_filterable(ScopedDummyInstrument)]" not in logs.value + + +def test_submodule_logger_is_child_of_instrument_logger() -> None: + """A submodule must sit below its parent in the logger hierarchy.""" + inst = ScopedDummyChannelInstrument("scoped_channels") + channel = inst.submodules["A"] + + assert ( + channel.log.logger.name # type: ignore[union-attr] + == f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyChannelInstrument" + ".scoped_channels.ChanA" + ) + assert channel.log.logger is not inst.log.logger # type: ignore[union-attr] + + +def test_instrument_level_applies_to_its_submodules() -> None: + """Setting the level on an instrument must also cover its channels.""" + inst = ScopedDummyChannelInstrument("level_to_channels") + channel = inst.submodules["A"] + + inst.log.logger.setLevel(logging.DEBUG) + + assert channel.log.logger.getEffectiveLevel() == logging.DEBUG # type: ignore[union-attr] + + +def test_submodule_of_unscoped_instrument_uses_shared_logger() -> None: + inst = DummyChannelInstrument("unscoped_channels") + channel = inst.submodules["A"] + + assert channel.log.logger.name == SHARED_INSTRUMENT_LOGGER_NAME # type: ignore[union-attr] + + +def test_visa_log_is_shared_by_default() -> None: + inst = AMIModel430( + "shared_visa_log", + address="GPIB::1::INSTR", + pyvisa_sim_file="AMI430.yaml", + terminator="\n", + ) + + assert inst.visa_log.logger.name == SHARED_VISA_LOGGER_NAME + assert inst.log.logger.name == SHARED_INSTRUMENT_LOGGER_NAME + + +def test_visa_log_follows_instrument_scope() -> None: + inst = ScopedAMIModel430( + "scoped_visa_log", + address="GPIB::1::INSTR", + pyvisa_sim_file="AMI430.yaml", + terminator="\n", + ) + + assert ( + inst.visa_log.logger.name + == f"{SHARED_VISA_LOGGER_NAME}.ScopedAMIModel430.scoped_visa_log" + ) + assert ( + inst.log.logger.name + == f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedAMIModel430.scoped_visa_log" + ) + assert inst.visa_log.logger is not inst.log.logger From 4904ea87722537c3110bc30bc07616b77568c2aa Mon Sep 17 00:00:00 2001 From: Yan Date: Mon, 21 Sep 2026 15:47:28 +0200 Subject: [PATCH 2/7] add newsfragment --- docs/changes/newsfragments/8509.new | 21 +++++++++++++++++++++ 1 file changed, 21 insertions(+) create mode 100644 docs/changes/newsfragments/8509.new diff --git a/docs/changes/newsfragments/8509.new b/docs/changes/newsfragments/8509.new new file mode 100644 index 000000000000..54911b94e66c --- /dev/null +++ b/docs/changes/newsfragments/8509.new @@ -0,0 +1,21 @@ +Instruments can now opt in to a logger of their own, rather than sharing a +single logger with every other instrument in the process. Setting the class +attribute ``default_logger_scope`` to ``"instrument"`` makes ``Instrument.log`` +(and ``VisaInstrument.visa_log``) use a logger named after the driver class and +the instrument's ``name_parts``, so that levels, handlers and ``propagate`` can +be configured per instrument:: + + MyDriver.default_logger_scope = "instrument" + +The scoped loggers mirror the instrument hierarchy, for example +``qcodes.instrument.instrument_base.MyDriver`` for the driver, +``qcodes.instrument.instrument_base.MyDriver.myinst`` for one of its +instruments and ``qcodes.instrument.instrument_base.MyDriver.myinst.ChanA`` for +one of that instrument's channels. A level can therefore be set for a whole +driver class, a single instrument or a single channel, and is inherited by +everything below it. Setting the level for a whole driver also works before any +of its instruments exist, so it can be configured via ``logger_levels`` in +``qcodesrc.json``. + +The default is unchanged: without opting in, all instruments keep sharing one +logger exactly as before. From 944512b3d20e985a3f3313dd52f2560e92496750 Mon Sep 17 00:00:00 2001 From: Yan Date: Mon, 21 Sep 2026 15:51:03 +0200 Subject: [PATCH 3/7] Rename newsfragment to match PR number Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/changes/newsfragments/{8509.new => 8523.new} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename docs/changes/newsfragments/{8509.new => 8523.new} (100%) diff --git a/docs/changes/newsfragments/8509.new b/docs/changes/newsfragments/8523.new similarity index 100% rename from docs/changes/newsfragments/8509.new rename to docs/changes/newsfragments/8523.new From d2581a953a4fe33a28491beff9d83a83f29de13f Mon Sep 17 00:00:00 2001 From: Yan Date: Thu, 1 Oct 2026 13:21:11 +0200 Subject: [PATCH 4/7] Document logging registry growth caveat in the logging example The permanent logging registry growth under the "instrument" scope was only described in the PR discussion, not in the user facing documentation. Add it to the caveats of the logging example notebook, together with the mitigation that instruments with stable names reuse their existing logger. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- docs/examples/logging/logging_example.ipynb | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/docs/examples/logging/logging_example.ipynb b/docs/examples/logging/logging_example.ipynb index 35beb597c4f7..2231318d28a8 100644 --- a/docs/examples/logging/logging_example.ipynb +++ b/docs/examples/logging/logging_example.ipynb @@ -416,10 +416,11 @@ "cell_type": "markdown", "metadata": {}, "source": [ - "Two things are worth keeping in mind:\n", + "A few things are worth keeping in mind:\n", "\n", "* QCoDeS attaches its console and file handlers to the **root** logger and those handlers have their own levels. Lowering the level of an instrument logger to `DEBUG` only becomes visible if the handler level lets the record through, so combine it with `console_level` or `handler_level` as shown above.\n", "* Setting `instrument.log.logger.propagate = False` silences that instrument everywhere, including in the QCoDeS log file.\n", + "* Python's logging registry keeps every logger it creates for the lifetime of the process, and closing an instrument does not release its logger. Instruments with stable names reuse their existing logger, so a normal station is unaffected, but a workload that repeatedly creates instruments under *dynamically generated* names accumulates one registry entry per distinct name while this scope is enabled.\n", "\n", "Note also that parameters log through the logger of their *root* instrument, so messages from a channel parameter appear on the root instrument's logger rather than on the channel's own logger." ] From 14e13a71315f445f26f24d1984a962fb89cf50e6 Mon Sep 17 00:00:00 2001 From: Yan Date: Thu, 1 Oct 2026 13:45:27 +0200 Subject: [PATCH 5/7] Clarify what propagate = False does in the logging example --- docs/examples/logging/logging_example.ipynb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/examples/logging/logging_example.ipynb b/docs/examples/logging/logging_example.ipynb index 2231318d28a8..b8afef017ec3 100644 --- a/docs/examples/logging/logging_example.ipynb +++ b/docs/examples/logging/logging_example.ipynb @@ -419,7 +419,7 @@ "A few things are worth keeping in mind:\n", "\n", "* QCoDeS attaches its console and file handlers to the **root** logger and those handlers have their own levels. Lowering the level of an instrument logger to `DEBUG` only becomes visible if the handler level lets the record through, so combine it with `console_level` or `handler_level` as shown above.\n", - "* Setting `instrument.log.logger.propagate = False` silences that instrument everywhere, including in the QCoDeS log file.\n", + "* Setting `instrument.log.logger.propagate = False` only stops records from reaching *ancestor* handlers, including QCoDeS' root handlers — it is not a general mute. Handlers attached directly to that logger still run, and VISA records travel through the separate `instrument.visa_log`, which propagates independently. Submodule loggers are descendants, so their records are stopped at the instrument as well.\n", "* Python's logging registry keeps every logger it creates for the lifetime of the process, and closing an instrument does not release its logger. Instruments with stable names reuse their existing logger, so a normal station is unaffected, but a workload that repeatedly creates instruments under *dynamically generated* names accumulates one registry entry per distinct name while this scope is enabled.\n", "\n", "Note also that parameters log through the logger of their *root* instrument, so messages from a channel parameter appear on the root instrument's logger rather than on the channel's own logger." From ea454fa359438cb1604f967b4e5c5b2d013ebc93 Mon Sep 17 00:00:00 2001 From: Yan Date: Thu, 1 Oct 2026 16:22:25 +0200 Subject: [PATCH 6/7] add ClassVar LoggerScope --- docs/changes/newsfragments/8523.new | 3 ++- src/qcodes/instrument/instrument_base.py | 29 ++++++++++++++--------- tests/test_logger.py | 30 ++++++++++++++++++++---- 3 files changed, 45 insertions(+), 17 deletions(-) diff --git a/docs/changes/newsfragments/8523.new b/docs/changes/newsfragments/8523.new index 54911b94e66c..f0e94cb2e5e9 100644 --- a/docs/changes/newsfragments/8523.new +++ b/docs/changes/newsfragments/8523.new @@ -5,7 +5,8 @@ attribute ``default_logger_scope`` to ``"instrument"`` makes ``Instrument.log`` the instrument's ``name_parts``, so that levels, handlers and ``propagate`` can be configured per instrument:: - MyDriver.default_logger_scope = "instrument" + class MyDriver(VisaInstrument): + default_logger_scope = "instrument" The scoped loggers mirror the instrument hierarchy, for example ``qcodes.instrument.instrument_base.MyDriver`` for the driver, diff --git a/src/qcodes/instrument/instrument_base.py b/src/qcodes/instrument/instrument_base.py index 2a3522ae1c71..9c32df4f0adf 100644 --- a/src/qcodes/instrument/instrument_base.py +++ b/src/qcodes/instrument/instrument_base.py @@ -86,26 +86,28 @@ class InstrumentBase(MetadatableWithName, DelegateAttributes): """ - default_logger_scope: LoggerScope = "shared" + default_logger_scope: ClassVar[LoggerScope] = "shared" """ Logger naming scope used for :attr:`log` (and :attr:`~qcodes.instrument.VisaInstrument.visa_log`). By default all instruments share a single logger. Set this to - ``"instrument"`` on a driver class to give each of its instruments a logger - of its own, so that log levels and handlers can be configured per - instrument:: + ``"instrument"`` in the definition of a driver class to give each of its + instruments a logger of its own, so that log levels and handlers can be + configured per instrument:: - >>> MyDriver.default_logger_scope = "instrument" + class MyDriver(VisaInstrument): + default_logger_scope = "instrument" The resulting loggers are named ``qcodes.instrument.instrument_base..``, so a level can be set for a whole driver class, a single instrument, or a single submodule. - The scope is looked up on the :meth:`root_instrument` while the instrument - is created, so it applies to the whole instrument including its submodules, - and changing it afterwards has no effect on existing instruments. + The scope is resolved once, when the :meth:`root_instrument` is created, + and every submodule uses the scope of its root. It therefore applies to the + whole instrument, including submodules added later, and changing it + afterwards has no effect on existing instruments. """ def __init__( @@ -155,6 +157,11 @@ def __init__( # This is needed for snapshot method to work self._meta_attrs = ["name", "label"] + root = self.root_instrument + self._logger_scope: LoggerScope = ( + type(self).default_logger_scope if root is self else root._logger_scope + ) + self.log: InstrumentLoggerAdapter = get_instrument_logger( self, self._logger_name(__name__) ) @@ -163,7 +170,7 @@ def __init__( def _logger_name(self, base: str) -> str: """ Name of the logger to use, derived from ``base`` according to the - logger scope of the :meth:`root_instrument`. + logger scope resolved when the :meth:`root_instrument` was created. Under the ``"instrument"`` scope the name is built from the class of the :meth:`root_instrument` followed by :meth:`name_parts`, e.g. @@ -177,8 +184,8 @@ def _logger_name(self, base: str) -> str: no scope was configured. """ - root = self.root_instrument - if root.default_logger_scope == "instrument": + if self._logger_scope == "instrument": + root = self.root_instrument return ".".join((base, type(root).__name__, *self.name_parts)) return base diff --git a/tests/test_logger.py b/tests/test_logger.py index 24afdd70fbb4..4c59546faf2a 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -5,7 +5,7 @@ import logging import os from copy import copy -from typing import TYPE_CHECKING +from typing import TYPE_CHECKING, ClassVar import numpy as np import pytest @@ -17,6 +17,7 @@ from qcodes.instrument.visa import VISA_LOGGER from qcodes.instrument_drivers.american_magnetics import AMIModel430, AMIModel4303D from qcodes.instrument_drivers.mock_instruments import ( + DummyChannel, DummyChannelInstrument, DummyInstrument, ) @@ -366,19 +367,19 @@ def test_get_level_code_with_invalid_type() -> None: class ScopedDummyInstrument(DummyInstrument): """Dummy instrument that opts in to a per instrument logger.""" - default_logger_scope: "LoggerScope" = "instrument" + default_logger_scope: ClassVar["LoggerScope"] = "instrument" class ScopedDummyChannelInstrument(DummyChannelInstrument): """Instrument with channels that opts in to a per instrument logger.""" - default_logger_scope: "LoggerScope" = "instrument" + default_logger_scope: ClassVar["LoggerScope"] = "instrument" class ScopedAMIModel430(AMIModel430): """VISA instrument that opts in to a per instrument logger.""" - default_logger_scope: "LoggerScope" = "instrument" + default_logger_scope: ClassVar["LoggerScope"] = "instrument" @pytest.fixture(name="restore_shared_logger_levels", autouse=True) @@ -457,6 +458,8 @@ def test_level_can_be_set_for_a_whole_driver_class() -> None: A level configured on the driver class node applies to every instrument of that driver, including ones created afterwards, and not to other drivers. """ + # pin the shared level so the result does not depend on ambient logging config + logging.getLogger(SHARED_INSTRUMENT_LOGGER_NAME).setLevel(logging.WARNING) class_logger = logging.getLogger( f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument" ) @@ -469,7 +472,7 @@ def test_level_can_be_set_for_a_whole_driver_class() -> None: assert inst_a.log.logger.getEffectiveLevel() == logging.DEBUG assert inst_b.log.logger.getEffectiveLevel() == logging.DEBUG - assert other.log.logger.getEffectiveLevel() != logging.DEBUG + assert other.log.logger.getEffectiveLevel() == logging.WARNING def test_driver_class_level_applies_to_submodules() -> None: @@ -484,6 +487,23 @@ def test_driver_class_level_applies_to_submodules() -> None: assert channel.log.logger.getEffectiveLevel() == logging.DEBUG # type: ignore[union-attr] +def test_scope_is_fixed_when_root_is_created( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """ + Changing the scope after the root was created must not split the hierarchy + for submodules that are added later. + """ + inst = ScopedDummyChannelInstrument("fixed_scope") + monkeypatch.setattr(ScopedDummyChannelInstrument, "default_logger_scope", "shared") + + channel = DummyChannel(inst, "late_channel", "Z") + inst.add_submodule("late_channel", channel) + + assert channel.log.logger.name == f"{inst.log.logger.name}.late_channel" + assert channel.log.logger.parent is inst.log.logger + + def test_instrument_level_overrides_driver_class_level() -> None: """The per instrument node must stay more specific than the class node.""" logging.getLogger( From e479ab4eac401927afaea4e5aff7ce23892561ab Mon Sep 17 00:00:00 2001 From: Yanick Mampaey Date: Tue, 6 Oct 2026 16:56:25 +0200 Subject: [PATCH 7/7] Use module-qualified scoped logger names Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 2a787d42-150d-48cb-8bc7-47add23e17ad --- docs/changes/newsfragments/8523.new | 24 ++-- docs/examples/logging/logging_example.ipynb | 18 ++- src/qcodes/instrument/instrument_base.py | 48 +++---- src/qcodes/instrument/ip_to_visa.py | 4 +- src/qcodes/instrument/visa.py | 4 +- tests/test_logger.py | 140 +++++++++++++++----- 6 files changed, 166 insertions(+), 72 deletions(-) diff --git a/docs/changes/newsfragments/8523.new b/docs/changes/newsfragments/8523.new index f0e94cb2e5e9..7302f5836e26 100644 --- a/docs/changes/newsfragments/8523.new +++ b/docs/changes/newsfragments/8523.new @@ -8,15 +8,21 @@ be configured per instrument:: class MyDriver(VisaInstrument): default_logger_scope = "instrument" -The scoped loggers mirror the instrument hierarchy, for example -``qcodes.instrument.instrument_base.MyDriver`` for the driver, -``qcodes.instrument.instrument_base.MyDriver.myinst`` for one of its -instruments and ``qcodes.instrument.instrument_base.MyDriver.myinst.ChanA`` for -one of that instrument's channels. A level can therefore be set for a whole -driver class, a single instrument or a single channel, and is inherited by -everything below it. Setting the level for a whole driver also works before any -of its instruments exist, so it can be configured via ``logger_levels`` in -``qcodesrc.json``. +The scoped loggers mirror the instrument hierarchy below the module-qualified +driver class, for example ``vendor.driver.MyDriver`` for the driver, +``vendor.driver.MyDriver.myinst`` for one of its instruments and +``vendor.driver.MyDriver.myinst.ChanA`` for one of that instrument's channels. +VISA traffic uses the parallel +``vendor.driver.MyDriver.com.visa.myinst`` branch. A level can therefore be set +for a whole driver class, a single instrument or a single channel, and is +inherited by everything below it. Setting the level for a whole driver also +works before any of its instruments exist, so it can be configured via +``logger_levels`` in ``qcodesrc.json``. + +Because module-qualified scoped loggers are no longer below +``qcodes.instrument.instrument_base``, opted-in drivers do not inherit levels +configured on that shared logger. Configure the module-qualified driver class +logger instead. The default is unchanged: without opting in, all instruments keep sharing one logger exactly as before. diff --git a/docs/examples/logging/logging_example.ipynb b/docs/examples/logging/logging_example.ipynb index b8afef017ec3..f1b113a9a06f 100644 --- a/docs/examples/logging/logging_example.ipynb +++ b/docs/examples/logging/logging_example.ipynb @@ -366,7 +366,7 @@ "cell_type": "markdown", "metadata": {}, "source": [ - "The logger name is built from the driver class followed by the instrument's `name_parts`, so scoped loggers mirror the instrument hierarchy: a submodule logger is a child of its instrument's logger, which is a child of a per-driver-class logger, which is a child of the shared logger. Any level configured on `qcodes.instrument.instrument_base`, for instance via `logger_levels` in `qcodesrc.json`, is therefore still inherited.\n", + "The logger name is built from the root driver's module-qualified class followed by the instrument's `name_parts`, so scoped loggers mirror the instrument hierarchy. For example, `AMIModel430` uses the class logger `qcodes.instrument_drivers.american_magnetics.AMI430_visa.AMIModel430`, an instrument named `mag_x` uses `qcodes.instrument_drivers.american_magnetics.AMI430_visa.AMIModel430.mag_x`, and its VISA traffic uses `qcodes.instrument_drivers.american_magnetics.AMI430_visa.AMIModel430.com.visa.mag_x`. A channel logger is a child of its instrument logger. Opted-in drivers are no longer children of `qcodes.instrument.instrument_base`, so levels configured there are not inherited.\n", "\n", "The scope is looked up on the root instrument when the instrument is created, so it has to be set before instantiating the driver and applies to the whole instrument.\n", "\n", @@ -389,7 +389,11 @@ "cell_type": "markdown", "metadata": {}, "source": [ - "Because there is a node per driver class, you can also raise the level for *every* instrument of a driver at once, which is typically what you want while developing or debugging that driver. This works for instruments that do not exist yet, so it can equally well be put in the `logger_levels` section of `qcodesrc.json`:" + "Because there is a node per module-qualified driver class, you can also raise the level for *every* instrument of a driver at once, which is typically what you want while developing or debugging that driver. This works for instruments that do not exist yet, so it can equally well be put in the `logger_levels` section of `qcodesrc.json`:\n", + "\n", + "```json\n", + "\"logger_levels\": {\"qcodes.instrument_drivers.american_magnetics.AMI430_visa.AMIModel430\": \"DEBUG\"}\n", + "```" ] }, { @@ -398,9 +402,9 @@ "metadata": {}, "outputs": [], "source": [ - "logging.getLogger(\"qcodes.instrument.instrument_base.ScopedAMIModel430\").setLevel(\n", - " logging.DEBUG\n", - ")\n", + "logging.getLogger(\n", + " f\"{ScopedAMIModel430.__module__}.{ScopedAMIModel430.__qualname__}\"\n", + ").setLevel(logging.DEBUG)\n", "\n", "mag_v = ScopedAMIModel430(\n", " \"v\", address=\"GPIB::2::INSTR\", pyvisa_sim_file=\"AMI430.yaml\", terminator=\"\\n\"\n", @@ -420,7 +424,11 @@ "\n", "* QCoDeS attaches its console and file handlers to the **root** logger and those handlers have their own levels. Lowering the level of an instrument logger to `DEBUG` only becomes visible if the handler level lets the record through, so combine it with `console_level` or `handler_level` as shown above.\n", "* Setting `instrument.log.logger.propagate = False` only stops records from reaching *ancestor* handlers, including QCoDeS' root handlers — it is not a general mute. Handlers attached directly to that logger still run, and VISA records travel through the separate `instrument.visa_log`, which propagates independently. Submodule loggers are descendants, so their records are stopped at the instrument as well.\n", + "* A level set on one instrument logger, such as `...AMIModel430.mag_x`, does not reach that instrument's VISA logger at `...AMIModel430.com.visa.mag_x`. Set the driver class level to cover both branches, or configure both instrument loggers.\n", + "* An instrument named `com` is the parent of the driver's `com.visa` branch. Avoid that instrument name when scoped logging is enabled.\n", + "* The logger starts with the module where the driver class is defined. Third-party and notebook drivers may therefore start with `qcodes_contrib_drivers`, `__main__`, or another name rather than `qcodes`. Classes defined inside functions include `` in their logger name.\n", "* Python's logging registry keeps every logger it creates for the lifetime of the process, and closing an instrument does not release its logger. Instruments with stable names reuse their existing logger, so a normal station is unaffected, but a workload that repeatedly creates instruments under *dynamically generated* names accumulates one registry entry per distinct name while this scope is enabled.\n", + "* Module-qualified logger names can be long and are shown in the `%(name)s` field of QCoDeS log output.\n", "\n", "Note also that parameters log through the logger of their *root* instrument, so messages from a channel parameter appear on the root instrument's logger rather than on the channel's own logger." ] diff --git a/src/qcodes/instrument/instrument_base.py b/src/qcodes/instrument/instrument_base.py index 9c32df4f0adf..8c752d787cdf 100644 --- a/src/qcodes/instrument/instrument_base.py +++ b/src/qcodes/instrument/instrument_base.py @@ -45,10 +45,10 @@ ``"shared"`` All instruments share a single logger. ``"instrument"`` - Each instrument gets its own logger, named after the class of its - ``root_instrument`` followed by its ``name_parts``. This creates one logger - per driver class, one per instrument and one per submodule, each a child of - the previous one, so a level configured on any of them applies to + Each instrument gets its own logger, named after the module-qualified class + of its ``root_instrument`` followed by its ``name_parts``. This creates one + logger per driver class, one per instrument and one per submodule, each a + child of the previous one, so a level configured on any of them applies to everything below it. """ @@ -100,9 +100,8 @@ class MyDriver(VisaInstrument): default_logger_scope = "instrument" The resulting loggers are named - ``qcodes.instrument.instrument_base..``, so a - level can be set for a whole driver class, a single instrument, or a single - submodule. + ``..``, so a level can be set for a + whole driver class, a single instrument, or a single submodule. The scope is resolved once, when the :meth:`root_instrument` is created, and every submodule uses the scope of its root. It therefore applies to the @@ -158,36 +157,39 @@ def __init__( self._meta_attrs = ["name", "label"] root = self.root_instrument - self._logger_scope: LoggerScope = ( - type(self).default_logger_scope if root is self else root._logger_scope - ) + if root is self: + self._logger_scope: LoggerScope = type(self).default_logger_scope self.log: InstrumentLoggerAdapter = get_instrument_logger( self, self._logger_name(__name__) ) self.log.debug("Created instrument: %s", self.full_name) - def _logger_name(self, base: str) -> str: + def _logger_name(self, default: str, *branch: str) -> str: """ - Name of the logger to use, derived from ``base`` according to the + Name of the logger to use, derived from ``default`` according to the logger scope resolved when the :meth:`root_instrument` was created. Under the ``"instrument"`` scope the name is built from the class of - the :meth:`root_instrument` followed by :meth:`name_parts`, e.g. - ``.MyDriver.myinst.ChanA``. That gives one node per driver class, - one per instrument and one per submodule, so a level can be configured - for a whole driver, a single instrument, or a single channel, and each - is inherited by everything below it. + the :meth:`root_instrument`, an optional branch, and + :meth:`name_parts`, e.g. ``vendor.driver.MyDriver.myinst.ChanA`` or + ``vendor.driver.MyDriver.com.visa.myinst``. That gives one node per + driver class, one per instrument and one per submodule, so a level can + be configured for a whole driver, a single instrument, or a single + channel, and each is inherited by everything below it. Args: - base: Name of the shared logger that this instrument would use if - no scope was configured. + default: Name of the shared logger that this instrument would use + if no scope was configured. + branch: Optional branch between the driver class and the + instrument name. """ - if self._logger_scope == "instrument": - root = self.root_instrument - return ".".join((base, type(root).__name__, *self.name_parts)) - return base + root = self.root_instrument + if root._logger_scope != "instrument": + return default + cls = type(root) + return ".".join((cls.__module__, cls.__qualname__, *branch, *self.name_parts)) @property def label(self) -> str: diff --git a/src/qcodes/instrument/ip_to_visa.py b/src/qcodes/instrument/ip_to_visa.py index 47ef12da7695..b7bfc3474167 100644 --- a/src/qcodes/instrument/ip_to_visa.py +++ b/src/qcodes/instrument/ip_to_visa.py @@ -57,7 +57,9 @@ def __init__( newkwargs = {kw: val for (kw, val) in kwargs.items() if kw not in ipkwargs} Instrument.__init__(self, name, **newkwargs) - self.visa_log = get_instrument_logger(self, self._logger_name(VISA_LOGGER)) + self.visa_log = get_instrument_logger( + self, self._logger_name(VISA_LOGGER, "com", "visa") + ) ################################################## # __init__ of VisaInstrument diff --git a/src/qcodes/instrument/visa.py b/src/qcodes/instrument/visa.py index 7f7169bd9d0e..fb4b05c3e07e 100644 --- a/src/qcodes/instrument/visa.py +++ b/src/qcodes/instrument/visa.py @@ -167,7 +167,9 @@ def __init__( timeout = self.default_timeout super().__init__(name, **kwargs) - self.visa_log = get_instrument_logger(self, self._logger_name(VISA_LOGGER)) + self.visa_log = get_instrument_logger( + self, self._logger_name(VISA_LOGGER, "com", "visa") + ) self.timeout: Parameter[float | None, Self] = self.add_parameter( "timeout", diff --git a/tests/test_logger.py b/tests/test_logger.py index 4c59546faf2a..c0d172ac539a 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -14,6 +14,7 @@ import qcodes as qc from qcodes import logger from qcodes.instrument import Instrument +from qcodes.instrument.ip_to_visa import IPToVisa from qcodes.instrument.visa import VISA_LOGGER from qcodes.instrument_drivers.american_magnetics import AMIModel430, AMIModel4303D from qcodes.instrument_drivers.mock_instruments import ( @@ -40,6 +41,19 @@ _LOGGER = logging.getLogger(__name__) +def scoped_class_logger_name(cls: type[object]) -> str: + return f"{cls.__module__}.{cls.__qualname__}" + + +def logger_is_descendant(logger_: logging.Logger, ancestor: logging.Logger) -> bool: + parent = logger_.parent + while parent is not None: + if parent is ancestor: + return True + parent = parent.parent + return False + + @pytest.fixture(autouse=True) def cleanup_started_logger() -> "Generator[None, None, None]": # cleanup state left by a test calling start_logger @@ -382,15 +396,27 @@ class ScopedAMIModel430(AMIModel430): default_logger_scope: ClassVar["LoggerScope"] = "instrument" +class ScopedIPToVisa(IPToVisa): + """IP-to-VISA instrument that opts in to a per instrument logger.""" + + default_logger_scope: ClassVar["LoggerScope"] = "instrument" + + @pytest.fixture(name="restore_shared_logger_levels", autouse=True) def _restore_shared_logger_levels() -> "Generator[None, None, None]": """ - Restore the level of the shared loggers and of every logger below them. + Restore levels of the shared and test-scoped loggers. Scoped loggers stay in the logging registry for the lifetime of the process, so a level set by one test would otherwise leak into the next. """ - roots = (SHARED_INSTRUMENT_LOGGER_NAME, SHARED_VISA_LOGGER_NAME) + roots = ( + SHARED_INSTRUMENT_LOGGER_NAME, + SHARED_VISA_LOGGER_NAME, + __name__, + "test_logger_module_a", + "test_logger_module_b", + ) def scoped_loggers() -> list[logging.Logger]: return [ @@ -417,22 +443,17 @@ def test_default_logger_scope_is_shared() -> None: def test_instrument_scope_gives_one_logger_per_instrument() -> None: inst_a = ScopedDummyInstrument("instrument_scope_a") inst_b = ScopedDummyInstrument("instrument_scope_b") + class_logger_name = scoped_class_logger_name(ScopedDummyInstrument) - assert ( - inst_a.log.logger.name - == f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument.instrument_scope_a" - ) - assert ( - inst_b.log.logger.name - == f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument.instrument_scope_b" - ) + assert inst_a.log.logger.name == f"{class_logger_name}.instrument_scope_a" + assert inst_b.log.logger.name == f"{class_logger_name}.instrument_scope_b" assert inst_a.log.logger is not inst_b.log.logger def test_instrument_scope_isolates_logger_level() -> None: """Changing the level of one scoped logger must not affect any other.""" - shared_logger = logging.getLogger(SHARED_INSTRUMENT_LOGGER_NAME) - shared_level = shared_logger.level + class_logger = logging.getLogger(scoped_class_logger_name(ScopedDummyInstrument)) + class_logger.setLevel(logging.WARNING) inst_a = ScopedDummyInstrument("level_isolation_a") inst_b = ScopedDummyInstrument("level_isolation_b") @@ -440,17 +461,18 @@ def test_instrument_scope_isolates_logger_level() -> None: assert inst_a.log.logger.level == logging.DEBUG assert inst_b.log.logger.level == logging.NOTSET - assert shared_logger.level == shared_level + assert inst_b.log.logger.getEffectiveLevel() == logging.WARNING -def test_scoped_logger_inherits_level_from_shared_logger() -> None: - """Opting in must not disconnect an instrument from existing configuration.""" +def test_scoped_logger_does_not_inherit_level_from_shared_logger() -> None: + """Opted-in drivers leave the shared instrument logger hierarchy.""" + logging.getLogger(__name__).setLevel(logging.WARNING) logging.getLogger(SHARED_INSTRUMENT_LOGGER_NAME).setLevel(logging.ERROR) inst = ScopedDummyInstrument("level_inheritance") assert inst.log.logger.level == logging.NOTSET - assert inst.log.logger.getEffectiveLevel() == logging.ERROR + assert inst.log.logger.getEffectiveLevel() == logging.WARNING def test_level_can_be_set_for_a_whole_driver_class() -> None: @@ -458,11 +480,8 @@ def test_level_can_be_set_for_a_whole_driver_class() -> None: A level configured on the driver class node applies to every instrument of that driver, including ones created afterwards, and not to other drivers. """ - # pin the shared level so the result does not depend on ambient logging config - logging.getLogger(SHARED_INSTRUMENT_LOGGER_NAME).setLevel(logging.WARNING) - class_logger = logging.getLogger( - f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument" - ) + logging.getLogger(__name__).setLevel(logging.WARNING) + class_logger = logging.getLogger(scoped_class_logger_name(ScopedDummyInstrument)) class_logger.setLevel(logging.DEBUG) # created only after the level was configured @@ -476,8 +495,9 @@ def test_level_can_be_set_for_a_whole_driver_class() -> None: def test_driver_class_level_applies_to_submodules() -> None: + logging.getLogger(__name__).setLevel(logging.WARNING) class_logger = logging.getLogger( - f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyChannelInstrument" + scoped_class_logger_name(ScopedDummyChannelInstrument) ) class_logger.setLevel(logging.DEBUG) @@ -506,9 +526,9 @@ def test_scope_is_fixed_when_root_is_created( def test_instrument_level_overrides_driver_class_level() -> None: """The per instrument node must stay more specific than the class node.""" - logging.getLogger( - f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyInstrument" - ).setLevel(logging.ERROR) + logging.getLogger(scoped_class_logger_name(ScopedDummyInstrument)).setLevel( + logging.ERROR + ) inst_a = ScopedDummyInstrument("override_a") inst_b = ScopedDummyInstrument("override_b") @@ -521,6 +541,7 @@ def test_instrument_level_overrides_driver_class_level() -> None: def test_scoped_logger_keeps_instrument_extra_info(caplog: LogCaptureFixture) -> None: """Records must keep the info that ``filter_instrument`` relies on.""" inst = ScopedDummyInstrument("extra_info") + inst.log.logger.setLevel(logging.INFO) with caplog.at_level(logging.INFO): inst.log.info(TEST_LOG_MESSAGE) @@ -534,6 +555,8 @@ def test_scoped_logger_keeps_instrument_extra_info(caplog: LogCaptureFixture) -> def test_scoped_logger_is_filterable_by_instrument() -> None: inst = ScopedDummyInstrument("filterable") other = ScopedDummyInstrument("not_filterable") + inst.log.logger.setLevel(logging.INFO) + other.log.logger.setLevel(logging.INFO) with ( logger.LogCapture(level=logging.DEBUG) as logs, @@ -553,10 +576,10 @@ def test_submodule_logger_is_child_of_instrument_logger() -> None: assert ( channel.log.logger.name # type: ignore[union-attr] - == f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedDummyChannelInstrument" + == f"{scoped_class_logger_name(ScopedDummyChannelInstrument)}" ".scoped_channels.ChanA" ) - assert channel.log.logger is not inst.log.logger # type: ignore[union-attr] + assert channel.log.logger.parent is inst.log.logger # type: ignore[union-attr] def test_instrument_level_applies_to_its_submodules() -> None: @@ -589,6 +612,7 @@ def test_visa_log_is_shared_by_default() -> None: def test_visa_log_follows_instrument_scope() -> None: + class_logger_name = scoped_class_logger_name(ScopedAMIModel430) inst = ScopedAMIModel430( "scoped_visa_log", address="GPIB::1::INSTR", @@ -596,12 +620,62 @@ def test_visa_log_follows_instrument_scope() -> None: terminator="\n", ) - assert ( - inst.visa_log.logger.name - == f"{SHARED_VISA_LOGGER_NAME}.ScopedAMIModel430.scoped_visa_log" + assert inst.visa_log.logger.name == f"{class_logger_name}.com.visa.scoped_visa_log" + assert inst.log.logger.name == f"{class_logger_name}.scoped_visa_log" + assert inst.visa_log.logger is not inst.log.logger + + +def test_driver_class_logger_is_parent_of_log_and_visa_branches() -> None: + class_logger = logging.getLogger(scoped_class_logger_name(ScopedAMIModel430)) + visa_class_logger = logging.getLogger(f"{class_logger.name}.com.visa") + inst = ScopedAMIModel430( + "scoped_logger_parents", + address="GPIB::1::INSTR", + pyvisa_sim_file="AMI430.yaml", + terminator="\n", + ) + + assert inst.log.logger.parent is class_logger + assert logger_is_descendant(visa_class_logger, class_logger) + assert inst.visa_log.logger.parent is visa_class_logger + + +def test_same_class_name_in_different_modules_has_distinct_loggers() -> None: + driver_a: type[DummyInstrument] = type( + "DuplicateDriver", + (DummyInstrument,), + { + "__module__": "test_logger_module_a", + "default_logger_scope": "instrument", + }, ) + driver_b: type[DummyInstrument] = type( + "DuplicateDriver", + (DummyInstrument,), + { + "__module__": "test_logger_module_b", + "default_logger_scope": "instrument", + }, + ) + + inst_a = driver_a("duplicate_a") + inst_b = driver_b("duplicate_b") + + assert inst_a.log.logger.name == "test_logger_module_a.DuplicateDriver.duplicate_a" + assert inst_b.log.logger.name == "test_logger_module_b.DuplicateDriver.duplicate_b" + assert inst_a.log.logger is not inst_b.log.logger + + +def test_ip_to_visa_log_follows_instrument_scope() -> None: + class_logger_name = scoped_class_logger_name(ScopedIPToVisa) + inst = ScopedIPToVisa( + "scoped_ip_to_visa", + address="GPIB::1::INSTR", + port=None, + pyvisa_sim_file="AMI430.yaml", + ) + + assert inst.log.logger.name == f"{class_logger_name}.scoped_ip_to_visa" assert ( - inst.log.logger.name - == f"{SHARED_INSTRUMENT_LOGGER_NAME}.ScopedAMIModel430.scoped_visa_log" + inst.visa_log.logger.name == f"{class_logger_name}.com.visa.scoped_ip_to_visa" ) - assert inst.visa_log.logger is not inst.log.logger