search

NordicSemiconductor / IOS-DFU-Library

OTA DFU Library for Mac and iOS, compatible with nRF5x SoCs
http://www.nordicsemi.com
BSD 3-Clause "New" or "Revised" License
526 stars 215 forks source link

Delegate Methods (ex. Logs) only called while stepping through DFU #453

Closed Crudough closed 3 years ago

Crudough commented 3 years ago

DFU Bootloader version (please complete the following information):

Device information (please complete the following information):

Your question I only get logs in my Xcode console if I step through the program which, correctly, results in a connection timeout for the DFU process. I can confirm that a DFU indeed takes place and am using the CPU usage as the indicator that the process is done. I only receive one "Connecting" log initially when I prompt the DFU but nothing after that. I've included some code snippets below and the "Connecting" log.

I've tried using different queues for each delegate but no change in behaviour was observed.

Code & Logs Code Snippet

class DFUManager: DFUServiceDelegate, DFUProgressDelegate, LoggerDelegate {

    /* Class Properties */
    private var dfuPeripheral   : CBPeripheral!
    private var peripheralName  : String?
    private var dfuController   : DFUServiceController!
    private var dfuInitiator    : DFUServiceInitiator!
    private var dfuFirmware     : DFUFirmware!

    private var dfuProgress: Int = 0

    init(peripheral: Peripheral, dfuUrl: URL) {
        self.dfuPeripheral = peripheral.manager.connectedPeripheral
        self.peripheralName = peripheral.name
        guard
            let firmware = DFUFirmware(urlToZipFile: dfuUrl) else {
                print("Cannot get DFU firmware for url: \(dfuUrl).")
                return
            }
        self.dfuFirmware  = firmware 
        self.dfuInitiator = DFUServiceInitiator(queue: DispatchQueue(label: "DFU Queue").with(firmware: self.dfuFirmware)
    }

    /* DFUServiceDelegate */
    func dfuStateDidChange(to state: DFUState) {
        switch state {
        case .completed, .disconnecting:
            /* Throw completion flag, forget the controller */
            print("I have completed the DFU!")
            dfuController = nil
        case .aborted:
            /* Throw abort status flag, forget the controller */
            dfuController = nil
        case .connecting:
            /* Should not happen, the peripheral should be connected. */
           // >>>>>> This is the only log from any delegate methods that every gets called.
            print("Connecting")
        default:
            /* Nothing had happened, keep the option to stop/abort open */
            print("Default")
        }
    }

    func dfuError(_ error: DFUError, didOccurWithMessage message: String) {
        print("Error \(error.rawValue): \(message)")

        // Forget the controller when DFU finished with an error
        dfuController = nil
    }

    /* DFUProgressDelegate */
    func dfuProgressDidChange(for part: Int, outOf totalParts: Int, to progress: Int, currentSpeedBytesPerSecond: Double, avgSpeedBytesPerSecond: Double) {
        dfuProgress = progress

        /* update views here or more state variables that will affect front end views */
        print("DFU Progress: \(progress).")
        print("DFU Part \(part) out of \(totalParts).")
        print("Current Speed: \(currentSpeedBytesPerSecond)")
        print("Average Speed: \(avgSpeedBytesPerSecond).")
    }

    func startDFUProcess() {

        guard let dfuPeripheral = self.dfuPeripheral else {
            print("No DFU peripheral was set")
            return
        }

        self.dfuInitiator.delegate = self
        self.dfuInitiator.progressDelegate = self
        self.dfuInitiator.logger = self
        self.dfuInitiator.enableUnsafeExperimentalButtonlessServiceInSecureDfu = true
        guard let controller = self.dfuInitiator.start(target: dfuPeripheral) else {
            print("Could not start controller!")
            return
        }
        print("\nI am starting the DFU Process")
        self.dfuController = controller
    }

    func logWith(_ level: LogLevel, message: String) {
        print("\(level.name()): \(message)")
    }
}

Sample Logs When running uninterrupted.

I am starting the DFU Process
Connecting

When being stepped through

I am starting the DFU Process
Connecting
D: [Callback] Central Manager did update state to: Powered ON
V: Connecting to JDRF_DFU...
D: centralManager.connect(peripheral, options: nil)
W: Connection timeout!
D: centralManager.cancelPeripheralConnection(peripheral)
D: [Callback] Central Manager did connect peripheral
I: Connected to JDRF_DFU
V: Discovering services...
D: peripheral.discoverServices(nil)
D: [Callback] Central Manager did disconnect peripheral
I: Disconnected
Connecting
V: Connecting to JDRF_DFU...
D: centralManager.connect(peripheral, options: nil)
W: Connection timeout!
D: centralManager.cancelPeripheralConnection(peripheral)
D: [Callback] Central Manager did connect peripheral
I: Connected to JDRF_DFU
V: Discovering services...
D: peripheral.discoverServices(nil)
D: [Callback] Central Manager did disconnect peripheral
I: Disconnected
Connecting
V: Connecting to JDRF_DFU...
D: centralManager.connect(peripheral, options: nil)
D: [Callback] Central Manager did connect peripheral
I: Connected to JDRF_DFU
V: Discovering services...
D: peripheral.discoverServices(nil)
I: Services discovered
V: Starting Secure DFU...
I: Connected to JDRF_DFU
I: Services discovered
V: Secure DFU Service found
V: Discovering characteristics in DFU Service...
D: peripheral.discoverCharacteristics(nil, for: FE59)
I: DFU characteristics discovered
V: MTU set to 247
Default
V: Enabling notifications for 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.setNotifyValue(true, for: 8EC90001-F315-4F60-9FB8-838830DAEA50)
V: Notifications enabled for 8EC90001-F315-4F60-9FB8-838830DAEA50
A: Secure DFU Control Point notifications enabled
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x0601, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
I: Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
I: Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600601800200000000000000000000
A: Command object selected (Max size = 640, Offset = 0, CRC = 00000000) received
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x010145010000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
I: Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
I: Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x020000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
I: Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
I: Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600201
A: Packet Receipt Notif disabled (Op Code = 2, Value = 0)
V: Writing to characteristic 8EC90002-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x12c2020afb01080112f60108808084e00f10341a02cc0120002800300038dcb40542240803122037830b9f964991f2e5a71bb36720fd9bc5cec4bb19dcafacd485dea4d249bf474800524408031240325d737e16e8c6e8202542c941ed6b38062ce0c014cced9c96af72663642aea0d5d4e8d87132ffb3d58b157aa98dda0404e1e371d3a4bbabed7d67520f9fc27f5a70018eedf2076e52f62a05c05d810f70894b62cae6e84d376fc2cc4be37b0af86c1071f94fb4d44460aabcf97acd3b403f6252b9234945a1b89b28b9004548aa5f4a050669aebe56b81f7e34b61087d448b88f10a6bdb41f4d1e73d2d38ce99360099725, for: 8EC90002-F315-4F60-9FB8-838830DAEA50, type: .withoutResponse)
V: Writing to characteristic 8EC90002-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x7fef22876d7a82bfa1c7924ba910001a400bdb2533ce87d03473a78c17e4a4cc5df0e4e21a50cb4fd691ade664764c7154d199d541e2036c0649f21d4a2cf2fe7a48bef99b3a20569e925c4ff635ec324c, for: 8EC90002-F315-4F60-9FB8-838830DAEA50, type: .withoutResponse)
A: Command object sent (CRC = 4F1191DD)
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
I: Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
I: Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 60030145010000dd91114f
A: Checksum (Offset = 325, CRC = 4F1191DD) received
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x04, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
I: Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
I: Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600401
A: Command object executed
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x020c00, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
I: Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
I: Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600201
A: Packet Receipt Notif enabled (Op Code = 2, Value = 12)
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x0602, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
I: Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
I: Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600601001000000000000000000000
A: Data object selected (Max size = 4096, Offset = 0, CRC = 00000000) received
Default
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x010200100000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
I: Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
I: Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
I: Data object 1/22 created
D: wait(400)
A: Uploading firmware...
V: Sending firmware to DFU Packet characteristic...
V: Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
D: peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
DFU Progress: 0.
DFU Part 1 out of 1.
Current Speed: 0.0
Average Speed: 0.0.
DFU Progress: 1.
DFU Part 1 out of 1.
Current Speed: 27.54711619852742
Average Speed: 27.54711619852742.
DFU Progress: 2.
DFU Part 1 out of 1.
Current Speed: 584764.0459967145
Average Speed: 55.0916371353589.
DFU Progress: 3.
DFU Part 1 out of 1.
Current Speed: 722662.240320113
Average Speed: 75.7488355643296.
DFU Progress: 4.
DFU Part 1 out of 1.
Current Speed: 21.724603606611332
Average Speed: 45.545665627492994.
2021-09-08 13:03:22.462550-0400 JDRFElectromag[1637:545352] [CoreBluetooth] XPC connection invalid
philips77 commented 3 years ago

Hello, Regarding why the state goes to .connecting, each client (CBCentralManager) may connect to a device separately and they are not aware of each other. The OS system manages the physical connection, but informs clients as if they were the only client connected, to some degree. The state changes to connecting even before anything starts: https://github.com/NordicSemiconductor/IOS-DFU-Library/blob/8f935c6516969a874d8c2c01f4fdc4188c3d9910/iOSDFULibrary/Classes/Implementation/DFUSelector/DFUServiceSelector.swift#L69-L74

Could you debug why you don't get logger events, and where the process actually stops? This method should be called https://github.com/NordicSemiconductor/IOS-DFU-Library/blob/8f935c6516969a874d8c2c01f4fdc4188c3d9910/iOSDFULibrary/Classes/Implementation/GenericDFU/DFUPeripheral.swift#L158-L175 and the state should be .connected, of the connect() method should be called. As you don't get Connected to NAME log, I guess it starts to connect, but than you should get this log: https://github.com/NordicSemiconductor/IOS-DFU-Library/blob/8f935c6516969a874d8c2c01f4fdc4188c3d9910/iOSDFULibrary/Classes/Implementation/GenericDFU/DFUPeripheral.swift#L475-L480

Crudough commented 3 years ago

@philips77 I've stepped through and it seems that it's not picking up the logger peripheral in LoggerHelper.swift.

https://github.com/NordicSemiconductor/IOS-DFU-Library/blob/d4a1da27fbf195b325cea3036235a4939a8f4efa/iOSDFULibrary/Classes/Utilities/Logging/LoggerHelper.swift#L76-L82

The logger.X calls happen but the Logger Helper cannot resolve the logger - the if let logger = logger does not execute. As far as I'm aware I believe I am connecting the delegate correctly.

Crudough commented 3 years ago

As additional information. Right before the code snippet for the DFUServiceSelector.swift file that you've included, in the init, I can confirm that it is indeed my logger where it is referenced as initiator.logger.

https://github.com/NordicSemiconductor/IOS-DFU-Library/blob/8f935c6516969a874d8c2c01f4fdc4188c3d9910/iOSDFULibrary/Classes/Implementation/DFUSelector/DFUServiceSelector.swift#L60-L67

Also, I've confirmed that the logger delegate between the self.initiator.logger = self line in my code snippet above and the logger in the init for the LoggerHelper are the same object. I'm not aware of any but is there a configuration flag or setting in either the code or Xcode to enable the logging?

Crudough commented 3 years ago

I've updated the issue above to include the full logs while the code is stepped through. @philips77 Is it possible that a delay is needed?

Crudough commented 3 years ago

To leave a trail and hints for anyone else that may be stuck with this issue. I've found that this seems to be a timing issue. Initially I was instantiating a DFUManager from my code snippet in my original description then immediately starting the DFU process. I've since changed the architecture to instantiate the DFUManager in an .onAppear closure and waiting until a second action (button) to start the DFUProcess itself. It appears that this is logging correctly now!

@philips77 I will leave this open for a day or two if you are able to clarify why this might be the case. Thank you for all the help!