NordicSemiconductor / Flutter-nRF-Connect-Device-Manager

A Flutter plugin for McuMgr libraries for Android and iOS.
BSD 3-Clause "New" or "Revised" License
36 stars 17 forks source link

Basic upgrade fails because stream is already closed #63

Closed Laur1nMartins closed 8 months ago

Laur1nMartins commented 8 months ago

Using

 final image = await widget.image.getSelectedFwContent();

    // `deviceId` is a String with the device's MAC address (on Android) or UUID (on iOS)
    final updateManager = await FirmwareUpdateManagerFactory()
        .getUpdateManager(device.connectedDevice!.remoteId.str);
    // call `setup` before using the manager
    final stream = updateManager.setup();

    stream.listen((event) {
      if (event == FirmwareUpgradeState.success) {
        logger.d("Update Success");
      } else {
        logger.d("updateStateStream $event");
      }
    });

    updateManager.progressStream.listen((event) {
      logger.d("${event.bytesSent} / ${event.imageSize}} bytes sent");
    });

    updateManager.logger.logMessageStream
        .where((log) => log.level.rawValue > 1) // filter out debug messages
        .listen((log) {
      logger.d(log.message);
    });

    await updateManager.updateWithImageData(image: image);

    await updateManager.kill();

results in

E/flutter ( 8564): [ERROR:flutter/runtime/dart_vm_initializer.cc(41)] Unhandled Exception: Bad state: Cannot add new events after calling close
E/flutter ( 8564): #0      _BroadcastStreamController.add (dart:async/broadcast_stream_controller.dart:243:24)
E/flutter ( 8564): #1      DeviceUpdateManager._setupUpdateStateStream.<anonymous closure> (package:mcumgr_flutter/src/mcumgr_update_manager.dart:179:37)
E/flutter ( 8564): #2      _RootZone.runUnaryGuarded (dart:async/zone.dart:1594:10)
E/flutter ( 8564): #3      _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:339:11)
E/flutter ( 8564): #4      _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271:7)
E/flutter ( 8564): #5      _ForwardingStreamSubscription._add (dart:async/stream_pipe.dart:123:11)
E/flutter ( 8564): #6      _WhereStream._handleData (dart:async/stream_pipe.dart:195:12)
E/flutter ( 8564): #7      _ForwardingStreamSubscription._handleData (dart:async/stream_pipe.dart:153:13)
E/flutter ( 8564): #8      _RootZone.runUnaryGuarded (dart:async/zone.dart:1594:10)
E/flutter ( 8564): #9      _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:339:11)
E/flutter ( 8564): #10     _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271:7)
E/flutter ( 8564): #11     _ForwardingStreamSubscription._add (dart:async/stream_pipe.dart:123:11)
E/flutter ( 8564): #12     _MapStream._handleData (dart:async/stream_pipe.dart:218:10)
E/flutter ( 8564): #13     _ForwardingStreamSubscription._handleData (dart:async/stream_pipe.dart:153:13)
E/flutter ( 8564): #14     _RootZone.runUnaryGuarded (dart:async/zone.dart:1594:10)
E/flutter ( 8564): #15     _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:339:11)
E/flutter ( 8564): #16     _DelayedData.perform (dart:async/stream_impl.dart:515:14)
E/flutter ( 8564): #17     _PendingEvents.handleNext (dart:async/stream_impl.dart:620:11)
E/flutter ( 8564): #18     _PendingEvents.schedule.<anonymous closure> (dart:async/stream_impl.dart:591:7)
E/flutter ( 8564): #19     _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
E/flutter ( 8564): #20     _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)
E/flutter ( 8564): 

The log shows that the connection was successful and the last received messages shows the current DFU state.

I/flutter ( 8564): {"t":"2024-03-06T18:15:52.229937","level":"Level.debug","msg":"Received Header (Version: 0, Op: 1, Flags: 0, Len: 246, Group: 1, Seq: 0, Command: 0) CBOR {\"images\":[{\"slot\":0,\"version\":\"0.3.0\",\"hash\":\"n/waqQy08RuxzV5Sh8jrSJs5OCUcpzKKYM6677ydN60=\",\"bootable\":true,\"pending\":false,\"confirmed\":true,\"active\":true,\"permanent\":false},{\"slot\":1,\"version\":\"0.2.9.1\",\"hash\":\"GiXHB9DsKb0nspIxdlu4uEnPfZjPNZ0K0Wwe+OVeqoM=\",\"bootable\":true,\"pending\":false,\"confirmed\":false,\"active\":false,\"permanent\":false}],\"splitStatus\":0}","error":"null","stacktrace":[]}

So the question is what am I doing wrong here? Looking at the example code didnt really help me sorry.

And I also saw that when the app is already connected to the device the connection gets duplicated every time I run the above code. So each run of the code creates a new connection.

Is it recommended to disconnect the app connection before using the DFU functionality?

NickKibish commented 8 months ago

Hi @Laur1nMartins ,

It seems you are using the kill method prematurely. It should only be called after the update process is finished, whether it concludes with an error or success. In your case, the corrected code would look like this:

final updateManager = await FirmwareUpdateManagerFactory()
    .getUpdateManager(device.connectedDevice!.remoteId.str);

final stream = updateManager.setup();

stream.listen((event) {},
    onDone: () async => await updateManager.kill(),
    onError: (error) async => await updateManager.kill());

await updateManager.updateWithImageData(image: fwImage!);

Please note that the await before updateManager.updateWithImageData(image: fwImage!); doesn't indicate waiting for the update to finish. It simply waits for the update request to be sent to the device.

Alternatively, you can listen to the stream from the updateManager.setup() method or updateManager.updateStateStream to detect when the update is completed.

Consider the kill() method as a clear operation to close all opened streams.

Let me know if you have any further questions or concerns.

Laur1nMartins commented 8 months ago

Thank you very much for the fast reply!

Moving the kill() into the onDone and onError of the stream did fix the error that I encountered.

Could please be so kind and update the readme so that others don't make the same mistake I did? I imagine that having the code you posted as a minimal example would be very nice in conjunction with what's already there.

But unfortunately the fix didn't lead me to a working version yet.

It seems like the update process still stops directly after getting the above mentioned final log line. But directly after that log line I now see

I/flutter ( 8600): {"t":"2024-03-06T23:48:09.209157","level":"Level.debug","msg":"Update Success","error":"null","stacktrace":[]}

indicating that the stream is closed by the library but no transfer of the image was done. The whole thing takes about a second and the device shows no sign of having received any new image on the second slot and logs don't show anything related to transferring the image. Also the logger.d("updateStateStream $event"); is not getting logged at all. So the only events is see are success and onDone.

Just to confirm, for the firmware image I use the app_update.bin from a dfu_application.zip embedded in the app itself. Is that the correct file to use here?

Another question: Is there a way to retrieve the image list from the device directly without starting the whole upgrade process?

NickKibish commented 8 months ago

I understand that troubleshooting this issue can be challenging. To help you identify the problem, consider the following steps:

  1. Test with Example App:

    • Run the example app and give uploading firmware a shot. See if the issue pops up there too. Screenshot_20240307-200654
  2. Check out the Code:

    • firmware_update_handler.dart (Line 124): This is where the UpdateManager is created.
    • update_bloc.dart (Line 30): Explore how we handle updateState, progress, and logs.
  3. Multiimage Applications:

    • If it’s a multiimage application, consider using the update method instead of updateWithImageData. To get the hang of it, check how we unzip firmware and read the manifest file at firmware_update_handler.dart (line 92).

Now, I won't pretend this code is the epitome of clarity – I may not be a Flutter expert. But I hope it will give you some clue.

cc @philips77

Laur1nMartins commented 8 months ago

I did what you suggested (should have thought of that before opening an issue here...). Thanks to the example I could verify that my dfu_application.zip should work as intended. So the error must be in my code that I posted.

Looking at the code of the example didnt really give me any hints as to why my code is not working as I am pretty sure that there are no meaningful differences that I know of right now.

Getting back to the example code: It let me only select the .zip file and not the .bin for some reason even though the FilePicker in firmware_list.dart has bin as an allowed extension.

Regardless, the only difference seems to be that in my code I tried using a single image DFU and the example uses the multi image as it reads both images from the dfu_application.zip file as this is targeting a nRF5340.

Changing my code to use the multi image update function instead, made it suddenly work as intended. So DFU works now but only with the await updateManager.update(images);instead of the await updateManager.updateWithImageData(image: image);.

My final, now working, code looks like this

_applyUpdate() async {
    final images = await widget.image.getSelectedFwContent();

    final updateManager = await FirmwareUpdateManagerFactory()
        .getUpdateManager(device.connectedDevice!.remoteId.str);

    updateManager.setup();

    updateManager.updateStateStream!.listen(
      (event) {
        if (event == FirmwareUpgradeState.success) {
          logger.d("Update Success");
          setState(() {
            _showProgress = false;
          });
        } else {
          logger.d("updateStateStream $event");
        }
      },
      // cleanup afterwards
      onDone: () async => {
        await updateManager.kill(),
      },
      onError: (error) async => {
        logger.e("DFU failed", error),
        await updateManager.kill(),
      },
    );

    updateManager.progressStream.listen((event) {
      logger.d("${event.bytesSent} / ${event.imageSize}} bytes sent");
    });

    updateManager.logger.logMessageStream
        .listen((log) {
      logger.d(log.message);
    });

    await updateManager.update(images);
  }

What could possibly be the reason here from a library user perspective? Is there a configuration issue when using the .updateWithImageData(image: image) function?

To reiterate the problem I encountered: When using the single image update function the process stops before any data is uploaded. Using the multi image update function upgrades the firmware as expected without any issue. Both calls were done without any configuration done prior besides what is visible in the code I posted.

Thank you very much for your timely responses so far!

Edit: Problem was with mismatching version tags. When they are correct both versions now behave the same (Example code and my code).