From c83c707444b478892188882f85a11c1a370f3dcf Mon Sep 17 00:00:00 2001 From: DJDavid98 Date: Sun, 8 Oct 2023 15:40:45 +0200 Subject: [PATCH] Add additional debug logging --- .../BluetoothHeartrateModule.cs | 18 +++++ .../BluetoothHeartrateModule.csproj | 4 +- .../BluetoothHeartrateProvider.cs | 80 ++++++++++++++++--- .../DeviceNameResolver.cs | 32 +++++++- .../WebsocketHeartrateServer.cs | 29 +++++-- 5 files changed, 140 insertions(+), 23 deletions(-) diff --git a/BluetoothHeartrateModule/BluetoothHeartrateModule.cs b/BluetoothHeartrateModule/BluetoothHeartrateModule.cs index 995b769..f5055fe 100644 --- a/BluetoothHeartrateModule/BluetoothHeartrateModule.cs +++ b/BluetoothHeartrateModule/BluetoothHeartrateModule.cs @@ -19,6 +19,7 @@ public BluetoothHeartrateModule() protected override BluetoothHeartrateProvider CreateProvider() { + LogDebug("Creating provider"); var provider = new BluetoothHeartrateProvider(this); provider.OnHeartrateUpdate += SendWebcoketHeartrate; return provider; @@ -29,8 +30,14 @@ protected override BluetoothHeartrateProvider CreateProvider() base.Log(message); } + internal new void LogDebug(string message) + { + base.LogDebug(message); + } + protected override void CreateAttributes() { + LogDebug("Creating attributes"); base.CreateAttributes(); CreateSetting(BluetoothHeartrateSetting.DeviceMac, "Device MAC address", "MAC address of the Bluetooth heartrate monitor", string.Empty); @@ -43,19 +50,23 @@ protected override void CreateAttributes() protected override async void OnModuleStart() { + LogDebug("Starting module"); CreateWatcher(); base.OnModuleStart(); if (GetWebocketEnabledSetting()) { + LogDebug("Starting wsServer"); await wsServer.Start(); } } protected override void OnModuleStop() { + LogDebug("Stopping module"); StopWatcher(); if (GetWebocketEnabledSetting()) { + LogDebug("Stopping wsServer"); wsServer.Stop(); } base.OnModuleStop(); @@ -87,6 +98,7 @@ private async void SendWebcoketHeartrate(int heartrate) { if (!GetWebocketEnabledSetting()) { + LogDebug("Not sending HR to websocket because it is disabled"); return; } @@ -96,7 +108,9 @@ internal BluetoothLEAdvertisementWatcher CreateWatcher() { if (watcher == null) { + LogDebug("Creating new watcher"); watcher = new BluetoothLEAdvertisementWatcher { ScanningMode = BluetoothLEScanningMode.Active }; + LogDebug("Adding watcher stopped event handler"); watcher.Stopped += Watcher_Stopped; } return watcher; @@ -104,6 +118,7 @@ internal BluetoothLEAdvertisementWatcher CreateWatcher() private void Watcher_Stopped(BluetoothLEAdvertisementWatcher sender, BluetoothLEAdvertisementWatcherStoppedEventArgs args) { + LogDebug($"Watcher stopped, error: {args.Error}"); string scanStatus; bool invokeDisconnect = true; switch (args.Error) @@ -122,6 +137,7 @@ private void Watcher_Stopped(BluetoothLEAdvertisementWatcher sender, BluetoothLE Log($"Stopped scanning for devices ({scanStatus})"); if (invokeDisconnect) { + LogDebug("Invoking OnDisconnected action"); HeartrateProvider?.OnDisconnected?.Invoke(); } } @@ -130,6 +146,7 @@ internal void StartWatcher() { if (watcher != null) { + LogDebug($"Starting watcher, current status: {watcher.Status}"); if (watcher.Status != BluetoothLEAdvertisementWatcherStatus.Started) { watcher.Start(); @@ -140,6 +157,7 @@ internal void StartWatcher() internal void StopWatcher() { + LogDebug("Stopping watcher"); watcher?.Stop(); } diff --git a/BluetoothHeartrateModule/BluetoothHeartrateModule.csproj b/BluetoothHeartrateModule/BluetoothHeartrateModule.csproj index be16a20..c1b0f4e 100644 --- a/BluetoothHeartrateModule/BluetoothHeartrateModule.csproj +++ b/BluetoothHeartrateModule/BluetoothHeartrateModule.csproj @@ -4,8 +4,8 @@ net6.0-windows10.0.22621.0 enable enable - 1.3.3 - 1.3.3 + 1.3.4 + 1.3.4 DJDavid98 Bluetooth Heartrate logo\logo.ico diff --git a/BluetoothHeartrateModule/BluetoothHeartrateProvider.cs b/BluetoothHeartrateModule/BluetoothHeartrateProvider.cs index e48c5b0..b2fcbb8 100644 --- a/BluetoothHeartrateModule/BluetoothHeartrateProvider.cs +++ b/BluetoothHeartrateModule/BluetoothHeartrateProvider.cs @@ -25,6 +25,7 @@ public BluetoothHeartrateProvider(BluetoothHeartrateModule module) public override void Initialise() { + module.LogDebug("Initializing BluetoothHeartrateProvider"); if (module.GetDeviceMacSetting() == string.Empty) { Log("Device MAC setting is not set, module will log discovered devices"); @@ -36,7 +37,9 @@ public override void Initialise() return; } + module.LogDebug("Registering watcher received handler"); module.watcher.Received += Watcher_Received; + module.LogDebug("Starting watcher"); module.StartWatcher(); } @@ -49,12 +52,15 @@ public override async Task Teardown() private void Reset() { - + module.LogDebug("Resetting provider"); if (module.watcher != null) { + module.LogDebug("Unregistering watcher received handler"); module.watcher.Received -= Watcher_Received; } + module.LogDebug("Clearing device names"); deviceNames.Clear(); + module.LogDebug("Clearing missing characteristics"); missingCharacteristicDevices.Clear(); ResetDevice(); processingData = false; @@ -62,8 +68,10 @@ private void Reset() private async void ResetDevice() { + module.LogDebug("Resetting device data"); if (heartRateService != null) { + module.LogDebug("Resetting heartRateService"); try { heartRateService.Dispose(); @@ -71,11 +79,13 @@ private async void ResetDevice() catch (ObjectDisposedException) { // Ignore if object is already disposed + module.LogDebug("heartRateService already disposed"); } heartRateService = null; } if (heartRateCharacteristic != null) { + module.LogDebug("Resetting heartRateCharacteristic"); try { heartRateCharacteristic.ValueChanged -= HeartRateCharacteristic_ValueChanged; @@ -83,11 +93,13 @@ private async void ResetDevice() catch (ObjectDisposedException) { // Ignore if object is already disposed + module.LogDebug("heartRateCharacteristic already disposed"); } heartRateCharacteristic = null; } if (currentDevice != null) { + module.LogDebug("Resetting currentDevice"); try { currentDevice.ConnectionStatusChanged -= Device_ConnectionStatusChanged; @@ -96,6 +108,7 @@ private async void ResetDevice() catch (ObjectDisposedException) { // Ignore if object is already disposed + module.LogDebug("currentDevice already disposed"); } currentDevice = null; } @@ -104,57 +117,79 @@ private async void ResetDevice() private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, BluetoothLEAdvertisementReceivedEventArgs args) { - + var advertisementId = Guid.NewGuid().ToString(); + // We need a prefix to follow the logs as advertisements can come in pretty rapidly + var logPrefix = $"[{advertisementId}]"; + module.LogDebug($"{logPrefix} Watcher received advertisement"); var advertisementMac = Converter.FormatAsMac(args.BluetoothAddress); + module.LogDebug($"{logPrefix} advertisementMac = {advertisementMac}"); var deviceMacSetting = module.GetDeviceMacSetting(); + module.LogDebug($"{logPrefix} deviceMacSetting = {deviceMacSetting}"); var isConfiguredDevice = advertisementMac == deviceMacSetting; + module.LogDebug($"{logPrefix} isConfiguredDevice = {isConfiguredDevice}"); if (deviceMacSetting == string.Empty || isConfiguredDevice) { var deviceNamesValue = deviceNames.GetValueOrDefault(advertisementMac, null); + module.LogDebug($"{logPrefix} Cached device name: {deviceNamesValue}"); if (deviceNamesValue == null) { + module.LogDebug($"{logPrefix} Creating device name resolver"); var dnr = new DeviceNameResolver(module); - var advertisementDeviceName = await dnr.GetDeviceNameAsync(args.Advertisement, args.BluetoothAddress); - deviceNames[advertisementMac] = advertisementDeviceName; + module.LogDebug($"{logPrefix} Resolving device name"); + var resolvedDeviceName = await dnr.GetDeviceNameAsync(args.Advertisement, args.BluetoothAddress); + module.LogDebug($"{logPrefix} Caching device name"); + deviceNames[advertisementMac] = resolvedDeviceName; if (!isConfiguredDevice) { - Log($"Discovered device: {advertisementDeviceName} (MAC: {advertisementMac})"); + Log($"Discovered device: {resolvedDeviceName} (MAC: {advertisementMac})"); } } - if (!isConfiguredDevice) - { - return; - } } if (!isConfiguredDevice) { // Not the droid we're looking for + module.LogDebug($"{logPrefix} Not the configured device, stop further advertisement processing"); return; } if (heartRateCharacteristic != null) { // Characteristic already found + module.LogDebug($"{logPrefix} heartRateCharacteristic already found, stop further advertisement processing"); return; } - if (processingData) return; + if (processingData) + { + module.LogDebug($"{logPrefix} Currently another advertisement is being processed, ignore this advertisement"); + return; + } processingData = true; + module.LogDebug($"{logPrefix} Begin processing advertisement data"); try { if (currentDevice == null) { + module.LogDebug($"{logPrefix} Setting currrent device"); currentDevice = await BluetoothLEDevice.FromBluetoothAddressAsync(args.BluetoothAddress); var currentDeviceName = deviceNames[advertisementMac] ?? "Unknown"; Log($"Found device named {currentDeviceName} for MAC {advertisementMac}"); module.SetDeviceName(currentDeviceName); + module.LogDebug($"{logPrefix} Register connection status change handler"); currentDevice.ConnectionStatusChanged += Device_ConnectionStatusChanged; } + else + { + module.LogDebug($"{logPrefix} Current device already set"); + } var missungUnknown = !missingCharacteristicDevices.Contains(deviceMacSetting); + module.LogDebug($"{logPrefix} missungUnknown = {missungUnknown}"); + module.LogDebug($"{logPrefix} Finding HeratRate service"); var services = await currentDevice.GetGattServicesForUuidAsync(GattServiceUuids.HeartRate, BluetoothCacheMode.Uncached); if (services.Services.Count > 0) { + module.LogDebug($"{logPrefix} Queueuing all found services for cleanup"); IEnumerable cleanupServices = services.Services; var firstService = cleanupServices.First(); if (missungUnknown) @@ -162,6 +197,7 @@ private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, Blue Log("Found heartrate service"); } var characteristics = await firstService.GetCharacteristicsForUuidAsync(GattCharacteristicUuids.HeartRateMeasurement, BluetoothCacheMode.Uncached); + module.LogDebug($"{logPrefix} Finding HeartRateMeasurement characteristic"); if (characteristics.Characteristics.Count > 0) { if (heartRateCharacteristic == null) @@ -181,11 +217,15 @@ private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, Blue // Remove receive handler if (module.watcher != null) { + module.LogDebug($"{logPrefix} Unregistering watcher recived handler"); module.watcher.Received -= Watcher_Received; } + module.LogDebug($"{logPrefix} Invoking OnConnected action"); OnConnected?.Invoke(); Log("Connection successful"); + module.LogDebug($"{logPrefix} Stopping watcher"); module.StopWatcher(); + module.LogDebug($"{logPrefix} Excluding first service from cleanup"); cleanupServices = services.Services.Skip(1); } else @@ -194,16 +234,26 @@ private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, Blue } } } + else + { + module.LogDebug($"{logPrefix} No characteristics found"); + } if (cleanupServices.Any()) { + module.LogDebug($"{logPrefix} Cleaning up services queued for cleanup"); foreach (var service in cleanupServices) service.Dispose(); } } + else + { + module.LogDebug($"{logPrefix} No services found"); + } if (heartRateCharacteristic == null && missungUnknown) { + module.LogDebug($"{logPrefix} Adding device to missing characteristic list"); missingCharacteristicDevices.Add(deviceMacSetting); throw new Exception("No heartrate characteristic found"); } @@ -216,22 +266,30 @@ private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, Blue finally { processingData = false; + module.LogDebug($"{logPrefix} Stopped processing advertisement"); } } private void HeartRateCharacteristic_ValueChanged(GattCharacteristic sender, GattValueChangedEventArgs args) { + module.LogDebug("HeartRateCharacteristic_ValueChanged"); var data = new byte[args.CharacteristicValue.Length]; + module.LogDebug("Reading new hartrate value into buffer"); DataReader.FromBuffer(args.CharacteristicValue).ReadBytes(data); - OnHeartrateUpdate?.Invoke(data[1]); + var updateData = data[1]; + module.LogDebug($"Invoking OnHeartrateUpdate action with data {updateData}"); + OnHeartrateUpdate?.Invoke(updateData); } private async void Device_ConnectionStatusChanged(BluetoothLEDevice sender, object args) { + module.LogDebug("Device_ConnectionStatusChanged"); + module.LogDebug($"sender.ConnectionStatus = {sender.ConnectionStatus}"); if (sender.ConnectionStatus == BluetoothConnectionStatus.Disconnected) { Log("Current device disconected"); + module.LogDebug($"Invoking OnDisconnected action"); OnDisconnected?.Invoke(); } } diff --git a/BluetoothHeartrateModule/DeviceNameResolver.cs b/BluetoothHeartrateModule/DeviceNameResolver.cs index c956e55..3145126 100644 --- a/BluetoothHeartrateModule/DeviceNameResolver.cs +++ b/BluetoothHeartrateModule/DeviceNameResolver.cs @@ -17,39 +17,58 @@ public DeviceNameResolver(BluetoothHeartrateModule module) internal async Task GetDeviceNameAsync(BluetoothLEAdvertisement advertisement, ulong bluetoothAddress) { + module.LogDebug("Getting device name"); var deviceName = string.Empty; try { var advertisementDeviceName = advertisement.LocalName; if (advertisementDeviceName != string.Empty) { + module.LogDebug($"Device name picked from advertisement: {advertisementDeviceName}"); return advertisementDeviceName; } + module.LogDebug("Advertisement missing device name"); + module.LogDebug($"Getting device object with address {Converter.FormatAsMac(bluetoothAddress)}"); using var device = await BluetoothLEDevice.FromBluetoothAddressAsync(bluetoothAddress); + module.LogDebug($"Creating DeviceInfo class with device ID {device.DeviceId}"); // Get the device name using the DeviceInformation class DeviceInformation deviceInfo = await DeviceInformation.CreateFromIdAsync(device.DeviceId); deviceName = deviceInfo.Name; if (deviceName == string.Empty) { + module.LogDebug("Cound lot read device name from DeviceInfo class"); + module.LogDebug("Attempting to find GenericAccess service"); var services = await device.GetGattServicesForUuidAsync(GattServiceUuids.GenericAccess); if (services.Services.Count > 0) { - var service = services.Services[0]; - var characteristics = await service.GetCharacteristicsForUuidAsync(GattCharacteristicUuids.GapDeviceName); + var firstService = services.Services.First(); + module.LogDebug("Attempting to read GapDeviceName characteristic from GenericAccess service"); + var characteristics = await firstService.GetCharacteristicsForUuidAsync(GattCharacteristicUuids.GapDeviceName); if (characteristics.Characteristics.Count > 0) { var characteristic = characteristics.Characteristics[0]; + module.LogDebug("Attempting to read device name from GapDeviceName characteristic"); var value = await characteristic.ReadValueAsync(BluetoothCacheMode.Uncached); if (value != null) { deviceName = DataReader.FromBuffer(value.Value).ReadString(value.Value.Length); + module.LogDebug($"Read device name from GapDeviceName characteristic ({deviceName})"); + } + else + { + module.LogDebug($"Could not read device name from GapDeviceName characteristic"); } } } + module.LogDebug($"Cleaning up all found services"); foreach (var service in services.Services) service.Dispose(); } + else + { + module.LogDebug($"Device name received from DeviceInfo class ({deviceName})"); + } } catch (Exception ex) { @@ -58,9 +77,14 @@ internal async Task GetDeviceNameAsync(BluetoothLEAdvertisement advertis return GetDeviceNameOrFallback(deviceName); } - private static string GetDeviceNameOrFallback(string? deviceName) + private string GetDeviceNameOrFallback(string? deviceName) { - return deviceName == string.Empty || deviceName == null ? "Unknown" : deviceName; + if (deviceName == string.Empty || deviceName == null) + { + module.LogDebug($"Device name not found, using fallback value"); + return "Unknown"; + } + return deviceName; } } } diff --git a/BluetoothHeartrateModule/WebsocketHeartrateServer.cs b/BluetoothHeartrateModule/WebsocketHeartrateServer.cs index f25b296..a51fd1a 100644 --- a/BluetoothHeartrateModule/WebsocketHeartrateServer.cs +++ b/BluetoothHeartrateModule/WebsocketHeartrateServer.cs @@ -21,19 +21,27 @@ public WebsocketHeartrateServer(BluetoothHeartrateModule module) internal async Task Start() { + module.LogDebug("Starting WebSocket server"); + + module.LogDebug("Clearing connected clients"); connectedClients.Clear(); + module.LogDebug("Resetting server cancellation token"); ResetServerCancellation(); if (!module.GetWebocketEnabledSetting()) { + module.LogDebug("WebSocket server is disabled, start aborted"); return; } + module.LogDebug("Creating new cancellation token"); serverCancellation = new CancellationTokenSource(); - var httpAddress = GetListenAddress(); + module.LogDebug("Determining listen addresses"); + var httpAddress = GetListenAddress("http"); var wsAddress = GetListenAddress("ws"); if (httpListener == null) { + module.LogDebug("Creating HTTP listener"); httpListener = new HttpListener(); httpListener.Prefixes.Add(httpAddress); } @@ -61,10 +69,13 @@ internal async Task Start() var context = await httpListener.GetContextAsync(); if (context.Request.IsWebSocketRequest) { + module.LogDebug("Accepting WebSocket request"); var webSocketContext = await context.AcceptWebSocketAsync(null); var clientId = Guid.NewGuid(); + module.LogDebug("Storing connected client"); connectedClients.TryAdd(clientId, webSocketContext.WebSocket); module.Log($"Websocket client {clientId} connected."); + module.LogDebug("Invoking OnClientConnect action"); OnClientConnect?.Invoke(clientId); _ = HandleWebSocketConnection(clientId, webSocketContext.WebSocket); @@ -79,6 +90,7 @@ internal async Task Start() catch (Exception ex) when (ex is HttpListenerException || ex is OperationCanceledException) { // Ignore exceptions caused by stopping the server + module.LogDebug("Caught exception while stopping WebSocket server"); } finally { @@ -92,6 +104,7 @@ private void ResetServerCancellation() { if (serverCancellation != null) { + module.LogDebug("Resetting server cancellation"); serverCancellation.Cancel(); serverCancellation.Dispose(); serverCancellation = null; @@ -102,6 +115,7 @@ private void StopHttpListener() { if (httpListener?.IsListening == true) { + module.LogDebug("Stopping HTTP listener"); httpListener.Stop(); } } @@ -109,6 +123,7 @@ private void StopHttpListener() // Public method to send an int message to all clients internal async Task SendIntMessage(int message) { + module.LogDebug($"Sending message {message} to all clients"); var messageBuffer = new ArraySegment(Converter.GetAsciiStringInt(message)); foreach (var clientId in connectedClients.Keys) { @@ -118,6 +133,7 @@ internal async Task SendIntMessage(int message) // Public method to send an int message to specific client internal async Task SendIntMessage(int message, Guid clientId) { + module.LogDebug($"Sending message {message} to client {clientId}"); var messageBuffer = new ArraySegment(Converter.GetAsciiStringInt(message)); await SendMessage(clientId, messageBuffer); } @@ -130,10 +146,6 @@ internal void Stop() StopHttpListener(); } - private string GetListenAddress() - { - return GetListenAddress("http"); - } private string GetListenAddress(string protocol) { return $"{protocol}://{module.GetWebocketHostSetting()}:{module.GetWebocketPortSetting()}/"; @@ -160,11 +172,12 @@ private async Task HandleWebSocketConnection(Guid clientId, WebSocket webSocket) private async void DisconnectClient(Guid clientId) { + module.LogDebug($"Disconnecting client {clientId}"); WebSocket? removedClient; connectedClients.TryRemove(clientId, out removedClient); if (removedClient != null) { - await removedClient.CloseAsync(WebSocketCloseStatus.EndpointUnavailable, null, new CancellationToken()); + await removedClient.CloseAsync(WebSocketCloseStatus.NormalClosure, null, CancellationToken.None); removedClient.Dispose(); } module.Log($"WebSocket client {clientId} disconnected."); @@ -175,19 +188,23 @@ private async Task SendMessage(Guid clientId, ArraySegment buffer) { if (!module.GetWebocketEnabledSetting()) { + module.LogDebug("WebSocket server found to be disbled while sending message, stopping"); Stop(); return; } + module.LogDebug($"Trying to find client {clientId} for messaging"); if (connectedClients.TryGetValue(clientId, out WebSocket? webSocket)) { if (webSocket == null || webSocket.State != WebSocketState.Open) { + module.LogDebug($"Cound not find open socket for client {clientId}, skipping"); return; } try { + module.LogDebug($"Sending message to client {clientId}"); await webSocket.SendAsync(buffer, WebSocketMessageType.Text, true, CancellationToken.None); } catch (WebSocketException ex)