Author Topic: OTA upload hang with IOS-Pods-DFU-Library  (Read 276 times)

Tim

  • RFduino Sr. Member
  • ****
  • Posts: 126
  • Karma: +2/-0
    • View Profile
OTA upload hang with IOS-Pods-DFU-Library
« on: August 27, 2017, 12:59:34 PM »
Hi all,

I've implemented OTA sketch updates for our product using Nordic's iOS library IOS-Pods-DFU-Library (See http://forum.rfduino.com/index.php?topic=1273.msg5793#msg5793 ).

I'm concerned that I may have encountered a sketch size limit that breaks OTA uploading. Consider two different sketches. Sketch A compiles to 34424 bytes of program storage space. End of Arduino log when compiling is:

Code: [Select]
Using library Wire in folder: /Users/timsenger/Library/Arduino15/packages/Simblee/hardware/Simblee/1.1.3/libraries/Wire (legacy)
Using library SimbleeBLE in folder: /Users/timsenger/Library/Arduino15/packages/Simblee/hardware/Simblee/1.1.3/libraries/SimbleeBLE (legacy)
Sketch uses 34424 bytes (26%) of program storage space. Maximum is 131072 bytes.
Global variables use 2668 bytes of dynamic memory.

Sketch B compiles to 38224 bytes of program storage. End of compile log:

Code: [Select]
Using library SimbleeBLE in folder: /Users/timsenger/Library/Arduino15/packages/Simblee/hardware/Simblee/1.1.3/libraries/SimbleeBLE (legacy)
Using library Wire in folder: /Users/timsenger/Library/Arduino15/packages/Simblee/hardware/Simblee/1.1.3/libraries/Wire (legacy)
Sketch uses 38224 bytes (29%) of program storage space. Maximum is 131072 bytes.
Global variables use 2732 bytes of dynamic memory.

If Simblee has sketch A loaded and running, OTA upload works. Log generated by DFU library is:

Code: [Select]
2017-08-27 13:20:30.116 rockhawk[2123:786109] logWith: Connected to simblee
2017-08-27 13:20:30.119 rockhawk[2123:786109] logWith: Discovering services...
2017-08-27 13:20:30.120 rockhawk[2123:786109] logWith: peripheral.discoverServices(nil)
2017-08-27 13:20:30.125 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateConnecting
2017-08-27 13:20:30.126 rockhawk[2123:786109] logWith: Services discovered
2017-08-27 13:20:30.126 rockhawk[2123:786109] logWith: Starting Legacy DFU...
2017-08-27 13:20:30.128 rockhawk[2123:786109] logWith: Connected to simblee
2017-08-27 13:20:30.129 rockhawk[2123:786109] logWith: Services discovered
2017-08-27 13:20:30.130 rockhawk[2123:786109] logWith: Legacy DFU Service found
2017-08-27 13:20:30.131 rockhawk[2123:786109] logWith: Discovering characteristics in DFU Service...
2017-08-27 13:20:30.131 rockhawk[2123:786109] logWith: peripheral.discoverCharacteristics(nil, for: 00001530-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:20:30.374 rockhawk[2123:786109] logWith: DFU characteristics discovered
2017-08-27 13:20:30.375 rockhawk[2123:786109] logWith: Reading DFU Version number...
2017-08-27 13:20:30.376 rockhawk[2123:786109] logWith: peripheral.readValue(00001534-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:20:30.435 rockhawk[2123:786109] logWith: Read Response received from 00001534-1212-EFDE-1523-785FEABCD123, value (0x): 0100
2017-08-27 13:20:30.435 rockhawk[2123:786109] logWith: Version number read: 0.1
2017-08-27 13:20:30.435 rockhawk[2123:786109] logWith: Enabling notifications for 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:30.435 rockhawk[2123:786109] logWith: peripheral.setNotifyValue(true, for: 00001531-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:20:30.436 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateStarting
2017-08-27 13:20:30.554 rockhawk[2123:786109] logWith: Notifications enabled for 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:30.554 rockhawk[2123:786109] logWith: DFU Control Point notifications enabled
2017-08-27 13:20:30.554 rockhawk[2123:786109] logWith: Application with buttonless update found
2017-08-27 13:20:30.555 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:30.555 rockhawk[2123:786109] logWith: peripheral.writeValue(0x0104, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:20:30.556 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateEnablingDfuMode
2017-08-27 13:20:30.614 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:30.614 rockhawk[2123:786109] logWith: Jump to bootloader (Op Code = 1, Upload Mode = 4) request sent
2017-08-27 13:20:30.826 rockhawk[2123:786109] logWith: [Callback] Central Manager did disconnect peripheral
2017-08-27 13:20:30.826 rockhawk[2123:786109] logWith: Disconnected by the remote device
2017-08-27 13:20:30.827 rockhawk[2123:786109] logWith: Connecting to simblee...
2017-08-27 13:20:30.827 rockhawk[2123:786109] logWith: centralManager.connect(peripheral, options:nil)
2017-08-27 13:20:31.120 rockhawk[2123:786109] logWith: [Callback] Central Manager did connect peripheral
2017-08-27 13:20:31.121 rockhawk[2123:786109] logWith: Connected to simblee
2017-08-27 13:20:31.121 rockhawk[2123:786109] logWith: Discovering services...
2017-08-27 13:20:31.121 rockhawk[2123:786109] logWith: peripheral.discoverServices([00001530-1212-EFDE-1523-785FEABCD123])
2017-08-27 13:20:31.529 rockhawk[2123:786109] logWith: Services discovered
2017-08-27 13:20:31.529 rockhawk[2123:786109] logWith: Legacy DFU Service found
2017-08-27 13:20:31.530 rockhawk[2123:786109] logWith: Discovering characteristics in DFU Service...
2017-08-27 13:20:31.530 rockhawk[2123:786109] logWith: peripheral.discoverCharacteristics(nil, for: 00001530-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:20:31.769 rockhawk[2123:786109] logWith: DFU characteristics discovered
2017-08-27 13:20:31.770 rockhawk[2123:786109] logWith: Reading DFU Version number...
2017-08-27 13:20:31.770 rockhawk[2123:786109] logWith: peripheral.readValue(00001534-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:20:31.829 rockhawk[2123:786109] logWith: Read Response received from 00001534-1212-EFDE-1523-785FEABCD123, value (0x): 0600
2017-08-27 13:20:31.830 rockhawk[2123:786109] logWith: Version number read: 0.6
2017-08-27 13:20:31.830 rockhawk[2123:786109] logWith: Enabling notifications for 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:31.830 rockhawk[2123:786109] logWith: peripheral.setNotifyValue(true, for: 00001531-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:20:31.830 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateStarting
2017-08-27 13:20:31.979 rockhawk[2123:786109] logWith: Notifications enabled for 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:31.979 rockhawk[2123:786109] logWith: DFU Control Point notifications enabled
2017-08-27 13:20:31.980 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:31.980 rockhawk[2123:786109] logWith: peripheral.writeValue(0x0104, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:20:31.982 rockhawk[2123:786109] logWith: Writing image sizes (0b, 0b, 34376b) to characteristic 00001532-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:31.982 rockhawk[2123:786109] logWith: peripheral.writeValue(0x000000000000000048860000, for: 00001532-1212-EFDE-1523-785FEABCD123, type: .withoutResponse)
2017-08-27 13:20:32.039 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:32.040 rockhawk[2123:786109] logWith: Start DFU (Op Code = 1, Upload Mode = 4) request sent
2017-08-27 13:20:33.809 rockhawk[2123:786109] logWith: Notification received from 00001531-1212-EFDE-1523-785FEABCD123, value (0x): 100101
2017-08-27 13:20:33.809 rockhawk[2123:786109] logWith: Response (Op Code = 1, Status = 1) received
2017-08-27 13:20:33.810 rockhawk[2123:786109] logWith: Writing Initialize DFU Parameters...
2017-08-27 13:20:33.810 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:33.810 rockhawk[2123:786109] logWith: peripheral.writeValue(0x0200, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:20:33.811 rockhawk[2123:786109] logWith: Writing to characteristic 00001532-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:33.811 rockhawk[2123:786109] logWith: peripheral.writeValue(0xffffffffffff00000100feff0cc0, for: 00001532-1212-EFDE-1523-785FEABCD123, type: .withoutResponse)
2017-08-27 13:20:33.812 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:33.812 rockhawk[2123:786109] logWith: peripheral.writeValue(0x0201, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:20:33.869 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:33.929 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:33.929 rockhawk[2123:786109] logWith: Notification received from 00001531-1212-EFDE-1523-785FEABCD123, value (0x): 100201
2017-08-27 13:20:33.930 rockhawk[2123:786109] logWith: Response (Op Code = 2, Status = 1) received
2017-08-27 13:20:33.930 rockhawk[2123:786109] logWith: Initialize DFU Parameters completed
2017-08-27 13:20:33.930 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:33.931 rockhawk[2123:786109] logWith: peripheral.writeValue(0x080c00, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:20:33.931 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateUploading
2017-08-27 13:20:33.989 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:33.989 rockhawk[2123:786109] logWith: Packet Receipt Notif Req (Op Code = 8, Value = 12) request sent
2017-08-27 13:20:33.989 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:33.990 rockhawk[2123:786109] logWith: peripheral.writeValue(0x03, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:20:34.049 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:34.049 rockhawk[2123:786109] logWith: Uploading firmware...
2017-08-27 13:20:34.049 rockhawk[2123:786109] logWith: Sending firmware DFU Packet characteristic...

2017-08-27 13:20:34.052 rockhawk[2123:786109] dfuProgressDidChangeFor: called repeatedly as sketch uploaded ...

2017-08-27 13:20:47.220 rockhawk[2123:786109] logWith: Notification received from 00001531-1212-EFDE-1523-785FEABCD123, value (0x): 100301
2017-08-27 13:20:47.221 rockhawk[2123:786109] logWith: Response (Op Code = 3, Status = 1) received
2017-08-27 13:20:47.221 rockhawk[2123:786109] logWith: Upload completed in 13.17 seconds
2017-08-27 13:20:47.222 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:47.222 rockhawk[2123:786109] logWith: peripheral.writeValue(0x04, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:20:47.223 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateValidating
2017-08-27 13:20:47.280 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:47.280 rockhawk[2123:786109] logWith: Validate Firmware (Op Code = 4) request sent
2017-08-27 13:20:47.310 rockhawk[2123:786109] logWith: Notification received from 00001531-1212-EFDE-1523-785FEABCD123, value (0x): 100401
2017-08-27 13:20:47.311 rockhawk[2123:786109] logWith: Response (Op Code = 4, Status = 1) received
2017-08-27 13:20:47.311 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:20:47.312 rockhawk[2123:786109] logWith: peripheral.writeValue(0x05, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:20:47.312 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateDisconnecting
2017-08-27 13:20:47.370 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:20:47.370 rockhawk[2123:786109] logWith: Activate and Reset (Op Code = 5) request sent
2017-08-27 13:20:47.579 rockhawk[2123:786109] logWith: [Callback] Central Manager did disconnect peripheral
2017-08-27 13:20:47.579 rockhawk[2123:786109] logWith: Disconnected by the remote device
2017-08-27 13:20:47.580 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateCompleted

But if Simblee has sketch B loaded and running, OTA upload hangs on a call to connect to the peripheral:

Code: [Select]
2017-08-27 13:28:33.390 rockhawk[2123:786109] logWith: Connected to simblee
2017-08-27 13:28:33.391 rockhawk[2123:786109] logWith: Discovering services...
2017-08-27 13:28:33.391 rockhawk[2123:786109] logWith: peripheral.discoverServices(nil)
2017-08-27 13:28:33.394 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateConnecting
2017-08-27 13:28:33.395 rockhawk[2123:786109] logWith: Services discovered
2017-08-27 13:28:33.396 rockhawk[2123:786109] logWith: Starting Legacy DFU...
2017-08-27 13:28:33.396 rockhawk[2123:786109] logWith: Connected to simblee
2017-08-27 13:28:33.397 rockhawk[2123:786109] logWith: Services discovered
2017-08-27 13:28:33.397 rockhawk[2123:786109] logWith: Legacy DFU Service found
2017-08-27 13:28:33.397 rockhawk[2123:786109] logWith: Discovering characteristics in DFU Service...
2017-08-27 13:28:33.398 rockhawk[2123:786109] logWith: peripheral.discoverCharacteristics(nil, for: 00001530-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:28:33.641 rockhawk[2123:786109] logWith: DFU characteristics discovered
2017-08-27 13:28:33.642 rockhawk[2123:786109] logWith: Reading DFU Version number...
2017-08-27 13:28:33.642 rockhawk[2123:786109] logWith: peripheral.readValue(00001534-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:28:33.701 rockhawk[2123:786109] logWith: Read Response received from 00001534-1212-EFDE-1523-785FEABCD123, value (0x): 0100
2017-08-27 13:28:33.702 rockhawk[2123:786109] logWith: Version number read: 0.1
2017-08-27 13:28:33.702 rockhawk[2123:786109] logWith: Enabling notifications for 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:28:33.702 rockhawk[2123:786109] logWith: peripheral.setNotifyValue(true, for: 00001531-1212-EFDE-1523-785FEABCD123)
2017-08-27 13:28:33.703 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateStarting
2017-08-27 13:28:33.821 rockhawk[2123:786109] logWith: Notifications enabled for 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:28:33.821 rockhawk[2123:786109] logWith: DFU Control Point notifications enabled
2017-08-27 13:28:33.822 rockhawk[2123:786109] logWith: Application with buttonless update found
2017-08-27 13:28:33.822 rockhawk[2123:786109] logWith: Writing to characteristic 00001531-1212-EFDE-1523-785FEABCD123...
2017-08-27 13:28:33.823 rockhawk[2123:786109] logWith: peripheral.writeValue(0x0104, for: 00001531-1212-EFDE-1523-785FEABCD123, type: .withResponse)
2017-08-27 13:28:33.823 rockhawk[2123:786109] dfuStateDidChangeTo: DFUStateEnablingDfuMode
2017-08-27 13:28:33.881 rockhawk[2123:786109] logWith: Data written to 00001531-1212-EFDE-1523-785FEABCD123
2017-08-27 13:28:33.882 rockhawk[2123:786109] logWith: Jump to bootloader (Op Code = 1, Upload Mode = 4) request sent
2017-08-27 13:28:34.095 rockhawk[2123:786109] logWith: [Callback] Central Manager did disconnect peripheral
2017-08-27 13:28:34.095 rockhawk[2123:786109] logWith: Disconnected by the remote device
2017-08-27 13:28:34.096 rockhawk[2123:786109] logWith: Connecting to simblee...
2017-08-27 13:28:34.096 rockhawk[2123:786109] logWith: centralManager.connect(peripheral, options:nil)

It doesn't seem to matter which sketch is being uploaded (A or B). When Simblee has sketch A loaded and running, my app can upload either A or B via OTA. When Simblee has sketch B loaded and running, app hangs (as above) when attempting to upload either A or B via OTA. In fact, when Simblee has sketch B loaded and running, app fails to upload OTA the following minimal sketch:

Code: [Select]
#include <ota_bootloader.h>
#include <SimbleeBLE.h>

void setup() {
  // put your setup code here, to run once:
  SimbleeBLE.begin();
}

void loop() {
  // put your main code here, to run repeatedly:

}


There are many differences in the sketches A and B, besides size, but I'd like to first rule out the possibility that I've hit the sketch upper size limit before investigating further.

Any experiences, insights?

Many thanks,

Tim
« Last Edit: August 28, 2017, 10:44:05 AM by Tim »

Wayne

  • RFduino Jr. Member
  • **
  • Posts: 45
  • Karma: +0/-0
    • View Profile
Re: OTA upload hang with IOS-Pods-DFU-Library
« Reply #1 on: August 28, 2017, 02:41:29 PM »
Dunno if this makes any sense, but the start of the 2 are different..
A states Wire in folder the SimbleeBLE in folder while
B states SimbleeBLE in folder then Wire in folder..

Thats the difference is see..

But I don't do this, just looking at what you posted..

Tim

  • RFduino Sr. Member
  • ****
  • Posts: 126
  • Karma: +2/-0
    • View Profile
Re: OTA upload hang with IOS-Pods-DFU-Library
« Reply #2 on: August 28, 2017, 06:39:13 PM »
Thanks Wayne. That was a copy/paste typo on my part. Order of those lines is the same for both compile logs. Thanks for pointing out though. Hoping to hear something from RF Digital support.

Cheers,

Tim

Tim

  • RFduino Sr. Member
  • ****
  • Posts: 126
  • Karma: +2/-0
    • View Profile
Re: OTA upload hang with IOS-Pods-DFU-Library
« Reply #3 on: August 29, 2017, 08:47:55 AM »
Hi ...

I think I found the issue. The larger sketch B uses TIMER1, TIMER2, RTC1 and PPI for precise timing functions. (Sketch A does the same but does not use as many PPI channels.) If I comment out the code that configures this, OTA upload works. Looks like our iOS app will have to send a message to Simblee to deconfigure timers and PPI prior to initiating OTA upload. I assumed that booting the OTA bootloader would reset Simblee. Perhaps not the case.

Will post more detail once discovered.

Tim


Tim

  • RFduino Sr. Member
  • ****
  • Posts: 126
  • Karma: +2/-0
    • View Profile
Re: OTA upload hang with IOS-Pods-DFU-Library
« Reply #4 on: August 29, 2017, 04:09:38 PM »
Found the culprit. For normal operation, our Simblee app uses RTC1 and it is normally in the stopped state. It responds to two different GPIO events to start/stop and accurately measure time between the events. OTA DFU must rely on RTC1 and seems it expects it to be started. If just prior to initiating OTA DFU, sketch starts RTC1 (NRF_RTC1->TASKS_START = 1;), all works okay.

Thanks,

Tim