dev: add some logging for dfu

This commit is contained in:
2026-05-04 14:51:53 +02:00
parent bcccd03ecc
commit 073d825a3e
2 changed files with 204 additions and 1 deletions

View File

@ -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<void> _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<void> _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<void> _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<void> _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<void> _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<DfuBootloaderStatus> _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<Result<bool>> 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<Result<void>> 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<List<int>> 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<Result<void>> 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<Result<void>> 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();