From 073d825a3e54e8f8ab7038aa75a761adb8e56db2 Mon Sep 17 00:00:00 2001 From: Yandrik Date: Mon, 4 May 2026 14:51:53 +0200 Subject: [PATCH] dev: add some logging for dfu --- lib/pages/device_details_page.dart | 25 ++++ lib/service/firmware_update_service.dart | 180 ++++++++++++++++++++++- 2 files changed, 204 insertions(+), 1 deletion(-) diff --git a/lib/pages/device_details_page.dart b/lib/pages/device_details_page.dart index 638d2f7..55d2efa 100644 --- a/lib/pages/device_details_page.dart +++ b/lib/pages/device_details_page.dart @@ -13,11 +13,14 @@ import 'package:abawo_bt_app/widgets/gear_ratio_editor_card.dart'; import 'package:flutter/material.dart'; import 'package:flutter_riverpod/flutter_riverpod.dart'; import 'package:go_router/go_router.dart'; +import 'package:logging/logging.dart'; import 'package:nb_utils/nb_utils.dart'; import '../controller/bluetooth.dart'; import '../database/database.dart'; +final _log = Logger('DeviceDetailsPage'); + class DeviceDetailsPage extends ConsumerStatefulWidget { const DeviceDetailsPage({ required this.deviceAddress, @@ -139,6 +142,10 @@ class _DeviceDetailsPageState extends ConsumerState { @override void dispose() { + _log.info( + 'Disposing device details page for ${widget.deviceAddress}; ' + 'dfuState=${_dfuProgress.state}, isFirmwareUpdateBusy=$_isFirmwareUpdateBusy', + ); unawaited(_disconnectOnClose()); _connectionStatusSubscription?.close(); _statusSubscription?.cancel(); @@ -150,10 +157,12 @@ class _DeviceDetailsPageState extends ConsumerState { Future _disconnectOnClose() async { if (_isFirmwareUpdateBusy) { + _log.info('Skipping disconnect on close because firmware update is busy'); return; } if (_hasRequestedDisconnect) { + _log.fine('Disconnect on close already requested'); return; } @@ -174,6 +183,13 @@ class _DeviceDetailsPageState extends ConsumerState { final (status, connectedDeviceId) = data; final isCurrentDevice = connectedDeviceId == widget.deviceAddress; + if (_isFirmwareUpdateBusy || _dfuProgress.state != DfuUpdateState.idle) { + _log.info( + 'Connection update during firmware flow: status=$status, ' + 'connectedDevice=$connectedDeviceId, expected=${widget.deviceAddress}, ' + 'isCurrentDevice=$isCurrentDevice, dfuState=${_dfuProgress.state}', + ); + } if (isCurrentDevice && status == ConnectionStatus.connected) { _startStatusStreamingIfNeeded(); @@ -520,6 +536,11 @@ class _DeviceDetailsPageState extends ConsumerState { if (!mounted) { return; } + _log.info( + 'Firmware progress: state=${progress.state}, ' + 'sent=${progress.sentBytes}/${progress.totalBytes}, ' + 'expectedOffset=${progress.expectedOffset}, error=${progress.errorMessage}', + ); setState(() { _dfuProgress = progress; if (progress.state == DfuUpdateState.failed && @@ -744,6 +765,7 @@ class _DeviceDetailsPageState extends ConsumerState { Future _exitPage() async { if (_isFirmwareUpdateBusy) { + _log.warning('Blocked page exit while firmware update is busy'); ScaffoldMessenger.of(context).showSnackBar( const SnackBar( content: Text( @@ -753,6 +775,7 @@ class _DeviceDetailsPageState extends ConsumerState { return; } + _log.info('Exiting device details page to /devices'); await _disconnectOnClose(); if (!mounted) { return; @@ -761,6 +784,8 @@ class _DeviceDetailsPageState extends ConsumerState { } void _dismissFirmwareFullscreen() { + _log.info( + 'Dismissing firmware fullscreen from state ${_dfuProgress.state}'); setState(() { _dfuProgress = const DfuUpdateProgress( state: DfuUpdateState.idle, diff --git a/lib/service/firmware_update_service.dart b/lib/service/firmware_update_service.dart index b2f7e7e..26d6398 100644 --- a/lib/service/firmware_update_service.dart +++ b/lib/service/firmware_update_service.dart @@ -7,6 +7,9 @@ import 'package:abawo_bt_app/service/shifter_service.dart'; import 'package:anyhow/anyhow.dart'; import 'package:flutter_reactive_ble/flutter_reactive_ble.dart' show DiscoveredDevice, Uuid; +import 'package:logging/logging.dart'; + +final _log = Logger('FirmwareUpdateService'); class FirmwareUpdateService { FirmwareUpdateService({ @@ -116,6 +119,14 @@ class FirmwareUpdateService { var startAccepted = false; + _log.info( + 'Starting firmware update: bytes=${imageBytes.length}, ' + 'session=$normalizedSessionId, appStart=0x${appStart.toRadixString(16)}, ' + 'imageVersion=$imageVersion, flags=0x${flags.rawValue.toRadixString(16)}, ' + 'crc32=0x${imageCrc32.toRadixString(16).padLeft(8, '0')}, ' + 'requestedMtu=$requestedMtu', + ); + _emitProgress( state: DfuUpdateState.starting, totalBytes: imageBytes.length, @@ -130,8 +141,17 @@ class FirmwareUpdateService { _throwIfCancelled(); _emitProgress(state: DfuUpdateState.enteringBootloader); final alreadyInBootloader = await _isConnectedToBootloader(); + _log.info( + 'Bootloader connection check: alreadyInBootloader=$alreadyInBootloader'); if (!alreadyInBootloader) { + _log.info('Requesting app to enter bootloader mode'); final enterResult = await _transport.enterBootloader(); + if (enterResult.isErr()) { + _log.warning( + 'Enter bootloader command returned an error; waiting for disconnect anyway: ' + '${enterResult.unwrapErr()}', + ); + } final appDisconnectResult = await _transport.waitForAppDisconnect( timeout: effectiveBootloaderConnectTimeout, ); @@ -146,12 +166,15 @@ class FirmwareUpdateService { ); } + _log.info('App disconnected for bootloader mode'); + _emitProgress(state: DfuUpdateState.connectingBootloader); await _connectToBootloader(timeout: effectiveBootloaderConnectTimeout); } await _optimizeBootloaderConnection(); + _log.info('Negotiating bootloader MTU: requested=$requestedMtu'); final mtuResult = await _transport.negotiateMtu(requestedMtu: requestedMtu); if (mtuResult.isErr()) { @@ -159,6 +182,7 @@ class FirmwareUpdateService { 'Could not negotiate bootloader DFU MTU: ${mtuResult.unwrapErr()}', ); } + _log.info('Bootloader MTU negotiated: ${mtuResult.unwrap()}'); final payloadSize = BootloaderDfuProtocol.maxPayloadSizeForMtu( mtuResult.unwrap(), ); @@ -167,12 +191,14 @@ class FirmwareUpdateService { 'Negotiated MTU ${mtuResult.unwrap()} is too small for bootloader DFU frames.', ); } + _log.info('Bootloader DFU payload size selected: $payloadSize bytes'); await _subscribeToStatus(); _emitProgress(state: DfuUpdateState.waitingForStatus); await _readInitialStatus(); _emitProgress(state: DfuUpdateState.erasing); + _log.info('Sending START command'); final startStatus = await _sendStartAndWaitForStatus( startPayload, timeout: effectiveStatusTimeout, @@ -184,8 +210,13 @@ class FirmwareUpdateService { operation: 'START', ); startAccepted = true; + _log.info( + 'START accepted: session=${startStatus.sessionId}, ' + 'expectedOffset=${startStatus.expectedOffset}', + ); _emitProgress(state: DfuUpdateState.transferring); + _log.info('Starting firmware transfer'); await _transferImage( imageBytes: imageBytes, sessionId: normalizedSessionId, @@ -194,6 +225,7 @@ class FirmwareUpdateService { statusTimeout: effectiveStatusTimeout, bootloaderConnectTimeout: effectiveBootloaderConnectTimeout, ); + _log.info('Firmware transfer completed; sending FINISH'); _emitProgress(state: DfuUpdateState.finishing); await _writeFinishAndWaitForReset( @@ -208,6 +240,7 @@ class FirmwareUpdateService { _emitProgress( state: DfuUpdateState.rebooting, sentBytes: imageBytes.length); + _log.info('Bootloader reset observed after FINISH'); if (!verifyAfterFinish) { _emitProgress( @@ -219,6 +252,7 @@ class FirmwareUpdateService { } _emitProgress(state: DfuUpdateState.verifying); + _log.info('Reconnecting to updated app for verification'); final reconnectResult = await _transport.reconnectForVerification( timeout: effectiveReconnectTimeout, ); @@ -228,6 +262,7 @@ class FirmwareUpdateService { ); } + _log.info('Updated app reconnected; verifying status characteristic'); final verificationResult = await _transport.verifyDeviceReachable( timeout: effectiveVerificationTimeout, ); @@ -242,20 +277,24 @@ class FirmwareUpdateService { sentBytes: imageBytes.length, expectedOffset: imageBytes.length, ); + _log.info('Firmware update completed successfully'); return Ok(null); } on _DfuCancelled { + _log.warning('Firmware update canceled by user'); if (startAccepted) { await _sendAbortForCancel(normalizedSessionId); } _emitProgress(state: DfuUpdateState.aborted); return bail('Firmware update canceled by user.'); } on _DfuFailure catch (failure) { + _log.severe('Firmware update failed: ${failure.message}'); _emitProgress( state: DfuUpdateState.failed, errorMessage: failure.message); return bail(failure.message); - } catch (error) { + } catch (error, stackTrace) { final message = 'Firmware update failed unexpectedly: $error. Reconnect to the button or bootloader and retry.'; + _log.severe(message, error, stackTrace); _emitProgress(state: DfuUpdateState.failed, errorMessage: message); return bail(message); } finally { @@ -291,24 +330,30 @@ class FirmwareUpdateService { Future _subscribeToStatus() async { await _statusSubscription?.cancel(); _statusStreamError = null; + _log.info('Subscribing to bootloader DFU status indications'); _statusSubscription = _transport.subscribeToStatus().listen( _handleStatusPayload, onError: (Object error) { _statusStreamError = 'Bootloader status indication stream failed: $error. Reconnect and retry the update.'; + _log.severe(_statusStreamError); _signalStatusWaiters(); }, ); } Future _readInitialStatus() async { + _log.info('Reading initial bootloader DFU status'); final statusResult = await _transport.readStatus(); if (statusResult.isErr()) { + _log.warning( + 'Initial bootloader DFU status read failed: ${statusResult.unwrapErr()}'); throw _DfuFailure( 'Could not read initial bootloader DFU status: ${statusResult.unwrapErr()}', ); } _handleStatusPayload(statusResult.unwrap()); + _log.info('Initial bootloader DFU status read succeeded'); } Future _transferImage({ @@ -389,9 +434,15 @@ class FirmwareUpdateService { } on _DfuFailure catch (failure) { if (!failure.recoverable || reconnectResumeAttempts >= maxReconnectResumeAttempts) { + _log.warning( + 'Transfer failure is not recoverable: ${failure.message}'); rethrow; } reconnectResumeAttempts += 1; + _log.warning( + 'Recoverable transfer failure, reconnect attempt ' + '$reconnectResumeAttempts/$maxReconnectResumeAttempts: ${failure.message}', + ); final recoveredStatus = await _recoverTransferStatus( timeout: statusTimeout, bootloaderConnectTimeout: bootloaderConnectTimeout, @@ -445,6 +496,8 @@ class FirmwareUpdateService { } Future _connectToBootloader({required Duration timeout}) async { + _log.info( + 'Connecting to bootloader with timeout ${timeout.inMilliseconds}ms'); final bootloaderConnectResult = await _transport.connectToBootloader( timeout: timeout, ); @@ -453,13 +506,19 @@ class FirmwareUpdateService { 'Could not connect to bootloader DFU mode: ${bootloaderConnectResult.unwrapErr()}', ); } + _log.info('Connected to bootloader'); } Future _optimizeBootloaderConnection() async { + _log.info('Optimizing bootloader connection'); final result = await _transport.optimizeBootloaderConnection(); if (result.isErr()) { + _log.warning( + 'Bootloader connection optimization failed: ${result.unwrapErr()}'); _emitProgress(errorMessage: result.unwrapErr().toString()); + return; } + _log.info('Bootloader connection optimization completed'); } Future _sendStartAndWaitForStatus( @@ -500,8 +559,16 @@ class FirmwareUpdateService { bool recoverable = false, }) async { final eventCount = _statusEventCount; + _log.fine( + 'Writing DFU control opcode 0x${payload.first.toRadixString(16).padLeft(2, '0')} ' + '(len=${payload.length}, recoverable=$recoverable)', + ); final result = await _transport.writeControl(payload); if (result.isErr()) { + _log.warning( + 'DFU control write failed for opcode ' + '0x${payload.first.toRadixString(16).padLeft(2, '0')}: ${result.unwrapErr()}', + ); throw _DfuFailure( 'Failed to write bootloader control command: ${result.unwrapErr()}', recoverable: recoverable, @@ -519,8 +586,17 @@ class FirmwareUpdateService { required Duration timeout, }) async { final eventCount = _statusEventCount; + if (frame.offset == 0 || frame.offset % 4096 == 0) { + _log.fine( + 'Writing DFU data frame: offset=${frame.offset}, ' + 'payload=${frame.payloadLength}, frameLen=${frame.bytes.length}', + ); + } final result = await _transport.writeDataFrame(frame.bytes); if (result.isErr()) { + _log.warning( + 'DFU data write failed at offset ${frame.offset}: ${result.unwrapErr()}', + ); throw _DfuFailure( 'Failed sending DFU data at offset ${frame.offset}: ${result.unwrapErr()}', recoverable: true, @@ -548,10 +624,15 @@ class FirmwareUpdateService { required Duration resetTimeout, }) async { final eventCount = _statusEventCount; + _log.info( + 'Writing FINISH command: session=$sessionId, expectedOffset=$expectedOffset, ' + 'resetTimeout=${resetTimeout.inMilliseconds}ms', + ); final result = await _transport.writeControl( BootloaderDfuProtocol.encodeFinishPayload(sessionId), ); if (result.isErr()) { + _log.warning('FINISH write failed: ${result.unwrapErr()}'); throw _DfuFailure( 'Failed to write bootloader control command: ${result.unwrapErr()}', ); @@ -577,10 +658,15 @@ class FirmwareUpdateService { timeout: remaining > Duration.zero ? remaining : Duration.zero, ); if (resetDisconnectResult.isErr()) { + _log.warning( + 'Bootloader reset disconnect wait failed after FINISH status: ' + '${resetDisconnectResult.unwrapErr()}', + ); throw _DfuFailure( 'Bootloader did not perform the expected post-FINISH reset disconnect: ${resetDisconnectResult.unwrapErr()}', ); } + _log.info('Bootloader reset disconnect observed after FINISH status'); return; } @@ -588,11 +674,15 @@ class FirmwareUpdateService { timeout: Duration.zero, ); if (disconnectResult.isOk()) { + _log.info( + 'Bootloader reset disconnect observed before FINISH status indication'); return; } final remaining = deadline.difference(DateTime.now()); if (remaining <= Duration.zero) { + _log.warning( + 'Timed out waiting for bootloader reset disconnect after FINISH'); throw _DfuFailure( 'Bootloader did not perform the expected post-FINISH reset disconnect within ${resetTimeout.inMilliseconds}ms.', ); @@ -624,11 +714,20 @@ class FirmwareUpdateService { _throwIfStatusStreamErrored(recoverable: recoverable); if (_statusEventCount > observedEvents && _latestStatus != null) { + _log.fine( + 'Received DFU status for wait: events=$_statusEventCount, ' + 'session=${_latestStatus!.sessionId}, offset=${_latestStatus!.expectedOffset}, ' + 'code=${_statusLabel(_latestStatus!)}', + ); return _latestStatus!; } final remaining = deadline.difference(DateTime.now()); if (remaining <= Duration.zero) { + _log.warning( + 'Timed out waiting for DFU status afterEventCount=$afterEventCount, ' + 'currentEventCount=$_statusEventCount', + ); throw _DfuFailure( 'Timed out waiting for bootloader DFU status. Reconnect and retry the update.', recoverable: recoverable, @@ -680,6 +779,10 @@ class FirmwareUpdateService { try { final status = BootloaderDfuProtocol.parseStatusPayload(payload); _latestStatus = status; + _log.fine( + 'Bootloader status: code=${_statusLabel(status)}, session=${status.sessionId}, ' + 'expectedOffset=${status.expectedOffset}, rawLen=${payload.length}', + ); final sentBytes = status.expectedOffset.clamp(0, _totalBytes).toInt(); _emitProgress( bootloaderStatus: status, @@ -689,6 +792,7 @@ class FirmwareUpdateService { } on FormatException catch (error) { _statusStreamError = 'Received malformed bootloader DFU status: $error. Reconnect and retry.'; + _log.severe('Malformed bootloader DFU status payload: $payload', error); } finally { _statusEventCount += 1; _signalStatusWaiters(); @@ -859,6 +963,10 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { @override Future> isConnectedToBootloader() async { final currentState = bluetoothController.currentConnectionState; + _log.info( + 'Checking current connection for bootloader service: ' + 'state=${currentState.$1}, device=${currentState.$2}', + ); if (currentState.$1 != ConnectionStatus.connected || currentState.$2 == null) { return Ok(false); @@ -870,9 +978,14 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { universalShifterDfuStatusCharacteristicUuid, ); if (statusResult.isErr()) { + _log.info( + 'Connected device does not expose bootloader status characteristic: ' + '${statusResult.unwrapErr()}', + ); return Ok(false); } _bootloaderDeviceId = currentState.$2; + _log.info('Current connection is bootloader: $_bootloaderDeviceId'); return Ok(true); } @@ -893,27 +1006,41 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { @override Future> connectToBootloader({required Duration timeout}) async { final currentState = bluetoothController.currentConnectionState; + _log.info( + 'Transport connectToBootloader: state=${currentState.$1}, ' + 'currentDevice=${currentState.$2}, cachedBootloader=$_bootloaderDeviceId, ' + 'buttonDevice=$buttonDeviceId', + ); if (currentState.$1 == ConnectionStatus.connected && currentState.$2 == _bootloaderDeviceId && _bootloaderDeviceId != null) { + _log.info('Already connected to cached bootloader $_bootloaderDeviceId'); return Ok(null); } if (shifterService == null) { _bootloaderDeviceId = buttonDeviceId; + _log.info( + 'Recovery mode: connecting directly to bootloader id $buttonDeviceId'); return bluetoothController.connectById( buttonDeviceId, timeout: timeout, ); } + _log.info('Scanning for bootloader advertisement'); final scanResult = await _scanForBootloader(timeout: timeout); if (scanResult.isErr()) { + _log.warning('Bootloader scan failed: ${scanResult.unwrapErr()}'); return Err(scanResult.unwrapErr()); } final bootloaderDevice = scanResult.unwrap(); _bootloaderDeviceId = bootloaderDevice.id; + _log.info( + 'Bootloader advertisement selected: id=${bootloaderDevice.id}, ' + 'name=${bootloaderDevice.name}, rssi=${bootloaderDevice.rssi}', + ); return bluetoothController.connectById( bootloaderDevice.id, timeout: timeout, @@ -946,6 +1073,7 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { @override Stream> subscribeToStatus() { final deviceId = _requireBootloaderDeviceId().unwrap(); + _log.info('Transport subscribeToStatus on bootloader $deviceId'); return bluetoothController.subscribeToCharacteristic( deviceId, universalShifterControlServiceUuid, @@ -959,6 +1087,7 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { if (deviceId.isErr()) { return Future.value(Err(deviceId.unwrapErr())); } + _log.info('Transport readStatus from bootloader ${deviceId.unwrap()}'); return bluetoothController.readCharacteristic( deviceId.unwrap(), universalShifterControlServiceUuid, @@ -972,6 +1101,10 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { if (deviceId.isErr()) { return Future.value(Err(deviceId.unwrapErr())); } + _log.fine( + 'Transport writeControl to ${deviceId.unwrap()}: ' + 'opcode=0x${payload.first.toRadixString(16).padLeft(2, '0')}, len=${payload.length}', + ); return bluetoothController.writeCharacteristic( deviceId.unwrap(), universalShifterControlServiceUuid, @@ -986,6 +1119,10 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { if (deviceId.isErr()) { return Future.value(Err(deviceId.unwrapErr())); } + if (frame.length >= universalShifterBootloaderDfuDataHeaderSizeBytes) { + _log.fine( + 'Transport writeDataFrame to ${deviceId.unwrap()}: len=${frame.length}'); + } return bluetoothController.writeCharacteristic( deviceId.unwrap(), universalShifterControlServiceUuid, @@ -1003,15 +1140,22 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { @override Future> reconnectForVerification( {required Duration timeout}) async { + _log.info( + 'Transport reconnectForVerification to app id $buttonDeviceId ' + 'with timeout ${timeout.inMilliseconds}ms', + ); final connectResult = await bluetoothController.connectById(buttonDeviceId, timeout: timeout); if (connectResult.isErr()) { + _log.warning( + 'Updated app reconnect connectById failed: ${connectResult.unwrapErr()}'); return Err(connectResult.unwrapErr()); } final currentState = bluetoothController.currentConnectionState; if (currentState.$1 == ConnectionStatus.connected && currentState.$2 == buttonDeviceId) { + _log.info('Updated app reconnect completed immediately'); return Ok(null); } @@ -1023,12 +1167,15 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { state.$2 == buttonDeviceId, ) .timeout(timeout); + _log.info('Updated app reconnect observed on connection stream'); return Ok(null); } on TimeoutException { + _log.warning('Timed out waiting for updated app reconnect stream event'); return bail( 'Timed out after ${timeout.inMilliseconds}ms waiting for updated app reconnect.', ); } catch (error) { + _log.warning('Updated app reconnect wait failed: $error'); return bail('Updated app reconnect wait failed: $error'); } } @@ -1037,6 +1184,10 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { Future> verifyDeviceReachable( {required Duration timeout}) async { try { + _log.info( + 'Reading updated app status characteristic for verification ' + '(timeout ${timeout.inMilliseconds}ms)', + ); final statusResult = await bluetoothController .readCharacteristic( buttonDeviceId, @@ -1045,15 +1196,20 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { ) .timeout(timeout); if (statusResult.isErr()) { + _log.warning( + 'Updated app status verification read failed: ${statusResult.unwrapErr()}'); return Err(statusResult.unwrapErr()); } CentralStatus.fromBytes(statusResult.unwrap()); + _log.info('Updated app status verification succeeded'); return Ok(null); } on TimeoutException { + _log.warning('Timed out reading updated app status for verification'); return bail( 'Timed out after ${timeout.inMilliseconds}ms while reading status for post-update verification.', ); } catch (error) { + _log.warning('Post-update verification failed: $error'); return bail('Post-update verification failed: $error'); } } @@ -1063,6 +1219,10 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { required String label, }) async { final currentState = bluetoothController.currentConnectionState; + _log.fine( + 'Waiting for $label disconnect: currentState=${currentState.$1}, ' + 'device=${currentState.$2}, timeout=${timeout.inMilliseconds}ms', + ); if (currentState.$1 == ConnectionStatus.disconnected) { return Ok(null); } @@ -1071,12 +1231,15 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { await bluetoothController.connectionStateStream .firstWhere((state) => state.$1 == ConnectionStatus.disconnected) .timeout(timeout); + _log.info('$label disconnect observed'); return Ok(null); } on TimeoutException { + _log.warning('Timed out waiting for $label disconnect'); return bail( 'Timed out after ${timeout.inMilliseconds}ms waiting for $label disconnect.', ); } catch (error) { + _log.warning('Failed while waiting for $label disconnect: $error'); return bail('Failed while waiting for $label disconnect: $error'); } } @@ -1085,6 +1248,10 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { required Duration timeout, }) async { final serviceUuid = Uuid.parse(universalShifterControlServiceUuid); + _log.info( + 'Starting bootloader scan: service=$universalShifterControlServiceUuid, ' + 'timeout=${timeout.inMilliseconds}ms', + ); final scanResult = await bluetoothController.startScan( withServices: [serviceUuid], timeout: timeout, @@ -1096,12 +1263,17 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { try { DiscoveredDevice? immediate; for (final device in bluetoothController.scanResults) { + _log.fine( + 'Bootloader scan cached result: id=${device.id}, name=${device.name}, ' + 'rssi=${device.rssi}, services=${device.serviceUuids.length}', + ); if (_isBootloaderAdvertisement(device)) { immediate = device; break; } } if (immediate != null) { + _log.info('Bootloader found in cached scan results: ${immediate.id}'); return Ok(immediate); } @@ -1109,12 +1281,18 @@ class ShifterFirmwareUpdateTransport implements FirmwareUpdateTransport { .expand((devices) => devices) .firstWhere(_isBootloaderAdvertisement) .timeout(timeout); + _log.info( + 'Bootloader found from scan stream: id=${device.id}, name=${device.name}, ' + 'rssi=${device.rssi}', + ); return Ok(device); } on TimeoutException { + _log.warning('Timed out scanning for bootloader advertisement'); return bail( 'Timed out after ${timeout.inMilliseconds}ms scanning for US-DFU bootloader.', ); } catch (error) { + _log.warning('Bootloader scan failed: $error'); return bail('Bootloader scan failed: $error'); } finally { await bluetoothController.stopScan();