search

NordicSemiconductor / Android-DFU-Library

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

Device got disconnected before service discovery finished #35

Closed LouisLuo2016 closed 5 years ago

LouisLuo2016 commented 7 years ago

Hi,phillip

I have met another problem. The twice dfu is on same MAC address. Becasue they are same Mac address,so does not do gatt.refresh(). At second dfu happend

Device got disconnected before service discovery finished

Could you help me?

11-30 18:42:53.392 22344-27217/com.putao.wd I/DfuBaseService: Connecting to the device...
11-30 18:42:53.403 22344-22394/com.putao.wd I/DfuBaseService: Connected to GATT server
11-30 18:42:53.406 22344-22394/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed
11-30 18:42:54.828 22344-22355/com.putao.wd I/DfuBaseService: Services discovered
11-30 18:42:55.844 22344-27217/com.putao.wd I/DfuImpl: Reading DFU version number...
11-30 18:42:56.048 22344-27217/com.putao.wd I/DfuImpl: Version number read: 0.1
11-30 18:42:56.048 22344-27217/com.putao.wd W/DfuImpl: Application with buttonless update found
11-30 18:42:56.048 22344-27217/com.putao.wd I/DfuImpl: Enabling notifications...
11-30 18:42:57.241 22344-27217/com.putao.wd I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4)
11-30 18:42:57.801 22344-22356/com.putao.wd E/DfuBaseService: Connection state change error: 19 newState: 0
11-30 18:42:57.809 22344-27217/com.putao.wd I/DfuBaseService: Refreshing result: true
11-30 18:42:57.809 22344-27217/com.putao.wd I/DfuBaseService: Cleaning up...
11-30 18:42:57.811 22344-27217/com.putao.wd I/DfuImpl: Starting service that will connect to the DFU bootloader
11-30 18:42:57.821 22344-22344/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
11-30 18:42:59.863 22344-27217/com.putao.wd I/DfuBaseService: Connecting to the device...
11-30 18:43:00.190 22344-22356/com.putao.wd I/DfuBaseService: Connected to GATT server
11-30 18:43:00.195 22344-22356/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed
11-30 18:43:01.222 22344-22394/com.putao.wd I/DfuBaseService: Services discovered
11-30 18:43:02.229 22344-27217/com.putao.wd I/DfuImpl: Reading DFU version number...
11-30 18:43:02.293 22344-27217/com.putao.wd I/DfuImpl: Version number read: 0.8
11-30 18:43:02.293 22344-27217/com.putao.wd I/DfuImpl: Enabling notifications...
11-30 18:43:03.353 22344-27217/com.putao.wd I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4)
11-30 18:43:03.412 22344-27217/com.putao.wd I/DfuImpl: Sending image size array to DFU Packet (0b, 0b, 142544b)
11-30 18:43:07.634 22344-27217/com.putao.wd I/DfuImpl: Sending the Initialize DFU Parameters START (Op Code = 2, Value = 0)
11-30 18:43:07.701 22344-27217/com.putao.wd I/DfuImpl: Sending 142544 bytes of init packet
11-30 18:43:07.702 22344-27217/com.putao.wd I/DfuImpl: Sending init packet (Value = FF-FF-FF-FF-FF-FF-00-00-01-00-64-00-84-17)
11-30 18:43:07.704 22344-27217/com.putao.wd I/DfuImpl: Sending the Initialize DFU Parameters COMPLETE (Op Code = 2, Value = 1)
11-30 18:43:07.763 22344-27217/com.putao.wd I/DfuImpl: Sending Receive Firmware Image request (Op Code = 3)
11-30 18:43:07.822 22344-27217/com.putao.wd I/DfuImpl: Uploading firmware...
11-30 18:43:48.613 22344-27217/com.putao.wd I/DfuImpl: Response received. Op Code: 16 Req Op Code = 3, Status = 1
11-30 18:43:48.614 22344-27217/com.putao.wd I/DfuImpl: Transfer of 142544 bytes has taken 39790 ms
11-30 18:43:48.614 22344-27217/com.putao.wd I/DfuImpl: Sending Validate request (Op Code = 4)
11-30 18:43:48.853 22344-27217/com.putao.wd I/DfuImpl: Response received. Op Code: 16 Req Op Code = 4, Status = 1
11-30 18:43:48.854 22344-27217/com.putao.wd I/DfuImpl: Sending Activate and Reset request (Op Code = 5)
11-30 18:43:48.984 22344-22394/com.putao.wd E/DfuBaseService: Connection state change error: 19 newState: 0
11-30 18:43:48.986 22344-27217/com.putao.wd I/DfuBaseService: Refreshing result: true
11-30 18:43:48.986 22344-27217/com.putao.wd I/DfuBaseService: Cleaning up...
11-30 18:43:49.000 22344-22344/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
11-30 18:44:16.007 22344-28502/com.putao.wd I/DfuBaseService: Connecting to the device...
11-30 18:44:16.021 22344-22355/com.putao.wd I/DfuBaseService: Connected to GATT server
11-30 18:44:16.025 22344-22355/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed
11-30 18:44:16.771 22344-22356/com.putao.wd I/DfuBaseService: Services discovered
11-30 18:44:17.776 22344-28502/com.putao.wd I/DfuImpl: Reading DFU version number...
11-30 18:44:17.863 22344-28502/com.putao.wd I/DfuImpl: Version number read: 0.1
11-30 18:44:17.863 22344-28502/com.putao.wd W/DfuImpl: Application with buttonless update found
11-30 18:44:17.864 22344-28502/com.putao.wd I/DfuImpl: Enabling notifications...
11-30 18:44:19.014 22344-28502/com.putao.wd I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4)
11-30 18:44:19.296 22344-22394/com.putao.wd E/DfuBaseService: Connection state change error: 19 newState: 0
11-30 18:44:19.303 22344-28502/com.putao.wd I/DfuBaseService: Refreshing result: true
11-30 18:44:19.303 22344-28502/com.putao.wd I/DfuBaseService: Cleaning up...
11-30 18:44:19.306 22344-28502/com.putao.wd I/DfuImpl: Starting service that will connect to the DFU bootloader
11-30 18:44:19.314 22344-22344/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
11-30 18:44:21.349 22344-28502/com.putao.wd I/DfuBaseService: Connecting to the device...
11-30 18:44:21.656 22344-22394/com.putao.wd I/DfuBaseService: Connected to GATT server
11-30 18:44:21.662 22344-22394/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed
11-30 18:44:24.018 22344-22400/com.putao.wd E/DfuBaseService: Connection state change error: 34 newState: 0
11-30 18:44:24.018 22344-28502/com.putao.wd E/DfuBaseService: Device got disconnected before service discovery finished
11-30 18:44:24.023 22344-28502/com.putao.wd I/DfuBaseService: Refreshing result: true
11-30 18:44:24.023 22344-28502/com.putao.wd I/DfuBaseService: Cleaning up...
11-30 18:44:24.028 22344-22344/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
LouisLuo2016 commented 7 years ago

These are log that add gatt.refresh() before second dfu.

11-30 19:09:23.250 14278-15397/com.putao.wd I/DfuBaseService: Connecting to the device...
11-30 19:09:23.267 14278-14343/com.putao.wd I/DfuBaseService: Connected to GATT server
11-30 19:09:23.271 14278-14343/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed
11-30 19:09:24.622 14278-14290/com.putao.wd I/DfuBaseService: Services discovered
11-30 19:09:25.627 14278-15397/com.putao.wd I/DfuImpl: Reading DFU version number...
11-30 19:09:25.885 14278-15397/com.putao.wd I/DfuImpl: Version number read: 0.1
11-30 19:09:25.885 14278-15397/com.putao.wd W/DfuImpl: Application with buttonless update found
11-30 19:09:25.886 14278-15397/com.putao.wd I/DfuImpl: Enabling notifications...
11-30 19:09:27.275 14278-15397/com.putao.wd I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4)
11-30 19:09:27.636 14278-14383/com.putao.wd E/DfuBaseService: Connection state change error: 19 newState: 0
11-30 19:09:27.642 14278-15397/com.putao.wd I/DfuBaseService: Refreshing result: true
11-30 19:09:27.643 14278-15397/com.putao.wd I/DfuBaseService: Cleaning up...
11-30 19:09:27.644 14278-15397/com.putao.wd I/DfuImpl: Starting service that will connect to the DFU bootloader
11-30 19:09:27.658 14278-14278/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
11-30 19:09:29.677 14278-15397/com.putao.wd I/DfuBaseService: Connecting to the device...
11-30 19:09:29.846 14278-14291/com.putao.wd I/DfuBaseService: Connected to GATT server
11-30 19:09:29.849 14278-14291/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed
11-30 19:09:30.893 14278-14290/com.putao.wd I/DfuBaseService: Services discovered
11-30 19:09:31.895 14278-15397/com.putao.wd I/DfuImpl: Reading DFU version number...
11-30 19:09:31.935 14278-15397/com.putao.wd I/DfuImpl: Version number read: 0.8
11-30 19:09:31.935 14278-15397/com.putao.wd I/DfuImpl: Enabling notifications...
11-30 19:09:32.995 14278-15397/com.putao.wd I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4)
11-30 19:09:33.084 14278-15397/com.putao.wd I/DfuImpl: Sending image size array to DFU Packet (0b, 0b, 142544b)
11-30 19:09:37.305 14278-15397/com.putao.wd I/DfuImpl: Sending the Initialize DFU Parameters START (Op Code = 2, Value = 0)
11-30 19:09:37.400 14278-15397/com.putao.wd I/DfuImpl: Sending 142544 bytes of init packet
11-30 19:09:37.400 14278-15397/com.putao.wd I/DfuImpl: Sending init packet (Value = FF-FF-FF-FF-FF-FF-00-00-01-00-64-00-84-17)
11-30 19:09:37.402 14278-15397/com.putao.wd I/DfuImpl: Sending the Initialize DFU Parameters COMPLETE (Op Code = 2, Value = 1)
11-30 19:09:37.491 14278-15397/com.putao.wd I/DfuImpl: Sending Receive Firmware Image request (Op Code = 3)
11-30 19:09:37.551 14278-15397/com.putao.wd I/DfuImpl: Uploading firmware...
11-30 19:10:19.905 14278-15397/com.putao.wd I/DfuImpl: Response received. Op Code: 16 Req Op Code = 3, Status = 1
11-30 19:10:19.905 14278-15397/com.putao.wd I/DfuImpl: Transfer of 142544 bytes has taken 41067 ms
11-30 19:10:19.905 14278-15397/com.putao.wd I/DfuImpl: Sending Validate request (Op Code = 4)
11-30 19:10:20.145 14278-15397/com.putao.wd I/DfuImpl: Response received. Op Code: 16 Req Op Code = 4, Status = 1
11-30 19:10:20.146 14278-15397/com.putao.wd I/DfuImpl: Sending Activate and Reset request (Op Code = 5)
11-30 19:10:20.273 14278-14343/com.putao.wd E/DfuBaseService: Connection state change error: 19 newState: 0
11-30 19:10:20.275 14278-15397/com.putao.wd I/DfuBaseService: Refreshing result: true
11-30 19:10:20.275 14278-15397/com.putao.wd I/DfuBaseService: Cleaning up...
11-30 19:10:20.289 14278-14278/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
11-30 19:10:48.238 14278-16716/com.putao.wd I/DfuBaseService: Connecting to the device...
11-30 19:10:48.257 14278-14383/com.putao.wd I/DfuBaseService: Connected to GATT server
11-30 19:10:48.262 14278-14383/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed
11-30 19:10:49.012 14278-14290/com.putao.wd I/DfuBaseService: Services discovered
11-30 19:10:50.014 14278-16716/com.putao.wd I/DfuImpl: Reading DFU version number...
11-30 19:10:50.123 14278-16716/com.putao.wd I/DfuImpl: Version number read: 0.1
11-30 19:10:50.124 14278-16716/com.putao.wd W/DfuImpl: Application with buttonless update found
11-30 19:10:50.124 14278-16716/com.putao.wd I/DfuImpl: Enabling notifications...
11-30 19:10:51.275 14278-16716/com.putao.wd I/DfuImpl: Sending Start DFU command (Op Code = 1, Upload Mode = 4)
11-30 19:10:51.621 14278-14291/com.putao.wd E/DfuBaseService: Connection state change error: 19 newState: 0
11-30 19:10:51.627 14278-16716/com.putao.wd I/DfuBaseService: Refreshing result: true
11-30 19:10:51.627 14278-16716/com.putao.wd I/DfuBaseService: Cleaning up...
11-30 19:10:51.628 14278-16716/com.putao.wd I/DfuImpl: Starting service that will connect to the DFU bootloader
11-30 19:10:51.635 14278-14278/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
11-30 19:10:53.659 14278-16716/com.putao.wd I/DfuBaseService: Connecting to the device...
11-30 19:10:53.882 14278-14383/com.putao.wd I/DfuBaseService: Connected to GATT server
11-30 19:10:53.886 14278-14383/com.putao.wd I/DfuBaseService: Attempting to start service discovery... succeed
11-30 19:10:54.922 14278-14290/com.putao.wd I/DfuBaseService: Services discovered
11-30 19:10:55.924 14278-16716/com.putao.wd I/DfuImpl: Reading DFU version number...
11-30 19:10:56.581 14278-14383/com.putao.wd E/DfuImpl: Characteristic read error: 133
11-30 19:10:56.582 14278-14383/com.putao.wd E/DfuBaseService: Connection state change error: 34 newState: 0
11-30 19:10:56.582 14278-16716/com.putao.wd E/DfuBaseService: Unable to read version number (error 133)
11-30 19:10:56.590 14278-16716/com.putao.wd I/DfuBaseService: Refreshing result: true
11-30 19:10:56.590 14278-16716/com.putao.wd I/DfuBaseService: Cleaning up...
11-30 19:10:56.604 14278-14278/com.putao.wd I/DfuBaseService: Action received: android.bluetooth.device.action.ACL_DISCONNECTED
KentaHarada commented 7 years ago

I have met this issue too on Android Nougat 7.1.1.

KentaHarada commented 7 years ago

@philips77 FYI : This issue is still happened on Android Nougat 7.1.2(Nexus 5X)

Tychus commented 7 years ago

i've been getting this quite a lot. (Android 7.1.1 - Oneplus one)

philips77 commented 7 years ago

Yes, I saw it as well. I think I kind of solved it by adding a delay before starting dfu after the device disconnected (in this case I was disconnecting and starting dfu afterwards). But I have no clue what causing it and why, and how to really solve it.

Tychus commented 7 years ago

added a scan after setting device to dfu mode, delays, retrying after failure sometimes works but failure rate is still too high.

philips77 commented 7 years ago

Could you enable snoop log and, after you get the error, send me the bug report? Can be via email if you don't want to post it here.

Tychus commented 7 years ago

i can send you the log can i use the @ in your profile page ?

philips77 commented 7 years ago

Yes you can.

dannep commented 7 years ago

Any update?

NOA-Scott commented 7 years ago 
08-15 19:04:21.595 808-2312/com.fensens.sensor E/DfuBaseService: Connection state change error: 133 newState: 0
08-15 19:04:21.595 808-4104/com.fensens.sensor E/DfuBaseService: Device got disconnected before service discovery finished
08-15 19:04:21.596 808-4104/com.fensens.sensor D/BluetoothGatt: refresh() - device: F5:D3:7E:83:6E:3F
08-15 19:04:21.597 808-4104/com.fensens.sensor D/BluetoothGatt: close()
08-15 19:04:21.597 808-4104/com.fensens.sensor D/BluetoothGatt: unregisterApp() - mClientIf=8
08-15 19:04:22.202 808-808/com.fensens.sensor E/BaseActivity: onDeviceDisconnected: deviceAddress:F5:D3:7E:83:6E:3F
08-15 19:04:22.202 808-808/com.fensens.sensor E/BaseActivity: onError: deviceAddress:F5:D3:7E:83:6E:3F   0  4096  DFU DEVICE DISCONNECTED 2

Hi @philips77 I was the same problem, Will you solve it?

philips77 commented 7 years ago

Hi, there is not much that can be done. It happens occasionally, I'm not sure why, not on all devices, etc. The only thing that could be done is adding some delay? But that's not solving and will not help 100% cases. Some investigation is required why this happens, does it happens also on new versions of Android, on Pixels, which chipsets, etc. And it's more to be fix on Android or even stack side, not app. The service can be just restarted. Make sure you scan for the device at least once before you do dfu if it's not bonded (creating the BluetoothDevice from address assumes public address).

NOA-Scott commented 7 years ago

OK, Thank you suggestion, @philips77

philips77 commented 5 years ago

I'll release version 1.8.0 of the DFU library today. It had some improvements since this issue was created. Let me close it here now. If you face it running 1.8.0, please open another issue.

philips77 commented 5 years ago

Also, duplicate of #28.

philips77 commented 5 years ago

1.8.0 is released now.

ghost commented 5 years ago

I just faced this issue using 1.8.0

Device is a Huawei P10 Lite on Android 7.0 and EMUI 5.1 (I hate huawei bluetooth engineers, btw. So many issues)

Should scanning for the device before starting DfuService help? Currently we have a delay before starting the service

DfuServiceListenerHelper.registerProgressListener(context, listener);
connection.disconnect();
Thread.sleep(TimeUnit.SECONDS.toMillis(2));
starter.start(context, MyFirmwareUpdaterService.class);

If it does help, could we add it to DFU library? (if it's not already)

philips77 commented 5 years ago

FYI: You don't need to disconnect before starting DFU. In nRF Connect we don't. The library doesn't scan before starting DFU, as the device may already be connected, so it most probably won't advertise. It will scan only when the address might have changes, that is after jumping to the bootloader, depending on the bootloader version found. I don't have any solution to this issue other then just try again. There may be so many reasons of it, it's hard to reproduce, as it happens only sometimes and on some devices. The lib could retry on it's own, but I was also wondering should I rewrite the lib to use the BLE Library, which handle those issues automatically...

savatagecriss commented 5 years ago

Hi Philips:

We also meet a similar issue as below log, we use 48 devices which all run secure bootloader at the same time, and using dfu-library1.8.1

image

This issue seems happen easier when devices become more in our environment.

Could you diagnose it and give us any suggestion? workaround is also welcome, thank you.