SweetBlue icon indicating copy to clipboard operation
SweetBlue copied to clipboard

Samsung S8 does not disconnect from peripheral

Open xmike opened this issue 8 years ago • 6 comments

The Samsung S8 phone with Android 7.0 does not disconnect from a previously connected device, even after closing the app and stopping the app process. I'm checking this using a ble sniffer. The connection is held "forever". Only turning Bluetooth off will cause a disconnect. This happens sometimes (once in two or three days of testing) and is not easily reproducible. Once the problem occured, it persists even after turning Bluetooth off/on. In this case, everytime the app is started (after turning bluetooth off/on, to break the previous connection) a connection is established properly, however the device is not disconnected when closing the app. The issue has not been seen on other phones yet, including S6 edge. If the issue happens, an Error is reported: ERRORMAIN(28477) The only way to get rid of the problem is to restart the phone. Then also the error message disappears.

Here is the log: Note: I'm calling disconnect in onPause() of the activity

01-10 16:33:57.810 28477-28477/com.itsme.test I/P_TaskQueue: MAIN(28477) print() - no current task [Connect(QUEUED itag_519_ABA5 35145974 )]

01-10 16:33:57.885 28477-28477/com.itsme.test I/P_TaskQueue: MAIN(28477) print() - Connect(EXECUTING itag_519_ABA5 35145974 ) [queue empty]

01-10 16:33:57.887 28477-28477/com.itsme.test I/P_NativeDeviceWrapper: ERRORMAIN(28477) performGetNativeState() - Tracked native state STATE_DISCONNECTED(0) doesn't match reported state STATE_CONNECTED(2).

01-10 16:33:57.889 28477-28477/com.itsme.test I/P_NativeDeviceWrapper: ERRORMAIN(28477) performGetNativeState() - Tracked native state STATE_DISCONNECTED(0) doesn't match reported state STATE_CONNECTED(2).

01-10 16:33:57.892 28477-28477/com.itsme.test I/P_NativeDeviceWrapper: ERRORMAIN(28477) performGetNativeState() - Tracked native state STATE_DISCONNECTED(0) doesn't match reported state STATE_CONNECTED(2).

01-10 16:33:58.027 28477-28477/com.itsme.test I/P_BleDevice_Listeners: MAIN(28477) onConnectionStateChange_updateThread() - GATT_CONN_SUCCESS(0) STATE_CONNECTED(2)

01-10 16:33:58.027 28477-28477/com.itsme.test I/P_NativeDeviceWrapper: MAIN(28477) updateNativeConnectionState() - STATE_CONNECTED(2)

01-10 16:33:58.028 28477-28477/com.itsme.test I/PA_Task: MAIN(28477) setState() - Connect(SUCCEEDED itag_519_ABA5 35145974 ) - 2027

01-10 16:33:58.032 28477-28477/com.itsme.test I/BleDevice: MAIN(28477) onNativeConnect() - BOND_BONDED(12)

01-10 16:33:58.038 28477-28477/com.itsme.test I/P_TaskQueue: MAIN(28477) print() - no current task [DiscoverServices(QUEUED itag_519_ABA5 34635577 )]

01-10 16:33:58.049 28477-28477/com.itsme.test I/P_TaskQueue: MAIN(28477) print() - DiscoverServices(EXECUTING itag_519_ABA5 34635577 ) [queue empty]

01-10 16:33:58.858 28477-28477/com.itsme.test I/P_BleDevice_Listeners: MAIN(28477) onServicesDiscovered_updateThread() - GATT_SUCCESS(0)

01-10 16:33:58.860 28477-28477/com.itsme.test I/PA_Task: MAIN(28477) setState() - DiscoverServices(SUCCEEDED itag_519_ABA5 34635577 ) - 2052

01-10 16:33:58.899 28477-28477/com.itsme.test I/P_TaskQueue: MAIN(28477) print() - no current task [queue empty]

01-10 16:34:01.086 28477-28477/com.itsme.test I/P_TaskQueue: MAIN(28477) print() - no current task [Write(QUEUED itag_519_ABA5 00001526-9f03-0de5-96c5-b8f4f3081186 txn==null 189127793 )]

01-10 16:34:01.096 28477-28477/com.itsme.test I/P_TaskQueue: MAIN(28477) print() - Write(EXECUTING itag_519_ABA5 00001526-9f03-0de5-96c5-b8f4f3081186 txn==null 189127793 ) [queue empty]

01-10 16:34:01.162 28477-28477/com.itsme.test I/P_BleDevice_Listeners: MAIN(28477) onCharacteristicWrite_updateThread() - char=00001526-9f03-0de5-96c5-b8f4f3081186

01-10 16:34:01.162 28477-28477/com.itsme.test I/P_BleDevice_Listeners: MAIN(28477) onCharacteristicWrite_updateThread() - GATT_SUCCESS(0)

01-10 16:34:01.163 28477-28477/com.itsme.test I/PA_Task: MAIN(28477) setState() - Write(SUCCEEDED itag_519_ABA5 00001526-9f03-0de5-96c5-b8f4f3081186 txn==null 189127793 ) - 2152

01-10 16:34:01.164 28477-28477/com.itsme.test I/P_TaskQueue: MAIN(28477) print() - no current task [queue empty]

....... do some more writes ......

01-10 16:34:06.669 28477-28477/? I/P_TaskQueue: MAIN(28477) print() - no current task [Disconnect(QUEUED itag_519_ABA5 249980753 )]

01-10 16:34:06.671 28477-28477/? I/BleManager: MAIN(28477) stopScan_private() - Clearing queue of any scan tasks...

01-10 16:34:06.672 28477-28477/? I/BleManager: MAIN(28477) stopScan_private() - Clearing queue of any scan tasks...

01-10 16:34:06.679 28477-28477/? I/P_TaskQueue: MAIN(28477) print() - Disconnect(EXECUTING itag_519_ABA5 249980753 ) [queue empty]

01-10 16:34:06.737 28477-28477/? I/BleManager: MAIN(28477) update() - Update loop took longer to run than the current interval of 20ms

01-10 16:34:06.761 28477-28477/? I/P_BleDevice_Listeners: MAIN(28477) onConnectionStateChange_updateThread() - GATT_CONN_SUCCESS(0) STATE_DISCONNECTED(0)

01-10 16:34:06.762 28477-28477/? I/P_NativeDeviceWrapper: MAIN(28477) updateNativeConnectionState() - STATE_DISCONNECTED(0)

01-10 16:34:06.767 28477-28477/? I/PA_Task: MAIN(28477) setState() - Disconnect(SUCCEEDED itag_519_ABA5 249980753 ) - 2407

01-10 16:34:06.771 28477-28477/? I/VibBleWrapper: Disconnected state entered

01-10 16:34:06.785 28477-28477/? I/P_NativeDeviceWrapper: ERRORMAIN(28477) performGetNativeState() - Tracked native state STATE_DISCONNECTED(0) doesn't match reported state STATE_CONNECTED(2).

01-10 16:34:06.786 28477-28477/? I/P_TaskQueue: MAIN(28477) print() - no current task [queue empty]

xmike avatar Jan 10 '18 18:01 xmike

We had a similar thing when Spotify was installed, it might be worth checking: https://community.spotify.com/t5/Ongoing-Issues/Android-app-interferes-with-BLE-devices/idi-p/1700631 https://stackoverflow.com/questions/43160195/android-ble-unexpectedly-and-repeatedly-reconnects-to-peripheral/43688791#43688791

kenwdelong avatar Jan 10 '18 18:01 kenwdelong

thanks, good to know! No, in this case Spotify is not installed on the phone.

xmike avatar Jan 10 '18 19:01 xmike

I've seen this happen before where the reported state doesn't match the state the device is actually in (we'll get a state from a callback, but if you query the state, it reports a different state). Whenever I've seen this, it's always been during pretty intense testing. I've never seen it happen in any of our production apps.

As it's a problem in the underlying android stack, I'm not sure there's much we can do. One thing I'd like you to try though; Try calling BleManager.nukeBle() when you get into this state again. It's essentially is the same thing as reset(), but calls another mysterious hidden method, which we're trying to determine if it helps in these extreme cases.

ryanhubbell avatar Jan 11 '18 14:01 ryanhubbell

Sorry to get back on this so late. We tested this a while ago but I forgot to respond to your comment. In fact, calling nukeBle() does help if this happens.

xmike avatar Apr 16 '18 18:04 xmike

Hi folks, I'm seeing similar behavior (no Spotify either), with the device reconnecting unexpectedly and repeatedly to the peripheral (see: https://stackoverflow.com/questions/50348465/ble-stack-repeatedly-reconnects-to-peripheral-after-connection-is-closed-and-app) after the connection is close()d.

I had a look at nukeBle() in the hopes that it might solve the problem, but realized that at least in current versions of Android, the underlying factoryReset call on the BluetoothAdapter checks for the BLUETOOTH_PRIVILEGED permission, which is not available to third-party apps, see: https://developer.android.com/reference/android/Manifest.permission#bluetooth_privileged

suzukieng avatar May 16 '18 10:05 suzukieng

Yes, we're aware of the permission requirement. However, it still does do something, although it's unclear exactly what it does do under the hood. We've had a couple people use it so far, and it seems to have helped in a couple of cases. Though I imagine this will vary greatly depending on device, and the issue that's happening.

ryanhubbell avatar May 16 '18 12:05 ryanhubbell