search

NordicSemiconductor / Android-DFU-Library

Device Firmware Update library and Android app
http://www.nordicsemi.com/dfu
BSD 3-Clause "New" or "Revised" License
768 stars 272 forks source link

Confused about connection state #31

Closed eliotstock closed 7 years ago

eliotstock commented 7 years ago

I'm implementing DFU OTA for a peripheral app for the nRF51822. My device is motion-activated and the behaviour of my firmware is that when there's a BLE disconnection, is simply goes into sys off. Motion will wake it up again.

Looks like this may cause a problem for me with the DFU service. Does the service expect to start from a point of NOT being connected to the peripheral and to have to create its own connection afresh? If so and I disconnect before calling DfuServiceInitiator.start(), my peripheral won't be advertising.

Is the service configurable or extensible to change this?

philips77 commented 7 years ago

Well.. yes, it expects the device is disconnected, but I think it should also work when it's connected, as you should be able to connect to a device multiple times with different callbacks. So I recommend trying this first. The service requires a connection and it can't be passed to the service so if this doesn't work.. you could do a 2 sec timeout before you stop advertising? Let's first try the first :)

eliotstock commented 7 years ago

OK, if I try from a state of being already connected, I get this in the logs:

11-10 17:37:23.749 17950-19170/cc.biketracker.android D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A2, auto: false
11-10 17:37:23.749 17950-19170/cc.biketracker.android D/BluetoothGatt: registerApp()
11-10 17:37:23.749 17950-19170/cc.biketracker.android D/BluetoothGatt: registerApp() - UUID=0fa268b3-3fa4-4bc1-be82-151d1b58fd56
11-10 17:37:23.753 17950-18049/cc.biketracker.android D/BluetoothGatt: onClientRegistered() - status=0 clientIf=7
11-10 17:37:23.758 17950-18049/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=7 device=D2:13:B7:46:E9:A2
11-10 17:37:25.363 17950-18049/cc.biketracker.android D/BluetoothGatt: discoverServices() - device: D2:13:B7:46:E9:A2
11-10 17:37:25.383 17950-17964/cc.biketracker.android D/BluetoothGatt: onSearchComplete() = Device=D2:13:B7:46:E9:A2 Status=0
11-10 17:37:25.547 17950-19170/cc.biketracker.android D/BluetoothGatt: cancelOpen() - device: D2:13:B7:46:E9:A2
11-10 17:37:25.564 17950-18057/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=7 device=D2:13:B7:46:E9:A2
11-10 17:37:25.566 17950-19170/cc.biketracker.android D/BluetoothGatt: close()
11-10 17:37:25.566 17950-19170/cc.biketracker.android D/BluetoothGatt: unregisterApp() - mClientIf=7

But no logging from your classes, strangely.

eliotstock commented 7 years ago

Oh, and the notification on the UI says it failed.

philips77 commented 7 years ago

In your DFUService class (the one that overrides DfuBaseService) you may override isDebug() method and return Build.DEBUG and you'll get more messages. Note I'm almost confident it should work.

eliotstock commented 7 years ago

OK, thanks. Better logs now. Seems to have no problem connecting, even though I'm already connected, but then disconnects. Can't see why.

11-10 18:02:44.681 3135-8290/cc.biketracker.android I/DfuBaseService: Connecting to the device...
11-10 18:02:44.682 3135-8290/cc.biketracker.android D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A2, auto: false
11-10 18:02:44.682 3135-8290/cc.biketracker.android D/BluetoothGatt: registerApp()
11-10 18:02:44.683 3135-8290/cc.biketracker.android D/BluetoothGatt: registerApp() - UUID=b1432f53-2be9-4abd-9562-ff18ad0e6399
11-10 18:02:44.686 3135-3655/cc.biketracker.android D/BluetoothGatt: onClientRegistered() - status=0 clientIf=7
11-10 18:02:44.688 3135-3147/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=7 device=D2:13:B7:46:E9:A2
11-10 18:02:44.688 3135-3147/cc.biketracker.android I/DfuBaseService: Connected to GATT server
11-10 18:02:44.691 3135-3147/cc.biketracker.android I/DfuBaseService: Waiting 1600 ms for a possible Service Changed indication...
11-10 18:02:46.293 3135-3147/cc.biketracker.android D/BluetoothGatt: discoverServices() - device: D2:13:B7:46:E9:A2
11-10 18:02:46.296 3135-3147/cc.biketracker.android I/DfuBaseService: Attempting to start service discovery... succeed
11-10 18:02:46.311 3135-3187/cc.biketracker.android D/BluetoothGatt: onSearchComplete() = Device=D2:13:B7:46:E9:A2 Status=0
11-10 18:02:46.312 3135-3187/cc.biketracker.android I/DfuBaseService: Services discovered
11-10 18:02:46.437 3135-8290/cc.biketracker.android I/DfuBaseService: Disconnecting from the device...
11-10 18:02:46.437 3135-8290/cc.biketracker.android D/BluetoothGatt: cancelOpen() - device: D2:13:B7:46:E9:A2
11-10 18:02:46.440 3135-3148/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=7 device=D2:13:B7:46:E9:A2
11-10 18:02:46.440 3135-3148/cc.biketracker.android I/DfuBaseService: Disconnected from GATT server
11-10 18:02:46.441 3135-8290/cc.biketracker.android I/DfuBaseService: Cleaning up...
11-10 18:02:46.441 3135-8290/cc.biketracker.android D/BluetoothGatt: close()
11-10 18:02:46.441 3135-8290/cc.biketracker.android D/BluetoothGatt: unregisterApp() - mClientIf=7
philips77 commented 7 years ago

Could you debug it? Looks like the mError is > 0 after connect() finished..?

eliotstock commented 7 years ago

Trying, but my breakpoints are not being reached. Leave it with me for a bit.

eliotstock commented 7 years ago

Got it. It's decided to use neither the secure nor the legacy implementation based on the services there on the GATT. I want the secure version. It's looking for this:

protected static final UUID DFU_SERVICE_UUID = new UUID(0x0000FE5900001000L, 0x800000805F9B34FBL);

ble_dfu.h in SDK 12.1.0 has this:

define BLE_UUID_DFU_SERVICE 0x0001

define BLE_DFU_BASE_UUID {{0x50, 0xEA, 0xDA, 0x30, 0x88, 0x83, 0xB8, 0x9F, 0x60, 0x4F, 0x15, 0xF3, 0x00, 0x00, 0x40, 0x8E}} /*< Used vendor specific UUID. /

I find these hard to read, but I don't think they match. What've I done wrong?

eliotstock commented 7 years ago

Here's how I init the DFU service in my application code:

static void dfu_init(void)
{
    uint32_t err_code;
    ble_dfu_init_t dfus_init;

    memset(&dfus_init, 0, sizeof(dfus_init));

    dfus_init.evt_handler = ble_dfu_evt_handler;
    dfus_init.ctrl_point_security_req_write_perm = SEC_SIGNED;
    dfus_init.ctrl_point_security_req_cccd_write_perm = SEC_SIGNED;

    err_code = ble_dfu_init(&m_dfus, &dfus_init);
    APP_ERROR_CHECK(err_code);
}
eliotstock commented 7 years ago

And here's what nRF Connect sees when it does service discovery on my device.

https://goo.gl/photos/rDkVWu1sJnCjxX8cA

philips77 commented 7 years ago

Is it the buttonless jump service? In sdk 12.1 it's experimental (the sample that demo it) and our mobile libraries don't support it. You'd have to enable notifications and write 01 there on your own before starting DFU. The device may start advertising with address +1 so you then need to start scanning, find such device and start the service for the new device. We wait until the buttonless will settle out the in-app-dfu will be done (I think it's still in plans, but have no idea).

eliotstock commented 7 years ago

It's just /components/ble/ble_services/ble_dfu/ble_dfu.c. Hasn't that been there for a while? Didn't think it was still experimental.

Where's the service that you do support?

philips77 commented 7 years ago

For legacy DFU it wasn't, but for secure it even doesn't support copying bond information between app and Bootloader. I'll check tomorrow what's the status. In theory the dfu should be handled by app and Bootloader should just swap app and restart, but that's future... Will back to you tomorrow.

eliotstock commented 7 years ago

OK, thanks. I'm now quite confused about the intended way to build DFU with SDK 12.1.0. If you could explain which services are intended to be running in the application and in the bootloader, and what the central mobile app is supposed to do, that'd be great. For our application we need secure DFU, really.

philips77 commented 7 years ago

To get answers to your questions you must ask on DevZone. I'm 'just' a mobile app developer ;)

From what I know, the he reason why Secure DFU doesn't have a final buttonless switch service is that this would cause a potential DOS attack where the device is constantly switched to bootloader mode be a third side. We want it to be secure, after all...

But you'll get a better answers on DevZone. Please, post the link here so I could ping or support.

eliotstock commented 7 years ago

OK thanks, will do. The DOS thing makes sense, but I wish it was explained somewhere. I'll bring it up on the devzone. Thanks for the quick responses. Closing this for now.

eliotstock commented 7 years ago

Hi again Aleksander. Could you please have someone respond to the devzone post about this here?

https://devzone.nordicsemi.com/question/102900/buttonless-dfu-secure-format-sdk-1210/

It's been sitting there a while and I need to get moving with DFU. Thanks.

philips77 commented 7 years ago

Sure, I'll let them know. From what I know: The Uuid starting at 8E40.. is the experimental and a bit dangerous (but currently the only option) "Buttonless jump service" that can be added to the app in order to add this feature. Writing 01 to it (perhaps after enabling notifications) will enforce bootloader after next reset. The risk is the DOS attack, and the service does not handle bond information so after the jump the bootloader should have address +1 or ios/Android will not be able to obtain the new services (old services from cache will be used). The dfu bootloader connection will not then be encrypted. Then, if your device is bondable, you have to make sure the bond info was not erased from the app space and the new app can still use it (perhaps some modification in bootloader required, at least it used to be), or your new app should add another +1 to the address so it will be visible as a new device and new binding will be required. On iOS users can be instructed to remove the old one from their phones. Remember, that adding +1s to addresses is a hack as devices (or chips) may be sold in batches with following addresses and they may overlap after incrementing.

The DFU_ SERVICE_UUIDs are more complicated. In case of Legacy DFU, this service (with identical characteristics) can be on both app and Bootloader, with different behavior. In the app, it is responsible for Buttonless jump. The steps to trigger jump are identical as starting DFU: enable notifications, write 0x01-04 to DFU Control Point, but then the device will reboot itself and start in Bootloader mode. The only diff is that DFU Version characteristic (if such exists) will return 0x01-00 (decided as Ver 0.1) if in app mode (which means that this service supports buttonless jump) (App is independent from the bootloader and does not know its features nor version number, thus returning 0.1). This characteristic in bootloader mode will return value 0x0X-00 where X can be 5, 6, or 7 or 8, depending on the bootloader version. On bootloader mode this service does DFU. Currently the DFU_SERVICE_UUID =FE59 is used only by the Secure DFU bootloader. In the next sdk, around January(?), there will be a Buttonless jump char introduced. Then the 8E40... Service Uuid in the app mode will be replaced by a service with Service DFU Uuid (FE59) and with one characteristic ....0003-....-....-....-............ where the dots are the base address used by current secure DFU characteristics. This service, as described in the issue #33, will have Notify and Write props and will be protected (only bonded devices will be able to write to it to protect from DOS attack). Writing 01 to it after enabling notifications will force bootloader mode on the next reboot as described there.

philips77 commented 7 years ago

One more thing. I will discuss it with my colleges, but I decided to add support for the experimental Buttonless jump device in Secure DFU (8E40...) to both Android and iOS libraries. But as it is not safe, additional line in the code will be required that developer knows the risk (something like setUNSAFEExperimentalBootloaderJumpFeatureEnabled(boolean).

philips77 commented 7 years ago

@eliotstock Hi, I added a comment here: https://github.com/NordicSemiconductor/Android-DFU-Library/issues/33#issuecomment-261512070 regarding the current experimental buttonless dfu service that you may find interesting.

eliotstock commented 7 years ago

@philips77 Thank you! Adding support for the experimental service with the unsafe setter sounds like a great approach. Looking forward to getting my hands on that. We will not use it in production, but this will allow us to keep moving at least.

philips77 commented 7 years ago

Hi, small FYI in case you also work with DFU on iOS, I've just added support for this experimental Buttonless DFU Service in the iOS library on Version3 branch: https://github.com/NordicSemiconductor/IOS-Pods-DFU-Library/commit/02a2306bd2eb39dbb78c312fbf3ed121ee4956dd

philips77 commented 7 years ago

Hi @eliotstock The experimental buttonless DFU is not added to this DFU library v1.1.0. The version was released on jcenter, Maven and here. I tested it, but please, let me know it it works for you. The service and characteristic UUID for this service must be as default in this service in SDK 12, also explained here: https://github.com/NordicSemiconductor/Android-DFU-Library/blob/release/dfu/src/main/java/no/nordicsemi/android/dfu/DfuServiceInitiator.java#L194

eliotstock commented 7 years ago

Fantastic, thank you! I'll test this in the next day or two.

eliotstock commented 7 years ago

OK, I am now getting a bit further, but still hitting errors. Not sure yet whether they're caused by the DFU library or the bootloader though. Prevalidation fails in the bootloader.

At first, I got a 133 on connecting. Then I saw issue #28 which recommends doing a scan before the DFU service connects, so I did that, which helped. The DFU library now gets as far as executing the init packet, then fails. Android logs:

11-30 12:55:03.622 24414-591/cc.biketracker.android I/DfuImpl: Starting service that will upload application
11-30 12:55:05.758 24414-591/cc.biketracker.android I/DfuBaseService: Connecting to the device...
11-30 12:55:05.759 24414-591/cc.biketracker.android D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A3, auto: false
11-30 12:55:05.760 24414-591/cc.biketracker.android D/BluetoothGatt: registerApp()
11-30 12:55:05.760 24414-591/cc.biketracker.android D/BluetoothGatt: registerApp() - UUID=5ee32cf0-de6c-4869-99f7-02e64c5b8e73
11-30 12:55:05.763 24414-24427/cc.biketracker.android D/BluetoothGatt: onClientRegistered() - status=0 clientIf=22
11-30 12:55:05.975 24414-24426/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=22 device=D2:13:B7:46:E9:A3
11-30 12:55:05.976 24414-24426/cc.biketracker.android I/DfuBaseService: Connected to GATT server
11-30 12:55:05.978 24414-24426/cc.biketracker.android D/BluetoothGatt: discoverServices() - device: D2:13:B7:46:E9:A3
11-30 12:55:05.981 24414-24426/cc.biketracker.android I/DfuBaseService: Attempting to start service discovery... succeed
11-30 12:55:06.703 24414-24426/cc.biketracker.android D/BluetoothGatt: onSearchComplete() = Device=D2:13:B7:46:E9:A3 Status=0
11-30 12:55:06.704 24414-24426/cc.biketracker.android I/DfuBaseService: Services discovered
11-30 12:55:06.713 24414-591/cc.biketracker.android I/DfuBaseService: Services discovered
11-30 12:55:07.777 24414-591/cc.biketracker.android I/DfuImpl: Enabling notifications...
11-30 12:55:07.778 24414-591/cc.biketracker.android D/BluetoothGatt: setCharacteristicNotification() - uuid: 8ec90001-f315-4f60-9fb8-838830daea50 enable: true
11-30 12:55:08.846 24414-591/cc.biketracker.android I/DfuImpl: Setting object to Command (Op Code = 6, Type = 1)
11-30 12:55:08.910 24414-591/cc.biketracker.android I/DfuImpl: Disabling Packet Receipt Notifications (Op Code = 2, Value = 0)
11-30 12:55:08.911 24414-591/cc.biketracker.android I/DfuImpl: Sending the number of packets before notifications (Op Code = 2, Value = 0)
11-30 12:55:08.986 24414-591/cc.biketracker.android I/DfuImpl: Creating Init packet object (Op Code = 1, Type = 1, Size = 135)
11-30 12:55:09.047 24414-591/cc.biketracker.android I/DfuImpl: Sending 135 bytes of init packet...
11-30 12:55:09.048 24414-591/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 12-84-01-0A-3E-08-01-12-3A-08-01-10-06-1A-02-87-01-20-00-28)
11-30 12:55:09.056 24414-591/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 00-30-00-38-9C-9B-04-42-24-08-03-12-20-B8-9F-92-28-17-66-D1)
11-30 12:55:09.068 24414-591/cc.biketracker.android I/DfuImpl: Sending init packet (Value = D9-00-73-9F-1D-87-89-53-7E-97-0B-63-FC-1A-97-4C-4C-D1-D2-E3)
11-30 12:55:09.074 24414-591/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 42-4E-43-FA-6E-48-00-10-00-1A-40-54-7A-AF-17-BC-35-0A-2D-5F)
11-30 12:55:09.084 24414-591/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 44-9C-A6-A8-3B-21-FA-BD-02-12-EB-57-AB-2B-3C-E3-80-2C-11-81)
11-30 12:55:09.092 24414-591/cc.biketracker.android I/DfuImpl: Sending init packet (Value = D6-1B-36-61-A6-A6-B9-05-27-13-3E-DC-CE-EB-2C-F1-46-65-4B-C7)
11-30 12:55:09.101 24414-591/cc.biketracker.android I/DfuImpl: Sending init packet (Value = A0-54-18-CD-70-BC-64-3F-A4-6E-48-90-E7-D5-8F)
11-30 12:55:09.108 24414-591/cc.biketracker.android I/DfuImpl: Sending Calculate Checksum command (Op Code = 3)
11-30 12:55:09.174 24414-591/cc.biketracker.android I/DfuImpl: Checksum received (Offset = 135, CRC = 6EA1774B)
11-30 12:55:09.174 24414-591/cc.biketracker.android I/DfuImpl: Executing init packet (Op Code = 4)
11-30 12:55:09.226 24414-591/cc.biketracker.android E/DfuImpl: Executing object failed (error 10)
11-30 12:55:09.274 24414-591/cc.biketracker.android I/DfuBaseService: Disconnecting from the device...
11-30 12:55:09.275 24414-591/cc.biketracker.android D/BluetoothGatt: cancelOpen() - device: D2:13:B7:46:E9:A3
11-30 12:55:09.287 24414-24498/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=22 device=D2:13:B7:46:E9:A3
11-30 12:55:09.288 24414-24498/cc.biketracker.android I/DfuBaseService: Disconnected from GATT server
11-30 12:55:09.290 24414-591/cc.biketracker.android D/BluetoothGatt: refresh() - device: D2:13:B7:46:E9:A3
11-30 12:55:09.292 24414-591/cc.biketracker.android I/DfuBaseService: Refreshing result: true
11-30 12:55:09.292 24414-591/cc.biketracker.android I/DfuBaseService: Cleaning up...
11-30 12:55:09.292 24414-591/cc.biketracker.android D/BluetoothGatt: close()
11-30 12:55:09.292 24414-591/cc.biketracker.android D/BluetoothGatt: unregisterApp() - mClientIf=22

Bootloader logs:

:INFO:In nrf_bootloader_init
:INFO:In real nrf_dfu_init
:INFO:running nrf_dfu_settings_init
:INFO:Enter nrf_dfu_continue
:INFO:bank_current is NRF_DFU_CURRENT_BANK_0. Using bank_0.
:INFO:p_bank image_size: 90560, image_crc: 1531564195, bank_code: 1.
:INFO:Valid App
:INFO:Erasing old settings at: 0x0003fc00
:INFO:Erasing: 0x0003fc00, num: 1
:INFO:Writing 0x00000057 words
:INFO:Writing settings...
:INFO:nrf_dfu_enter_check(): Returning true.
:INFO:Application sent bootloader request
:INFO:In nrf_dfu_transports_init
:INFO:num transports: 1
:INFO:vector table: 0x00037c00
SDH:INFO:sd_ble_enable: RAM START at 0x200025e0
:INFO:After nrf_dfu_transports_init
:INFO:------- nrf_dfu_flash_init-------
:INFO:Waiting for events
:INFO:Received select object
:INFO:Valid Command: NRF_DFU_OBJECT_OP_SELECT
:INFO:Sending Object Info: [0x60, 0x06, 0x01 max: 0:x00000100 0:x00000000, CRC:0x00000000]
:INFO:Set receipt notif
:INFO:Sending Response: [0x2, 0x1]
:INFO:Received create object
:INFO:Before OP create command
:INFO:Valid Command Create
:INFO:Sending Response: [0x1, 0x1]
:INFO:Before OP write command
:INFO:Before OP write command
:INFO:Before OP write command
:INFO:Before OP write command
:INFO:Before OP write command
:INFO:Before OP write command
:INFO:Before OP write command
:INFO:Received calculate CRC
:INFO:Valid Command CRC
:INFO:Sending CRC: [0x60, 0x03, 0x01, 0:x00000087, CRC:0x6ea1774b]
:INFO:Received execute object
:INFO:Before OP execute command
:INFO:Valid command execute
:INFO:
12 84 01 0A 3E 08 01 12 3A 08 01 10 06 1A 02 87  ....>...:.......
01 20 00 28 00 30 00 38 9C 9B 04 42 24 08 03 12  . .(.0.8...B$...
20 B8 9F 92 28 17 66 D1 D9 00 73 9F 1D 87 89 53   ...(.f...s....S
7E 97 0B 63 FC 1A 97 4C 4C D1 D2 E3 42 4E 43 FA  ~..c...LL...BNC.
6E 48 00 10 00 1A 40 54 7A AF 17 BC 35 0A 2D 5F  nH....@Tz...5.-_
44 9C A6 A8 3B 21 FA BD 02 12 EB 57 AB 2B 3C E3  D...;!.....W.+<.
80 2C 11 81 D6 1B 36 61 A6 A6 B9 05 27 13 3E DC  .,....6a....'.>.
CE EB 2C F1 46 65 4B C7 A0 54 18 CD 70 BC 64 3F  ..,.FeK..T..p.d?
A4 6E 48 90 E7 D5 8F                             .nH....         
:INFO:
:INFO:PB: Init data len: 58
:INFO:Handling signed command
:INFO:Prevalidate FAILED!
:INFO:Sending Response: [0x4, 0xa]

I'll check my key pair again.

eliotstock commented 7 years ago

Spoke too soon. I'm frequently, but not consistently, getting this when kicking off DFU:

11-30 14:23:14.777 8277-15572/cc.biketracker.android I/DfuImpl: Sending Enter Bootloader (Op Code = 1)
11-30 14:23:17.694 8277-8289/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=8 device=D2:13:B7:46:E9:A2
11-30 14:23:17.695 8277-8289/cc.biketracker.android E/DfuBaseService: Connection state change error: 19 newState: 0
philips77 commented 7 years ago

So currently you get the 0x0A (10) error = Operation Failed on Init packet validation if anything goes wrong (crc validation, signature mismatch, fw or hw version check, size check). In the next SDK the Extended errors should be added in such case. Instead of getting status 0x0A you will get 2 bytes: 0x0B-XX where XX is the extended error code. Both mobile libraries already are ready to support this new feature.

Regarding error 19 - this means that the peer has disconnected. It shouldn't be an error, but expected behavior. First the device, however, should send the notification 0x20-01-01. Perhaps when it disconnects before the notification is received you get this? I'll verify it. It should not cause abortion of the process.

eliotstock commented 7 years ago

OK, thanks. I'll step through dfu_handle_prevalidate() and see where the validation is failing.

As for the error 19, I'm sometimes an able to run past it, other times the Android app gives up and I get no further. It's inconsistent.

philips77 commented 7 years ago

Yes.. looks like there is a race condition. The notification is received, but immediately after that the device disconnects, so if the readNotificationResponse() finished its job is OK, when didn't it fails. Expect an 1.1.1 update in few minutes.

philips77 commented 7 years ago

Could you please send a bit longer log when you get the error 19? I want to check what exactly happens before and after that.

philips77 commented 7 years ago

Hmm... I see that the error 19 you got is a correct output. As I understand the DFU process finishes by another error, that comes later. Something like:

Invalid response received (response: , expected: 0x200101)
Refreshing result: true
...

or just stacks at where it was and nothing happens? I need some more information from you. Is that correct?

eliotstock commented 7 years ago

Sure, here you go.

11-30 17:49:40.988 19093-19093/cc.biketracker.android D/DfuActivity: onCreate() 140751033
11-30 17:49:41.019 19093-19093/cc.biketracker.android D/DfuActivity: onStart() 140751033
11-30 17:49:41.027 19093-19093/cc.biketracker.android D/DfuActivity: onResume() 140751033
11-30 17:49:41.106 19093-19093/cc.biketracker.android D/DfuActivity: onServiceConnected() We're bound, BikeTrackerService is now available to the Activity.
11-30 17:49:41.106 19093-19093/cc.biketracker.android D/DfuActivity: onServiceBound() 140751033
11-30 17:49:41.155 19093-19100/cc.biketracker.android I/art: Starting a blocking GC Instrumentation
11-30 17:49:41.585 19093-22805/cc.biketracker.android D/GetMeTask: doInBackground(): User: {"devices":[{"hasBikeImage":true,"id":"1AEAD","name":"Eliot's bike","sigfoxSequenceNumber":873,"state":"ORANGE"},{"hasBikeImage":true,"id":"1AEAE","name":"Eliot's blue bike","state":"GREEN"},{"frameNumber":"","hasBikeImage":true,"id":"1AEB2","name":"Susan's bike","sigfoxSequenceNumber":508,"state":"ORANGE"},{"hasBikeImage":true,"id":"1AEB4","name":"Eliot's bike","sigfoxSequenceNumber":248,"state":"ORANGE"},{"hasBikeImage":false,"id":"1B136","name":"Eliot's bike","sigfoxSequenceNumber":7,"state":"ORANGE"}],"email":"1@eliotstock.com","firstName":"Eliot","isAdmin":true,"lastLogin":"2016-11-30T17:49:42.096Z","lastName":"Stock","phoneNumber":"+44 7880 707 054","role":"DEVELOPER","kind":"bikeTrackerApi#resourcesItem","etag":"\"X2MUKmy5Bxj0ivCMHKKiSkmatdQ/3W4R3KWnCYSQpltCSVu6rY7b91g\""}
11-30 17:49:41.586 19093-19093/cc.biketracker.android D/SettingsActivity: onUserAvailable() 259921812
11-30 17:49:41.586 19093-19093/cc.biketracker.android D/BikeTrackerService: (Re)registering for GCM messages.
11-30 17:49:41.615 19093-19093/cc.biketracker.android D/SettingsActivity: onStop() 259921812
11-30 17:49:41.615 19093-19093/cc.biketracker.android D/SettingsActivity: onStop() 259921812
11-30 17:49:41.615 19093-19093/cc.biketracker.android D/SettingsActivity: Unbinding from service.
11-30 17:49:41.827 19093-19093/cc.biketracker.android D/BikeTrackerService: Registered for GCM messages. Good. GCM registration ID: APA91bGl1dpYGdUoT7oHjgj0_GgoHmRARoUAjHb4GV5DuMLhedBrEY83DV6tLeqI_0J6jfue_5ovh4o0D6vLY1Ttc9_-iLGlVNNbV5zLkMB1pnKrxTDpfIKHHUrMzLv3WqrXG0ShjVca
11-30 17:49:45.342 19093-23265/cc.biketracker.android I/DfuBaseService: Connecting to the device...
11-30 17:49:45.344 19093-23265/cc.biketracker.android D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A2, auto: false
11-30 17:49:45.344 19093-23265/cc.biketracker.android D/BluetoothGatt: registerApp()
11-30 17:49:45.345 19093-23265/cc.biketracker.android D/BluetoothGatt: registerApp() - UUID=0d489a00-2f75-4e72-8b5b-37cfd31a6dba
11-30 17:49:45.349 19093-19408/cc.biketracker.android D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
11-30 17:49:45.355 19093-19105/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=D2:13:B7:46:E9:A2
11-30 17:49:45.355 19093-19105/cc.biketracker.android I/DfuBaseService: Connected to GATT server
11-30 17:49:45.358 19093-19105/cc.biketracker.android I/DfuBaseService: Waiting 1600 ms for a possible Service Changed indication...
11-30 17:49:46.960 19093-19105/cc.biketracker.android D/BluetoothGatt: discoverServices() - device: D2:13:B7:46:E9:A2
11-30 17:49:46.962 19093-19105/cc.biketracker.android I/DfuBaseService: Attempting to start service discovery... succeed
11-30 17:49:46.982 19093-19106/cc.biketracker.android D/BluetoothGatt: onSearchComplete() = Device=D2:13:B7:46:E9:A2 Status=0
11-30 17:49:46.983 19093-19106/cc.biketracker.android I/DfuBaseService: Services discovered
11-30 17:49:47.022 19093-23265/cc.biketracker.android I/DfuBaseService: Services discovered
11-30 17:49:48.126 19093-23265/cc.biketracker.android W/DfuImpl: Experimental buttonless service found
11-30 17:49:48.126 19093-23265/cc.biketracker.android I/DfuImpl: Enabling notifications...
11-30 17:49:48.127 19093-23265/cc.biketracker.android D/BluetoothGatt: setCharacteristicNotification() - uuid: 8e400001-f315-4f60-9fb8-838830daea50 enable: true
11-30 17:49:50.626 19093-19408/cc.biketracker.android D/BikeTrackerService: No activity to send message to.
11-30 17:49:51.680 19093-23265/cc.biketracker.android I/DfuImpl: Sending Enter Bootloader (Op Code = 1)
11-30 17:49:53.594 19093-19106/cc.biketracker.android D/BikeTrackerService: No activity to send message to.
11-30 17:49:53.597 19093-19106/cc.biketracker.android D/BikeTrackerService: No activity to send message to.
11-30 17:49:53.601 19093-19106/cc.biketracker.android D/BikeTrackerService: No activity to send message to.
11-30 17:49:54.596 19093-19408/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=10 device=D2:13:B7:46:E9:A2
11-30 17:49:54.596 19093-19408/cc.biketracker.android D/BleDevice: onConnectionStateChange(): STATE_DISCONNECTED, GATT_CONN_TERMINATE_PEER_USER
11-30 17:49:54.596 19093-19408/cc.biketracker.android D/BleDevice: Closing BluetoothGatt instance.
11-30 17:49:54.596 19093-19408/cc.biketracker.android D/BluetoothGatt: close()
11-30 17:49:54.597 19093-19408/cc.biketracker.android D/BluetoothGatt: unregisterApp() - mClientIf=10
11-30 17:49:54.595 19093-19106/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=9 device=D2:13:B7:46:E9:A2
11-30 17:49:54.597 19093-19106/cc.biketracker.android E/DfuBaseService: Connection state change error: 19 newState: 0
11-30 17:49:54.600 19093-23265/cc.biketracker.android D/BluetoothGatt: refresh() - device: D2:13:B7:46:E9:A2
11-30 17:49:54.603 19093-23265/cc.biketracker.android I/DfuBaseService: Refreshing result: true
11-30 17:49:54.603 19093-23265/cc.biketracker.android I/DfuBaseService: Cleaning up...
11-30 17:49:54.604 19093-23265/cc.biketracker.android D/BluetoothGatt: close()
11-30 17:49:54.604 19093-23265/cc.biketracker.android D/BluetoothGatt: unregisterApp() - mClientIf=9
11-30 17:49:54.607 19093-19093/cc.biketracker.android I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
11-30 17:49:54.641 19093-23265/cc.biketracker.android D/BluetoothAdapter: STATE_ON
11-30 17:49:54.650 19093-19106/cc.biketracker.android D/BluetoothLeScanner: onClientRegistered() - status=0 clientIf=9 mClientIf=0
11-30 17:49:54.886 19093-19408/cc.biketracker.android D/BikeTrackerService: Getting last location and sending it to the API as a BLE_DISCONNECT.
11-30 17:49:54.896 19093-19408/cc.biketracker.android D/BikeTrackerService: Starting scanning at low power, looking only for our known devices.
11-30 17:49:54.898 19093-19408/cc.biketracker.android D/BikeTrackerService: We have 1 device(s). Scanning for them all now, except if we're already connected.
11-30 17:49:54.902 19093-19408/cc.biketracker.android D/BluetoothAdapter: STATE_ON
11-30 17:49:54.903 19093-19093/cc.biketracker.android W/BleScanCallback: Scan failed.
11-30 17:49:54.903 19093-19093/cc.biketracker.android W/BleScanCallback: Reason: 'Fails to start scan as BLE scan with the same settings is already started by the app.'
11-30 17:49:59.124 19093-23265/cc.biketracker.android D/BluetoothAdapter: STATE_ON
11-30 17:49:59.130 19093-23265/cc.biketracker.android I/DfuImpl: Starting service that will upload application
11-30 17:50:01.252 19093-23265/cc.biketracker.android I/DfuBaseService: Connecting to the device...
11-30 17:50:01.257 19093-23265/cc.biketracker.android D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A3, auto: false
11-30 17:50:01.258 19093-23265/cc.biketracker.android D/BluetoothGatt: registerApp()
11-30 17:50:01.258 19093-23265/cc.biketracker.android D/BluetoothGatt: registerApp() - UUID=0a37396e-d1b6-485b-996e-36be49677d6a
11-30 17:50:01.262 19093-19408/cc.biketracker.android D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
11-30 17:50:01.416 19093-19105/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=D2:13:B7:46:E9:A3
11-30 17:50:01.416 19093-19105/cc.biketracker.android I/DfuBaseService: Connected to GATT server
11-30 17:50:01.425 19093-19105/cc.biketracker.android D/BluetoothGatt: discoverServices() - device: D2:13:B7:46:E9:A3
11-30 17:50:01.426 19093-19105/cc.biketracker.android I/DfuBaseService: Attempting to start service discovery... succeed
11-30 17:50:02.160 19093-19408/cc.biketracker.android D/BluetoothGatt: onSearchComplete() = Device=D2:13:B7:46:E9:A3 Status=0
11-30 17:50:02.161 19093-19408/cc.biketracker.android I/DfuBaseService: Services discovered
11-30 17:50:02.171 19093-23265/cc.biketracker.android I/DfuBaseService: Services discovered
11-30 17:50:03.223 19093-23265/cc.biketracker.android I/DfuImpl: Enabling notifications...
11-30 17:50:03.224 19093-23265/cc.biketracker.android D/BluetoothGatt: setCharacteristicNotification() - uuid: 8ec90001-f315-4f60-9fb8-838830daea50 enable: true
11-30 17:50:04.285 19093-23265/cc.biketracker.android I/DfuImpl: Setting object to Command (Op Code = 6, Type = 1)
11-30 17:50:04.350 19093-23265/cc.biketracker.android I/DfuImpl: Disabling Packet Receipt Notifications (Op Code = 2, Value = 0)
11-30 17:50:04.351 19093-23265/cc.biketracker.android I/DfuImpl: Sending the number of packets before notifications (Op Code = 2, Value = 0)
11-30 17:50:04.400 19093-23265/cc.biketracker.android I/DfuImpl: Creating Init packet object (Op Code = 1, Type = 1, Size = 135)
11-30 17:50:04.458 19093-23265/cc.biketracker.android I/DfuImpl: Sending 135 bytes of init packet...
11-30 17:50:04.458 19093-23265/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 12-84-01-0A-3E-08-01-12-3A-08-01-10-06-1A-02-87-01-20-00-28)
11-30 17:50:04.467 19093-23265/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 00-30-00-38-C0-C3-05-42-24-08-03-12-20-2B-45-D8-4B-D7-90-42)
11-30 17:50:04.474 19093-23265/cc.biketracker.android I/DfuImpl: Sending init packet (Value = EB-0D-49-D4-1F-22-8C-43-C0-C1-7A-D7-B0-81-8D-C2-81-0C-04-3E)
11-30 17:50:04.479 19093-23265/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 54-2C-CB-A9-2F-48-00-10-00-1A-40-C8-6F-82-BB-88-77-94-A7-EA)
11-30 17:50:04.484 19093-23265/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 5A-6B-64-10-11-23-B3-E4-CE-D9-14-BA-B3-AE-54-33-F5-9D-A7-A8)
11-30 17:50:04.490 19093-23265/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 32-12-E6-DC-AB-8F-2F-52-0C-E5-15-FA-88-46-69-55-A6-98-AE-7B)
11-30 17:50:04.497 19093-23265/cc.biketracker.android I/DfuImpl: Sending init packet (Value = 2B-D2-CA-E8-6C-FD-C5-2A-36-7D-00-C1-7D-D7-D7)
11-30 17:50:04.502 19093-23265/cc.biketracker.android I/DfuImpl: Sending Calculate Checksum command (Op Code = 3)
11-30 17:50:04.554 19093-23265/cc.biketracker.android I/DfuImpl: Checksum received (Offset = 135, CRC = 70710ECE)
11-30 17:50:04.554 19093-23265/cc.biketracker.android I/DfuImpl: Executing init packet (Op Code = 4)
11-30 17:50:04.610 19093-23265/cc.biketracker.android E/DfuImpl: Executing object failed (error 10)
11-30 17:50:04.683 19093-23265/cc.biketracker.android I/DfuBaseService: Disconnecting from the device...
11-30 17:50:04.683 19093-23265/cc.biketracker.android D/BluetoothGatt: cancelOpen() - device: D2:13:B7:46:E9:A3
11-30 17:50:04.689 19093-19106/cc.biketracker.android D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=D2:13:B7:46:E9:A3
11-30 17:50:04.690 19093-19106/cc.biketracker.android I/DfuBaseService: Disconnected from GATT server
11-30 17:50:04.692 19093-23265/cc.biketracker.android D/BluetoothGatt: refresh() - device: D2:13:B7:46:E9:A3
11-30 17:50:04.695 19093-23265/cc.biketracker.android I/DfuBaseService: Refreshing result: true
11-30 17:50:04.695 19093-23265/cc.biketracker.android I/DfuBaseService: Cleaning up...
11-30 17:50:04.695 19093-23265/cc.biketracker.android D/BluetoothGatt: close()
11-30 17:50:04.696 19093-23265/cc.biketracker.android D/BluetoothGatt: unregisterApp() - mClientIf=9
eliotstock commented 7 years ago

Sorry, just saw your last comment and don't quite understand it. Where did you see "Invalid response received"? Should I expect to see that in my logs?

philips77 commented 7 years ago

Your log is enough, thanks. So the problem is not that error 19 is received, but that DFU aborts after that. Normally it expects a notification coming before disconnection, but in your case it just disconnects/the disconnection event is received before notification. I think I have fixed it on my computer but will verify with this log tomorrow before publishing. I actually wonder what's going when you receive this error... In my calculations it should stay at this line: https://github.com/NordicSemiconductor/Android-DFU-Library/blob/release/dfu/src/main/java/no/nordicsemi/android/dfu/ExperimentalButtonlessDfuImpl.java#L144 as mReceivedData is null and mError = 0, but instead it goes prints: Refreshing result: true, so it goes to terminateConnection(). How?

eliotstock commented 7 years ago

OK, thanks. I should probably explain what my Android app does that other apps using DFU may not, in case some of my scanning/connecting is the cause of this.

Our Android app (central) supports multiple devices (peripherals). We automatically scan for all our peripherals in the background at low power any time the Bluetooth adapter is powered on. If a device is not connected, we're scanning for it. The minute it disconnects, we scan again. When we connect, we always do discovery and start reading a few characteristics.

I can disable this kind of behaviour during DFU operations if it's causing trouble, but in fact I found that when I did that, I made less progress through DFU, not more. I think this is because of what's discussed at the end of issue #28.

Not sure all this is relevant, but I mention it just in case.

philips77 commented 7 years ago

In theory it shouldn't matter. You should be able do dfu and send data to other devices without any problems. Let me come back to you tomorrow when I do some tests.

eliotstock commented 7 years ago

It's not just "other" devices though, it's the one we're performing DFU on too. Anyway, sounds good. Chat tomorrow. Thanks.

philips77 commented 7 years ago

So you are saying your devices does dfu in app mode? Or the bootloader also has some app-related features? If course this should also work.

eliotstock commented 7 years ago

No, neither of those, my device resets to the bootloader before the DFU transfer starts as normal and my bootloader doesn't have any extra services or characteristics, but before the reset to the bootloader happens, I'm wondering if there's still time for my scanning to get in the way somehow. I guess not.

eliotstock commented 7 years ago

Attaching logs from a successful DFU transfer for both the bootloader and the Android app, in case it helps you debug. From my recent testing, I'd say this works about a quarter or a third of the time at the moment. dfu_success_android_log.txt dfu_success_bootloader_log.txt

philips77 commented 7 years ago

Hmm.. I see that even in the success case you have to start the DFU twice? Once to switch to DFU, second time to do DFU. This should be handled automatically. Does your device even try to send the 0x20-01-01 after receiving Enter to Bootloader command or immediately disconnects?

eliotstock commented 7 years ago

I see where the buttonless service is trying to write the 0x20-01-01, in ble_dfu.c:L251:

    resp_send(p_dfu, (ble_dfu_buttonless_op_code_t)p_evt_write->data[0], rsp_code);

    if (rsp_code == BLE_DFU_ENTER_BOOTLOADER
        && p_evt_write->data[0] == BLE_DFU_ENTER_BOOTLOADER)
    {
        enter_bootloader(p_dfu);
    }

But I never see the notification in my Android logs and I don't yet have logging from the app on the device. So I wonder if the call to sd_ble_gatts_hvx() in resp_send() returns immediately and executes asynchronously, by which time enter_bootloader() has already run and gone into a reset?

philips77 commented 7 years ago

The reap_send method is asynchronous, It calls sd_ble_gatts_hvx. As far as I know the enter bootloader command is also added to the queue and execute gracefully when all messages were sent (or some other mechanism to ensure all responses were sent). Btw, this experimental code is sooo buggy:

    switch (p_evt_write->data[0])
    {
        case BLE_DFU_ENTER_BOOTLOADER:
            rsp_code = DFU_RSP_SUCCESS;   /* <- the rsp_code is set to SUCCESS*/
            break;

         // Unrecognized Op Code
        default:
            rsp_code = DFU_RSP_OP_CODE_NOT_SUPPORTED;
            break;
    }

    resp_send(p_dfu, (ble_dfu_buttonless_op_code_t)p_evt_write->data[0], rsp_code);

    if (rsp_code == BLE_DFU_ENTER_BOOTLOADER /* <- SUCCESS should be checked! Accidentally the values are identical. */
        && p_evt_write->data[0] == BLE_DFU_ENTER_BOOTLOADER)
    {
        enter_bootloader(p_dfu);
    }
philips77 commented 7 years ago

Hi @eliotstock Could you try version 1.1.1? I found an issue that could have lead to your problems (lock wasn't notified in onCharacteristicWrite). That's why you never got the Response received message. It was received, but the only effect was that onCharacteristicChange callback sent a log boradcast, The writeOpCode method was still waiting on a lock until the disconnect event.

Now the library should automatically switch to the bootloader and proceed with DFU without need to start the server again. I hope it will work for you, sorry for trouble, and thanks for helping us finding it!

eliotstock commented 7 years ago

I tried with 1.1.1 but still got the GATT_CONN_TERMINATE_PEER_USER error (error 19), sorry.

D/SettingsActivity: onPause() 33470586
D/DfuActivity: onCreate() 77219755
D/DfuActivity: onStart() 77219755
D/DfuActivity: onResume() 77219755
D/DfuActivity: onServiceConnected() We're bound, BikeTrackerService is now available to the Activity.
D/DfuActivity: onServiceBound() 77219755
I/art: Starting a blocking GC Instrumentation
D/BikeTrackerService: No activity to send message to.
D/BikeTrackerService: No activity to send message to.
D/GetMeTask: doInBackground(): User: {"devices":[{"hasBikeImage":true,"id":"1AEAD","latestPosition":{"altitude":0.0,"dateTime":"2016-12-02T12:31:51.008Z","id":"6286568360771584","latitude":51.54611587524414,"longitude":-0.07557869702577591,"provider":"BLE_DISCONNECT"},"name":"Eliot's bike","sigfoxSequenceNumber":881,"state":"ORANGE"},{"hasBikeImage":true,"id":"1AEAE","name":"Eliot's blue bike","state":"GREEN"},{"frameNumber":"","hasBikeImage":true,"id":"1AEB2","name":"Susan's bike","sigfoxSequenceNumber":508,"state":"ORANGE"},{"hasBikeImage":true,"id":"1AEB4","latestPosition":{"altitude":0.0,"dateTime":"2016-12-02T10:32:09.005Z","id":"5154480479797248","latitude":51.54608154296875,"longitude":-0.07547180354595184,"provider":"BLE_DISCONNECT"},"name":"Eliot's bike","sigfoxSequenceNumber":271,"state":"ORANGE"},{"hasBikeImage":false,"id":"1B136","name":"Eliot's bike","sigfoxSequenceNumber":7,"state":"ORANGE"}],"email":"1@eliotstock.com","firstName":"Eliot","isAdmin":true,"lastLogin":"2016-12-02T12:41:11.325Z","lastName":"Stock","phoneNumber":"+44 7880 707 054","role":"DEVELOPER","kind":"bikeTrackerApi#resourcesItem","etag":"\"X2MUKmy5Bxj0ivCMHKKiSkmatdQ/Gig9g561ysNgQWOdOqlslZbvN30\""}
D/SettingsActivity: onUserAvailable() 33470586
D/BikeTrackerService: (Re)registering for GCM messages.
D/BikeTrackerService: Registered for GCM messages. Good. GCM registration ID: APA91bFKyxITAqbPLppmQd8TumRbmk7GuHtJqhm1HutPMQeJAE7NiAFtKykZYeLzSSjEYhyS0QjR_fhJLrFbUijyCs5iw543qDUPOwV41ZaL7RDBLT-7ZdlctKQUZkwfdoPSWpeTE2wh
D/SettingsActivity: onStop() 33470586
D/SettingsActivity: onStop() 33470586
D/SettingsActivity: Unbinding from service.
I/DfuBaseService: Connecting to the device...
D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A2, auto: false
D/BluetoothGatt: registerApp()
D/BluetoothGatt: registerApp() - UUID=bf587398-5311-495a-8227-0c8d6e57c534
D/BluetoothGatt: onClientRegistered() - status=0 clientIf=18
D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=18 device=D2:13:B7:46:E9:A2
I/DfuBaseService: Connected to GATT server
I/DfuBaseService: Waiting 1600 ms for a possible Service Changed indication...
D/BikeTrackerService: No activity to send message to.
D/BikeTrackerService: No activity to send message to.
D/BluetoothGatt: discoverServices() - device: D2:13:B7:46:E9:A2
I/DfuBaseService: Attempting to start service discovery... succeed
D/BluetoothGatt: onSearchComplete() = Device=D2:13:B7:46:E9:A2 Status=0
I/DfuBaseService: Services discovered
I/DfuBaseService: Services discovered
W/DfuImpl: Experimental buttonless service found
I/DfuImpl: Enabling notifications...
D/BluetoothGatt: setCharacteristicNotification() - uuid: 8e400001-f315-4f60-9fb8-838830daea50 enable: true
D/BikeTrackerService: No activity to send message to.
D/BikeTrackerService: No activity to send message to.
D/BikeTrackerService: No activity to send message to.
I/DfuImpl: Sending Enter Bootloader (Op Code = 1)
I/art: Compiler allocated 4MB to compile void android.app.ActivityThread$H.handleMessage(android.os.Message)
I/DfuImpl: Response received (Op Code = 1, Status = 1)
D/BikeTrackerService: No activity to send message to.
D/BikeTrackerService: No activity to send message to.
D/BikeTrackerService: No activity to send message to.
D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=18 device=D2:13:B7:46:E9:A2
E/DfuBaseService: Connection state change error: 19 newState: 0
D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=19 device=D2:13:B7:46:E9:A2
D/BleDevice: onConnectionStateChange(): STATE_DISCONNECTED, GATT_CONN_TERMINATE_PEER_USER
D/BleDevice: Closing BluetoothGatt instance.
D/BluetoothGatt: close()
D/BluetoothGatt: unregisterApp() - mClientIf=19
D/BluetoothGatt: refresh() - device: D2:13:B7:46:E9:A2
I/DfuBaseService: Refreshing result: true
I/DfuBaseService: Cleaning up...
D/BluetoothGatt: close()
D/BluetoothGatt: unregisterApp() - mClientIf=18
D/BluetoothAdapter: STATE_ON
I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D/BluetoothLeScanner: onClientRegistered() - status=0 clientIf=18 mClientIf=0
D/BikeTrackerService: Getting last location and sending it to the API as a BLE_DISCONNECT.
D/BikeTrackerService: Starting scanning at low power, looking only for our known devices.
D/BikeTrackerService: We have 2 device(s). Scanning for them all now, except if we're already connected.
D/BluetoothAdapter: STATE_ON
D/BluetoothLeScanner: onClientRegistered() - status=0 clientIf=19 mClientIf=0
D/BluetoothAdapter: STATE_ON
D/BluetoothLeScanner: onClientRegistered() - status=0 clientIf=20 mClientIf=0
E/ScanRecord: unable to parse scan record: [2, 1, 6, 17, 6, 27, -59, -43, -91, 2, 0, -70, -81, -30, 17, -88, -124, 0, -6, -31, 57, 2, -1, 3, 18, 9, 70, 108, 111, 119, 101, 114, 32, 112, 111, 119, 101, 114, 32, 49, 52, 48, 50, 5, 18, 10, 0, 100, 0, 2, 10, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
D/BluetoothAdapter: STATE_ON
I/DfuImpl: Starting service that will upload application
I/DfuBaseService: Connecting to the device...
D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A2, auto: false
D/BluetoothGatt: registerApp()
D/BluetoothGatt: registerApp() - UUID=6f7deafe-086e-476c-9b70-676324590ee3
D/BluetoothGatt: onClientRegistered() - status=0 clientIf=18
D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=18 device=D2:13:B7:46:E9:A2
I/DfuBaseService: Connected to GATT server
I/DfuBaseService: Waiting 1600 ms for a possible Service Changed indication...
D/BluetoothGatt: discoverServices() - device: D2:13:B7:46:E9:A2
I/DfuBaseService: Attempting to start service discovery... succeed
D/BluetoothGatt: onSearchComplete() = Device=D2:13:B7:46:E9:A2 Status=0
I/DfuBaseService: Services discovered
I/DfuBaseService: Services discovered
W/DfuImpl: Experimental buttonless service found
I/DfuImpl: Enabling notifications...
D/BluetoothGatt: setCharacteristicNotification() - uuid: 8e400001-f315-4f60-9fb8-838830daea50 enable: true
I/DfuImpl: Sending Enter Bootloader (Op Code = 1)
I/DfuImpl: Response received (Op Code = 1, Status = 1)
D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=18 device=D2:13:B7:46:E9:A2
E/DfuBaseService: Connection state change error: 19 newState: 0
I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D/BluetoothGatt: refresh() - device: D2:13:B7:46:E9:A2
I/DfuBaseService: Refreshing result: true
I/DfuBaseService: Cleaning up...
D/BluetoothGatt: close()
D/BluetoothGatt: unregisterApp() - mClientIf=18
D/BluetoothAdapter: STATE_ON
D/BluetoothLeScanner: onClientRegistered() - status=0 clientIf=18 mClientIf=0
E/ScanRecord: unable to parse scan record: [2, 1, 6, 17, 6, 27, -59, -43, -91, 2, 0, -70, -81, -30, 17, -88, -124, 0, -6, -31, 57, 2, -1, 3, 18, 9, 70, 108, 111, 119, 101, 114, 32, 112, 111, 119, 101, 114, 32, 49, 52, 48, 50, 5, 18, 10, 0, 100, 0, 2, 10, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
D/BluetoothAdapter: STATE_ON
I/DfuImpl: Starting service that will upload application
I/DfuBaseService: Connecting to the device...
D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A2, auto: false
D/BluetoothGatt: registerApp()
D/BluetoothGatt: registerApp() - UUID=e9210b6a-e5c0-41ee-b93f-6350096deb9c
D/BluetoothGatt: onClientRegistered() - status=0 clientIf=18
D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=18 device=D2:13:B7:46:E9:A2
E/DfuBaseService: Connection state change error: 133 newState: 0
E/DfuBaseService: Device got disconnected before service discovery finished
I/DfuBaseService: Cleaning up...
D/BluetoothGatt: close()
D/BluetoothGatt: unregisterApp() - mClientIf=18

If it would help I can make a build of my app that runs on the DK (PCA10028). It won't use any of my peripherals (accelerometer, modem, GPS) but should allow you to repro this quickly at your end. Or I can keep testing here, whichever.

philips77 commented 7 years ago

But error 19 is intended. It just means that the peripheral has disconnected. In my opinion it went very well right now:

  1. The 0x200101 notification was received 
    I/DfuImpl: Sending Enter Bootloader (Op Code = 1)
I/DfuImpl: Response received (Op Code = 1, Status = 1)
  2. After that the device disconnected and you received status 19.
  3. The DFU service started scanning for a new device (by default after switching to DFU the device changes its address by adding +1)
  4. And here we see something went wrong. 
    I/DfuImpl: Starting service that will upload application
I/DfuBaseService: Connecting to the device...
D/BluetoothGatt: connect() - device: D2:13:B7:46:E9:A2, auto: false

    It means that the same address was found. By looking at next logs we see that it connects and finds the experimental service again, instead of the proper Secure DFU one. The address should have A3 at the end.

Do you connect to this device when you receive 19 in your app or let the DFU Service to finish? The DFU service finises on one of 3 states: status completed, status aborted or error that hasn't been handled. Error 19 in this case was intended, so your app should not receive any broadcast and the DFU should go on. Could you check why your device didn't switch to bootloader mode after sending 01?

eliotstock commented 7 years ago

I see what you mean. You did mention earlier that error 19 was expected here, but I'd already forgotten that ;-) (You might consider not logging that particular disconnection as an error from DfuBaseService, since a lot of people will see that and then log an issue here.)

I agree that it looks like my device is resetting into the app, not the bootloader. It's quite hard for me to get logging from both the app and the bootloader at once, but I'll see if I can figure out what's going on.