Add opt-in per-instrument logger scope (default_logger_scope)

docs/changes/newsfragments/8523.new

@@ -0,0 +1,28 @@
+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::
+
+    class MyDriver(VisaInstrument):
+        default_logger_scope = "instrument"
+
+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.

docs/examples/logging/logging_example.ipynb

@@ -333,6 +333,116 @@
     "    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 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",
+    "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 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",
+    "```"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "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",
+    ")\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": [
+    "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` 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 `<locals>` 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."
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "mag_w.close()\n",
+    "mag_v.close()"
+   ]
+  },
   {
    "cell_type": "markdown",
    "metadata": {},

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 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.
+"""
+
 
 class InstrumentBaseKWArgs(TypedDict):
     """
@@ -71,6 +86,29 @@ class InstrumentBase(MetadatableWithName, DelegateAttributes):
 
     """
 
+    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"`` 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::
+
+        class MyDriver(VisaInstrument):
+            default_logger_scope = "instrument"
+
+    The resulting loggers are named
+    ``<DriverModule>.<DriverClass>.<name_parts>``, 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
+    whole instrument, including submodules added later, and changing it
+    afterwards has no effect on existing instruments.
+    """
+
     def __init__(
         self,
         name: str,
@@ -118,9 +156,41 @@ def __init__(
         # This is needed for snapshot method to work
         self._meta_attrs = ["name", "label"]
 
-        self.log: InstrumentLoggerAdapter = get_instrument_logger(self, __name__)
+        root = self.root_instrument
+        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, default: str, *branch: str) -> str:
+        """
+        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`, 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:
+            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.
+
+        """
+        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:
         """

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, VISA_LOGGER)
+        self.visa_log = get_instrument_logger(
+            self, self._logger_name(VISA_LOGGER, "com", "visa")
+        )
 
         ##################################################
         # __init__ of VisaInstrument

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, 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",