search

NordicSemiconductor / Android-DFU-Library

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

133 errors #28

Closed bbergshaven closed 6 years ago

bbergshaven commented 8 years ago

Hello

I'm getting a lot of the GATT 133 errors when trying to do a DFU. We've implemented the buttonless DFU and it works perfectly on IOS, but I keep getting the 133 in the DFUService. See attached logs: Any hints on what can be done to minimise this issue?

10-31 18:46:29.557 31469-31469/xxx D/BluetoothGatt: close()
10-31 18:46:29.567 31469-31469/xxx D/BluetoothGatt: unregisterApp() - mClientIf=9
10-31 18:46:30.037 31469-31469/xxx I/DfuService: DfuService onCreate
10-31 18:46:32.087 31469-31748/xxx I/DfuBaseService: Connecting to the device...
10-31 18:46:32.087 31469-31748/xxx D/BluetoothGatt: connect() - device: CD:B0:6F:A2:39:6E, auto: false
10-31 18:46:32.097 31469-31748/xxx D/BluetoothGatt: registerApp()
10-31 18:46:32.097 31469-31748/xxx D/BluetoothGatt: registerApp() - UUID=991273b2-06c7-4c4b-b129-c3282904c6e7
10-31 18:46:32.137 31469-31496/xxx D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
10-31 18:46:32.537 31469-31481/xxx D/BluetoothGattServer: onServerConnectionState() - status=0 serverIf=8 device=CD:B0:6F:A2:39:6E
10-31 18:46:32.537 31469-31481/xxx D/BluetoothGattServer: Server disconnected, update device to list
10-31 18:46:32.547 31469-31481/xxx D/AppManager: Server onConnectionStateChange DISCONNECTED DFU-H41J Address: CD:B0:6F:A2:39:6E
10-31 18:46:32.547 31469-31480/xxx D/BluetoothGatt: onClientConnectionState() - status=133 clientIf=9 device=CD:B0:6F:A2:39:6E
10-31 18:46:32.557 31469-31480/xxx E/DfuBaseService: Connection state change error: 133 newState: 0
10-31 18:46:32.557 31469-31748/xxx E/DfuBaseService: Device got disconnected before service discovery finished
10-31 18:46:32.567 31469-31748/xxx D/BluetoothGatt: refresh() - device: CD:B0:6F:A2:39:6E
10-31 18:46:32.567 31469-31748/xxx I/DfuBaseService: Refreshing result: true
10-31 18:46:32.567 31469-31748/xxx I/DfuBaseService: Cleaning up...
10-31 18:46:32.567 31469-31748/xxx D/BluetoothGatt: close()
10-31 18:46:32.577 31469-31748/xxx D/BluetoothGatt: unregisterApp() - mClientIf=9
10-31 18:46:33.257 31469-31469/xxx I/DfuService: DfuService onDestroy
Tychus commented 8 years ago

it happens once in a while for me aswell i guess nothing we can do about that for now. is it frequent ?

bbergshaven commented 8 years ago

Yeah, thats the big problem, it happens quite frequently. Like over 50% of the time. Any ideas what triggers this behaviour?

TomorrowDreamer commented 8 years ago

I met the same logcat info,whereras my error is " Connection state change error: 19 newState: 0"and toast"Upload failed: DFU SERVICE IS NOT FOUNDED".I can't find the answer.

nachtien commented 8 years ago

I'm also seeing this frequently. If I can provide any extra debugging information let me know. I spent a few hours trying to track down the issue yesterday with no success.

TomorrowDreamer commented 8 years ago

when i press the update button,this is the logcat info:

11-01 13:53:16.611 20786-20786/com.aragoncs.chronos E/ContentValues: mFileStreamUri=: file:///storage/emulated/0/firmware.zipmFilePath=/storage/emulated/0/firmware.zip
11-01 13:53:18.731 20786-22447/com.aragoncs.chronos D/BluetoothGatt: connect() - device: DA:7B:4D:51:CB:4C, auto: false
11-01 13:53:18.731 20786-22447/com.aragoncs.chronos D/BluetoothGatt: registerApp()
11-01 13:53:18.731 20786-22447/com.aragoncs.chronos D/BluetoothGatt: registerApp() - UUID=f3542e4f-e512-4aa0-9dd7-aebc94646e55
11-01 13:53:18.781 20786-21076/com.aragoncs.chronos D/BluetoothGatt: onClientRegistered() - status=0 clientIf=6
11-01 13:53:18.791 20786-20799/com.aragoncs.chronos D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=6 device=DA:7B:4D:51:CB:4C
11-01 13:53:20.391 20786-20799/com.aragoncs.chronos D/BluetoothGatt: discoverServices() - device: DA:7B:4D:51:CB:4C
11-01 13:53:20.421 20786-20799/com.aragoncs.chronos D/BluetoothGatt: onSearchComplete() = Device=DA:7B:4D:51:CB:4C Status=0
11-01 13:53:20.591 20786-22447/com.aragoncs.chronos D/BluetoothGatt: setCharacteristicNotification() - uuid: 00002a05-0000-1000-8000-00805f9b34fb enable: true
11-01 13:53:20.891 20786-22447/com.aragoncs.chronos D/BluetoothGatt: cancelOpen() - device: DA:7B:4D:51:CB:4C
11-01 13:53:20.901 20786-20799/com.aragoncs.chronos D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=6 device=DA:7B:4D:51:CB:4C
11-01 13:53:20.901 20786-22447/com.aragoncs.chronos D/BluetoothGatt: close()
11-01 13:53:20.901 20786-22447/com.aragoncs.chronos D/BluetoothGatt: unregisterApp() - mClientIf=6
11-01 13:53:22.991 20786-22447/com.aragoncs.chronos D/BluetoothGatt: connect() - device: DA:7B:4D:51:CB:4C, auto: false
11-01 13:53:22.991 20786-22447/com.aragoncs.chronos D/BluetoothGatt: registerApp()
11-01 13:53:22.991 20786-22447/com.aragoncs.chronos D/BluetoothGatt: registerApp() - UUID=f3b56e3d-39ec-4232-a554-f01cda9335cb
11-01 13:53:23.041 20786-20801/com.aragoncs.chronos D/BluetoothGatt: onClientRegistered() - status=0 clientIf=6
11-01 13:53:23.051 20786-20801/com.aragoncs.chronos D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=6 device=DA:7B:4D:51:CB:4C
11-01 13:53:24.651 20786-20801/com.aragoncs.chronos D/BluetoothGatt: discoverServices() - device: DA:7B:4D:51:CB:4C
11-01 13:53:24.681 20786-20801/com.aragoncs.chronos D/BluetoothGatt: onSearchComplete() = Device=DA:7B:4D:51:CB:4C Status=0
11-01 13:53:24.891 20786-20786/com.aragoncs.chronos E/ContentValues: onDeviceConnected: DA:7B:4D:51:CB:4C
11-01 13:53:26.051 20786-22447/com.aragoncs.chronos D/BluetoothGatt: setCharacteristicNotification() - uuid: 00001531-1212-efde-1523-785feabcd123 enable: true
11-01 13:53:28.201 20786-21076/com.aragoncs.chronos D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=6 device=DA:7B:4D:51:CB:4C
11-01 13:53:28.201 20786-21076/com.aragoncs.chronos E/DfuBaseService: Connection state change error: 19 newState: 0
11-01 13:53:28.201 20786-22447/com.aragoncs.chronos D/BluetoothGatt: close()
11-01 13:53:28.201 20786-22447/com.aragoncs.chronos D/BluetoothGatt: unregisterApp() - mClientIf=6
11-01 13:53:28.661 20786-20786/com.aragoncs.chronos D/MultiPhoneWindow: MinimizeAnimator::removeWindow
11-01 13:53:28.671 20786-20786/com.aragoncs.chronos D/MultiPhoneWindow: MinimizeAnimator::removeWindow
11-01 13:53:30.361 20786-22447/com.aragoncs.chronos D/BluetoothGatt: connect() - device: DA:7B:4D:51:CB:4C, auto: false
11-01 13:53:30.361 20786-22447/com.aragoncs.chronos D/BluetoothGatt: registerApp()
11-01 13:53:30.361 20786-22447/com.aragoncs.chronos D/BluetoothGatt: registerApp() - UUID=c534be4e-f0f0-463b-9f86-33b1d775e489
11-01 13:53:30.421 20786-20799/com.aragoncs.chronos D/BluetoothGatt: onClientRegistered() - status=0 clientIf=6
11-01 13:53:30.421 20786-20801/com.aragoncs.chronos D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=6 device=DA:7B:4D:51:CB:4C
11-01 13:53:32.031 20786-20801/com.aragoncs.chronos D/BluetoothGatt: discoverServices() - device: DA:7B:4D:51:CB:4C
11-01 13:53:32.031 20786-20799/com.aragoncs.chronos D/BluetoothGatt: onSearchComplete() = Device=DA:7B:4D:51:CB:4C Status=0
11-01 13:53:32.061 20786-22447/com.aragoncs.chronos D/BluetoothGatt: cancelOpen() - device: DA:7B:4D:51:CB:4C
11-01 13:53:32.071 20786-20799/com.aragoncs.chronos D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=6 device=DA:7B:4D:51:CB:4C
11-01 13:53:32.091 20786-22447/com.aragoncs.chronos D/BluetoothGatt: close()
11-01 13:53:32.091 20786-22447/com.aragoncs.chronos D/BluetoothGatt: unregisterApp() - mClientIf=6
11-01 13:53:32.871 20786-20786/com.aragoncs.chronos D/SRIB_DCS: log_dcs ThreadedRenderer::initialize entered! 
11-01 13:53:32.871 20786-21374/com.aragoncs.chronos D/mali_winsys: new_window_surface returns 0x3000,  [1071x154]-format:1
11-01 13:53:32.911 20786-21374/com.aragoncs.chronos V/RenderScript: 0xeec11000 Launching thread(s), CPUs 8

I doubt why I have call the DfuServiceInitiator,start() method, it still show me "Upload failed:DFU SERVICE NOT　FOUND"，Is it necessary to keep the dfuservice alive longly or How to initial the dfuservice? Do you have any ideas?

philips77 commented 8 years ago

The DFU Service Not Found message is shown when there is no... DFU Service or required cheracteristics in the peripheral's device attributes list. It may be a matter of cache. Try connecting with nRF Connect with the device and verify the DFU Service or Secure DFU Service is there by selecting Refresh device services from the top-right menu.

bbergshaven commented 8 years ago

Hello, I just discovered one thing that had a major impact on the amount of 133 errors we got while doing DFU. As you mention over the problem might be correlated with connection parameters and many before has mentioned that 133's can origin from timing issues.

What we saw was that after sending the necessary commands to put the device in bootloader modus and disconnecting, the act of connecting to the "new" (changed mac-address) device would randomly fail. After a full day of BLE sniffing and debugging I realised that when the connection failed, with an 133 error, Android had not sent any connection request over the air, so the whole "could not connect" or "got disconnected before service discovery" was generated internally in Android.

The solution that I tried was to do a short scan before trying to connect. I didn't care about the scan results, this was just a way to put the Bluetooth radio in another state. And it seems to work.

So the procedure is as follows:

  1. Write to the buttonless dfu service and make the device reboot into boot loader modus
  2. After getting the disconnected callback in android, do a short (500-1000ms) scan.
  3. Start the Nordic DFU service with the new mac-address.
  4. Wait for DFU to successfully complete.

This might help some others struggling with the same error. Please let me know if anyone has more info regarding this issue.

pasmontesinos commented 7 years ago

Hello,

I have a problem discovering services -> Connection state change error: 133 newState: 0

The error produces on Samsung Note 4 with Android 6.0.1 and OnePlus One with Android 6.0.1 but not on Nexus 5 with Android 6.0.1.

This problem not solved with waiting time before discovering services because not are bonded and not enter on waiting time. If these are bonded the problem not reproduce.

Regards.

troyjperales commented 7 years ago

We are also seeing this issue in our Android application.

In particular, we enter bootloader mode for our device which has the DFU service. We then start our DfuBaseService using the +1 MAC address. Afterwhich, the service will connect, then receive the 133 error and "Device got disconnected before service discovery finished" log. We attempt up to 3 more times with about 5 seconds of waiting in between, but to no avail. This will occur consistently until we open the nRF Connect app and force a connection then disconnection with DfuTarg and start the process again.

@philips77 It doesn't look like the use case of starting the DFU process when disconnected from DfuTarg is ever exercised with the nRF Connect app. Is your recommendation for implementers to handle the connection at the app level and not start DfuBaseService until the connection is established?

philips77 commented 7 years ago

Did you try to send connection parameters request from the peripheral/dfu targ after it gets connected? From my experience the 133 error happens when Android expected something or received something unexpectedly. We had a case where sending an update with connection interval helped. And in my opinion it should be possible to avoid it almost completely with some magic on the peripheral side. I didn't work with older Android versions for a while now so didn't see 133. The new versions are much more gentle when it comes to accepting something odd.

Regarding your question, both scenarios should work. Connection to a device is usually handled by the app while connection to the dfu targ after it resets is done by the lib only. On what phone and Android do you have this issue mostly?

troyjperales commented 7 years ago

I'll have to check with the firmware developer regarding if the connection parameters request is sent from the peripheral after connection and I'll suggest the connection interval update.

We have seen this issue occur on

troyjperales commented 7 years ago

I confirmed with the firmware developer that he is sending the connection interval upon connection.

@philips77 - Can you give any more insight to the "magic on the peripheral side" that might prevent 133 errors further?

philips77 commented 7 years ago

If only i knew... I'm not a firmware developer and i only rely on my experience on Android that this error happens (or rather used to happen on older Android versions) not without any reason, but when the old stack there got something unexpected or didn't get expected in some time frame. So in theory there should be a series of packets that were expected and such wouldn't cause 133. I was suspecting the connection param update at the beginning as it helped us in one project, but surely there are more possible options. Also, what would help on one phone may not help on others. The ble on Android has good coverage on tests since M, i guess. Now they have reimplemented it in c++ to have even better testing options in N. Unfortunately, there are still the old versions on low end devices with cheap and bad components...

My solution would be to use sniffer or built in snoop_log on Android and see when the error occurs. Perhaps there are some patterns. Some Research has to be added to Development to make it R&D. We could help as much as we can but we now mainly test on new Samsung/Nexus/Pixel devices with latest possible Android and really see any 133. We still have Nexus 4 or 5 or Samsung S3 with quite old systems that we could use for testing. But it would require 2/3 people, imho. Fw and Android developers and ble expert. Also, not much guarantee of success and kind of a pointless task in long term, as the old devices eventually will be replaced. But seems exciting.

troyjperales commented 7 years ago

@philips77 Thanks for the feedback!

soxunyi commented 7 years ago

If 133 error，please check the sensor address. If a sensor which is in dfu status is scanned, the sensor address should not be increased 1 when connecting it.

softcharles commented 7 years ago

Sometimes it is impossible for our app to DFU due to that the Connection fails with 133. A way to workaround this is that the DfuBaseService shall try autoconnect (passive) instead of an active Connection.

i.e. change from: device.connectGatt(this, false, mGattCallback); to device.connectGatt(this, true, mGattCallback) in dfubaseservice (and add a manual timeout);

This is also problably the same reason for why it works in some cases to put a manual scan before the connect. AFAIK, it shall never be possible to do an active connection without scanning first. Maybe it would be good to fallback to a passive connection if the active fails, before giving up the DFU

philips77 commented 6 years ago

I'll release 1.8.0 of the library today. It contains a lot of improvements since this issue was created, hopefully some 133s will be eliminated. Let me close the issue here. Feel free to open a new issue if you experience it again, but 133 is a common problem for 'something went wrong', so it usually is not related to the library itself, rather to the Android version or the hardware controller. You may also try to do the test in less 2.4GHz-noisy environment to avoid packet losses or collisions.