backends/bluez: Defer expensive debug logging (hbldh#1376)

- Switch usage of f-strings for log message formatting
- Guard expensive loggers with isEnableFor

CHANGELOG.rst

@@ -31,6 +31,7 @@ Fixed
 * Added support for 32bit UUIDs. Fixes #1314.
 * Fixed typing for ``BaseBleakScanner`` detection callback.
 * Fixed possible crash in ``_stopped_handler()`` in WinRT backend. Fixes #1330.
+* Reduce expensive logging in the BlueZ backend.
 
 `0.20.2`_ (2023-04-19)
 ======================

bleak/backends/bluezdbus/advertisement_monitor.py

@@ -75,12 +75,14 @@ def Activate(self):
     @method()
     @no_type_check
     def DeviceFound(self, device: "o"):  # noqa: F821
-        logger.debug("DeviceFound %s", device)
+        if logger.isEnabledFor(logging.DEBUG):
+            logger.debug("DeviceFound %s", device)
 
     @method()
     @no_type_check
     def DeviceLost(self, device: "o"):  # noqa: F821
-        logger.debug("DeviceLost %s", device)
+        if logger.isEnabledFor(logging.DEBUG):
+            logger.debug("DeviceLost %s", device)
 
     @dbus_property(PropertyAccess.READ)
     @no_type_check

bleak/backends/bluezdbus/client.py

@@ -150,7 +150,7 @@ async def connect(self, dangerous_use_bleak_cache: bool = False, **kwargs) -> bo
 
                 def on_connected_changed(connected: bool) -> None:
                     if not connected:
-                        logger.debug(f"Device disconnected ({self._device_path})")
+                        logger.debug("Device disconnected (%s)", self._device_path)
 
                         self._is_connected = False
 
@@ -340,22 +340,24 @@ def _cleanup_all(self) -> None:
         Free all the allocated resource in DBus. Use this method to
         eventually cleanup all otherwise leaked resources.
         """
-        logger.debug(f"_cleanup_all({self._device_path})")
+        logger.debug("_cleanup_all(%s)", self._device_path)
 
         if self._remove_device_watcher:
             self._remove_device_watcher()
             self._remove_device_watcher = None
 
         if not self._bus:
-            logger.debug(f"already disconnected ({self._device_path})")
+            logger.debug("already disconnected (%s)", self._device_path)
             return
 
         # Try to disconnect the System Bus.
         try:
             self._bus.disconnect()
         except Exception as e:
             logger.error(
-                f"Attempt to disconnect system bus failed ({self._device_path}): {e}"
+                "Attempt to disconnect system bus failed (%s): %s",
+                self._device_path,
+                e,
             )
         else:
             # Critical to remove the `self._bus` object here to since it was
@@ -376,18 +378,18 @@ async def disconnect(self) -> bool:
             BleakDBusError: If there was a D-Bus error
             asyncio.TimeoutError if the device was not disconnected within 10 seconds
         """
-        logger.debug(f"Disconnecting ({self._device_path})")
+        logger.debug("Disconnecting ({%s})", self._device_path)
 
         if self._bus is None:
             # No connection exists. Either one hasn't been created or
             # we have already called disconnect and closed the D-Bus
             # connection.
-            logger.debug(f"already disconnected ({self._device_path})")
+            logger.debug("already disconnected ({%s})", self._device_path)
             return True
 
         if self._disconnecting_event:
             # another call to disconnect() is already in progress
-            logger.debug(f"already in progress ({self._device_path})")
+            logger.debug("already in progress ({%s})", self._device_path)
             async with async_timeout(10):
                 await self._disconnecting_event.wait()
         elif self.is_connected:
@@ -804,9 +806,7 @@ async def read_gatt_descriptor(self, handle: int, **kwargs) -> bytearray:
 
         value = bytearray(reply.body[0])
 
-        logger.debug(
-            "Read Descriptor {0} | {1}: {2}".format(handle, descriptor.path, value)
-        )
+        logger.debug("Read Descriptor %s | %s: %s", handle, descriptor.path, value)
         return value
 
     async def write_gatt_char(
@@ -877,9 +877,10 @@ async def write_gatt_char(
                 os.close(fd)
 
         logger.debug(
-            "Write Characteristic {0} | {1}: {2}".format(
-                characteristic.uuid, characteristic.path, data
-            )
+            "Write Characteristic %s | %s: %s",
+            characteristic.uuid,
+            characteristic.path,
+            data,
         )
 
     async def write_gatt_descriptor(

bleak/backends/bluezdbus/manager.py

@@ -110,7 +110,6 @@ class DeviceRemovedCallbackAndState(NamedTuple):
 
 
 class DeviceWatcher(NamedTuple):
-
     device_path: str
     """
     The D-Bus object path of the device.
@@ -274,7 +273,8 @@ async def async_init(self):
                             desc_props["Characteristic"], set()
                         ).add(path)
 
-                logger.debug(f"initial properties: {self._properties}")
+                if logger.isEnabledFor(logging.DEBUG):
+                    logger.debug("initial properties: %s", self._properties)
 
             except BaseException:
                 # if setup failed, disconnect
@@ -727,13 +727,14 @@ def _parse_msg(self, message: Message):
         if message.message_type != MessageType.SIGNAL:
             return
 
-        logger.debug(
-            "received D-Bus signal: %s.%s (%s): %s",
-            message.interface,
-            message.member,
-            message.path,
-            message.body,
-        )
+        if logger.isEnabledFor(logging.DEBUG):
+            logger.debug(
+                "received D-Bus signal: %s.%s (%s): %s",
+                message.interface,
+                message.member,
+                message.path,
+                message.body,
+            )
 
         # type hints
         obj_path: str
@@ -884,7 +885,7 @@ def _run_advertisement_callbacks(
             device: The current D-Bus properties of the device.
             changed: A list of properties that have changed since the last call.
         """
-        for (callback, adapter_path) in self._advertisement_callbacks:
+        for callback, adapter_path in self._advertisement_callbacks:
             # filter messages from other adapters
             if adapter_path != device["Adapter"]:
                 continue