From 43e6c0d99e73a1bc479d41dd24f942c895bc51bd Mon Sep 17 00:00:00 2001 From: Rene Nulsch Date: Sat, 22 Nov 2025 14:39:28 +0100 Subject: [PATCH] CLeanup logging --- custom_components/mysmartbike_ble/__init__.py | 45 +-- .../mysmartbike_ble/coordinator.py | 308 ++++-------------- custom_components/mysmartbike_ble/switch.py | 57 +--- 3 files changed, 71 insertions(+), 339 deletions(-) diff --git a/custom_components/mysmartbike_ble/__init__.py b/custom_components/mysmartbike_ble/__init__.py index d87ee9c..7dfccbe 100644 --- a/custom_components/mysmartbike_ble/__init__.py +++ b/custom_components/mysmartbike_ble/__init__.py @@ -2,7 +2,6 @@ from __future__ import annotations import logging -from typing import Any from homeassistant.components import bluetooth from homeassistant.config_entries import ConfigEntry @@ -20,25 +19,18 @@ PLATFORMS: list[Platform] = [Platform.BINARY_SENSOR, Platform.SENSOR, Platform.S async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry) -> bool: """Set up MySmartBike BLE from a config entry.""" - _LOGGER.debug("Setting up MySmartBike BLE integration for entry_id: %s", entry.entry_id) - address = entry.data[CONF_DEVICE_ADDRESS] - _LOGGER.debug("Device address from config: %s", address) # Get BLE device - _LOGGER.debug("Looking up BLE device with address: %s", address) ble_device = bluetooth.async_ble_device_from_address(hass, address, connectable=True) if not ble_device: # Log warning only once per config entry - # Use hass.data for warning flag as it's separate from coordinator runtime_data hass.data.setdefault(DOMAIN, {}) warning_key = f"warned_{entry.entry_id}" if not hass.data[DOMAIN].get(warning_key): _LOGGER.warning( - "MySmartBike device with address %s not found. " - "Make sure the bike is powered on and in range. " - "Home Assistant will retry automatically", + "MySmartBike device %s not found - ensure bike is powered on and in range", address ) hass.data[DOMAIN][warning_key] = True @@ -48,58 +40,27 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry) -> bool: if DOMAIN in hass.data: hass.data[DOMAIN].pop(f"warned_{entry.entry_id}", None) - _LOGGER.debug("Found BLE device: %s", ble_device) - - # Create coordinator - _LOGGER.debug("Creating coordinator for device %s", address) + # Create and initialize coordinator coordinator = MySmartBikeCoordinator(hass, ble_device, entry) - - # Perform first refresh - _LOGGER.debug("Performing first coordinator refresh") await coordinator.async_config_entry_first_refresh() - _LOGGER.debug( - "First refresh completed - coordinator state: is_connected=%s, manual_disconnect=%s", - coordinator.is_connected, - coordinator._manual_disconnect, - ) - # Store coordinator in runtime_data entry.runtime_data = coordinator - _LOGGER.debug("Coordinator stored in entry.runtime_data") - - # Forward entry setup to platforms - _LOGGER.debug("Forwarding entry setup to platforms: %s", PLATFORMS) await hass.config_entries.async_forward_entry_setups(entry, PLATFORMS) - _LOGGER.debug("Platform setup completed") - _LOGGER.debug("MySmartBike BLE integration setup completed successfully for entry_id: %s", entry.entry_id) + _LOGGER.debug("MySmartBike BLE setup completed for %s", address) return True async def async_unload_entry(hass: HomeAssistant, entry: ConfigEntry) -> bool: """Unload a config entry.""" - _LOGGER.debug("Unloading MySmartBike BLE integration for entry_id: %s", entry.entry_id) - - # Unload platforms - _LOGGER.debug("Unloading platforms: %s", PLATFORMS) unload_ok = await hass.config_entries.async_unload_platforms(entry, PLATFORMS) - _LOGGER.debug("Platform unload result: %s", unload_ok) if unload_ok: coordinator: MySmartBikeCoordinator = entry.runtime_data - _LOGGER.debug( - "Coordinator retrieved from runtime_data - state: is_connected=%s, manual_disconnect=%s", - coordinator.is_connected, - coordinator._manual_disconnect, - ) await coordinator.async_shutdown() - _LOGGER.debug("Coordinator shutdown completed") # Clean up warning flag from hass.data if DOMAIN in hass.data: hass.data[DOMAIN].pop(f"warned_{entry.entry_id}", None) - else: - _LOGGER.warning("Platform unload was not successful") - _LOGGER.debug("MySmartBike BLE integration unload completed for entry_id: %s (result: %s)", entry.entry_id, unload_ok) return unload_ok diff --git a/custom_components/mysmartbike_ble/coordinator.py b/custom_components/mysmartbike_ble/coordinator.py index eeff8ed..92cfa77 100644 --- a/custom_components/mysmartbike_ble/coordinator.py +++ b/custom_components/mysmartbike_ble/coordinator.py @@ -59,13 +59,6 @@ class MySmartBikeCoordinator(DataUpdateCoordinator[dict[str, Any]]): self._is_connected = False self._notify_task: asyncio.Task | None = None self._manual_disconnect = False # Track if user manually disconnected - _LOGGER.debug( - "Coordinator initialized: address=%s, is_connected=%s, manual_disconnect=%s, scan_interval=%s", - ble_device.address, - self._is_connected, - self._manual_disconnect, - SCAN_INTERVAL, - ) @property def address(self) -> str: @@ -75,11 +68,6 @@ class MySmartBikeCoordinator(DataUpdateCoordinator[dict[str, Any]]): @property def is_connected(self) -> bool: """Return connection status.""" - _LOGGER.debug( - "Coordinator.is_connected property called: returning %s (manual_disconnect: %s)", - self._is_connected, - self._manual_disconnect, - ) return self._is_connected @property @@ -92,149 +80,77 @@ class MySmartBikeCoordinator(DataUpdateCoordinator[dict[str, Any]]): """Return the protocol version if available.""" return self._parser.protocol_version + async def _cleanup_client(self, send_close: bool = True, wait_for_slot: bool = True) -> None: + """Clean up BLE client connection. + + Args: + send_close: Whether to send close message to bike before disconnecting. + wait_for_slot: Whether to wait for BLE connection slot release. + """ + if not self._client: + return + + client = self._client + self._client = None + self._is_connected = False + + try: + if client.is_connected: + if send_close: + try: + await client.write_gatt_char(WRITE_UUID, CLOSE_MESSAGE) + await asyncio.sleep(0.5) + except Exception: + pass # Ignore close message errors + + try: + await client.stop_notify(NOTIFY_UUID) + except Exception: + pass # Ignore notification stop errors + + try: + await client.disconnect() + except Exception as ex: + _LOGGER.debug("Error during BLE disconnect: %s", ex) + except Exception as ex: + _LOGGER.debug("Unexpected error during client cleanup: %s", ex) + finally: + del client + if wait_for_slot: + await asyncio.sleep(3.0) # Wait for BLE connection slot release + async def async_disconnect(self) -> None: """Disconnect from the device (user initiated).""" - _LOGGER.debug( - "Coordinator.async_disconnect called for %s (user initiated) - current state: is_connected=%s, manual_disconnect=%s, client=%s", - self._ble_device.address, - self._is_connected, - self._manual_disconnect, - self._client is not None, - ) - - # Mark as manually disconnected to prevent auto-reconnect + _LOGGER.debug("User-initiated disconnect for %s", self._ble_device.address) self._manual_disconnect = True - _LOGGER.debug("Coordinator.async_disconnect: Set manual_disconnect=True") - - if self._client: - _LOGGER.debug("Coordinator.async_disconnect: Client exists, cleaning up connection") - client_to_cleanup = self._client - self._client = None # Clear reference immediately - self._is_connected = False - - try: - # Only send close message if still connected - if client_to_cleanup.is_connected: - # Send close message to bike before disconnecting - _LOGGER.debug("Coordinator.async_disconnect: Sending close message ($D$I#@)") - try: - await client_to_cleanup.write_gatt_char(WRITE_UUID, CLOSE_MESSAGE) - _LOGGER.debug("Coordinator.async_disconnect: Close message sent") - await asyncio.sleep(0.5) - except Exception as ex: - _LOGGER.debug("Coordinator.async_disconnect: Error sending close message: %s", ex) - - # Stop notifications - try: - await client_to_cleanup.stop_notify(NOTIFY_UUID) - _LOGGER.debug("Coordinator.async_disconnect: Stopped notifications") - except Exception as ex: - _LOGGER.debug("Coordinator.async_disconnect: Error stopping notifications: %s", ex) - - # Disconnect from device - try: - await client_to_cleanup.disconnect() - _LOGGER.debug("Coordinator.async_disconnect: Disconnected from device") - except Exception as ex: - _LOGGER.debug("Coordinator.async_disconnect: Error during disconnect: %s", ex) - else: - _LOGGER.debug("Coordinator.async_disconnect: Client exists but not connected, skipping disconnect") - - except Exception as ex: - _LOGGER.debug("Coordinator.async_disconnect: Unexpected error during disconnect: %s", ex, exc_info=True) - finally: - # Force delete the client object to help garbage collection - del client_to_cleanup - - # Give BLE adapter significant time to release connection slot - _LOGGER.debug("Coordinator.async_disconnect: Waiting for connection slot release (3 seconds)") - await asyncio.sleep(3.0) - _LOGGER.debug("Coordinator.async_disconnect: Cleaned up client (is_connected=%s)", self._is_connected) - else: - _LOGGER.debug("Coordinator.async_disconnect: No client to disconnect") - self._is_connected = False - - _LOGGER.debug( - "Coordinator.async_disconnect completed - final state: is_connected=%s, manual_disconnect=%s", - self._is_connected, - self._manual_disconnect, - ) + await self._cleanup_client(send_close=True, wait_for_slot=True) async def async_reconnect(self) -> None: """Reconnect to the device (user initiated).""" - _LOGGER.debug( - "Coordinator.async_reconnect called for %s (user initiated) - current state: is_connected=%s, manual_disconnect=%s, client=%s", - self._ble_device.address, - self._is_connected, - self._manual_disconnect, - self._client is not None, - ) + _LOGGER.debug("User-initiated reconnect for %s", self._ble_device.address) # Clean up any existing client first - if self._client: - _LOGGER.debug("Coordinator.async_reconnect: Found existing client, cleaning up first") - old_client = self._client - self._client = None - self._is_connected = False - - try: - if old_client.is_connected: - await old_client.disconnect() - _LOGGER.debug("Coordinator.async_reconnect: Disconnected existing client") - except Exception as ex: - _LOGGER.debug("Coordinator.async_reconnect: Error disconnecting old client: %s", ex) - finally: - del old_client - # Wait longer for connection slot to be released - _LOGGER.debug("Coordinator.async_reconnect: Waiting for connection slot release (3 seconds)") - await asyncio.sleep(3.0) - _LOGGER.debug("Coordinator.async_reconnect: Cleaned up old client and waited for slot release") + await self._cleanup_client(send_close=False, wait_for_slot=True) # Clear manual disconnect flag to allow auto-reconnect self._manual_disconnect = False - _LOGGER.debug("Coordinator.async_reconnect: Set manual_disconnect=False") try: await self._connect() - _LOGGER.debug( - "Coordinator.async_reconnect completed - final state: is_connected=%s, manual_disconnect=%s", - self._is_connected, - self._manual_disconnect, - ) except Exception as ex: - # Only log as error if it's not a "device not reachable" issue error_str = str(ex).lower() - if "not reachable" in error_str or "turn on the bike" in error_str: - _LOGGER.debug("Coordinator.async_reconnect: Device not reachable, will retry later") - else: - _LOGGER.error("Coordinator.async_reconnect failed: %s", ex, exc_info=True) + if "not reachable" not in error_str and "turn on the bike" not in error_str: + _LOGGER.error("Reconnect failed: %s", ex) raise async def _async_update_data(self) -> dict[str, Any]: """Fetch data from the device.""" - _LOGGER.debug( - "Coordinator._async_update_data called - current state: is_connected=%s, manual_disconnect=%s", - self._is_connected, - self._manual_disconnect, - ) - - # Don't auto-reconnect if user manually disconnected + # Auto-reconnect if not connected and not manually disconnected if not self._is_connected and not self._manual_disconnect: - _LOGGER.debug("Coordinator._async_update_data: Not connected and not manual disconnect, attempting auto-reconnect") try: await self._connect() - _LOGGER.debug("Coordinator._async_update_data: Auto-reconnect successful (is_connected=%s)", self._is_connected) - except Exception as ex: - # Only log as warning if device is not reachable, otherwise debug - error_str = str(ex).lower() - if "not reachable" in error_str or "turn on the bike" in error_str: - _LOGGER.debug("Coordinator._async_update_data: Auto-reconnect skipped - device not reachable") - else: - _LOGGER.debug("Coordinator._async_update_data: Auto-reconnect failed: %s", ex) - elif not self._is_connected and self._manual_disconnect: - _LOGGER.debug("Coordinator._async_update_data: Not connected but manual_disconnect=True, skipping auto-reconnect") - else: - _LOGGER.debug("Coordinator._async_update_data: Already connected, no action needed") + except Exception: + pass # Connection errors are logged in _connect() # Return current state from parser, ensure it's never None state = self._parser.state or { @@ -246,106 +162,55 @@ class MySmartBikeCoordinator(DataUpdateCoordinator[dict[str, Any]]): } # Add RSSI (signal strength) to state - # Get latest service info which contains current RSSI try: service_info = bluetooth.async_last_service_info( self.hass, self._ble_device.address, connectable=True ) state["rssi"] = service_info.rssi if service_info else None - except Exception as ex: - _LOGGER.debug("Could not get RSSI: %s", ex) + except Exception: state["rssi"] = None - _LOGGER.debug("Coordinator._async_update_data: Returning state (has_data=%s, rssi=%s)", self._parser.state is not None, state.get("rssi")) return state async def _connect(self) -> None: """Connect to the device and start notifications.""" - _LOGGER.debug( - "Coordinator._connect: Attempting to connect to %s (current is_connected=%s, manual_disconnect=%s, client=%s)", - self._ble_device.address, - self._is_connected, - self._manual_disconnect, - self._client is not None, - ) - # Clean up any existing client before connecting if self._client: - _LOGGER.warning("Coordinator._connect: Client already exists, cleaning up before new connection") - old_client = self._client - self._client = None - try: - if old_client.is_connected: - await old_client.disconnect() - except Exception as ex: - _LOGGER.debug("Coordinator._connect: Error cleaning up old client: %s", ex) - finally: - del old_client - _LOGGER.debug("Coordinator._connect: Waiting for connection slot release (3 seconds)") - await asyncio.sleep(3.0) + _LOGGER.debug("Cleaning up existing client before new connection") + await self._cleanup_client(send_close=False, wait_for_slot=True) try: - _LOGGER.debug("Coordinator._connect: Calling establish_connection for %s", self._ble_device.address) - self._client = await establish_connection( BleakClientWithServiceCache, self._ble_device, self._ble_device.address, ) - _LOGGER.debug("Coordinator._connect: Successfully connected to %s, client=%s", self._ble_device.address, self._client) - - # Start notifications first - _LOGGER.debug("Coordinator._connect: Starting notifications on UUID %s", NOTIFY_UUID) + # Start notifications and request device info await self._client.start_notify(NOTIFY_UUID, self._notification_handler) - _LOGGER.debug("Coordinator._connect: Started notifications successfully") - - # Request VIN/serial number ($S$V#@) - _LOGGER.debug("Coordinator._connect: Requesting VIN/serial number") await self._client.write_gatt_char(WRITE_UUID, VIN_REQUEST_MESSAGE) - _LOGGER.debug("Coordinator._connect: VIN request sent") - - # Small delay between requests await asyncio.sleep(0.2) - - # Request protocol version ($S$P#@) - _LOGGER.debug("Coordinator._connect: Requesting protocol version") await self._client.write_gatt_char(WRITE_UUID, PROTOCOL_REQUEST_MESSAGE) - _LOGGER.debug("Coordinator._connect: Protocol request sent") self._is_connected = True - _LOGGER.debug("Coordinator._connect: Set is_connected=True") + _LOGGER.debug("Connected to %s", self._ble_device.address) except (BleakError, asyncio.TimeoutError) as ex: self._is_connected = False - - # Check if error is due to device not being reachable (turned off) error_str = str(ex).lower() + if "no longer reachable" in error_str or "out of connection slots" in error_str: - _LOGGER.warning( - "Coordinator._connect: Device %s is not reachable or powered off. " - "Turn on the bike to connect.", - self._ble_device.address - ) - raise UpdateFailed( - f"Device {self._ble_device.address} is not reachable. " - "Please turn on the bike." - ) from ex + _LOGGER.warning("Device %s not reachable - turn on the bike", self._ble_device.address) + raise UpdateFailed(f"Device {self._ble_device.address} is not reachable") from ex else: - _LOGGER.error( - "Coordinator._connect: Failed to connect to device %s: %s (is_connected set to False)", - self._ble_device.address, - ex, - exc_info=True, - ) + _LOGGER.error("Failed to connect to %s: %s", self._ble_device.address, ex) raise UpdateFailed(f"Failed to connect to device: {ex}") from ex def _notification_handler(self, sender: int, data: bytearray) -> None: """Handle notification data.""" - _LOGGER.debug("Received notification from %s: %s", sender, data.hex()) - # Recognize message type before saving message_type = self._parser.recognize_message_type(bytes(data)) + _LOGGER.debug("BLE notification [%s]: %s", message_type, data.hex()) # Save BLE message to file if option is enabled (run in executor to avoid blocking) if self._entry.options.get(CONF_LOG_BLE_MESSAGES, False): @@ -403,61 +268,10 @@ class MySmartBikeCoordinator(DataUpdateCoordinator[dict[str, Any]]): with open(filepath, "a", encoding="utf-8") as f: f.write(message_line) - _LOGGER.debug("Saved BLE message to: %s", filepath) - except Exception as ex: - _LOGGER.error("Failed to save BLE message to file: %s", ex, exc_info=True) + _LOGGER.error("Failed to save BLE message to file: %s", ex) async def async_shutdown(self) -> None: """Shutdown the coordinator.""" - _LOGGER.debug( - "Coordinator.async_shutdown called - current state: is_connected=%s, manual_disconnect=%s, client=%s", - self._is_connected, - self._manual_disconnect, - self._client is not None, - ) - - if self._client: - _LOGGER.debug("Coordinator.async_shutdown: Client exists, cleaning up connection") - client_to_cleanup = self._client - self._client = None - self._is_connected = False - - try: - # Only send close message if still connected - if client_to_cleanup.is_connected: - # Send close message to bike before disconnecting - try: - _LOGGER.debug("Coordinator.async_shutdown: Sending close message ($D$I#@)") - await client_to_cleanup.write_gatt_char(WRITE_UUID, CLOSE_MESSAGE) - _LOGGER.debug("Coordinator.async_shutdown: Close message sent") - await asyncio.sleep(0.5) - except Exception as ex: - _LOGGER.debug("Coordinator.async_shutdown: Error sending close message: %s", ex) - - # Stop notifications - try: - await client_to_cleanup.stop_notify(NOTIFY_UUID) - _LOGGER.debug("Coordinator.async_shutdown: Stopped notifications") - except Exception as ex: - _LOGGER.debug("Coordinator.async_shutdown: Error stopping notifications: %s", ex) - - # Disconnect from device - try: - await client_to_cleanup.disconnect() - _LOGGER.debug("Coordinator.async_shutdown: Disconnected from device") - except Exception as ex: - _LOGGER.debug("Coordinator.async_shutdown: Error during disconnect: %s", ex) - else: - _LOGGER.debug("Coordinator.async_shutdown: Client exists but not connected, skipping disconnect") - - except Exception as ex: - _LOGGER.debug("Coordinator.async_shutdown: Unexpected error during shutdown: %s", ex, exc_info=True) - finally: - del client_to_cleanup - _LOGGER.debug("Coordinator.async_shutdown: Cleaned up client") - else: - _LOGGER.debug("Coordinator.async_shutdown: No client to clean up") - self._is_connected = False - - _LOGGER.debug("Coordinator.async_shutdown completed") + _LOGGER.debug("Shutting down coordinator") + await self._cleanup_client(send_close=True, wait_for_slot=False) diff --git a/custom_components/mysmartbike_ble/switch.py b/custom_components/mysmartbike_ble/switch.py index 5ab744d..1298086 100644 --- a/custom_components/mysmartbike_ble/switch.py +++ b/custom_components/mysmartbike_ble/switch.py @@ -22,10 +22,7 @@ async def async_setup_entry( async_add_entities: AddEntitiesCallback, ) -> None: """Set up MySmartBike BLE switch entities.""" - _LOGGER.debug("Setting up switch platform for entry_id: %s", entry.entry_id) coordinator: MySmartBikeCoordinator = entry.runtime_data - - _LOGGER.debug("Adding connection switch entity (coordinator.is_connected: %s)", coordinator.is_connected) async_add_entities([MySmartBikeConnectionSwitch(coordinator, entry)]) @@ -51,25 +48,11 @@ class MySmartBikeConnectionSwitch(CoordinatorEntity[MySmartBikeCoordinator], Swi if coordinator.protocol_version: self._attr_device_info["sw_version"] = coordinator.protocol_version self._attr_translation_key = "connection" - _LOGGER.debug( - "Switch initialized: unique_id=%s, coordinator.is_connected=%s", - self._attr_unique_id, - coordinator.is_connected, - ) @property def is_on(self) -> bool: """Return True if connection is desired (not manually disconnected).""" - # Switch represents the desired state, not the actual connection status - # If manual_disconnect is False, user wants to be connected - state = not self.coordinator._manual_disconnect - _LOGGER.debug( - "Switch is_on property called: returning %s (manual_disconnect=%s, is_connected=%s)", - state, - self.coordinator._manual_disconnect, - self.coordinator.is_connected - ) - return state + return not self.coordinator._manual_disconnect @property def icon(self) -> str: @@ -78,32 +61,16 @@ class MySmartBikeConnectionSwitch(CoordinatorEntity[MySmartBikeCoordinator], Swi async def async_turn_on(self, **kwargs: Any) -> None: """Turn on the switch - request connection to the bike.""" - _LOGGER.debug( - "Switch.async_turn_on called (current coordinator.is_connected: %s, manual_disconnect: %s)", - self.coordinator.is_connected, - self.coordinator._manual_disconnect, - ) - - # Update state immediately - switch is now ON (connection desired) self.async_write_ha_state() try: await self.coordinator.async_reconnect() - _LOGGER.debug( - "Switch.async_turn_on: reconnect completed (coordinator.is_connected: %s)", - self.coordinator.is_connected, - ) except Exception as ex: - # Provide user-friendly error message - error_msg = str(ex) - if "not reachable" in error_msg.lower(): - _LOGGER.warning( - "Switch.async_turn_on: Cannot connect now - bike is not reachable. " - "Will auto-connect when bike is powered on." - ) + error_msg = str(ex).lower() + if "not reachable" in error_msg: + _LOGGER.warning("Cannot connect - bike not reachable. Will auto-connect when available.") else: - _LOGGER.error("Switch.async_turn_on: Failed to connect to bike: %s", ex, exc_info=True) - # Switch stays ON - coordinator will auto-reconnect when bike becomes available + _LOGGER.error("Failed to connect to bike: %s", ex) async def async_turn_off(self, **kwargs: Any) -> None: """Turn off the switch - disconnect from the bike. @@ -111,19 +78,9 @@ class MySmartBikeConnectionSwitch(CoordinatorEntity[MySmartBikeCoordinator], Swi WARNING: This will turn off the bike after ~5 minutes! It must be manually turned on again or connected to power. """ - _LOGGER.warning( - "Switch.async_turn_off called - Disconnecting from bike (current coordinator.is_connected: %s). " - "Bike will turn off after approximately 5 minutes and must be manually turned on again or connected to power", - self.coordinator.is_connected, - ) + _LOGGER.warning("Disconnecting from bike - it will turn off after ~5 minutes") try: await self.coordinator.async_disconnect() - _LOGGER.debug( - "Switch.async_turn_off: disconnect completed (coordinator.is_connected: %s, manual_disconnect: %s)", - self.coordinator.is_connected, - self.coordinator._manual_disconnect, - ) self.async_write_ha_state() - _LOGGER.debug("Switch.async_turn_off: state written to HA") except Exception as ex: - _LOGGER.error("Switch.async_turn_off: Failed to disconnect from bike: %s", ex, exc_info=True) + _LOGGER.error("Failed to disconnect from bike: %s", ex)