bonneguldberg/ha-mysmartbike_ble
0
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

CLeanup logging

Browse Source
This commit is contained in:
Rene Nulsch
2025-11-22 14:39:28 +01:00
parent e8f91dc1cd
commit 43e6c0d99e
3 changed files with 71 additions and 339 deletions
Download Patch File Download Diff File Expand all files Collapse all files
custom_components/mysmartbike_ble/__init__.py
+3 -42
View File
@@ -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
custom_components/mysmartbike_ble/coordinator.py
+61 -247
View File
@@ -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)
custom_components/mysmartbike_ble/switch.py
+7 -50
View File
@@ -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)