Skip to content

Commit c83c707

Browse files
WentTheFoxWentTheFox
committed
Add additional debug logging
1 parent ce87cb7 commit c83c707

File tree

5 files changed

+140
-23
lines changed

5 files changed

+140
-23
lines changed

‎BluetoothHeartrateModule/BluetoothHeartrateModule.cs

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@ public BluetoothHeartrateModule()
1919

2020
protected override BluetoothHeartrateProvider CreateProvider()
2121
{
22+
LogDebug("Creating provider");
2223
var provider = new BluetoothHeartrateProvider(this);
2324
provider.OnHeartrateUpdate += SendWebcoketHeartrate;
2425
return provider;
@@ -29,8 +30,14 @@ protected override BluetoothHeartrateProvider CreateProvider()
2930
base.Log(message);
3031
}
3132

33+
internal new void LogDebug(string message)
34+
{
35+
base.LogDebug(message);
36+
}
37+
3238
protected override void CreateAttributes()
3339
{
40+
LogDebug("Creating attributes");
3441
base.CreateAttributes();
3542
CreateSetting(BluetoothHeartrateSetting.DeviceMac, "Device MAC address", "MAC address of the Bluetooth heartrate monitor", string.Empty);
3643

@@ -43,19 +50,23 @@ protected override void CreateAttributes()
4350

4451
protected override async void OnModuleStart()
4552
{
53+
LogDebug("Starting module");
4654
CreateWatcher();
4755
base.OnModuleStart();
4856
if (GetWebocketEnabledSetting())
4957
{
58+
LogDebug("Starting wsServer");
5059
await wsServer.Start();
5160
}
5261
}
5362

5463
protected override void OnModuleStop()
5564
{
65+
LogDebug("Stopping module");
5666
StopWatcher();
5767
if (GetWebocketEnabledSetting())
5868
{
69+
LogDebug("Stopping wsServer");
5970
wsServer.Stop();
6071
}
6172
base.OnModuleStop();
@@ -87,6 +98,7 @@ private async void SendWebcoketHeartrate(int heartrate)
8798
{
8899
if (!GetWebocketEnabledSetting())
89100
{
101+
LogDebug("Not sending HR to websocket because it is disabled");
90102
return;
91103
}
92104

@@ -96,14 +108,17 @@ internal BluetoothLEAdvertisementWatcher CreateWatcher()
96108
{
97109
if (watcher == null)
98110
{
111+
LogDebug("Creating new watcher");
99112
watcher = new BluetoothLEAdvertisementWatcher { ScanningMode = BluetoothLEScanningMode.Active };
113+
LogDebug("Adding watcher stopped event handler");
100114
watcher.Stopped += Watcher_Stopped;
101115
}
102116
return watcher;
103117
}
104118

105119
private void Watcher_Stopped(BluetoothLEAdvertisementWatcher sender, BluetoothLEAdvertisementWatcherStoppedEventArgs args)
106120
{
121+
LogDebug($"Watcher stopped, error: {args.Error}");
107122
string scanStatus;
108123
bool invokeDisconnect = true;
109124
switch (args.Error)
@@ -122,6 +137,7 @@ private void Watcher_Stopped(BluetoothLEAdvertisementWatcher sender, BluetoothLE
122137
Log($"Stopped scanning for devices ({scanStatus})");
123138
if (invokeDisconnect)
124139
{
140+
LogDebug("Invoking OnDisconnected action");
125141
HeartrateProvider?.OnDisconnected?.Invoke();
126142
}
127143
}
@@ -130,6 +146,7 @@ internal void StartWatcher()
130146
{
131147
if (watcher != null)
132148
{
149+
LogDebug($"Starting watcher, current status: {watcher.Status}");
133150
if (watcher.Status != BluetoothLEAdvertisementWatcherStatus.Started)
134151
{
135152
watcher.Start();
@@ -140,6 +157,7 @@ internal void StartWatcher()
140157

141158
internal void StopWatcher()
142159
{
160+
LogDebug("Stopping watcher");
143161
watcher?.Stop();
144162
}
145163

‎BluetoothHeartrateModule/BluetoothHeartrateModule.csproj

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -4,8 +4,8 @@
44
<TargetFramework>net6.0-windows10.0.22621.0</TargetFramework>
55
<ImplicitUsings>enable</ImplicitUsings>
66
<Nullable>enable</Nullable>
7-
<AssemblyVersion>1.3.3</AssemblyVersion>
8-
<FileVersion>1.3.3</FileVersion>
7+
<AssemblyVersion>1.3.4</AssemblyVersion>
8+
<FileVersion>1.3.4</FileVersion>
99
<Authors>DJDavid98</Authors>
1010
<Product>Bluetooth Heartrate</Product>
1111
<ApplicationIcon>logo\logo.ico</ApplicationIcon>

‎BluetoothHeartrateModule/BluetoothHeartrateProvider.cs

Lines changed: 69 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ public BluetoothHeartrateProvider(BluetoothHeartrateModule module)
2525

2626
public override void Initialise()
2727
{
28+
module.LogDebug("Initializing BluetoothHeartrateProvider");
2829
if (module.GetDeviceMacSetting() == string.Empty)
2930
{
3031
Log("Device MAC setting is not set, module will log discovered devices");
@@ -36,7 +37,9 @@ public override void Initialise()
3637
return;
3738
}
3839

40+
module.LogDebug("Registering watcher received handler");
3941
module.watcher.Received += Watcher_Received;
42+
module.LogDebug("Starting watcher");
4043
module.StartWatcher();
4144
}
4245

@@ -49,45 +52,54 @@ public override async Task Teardown()
4952

5053
private void Reset()
5154
{
52-
55+
module.LogDebug("Resetting provider");
5356
if (module.watcher != null)
5457
{
58+
module.LogDebug("Unregistering watcher received handler");
5559
module.watcher.Received -= Watcher_Received;
5660
}
61+
module.LogDebug("Clearing device names");
5762
deviceNames.Clear();
63+
module.LogDebug("Clearing missing characteristics");
5864
missingCharacteristicDevices.Clear();
5965
ResetDevice();
6066
processingData = false;
6167
}
6268

6369
private async void ResetDevice()
6470
{
71+
module.LogDebug("Resetting device data");
6572
if (heartRateService != null)
6673
{
74+
module.LogDebug("Resetting heartRateService");
6775
try
6876
{
6977
heartRateService.Dispose();
7078
}
7179
catch (ObjectDisposedException)
7280
{
7381
// Ignore if object is already disposed
82+
module.LogDebug("heartRateService already disposed");
7483
}
7584
heartRateService = null;
7685
}
7786
if (heartRateCharacteristic != null)
7887
{
88+
module.LogDebug("Resetting heartRateCharacteristic");
7989
try
8090
{
8191
heartRateCharacteristic.ValueChanged -= HeartRateCharacteristic_ValueChanged;
8292
}
8393
catch (ObjectDisposedException)
8494
{
8595
// Ignore if object is already disposed
96+
module.LogDebug("heartRateCharacteristic already disposed");
8697
}
8798
heartRateCharacteristic = null;
8899
}
89100
if (currentDevice != null)
90101
{
102+
module.LogDebug("Resetting currentDevice");
91103
try
92104
{
93105
currentDevice.ConnectionStatusChanged -= Device_ConnectionStatusChanged;
@@ -96,6 +108,7 @@ private async void ResetDevice()
96108
catch (ObjectDisposedException)
97109
{
98110
// Ignore if object is already disposed
111+
module.LogDebug("currentDevice already disposed");
99112
}
100113
currentDevice = null;
101114
}
@@ -104,64 +117,87 @@ private async void ResetDevice()
104117

105118
private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, BluetoothLEAdvertisementReceivedEventArgs args)
106119
{
107-
120+
var advertisementId = Guid.NewGuid().ToString();
121+
// We need a prefix to follow the logs as advertisements can come in pretty rapidly
122+
var logPrefix = $"[{advertisementId}]";
123+
module.LogDebug($"{logPrefix} Watcher received advertisement");
108124
var advertisementMac = Converter.FormatAsMac(args.BluetoothAddress);
125+
module.LogDebug($"{logPrefix} advertisementMac = {advertisementMac}");
109126
var deviceMacSetting = module.GetDeviceMacSetting();
127+
module.LogDebug($"{logPrefix} deviceMacSetting = {deviceMacSetting}");
110128
var isConfiguredDevice = advertisementMac == deviceMacSetting;
129+
module.LogDebug($"{logPrefix} isConfiguredDevice = {isConfiguredDevice}");
111130
if (deviceMacSetting == string.Empty || isConfiguredDevice)
112131
{
113132
var deviceNamesValue = deviceNames.GetValueOrDefault(advertisementMac, null);
133+
module.LogDebug($"{logPrefix} Cached device name: {deviceNamesValue}");
114134
if (deviceNamesValue == null)
115135
{
136+
module.LogDebug($"{logPrefix} Creating device name resolver");
116137
var dnr = new DeviceNameResolver(module);
117-
var advertisementDeviceName = await dnr.GetDeviceNameAsync(args.Advertisement, args.BluetoothAddress);
118-
deviceNames[advertisementMac] = advertisementDeviceName;
138+
module.LogDebug($"{logPrefix} Resolving device name");
139+
var resolvedDeviceName = await dnr.GetDeviceNameAsync(args.Advertisement, args.BluetoothAddress);
140+
module.LogDebug($"{logPrefix} Caching device name");
141+
deviceNames[advertisementMac] = resolvedDeviceName;
119142
if (!isConfiguredDevice)
120143
{
121-
Log($"Discovered device: {advertisementDeviceName} (MAC: {advertisementMac})");
144+
Log($"Discovered device: {resolvedDeviceName} (MAC: {advertisementMac})");
122145
}
123146
}
124-
if (!isConfiguredDevice)
125-
{
126-
return;
127-
}
128147
}
129148

130149
if (!isConfiguredDevice)
131150
{
132151
// Not the droid we're looking for
152+
module.LogDebug($"{logPrefix} Not the configured device, stop further advertisement processing");
133153
return;
134154
}
135155
if (heartRateCharacteristic != null)
136156
{
137157
// Characteristic already found
158+
module.LogDebug($"{logPrefix} heartRateCharacteristic already found, stop further advertisement processing");
138159
return;
139160
}
140161

141-
if (processingData) return;
162+
if (processingData)
163+
{
164+
module.LogDebug($"{logPrefix} Currently another advertisement is being processed, ignore this advertisement");
165+
return;
166+
}
142167
processingData = true;
168+
module.LogDebug($"{logPrefix} Begin processing advertisement data");
143169
try
144170
{
145171
if (currentDevice == null)
146172
{
173+
module.LogDebug($"{logPrefix} Setting currrent device");
147174
currentDevice = await BluetoothLEDevice.FromBluetoothAddressAsync(args.BluetoothAddress);
148175
var currentDeviceName = deviceNames[advertisementMac] ?? "Unknown";
149176
Log($"Found device named {currentDeviceName} for MAC {advertisementMac}");
150177
module.SetDeviceName(currentDeviceName);
178+
module.LogDebug($"{logPrefix} Register connection status change handler");
151179
currentDevice.ConnectionStatusChanged += Device_ConnectionStatusChanged;
152180
}
181+
else
182+
{
183+
module.LogDebug($"{logPrefix} Current device already set");
184+
}
153185

154186
var missungUnknown = !missingCharacteristicDevices.Contains(deviceMacSetting);
187+
module.LogDebug($"{logPrefix} missungUnknown = {missungUnknown}");
188+
module.LogDebug($"{logPrefix} Finding HeratRate service");
155189
var services = await currentDevice.GetGattServicesForUuidAsync(GattServiceUuids.HeartRate, BluetoothCacheMode.Uncached);
156190
if (services.Services.Count > 0)
157191
{
192+
module.LogDebug($"{logPrefix} Queueuing all found services for cleanup");
158193
IEnumerable<GattDeviceService> cleanupServices = services.Services;
159194
var firstService = cleanupServices.First();
160195
if (missungUnknown)
161196
{
162197
Log("Found heartrate service");
163198
}
164199
var characteristics = await firstService.GetCharacteristicsForUuidAsync(GattCharacteristicUuids.HeartRateMeasurement, BluetoothCacheMode.Uncached);
200+
module.LogDebug($"{logPrefix} Finding HeartRateMeasurement characteristic");
165201
if (characteristics.Characteristics.Count > 0)
166202
{
167203
if (heartRateCharacteristic == null)
@@ -181,11 +217,15 @@ private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, Blue
181217
// Remove receive handler
182218
if (module.watcher != null)
183219
{
220+
module.LogDebug($"{logPrefix} Unregistering watcher recived handler");
184221
module.watcher.Received -= Watcher_Received;
185222
}
223+
module.LogDebug($"{logPrefix} Invoking OnConnected action");
186224
OnConnected?.Invoke();
187225
Log("Connection successful");
226+
module.LogDebug($"{logPrefix} Stopping watcher");
188227
module.StopWatcher();
228+
module.LogDebug($"{logPrefix} Excluding first service from cleanup");
189229
cleanupServices = services.Services.Skip(1);
190230
}
191231
else
@@ -194,16 +234,26 @@ private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, Blue
194234
}
195235
}
196236
}
237+
else
238+
{
239+
module.LogDebug($"{logPrefix} No characteristics found");
240+
}
197241

198242
if (cleanupServices.Any())
199243
{
244+
module.LogDebug($"{logPrefix} Cleaning up services queued for cleanup");
200245
foreach (var service in cleanupServices)
201246
service.Dispose();
202247
}
203248
}
249+
else
250+
{
251+
module.LogDebug($"{logPrefix} No services found");
252+
}
204253

205254
if (heartRateCharacteristic == null && missungUnknown)
206255
{
256+
module.LogDebug($"{logPrefix} Adding device to missing characteristic list");
207257
missingCharacteristicDevices.Add(deviceMacSetting);
208258
throw new Exception("No heartrate characteristic found");
209259
}
@@ -216,22 +266,30 @@ private async void Watcher_Received(BluetoothLEAdvertisementWatcher sender, Blue
216266
finally
217267
{
218268
processingData = false;
269+
module.LogDebug($"{logPrefix} Stopped processing advertisement");
219270
}
220271
}
221272

222273
private void HeartRateCharacteristic_ValueChanged(GattCharacteristic sender, GattValueChangedEventArgs args)
223274
{
275+
module.LogDebug("HeartRateCharacteristic_ValueChanged");
224276
var data = new byte[args.CharacteristicValue.Length];
277+
module.LogDebug("Reading new hartrate value into buffer");
225278
DataReader.FromBuffer(args.CharacteristicValue).ReadBytes(data);
226279

227-
OnHeartrateUpdate?.Invoke(data[1]);
280+
var updateData = data[1];
281+
module.LogDebug($"Invoking OnHeartrateUpdate action with data {updateData}");
282+
OnHeartrateUpdate?.Invoke(updateData);
228283
}
229284

230285
private async void Device_ConnectionStatusChanged(BluetoothLEDevice sender, object args)
231286
{
287+
module.LogDebug("Device_ConnectionStatusChanged");
288+
module.LogDebug($"sender.ConnectionStatus = {sender.ConnectionStatus}");
232289
if (sender.ConnectionStatus == BluetoothConnectionStatus.Disconnected)
233290
{
234291
Log("Current device disconected");
292+
module.LogDebug($"Invoking OnDisconnected action");
235293
OnDisconnected?.Invoke();
236294
}
237295
}

0 commit comments

Comments
 (0)