diff --git a/lib/ble/ble_engine.dart b/lib/ble/ble_engine.dart index cf225c078..3d7f07476 100644 --- a/lib/ble/ble_engine.dart +++ b/lib/ble/ble_engine.dart @@ -682,6 +682,8 @@ class _Session { /// First-START retries this session ([kHistoryNoStartRetriesPerSession]). /// Reset by an accepted HISTORY_START. int noStartRetries = 0; + /// Inbound notification tally + the post-request capture window (logs only). + final NotifyDiag rx = NotifyDiag(); /// Banks the foreign buffer once another client's transfer goes quiet /// ([BleEngine._flushForeignBuffer]); re-armed per drained batch with a /// foreign record in it. @@ -3921,6 +3923,35 @@ class BleEngine { return resp != null; } + /// Last GATT table logged; an identical table on reconnect is not re-logged. + String? _lastGattTable; + + /// Every discovered service and characteristic with its properties + /// (r=read w=write W=write-no-response n=notify i=indicate), so a report + /// shows what the band exposes next to what we subscribed to. + void _logGattTable(List services) { + String props(CharacteristicProperties p) => [ + if (p.read) 'r', + if (p.write) 'w', + if (p.writeWithoutResponse) 'W', + if (p.notify) 'n', + if (p.indicate) 'i', + ].join(); + final table = [ + for (final s in services) + '${s.uuid.str128}{${[ + for (final c in s.characteristics) + '${c.uuid.str128}:${props(c.properties)}', + ].join(' ')}}', + ].join(' '); + if (table == _lastGattTable) { + _log('[GATT] ${services.length} services (same table as last connect).'); + return; + } + _lastGattTable = table; + _log('[GATT] ${services.length} services: $table'); + } + /// The ONE service-discovery and characteristic-validation path. /// /// BOTH connect routes come here — `_FbpGattOps.discoverAndValidate` on the @@ -3944,6 +3975,7 @@ class BleEngine { Future<_DiscoveredBand?> _discoverBand(BluetoothDevice device) async { final services = await device.discoverServices().timeout(_serviceDiscoveryTimeout); + _logGattTable(services); // Pin the band from whichever registered service the peripheral exposes. // This drives the frame header/CRC, command envelope, ACK, and record // decode for the session. @@ -4585,6 +4617,8 @@ class BleEngine { String role, ) async { await c.setNotifyValue(true).timeout(_notifySetupTimeout); + _log('[GATT] subscribed $role ${c.uuid.str128} ' + 'isNotifying=${c.isNotifying}'); session.subs.add( c.onValueReceived.listen((chunk) => _onChunk(session, role, chunk)), ); @@ -4596,6 +4630,7 @@ class BleEngine { // tearing down: ingress is frozen from the first line of the teardown. if (_session != session || !session.connected || session.closing) return; _lastRx = DateTime.now(); + session.rx.chunk(role, chunk); // A malformed/corrupt chunk (framer bug on an unusual firmware // revision) must not become an uncaught async error that silently // stops this characteristic's whole notification stream — degrade @@ -4603,6 +4638,12 @@ class BleEngine { // failure path in this file. try { for (final frame in session.asm[role]!.feed(chunk)) { + session.rx.frame( + role, + frame.decodable + ? '0x${frame.packetType.toRadixString(16)}' + : (frame.valid ? 'rev?' : 'crc'), + ); if (frame.decodable) { _onFrame(role, frame, session); } else if (frame.valid) { @@ -4690,9 +4731,12 @@ class BleEngine { BluetoothCharacteristic c, ) async { await c.setNotifyValue(true).timeout(_notifySetupTimeout); + _log('[GATT] subscribed memfault ${c.uuid.str128} ' + 'isNotifying=${c.isNotifying}'); session.subs.add( c.onValueReceived.listen((chunk) { if (_session != session || !session.connected) return; + session.rx.chunk('memfault', chunk); _onMemfaultChunk(chunk); }), ); @@ -6144,6 +6188,9 @@ class BleEngine { 'layout these offsets read (body ${h.rawHex.length ~/ 2}B) — ' 'serial, battery, charge and wrist state are NOT published or ' 'logged; the connection continues.'); + _log('[HELLO gen5] rev${h.helloRevision} ' + 'fw=${(h.helloRevision == 3 ? gen5HelloRev3Firmware(h.rawHex) : null) ?? '?'} ' + 'body=${h.rawHex}'); } } if (d.kind == 'realtime_hr') { @@ -6442,6 +6489,7 @@ class BleEngine { if (_sessionIsStale(session) || _historyTaskGen != taskGen) return; // The band can answer before the write future resolves. if (_historyTaskAnsweredGen == taskGen) return; + session.rx.openWindow(); session.firstStartWatchdog = Timer( const Duration(seconds: kHistoryFirstStartTimeoutSeconds), () { @@ -6474,6 +6522,7 @@ class BleEngine { } _historyTaskAnsweredGen = _historyTaskGen; session.cancelFirstStartWatchdog(); + session.rx.closeWindow(); } /// The band never answered this task's SEND_HISTORICAL_DATA. End the task @@ -6493,6 +6542,9 @@ class BleEngine { _log('[SYNC] no answer to SEND_HISTORICAL_DATA within ' '${kHistoryFirstStartTimeoutSeconds}s — ending the request with one ' 'abort${retry ? '; one retry after settle' : '; no further retry this session'}.'); + _log('[DIAG] inbound since SEND_HISTORICAL_DATA: ' + '${session.rx.closeWindow()} | session rx ${session.rx.totals()} ' + 'crc=$_crcFailuresThisSession revRejects=$_frameRevRejectsTotal'); session.historicalRetry?.cancel(); // The terminal owns everything else: historyTaskEnded latch, generation // bump, waiter release, abort write, offload release in its finally. diff --git a/lib/ble/ble_state.dart b/lib/ble/ble_state.dart index cf0457582..6641f3284 100644 --- a/lib/ble/ble_state.dart +++ b/lib/ble/ble_state.dart @@ -2352,3 +2352,74 @@ Future withSecondaryLinkSlot( releaseSecondaryLinkSlot(); } } + +/// Firmware version from a revision-3 gen5 HELLO body (hex): bytes 96..99 are +/// major, minor, patch, build. Null when the body is too short. Diagnostics +/// only — the revision-1 map stays the only one anything is published from. +String? gen5HelloRev3Firmware(String bodyHex) { + if (bodyHex.length < 200) return null; + int b(int i) => int.parse(bodyHex.substring(i * 2, i * 2 + 2), radix: 16); + return '${b(96)}.${b(97)}.${b(98)}.${b(99)}'; +} + +/// Per-session inbound notification tally plus an optional capped capture +/// window, so a log can say what (if anything) arrived after a request the +/// band accepted but never acted on. Pure bookkeeping, no behaviour. +class NotifyDiag { + static const int maxChunks = 40; + static const int prefixBytes = 12; + + final Map chunks = {}; + final Map bytes = {}; + bool _windowOpen = false; + final List _windowChunks = []; + final Map _windowFrames = {}; + int _windowDropped = 0; + + /// Start (or restart) the capture window. + void openWindow() { + _windowOpen = true; + _windowChunks.clear(); + _windowFrames.clear(); + _windowDropped = 0; + } + + void chunk(String role, List data) { + chunks[role] = (chunks[role] ?? 0) + 1; + bytes[role] = (bytes[role] ?? 0) + data.length; + if (!_windowOpen) return; + if (_windowChunks.length >= maxChunks) { + _windowDropped++; + return; + } + final n = data.length < prefixBytes ? data.length : prefixBytes; + final hex = [ + for (final x in data.take(n)) x.toRadixString(16).padLeft(2, '0'), + ].join(); + _windowChunks.add('$role/${data.length}B:$hex'); + } + + /// One reassembled frame (or reject) seen inside the window. [kind] is the + /// packet type for a decodable frame, or `rev?` / `crc` for a reject. + void frame(String role, String kind) { + if (!_windowOpen) return; + final k = '$role:$kind'; + _windowFrames[k] = (_windowFrames[k] ?? 0) + 1; + } + + String totals() => chunks.isEmpty + ? 'none' + : [for (final r in chunks.keys) '$r=${chunks[r]}/${bytes[r]}B'].join(' '); + + /// Close the window and render it as one line. + String closeWindow() { + _windowOpen = false; + final frames = _windowFrames.isEmpty + ? 'none' + : [for (final e in _windowFrames.entries) '${e.key}=${e.value}'] + .join(' '); + final list = _windowChunks.isEmpty ? 'none' : _windowChunks.join(' '); + final more = _windowDropped > 0 ? ' (+$_windowDropped more)' : ''; + return 'frames[$frames] chunks[$list]$more'; + } +} diff --git a/test/notify_diag_test.dart b/test/notify_diag_test.dart new file mode 100644 index 000000000..9e3fef143 --- /dev/null +++ b/test/notify_diag_test.dart @@ -0,0 +1,29 @@ +import 'package:flutter_test/flutter_test.dart'; +import 'package:openstrap_edge/ble/ble_state.dart'; + +void main() { + test('rev3 hello firmware reads bytes 96..99', () { + final body = List.filled(111, 0); + body.setAll(96, [50, 43, 2, 0]); + final hex = + body.map((b) => b.toRadixString(16).padLeft(2, '0')).join(); + expect(gen5HelloRev3Firmware(hex), '50.43.2.0'); + expect(gen5HelloRev3Firmware(hex.substring(0, 198)), isNull); + }); + + test('notify diag captures only inside the window, capped', () { + final d = NotifyDiag(); + d.chunk('data', [1, 2, 3]); + expect(d.closeWindow(), 'frames[none] chunks[none]'); + d.openWindow(); + d.chunk('cmd_from', [0xaa, 0x01]); + d.frame('cmd_from', '0x24'); + for (var i = 0; i < NotifyDiag.maxChunks + 2; i++) { + d.chunk('events', [0x30]); + } + final s = d.closeWindow(); + expect(s, startsWith('frames[cmd_from:0x24=1] chunks[cmd_from/2B:aa01 ')); + expect(s, endsWith('(+3 more)')); + expect(d.totals(), 'data=1/3B cmd_from=1/2B events=42/42B'); + }); +}