Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Android] After migration from 2.0.3 to 3.1.2 device disconnect after 5 second. #1157

Closed
4 tasks done
p4bl1t0 opened this issue Dec 18, 2023 · 24 comments · Fixed by #1226
Closed
4 tasks done

[Android] After migration from 2.0.3 to 3.1.2 device disconnect after 5 second. #1157

p4bl1t0 opened this issue Dec 18, 2023 · 24 comments · Fixed by #1226
Labels

Comments

@p4bl1t0
Copy link

p4bl1t0 commented Dec 18, 2023

Prerequisites

  • I checked the documentation and FAQ without finding a solution
  • I checked to make sure that this issue has not already been filed
  • I'm sure that question is related to the library itself and not Bluetooth Low Energy or Classic in general. If that so, please post your question on StackOverflow.
  • I'm running the latest version

Question

I've upgrade from v2 to v3. Now while connecting from an Android phone the BLE device disconnect 5 seconds without any other error. On the event "onDeviceDisconnected" error is equal to null.

The documentation said that this is because of a call to cancelConnection but no call is made.

Using exactly the same code with version 2 works all fine so I asking for hint to help me to find the problem with connection. It's has to be a changed in the library.

In JavaScript I doesn't have any log information. This is the phone logcat

12-18 12:21:54.414 13688 17245 D BluetoothGatt: connect() - device: F0:5C:7C:7A:CB:15, auto: false
12-18 12:21:54.415 13688 17245 D BluetoothGatt: registerApp()
12-18 12:21:54.415 13688 17245 D BluetoothGatt: registerApp() - UUID=922321d0-501a-41d0-8816-5711e7ab408f
12-18 12:21:54.415  2504  2521 D BtGatt.GattService: registerClient() - UUID=922321d0-501a-41d0-8816-5711e7ab408f
12-18 12:21:54.416  2504  2936 I bt_stack: [INFO:gatt_api.cc(950)] GATT_Register e30e9475-f3cf-4038-dfbc-17075ee9c589
12-18 12:21:54.416  2504  2936 I bt_stack: [INFO:gatt_api.cc(970)] allocated gatt_if=8
12-18 12:21:54.417  2504  2610 D BtGatt.GattService: onClientRegistered() - UUID=922321d0-501a-41d0-8816-5711e7ab408f, clientIf=8
12-18 12:21:54.417 13688 13705 D BluetoothGatt: onClientRegistered() - status=0 clientIf=8
12-18 12:21:54.418  2504  2521 D BtGatt.GattService: clientConnect() - address=F0:5C:7C:7A:CB:15, isDirect=true, opportunistic=false, phy=1
12-18 12:21:54.419  2504  2610 D bt_btif_config: btif_get_address_type: Device [f0:5c:7c:7a:cb:15] address type 1
12-18 12:21:54.419  2504  2610 D bt_btif_config: btif_get_device_type: Device [f0:5c:7c:7a:cb:15] type 2
12-18 12:21:54.420  2504  2936 I bt_stack: [INFO:gatt_api.cc(1122)] GATT_Connect gatt_if=8, address=f0:5c:7c:7a:cb:15 is_direct 1
12-18 12:21:54.451  2504  2936 I bt_stack: [INFO:connection_manager.cc(277)] lower the scan parameters used for connecting
12-18 12:21:54.452  2504  2936 I bt_stack: [INFO:btm_ble_bgconn.cc(406)] Already connection initiated (or) No Pending connections(or) Resources of lcb are exhausted
12-18 12:21:54.452  2504  2936 W bt_btm  : btm_acl_created hci_handle=9 link_role=0  transport=2
12-18 12:21:54.452  2504  2936 I bt_stack: [INFO:btm_ble_bgconn.cc(406)] Already connection initiated (or) No Pending connections(or) Resources of lcb are exhausted
12-18 12:21:54.523  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 8, msg_len = 6
12-18 12:21:54.524  2504  2936 E bt_btif : bta_dm_acl_change new acl connetion:count = 1
12-18 12:21:54.524  2504  2936 W bt_btif : bta_dm_acl_change info: 0x0
12-18 12:21:54.524  2504  2936 W bt_l2cap: L2CA_SetDesireRole() new:x1, disallow_switch:0
12-18 12:21:54.524  2504  2936 E bt_stack: [ERROR:bta_gattc_cache.cc(733)] bta_gattc_cache_load: can't open GATT cache file /data/misc/bluetooth/gatt_cache_f05c7c7acb15 for reading, error: No such file or directory
12-18 12:21:54.525  2504  2936 I bt_stack: [INFO:hearing_aid.cc(1804)] GetDeviceCount: Not initialized yet
12-18 12:21:54.525  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=1, s_handle=0x0001, e_handle=0xffff
12-18 12:21:54.526  2504  2610 D bt_btif_dm: remote version info [f0:5c:7c:7a:cb:15]: 0, 0, 0
12-18 12:21:54.532  2504  2610 D BtGatt.GattService: onConnected() - clientIf=8, connId=8, address=F0:5C:7C:7A:CB:15
12-18 12:21:54.533 13688 13705 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=F0:5C:7C:7A:CB:15
12-18 12:21:54.535  2504 17327 D BluetoothMetrics: btclass1f00
12-18 12:21:54.535  1062  1562 D NativeSensors: CapSensor:  mPendingEvent.distance=1.000000
12-18 12:21:54.537 16806 16806 W BluetoothEventManager: AclStateChangedHandler: activeDevice is null
12-18 12:21:54.539  2524  2757 W BluetoothEventManager: AclStateChangedHandler: activeDevice is null
12-18 12:21:54.541 13688 17245 D BluetoothGatt: configureMTU() - device: F0:5C:7C:7A:CB:15 mtu: 253
12-18 12:21:54.542  2504  2521 D BtGatt.GattService: configureMTU() - address=F0:5C:7C:7A:CB:15 mtu=253
12-18 12:21:54.546 12461 12461 D MCLOG   : [MC_Service] onStartcommand()
12-18 12:21:54.546  2504 17327 D Checkin : publish the event [tag = MOT_BT event name = CONN_SUC]
12-18 12:21:54.562   970   970 D Zygote  : Forked child process 17328
12-18 12:21:54.568  1537  1829 I ActivityManager: Start proc 17328:com.google.android.projection.gearhead:shared/u0a240 for broadcast {com.google.android.projection.gearhead/com.google.android.apps.auto.wireless.bluetooth.WifiBluetoothReceiver}
12-18 12:21:54.575 17328 17328 E gearhead:share: Unknown bits set in runtime_flags: 0x8000
12-18 12:21:54.584 17328 17328 E gearhead:share: Not starting debugger since process cannot load the jdwp agent.
12-18 12:21:54.613  1062  1562 D NativeSensors: CapSensor:  mPendingEvent.distance=2.000000
12-18 12:21:54.624 17328 17328 I gearhead:share: The ClassLoaderContext is a special shared library.
12-18 12:21:54.624  1089  3015 E WifiHAL : Received fatal event, sending alert
12-18 12:21:54.625  1537 12332 W WifiVendorHal: onDebugErrorAlert 4104
12-18 12:21:54.713 17328 17328 D ProcessLifecycleG3: androidx.startup is not available, initializing using ProcessLifecycleOwnerInitializer instead.
12-18 12:21:54.718  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 17, msg_len = 13
12-18 12:21:54.762 17328 17328 I CAR.GH  : onCreate
12-18 12:21:54.796 17328 17328 I GH.PrimesMgr: transmitting to prod
12-18 12:21:54.804 17328 17353 W gearhead:share: Accessing hidden field Ljava/util/Collections$SynchronizedCollection;->mutex:Ljava/lang/Object; (greylist-max-o, reflection, denied)
12-18 12:21:54.804 17328 17353 W gearhead:share: Accessing hidden method Ljava/util/Collections$SynchronizedSet;-><init>(Ljava/util/Set;Ljava/lang/Object;)V (greylist-max-o, reflection, denied)
12-18 12:21:54.804 17328 17353 W gearhead:share: Accessing hidden method Ljava/util/Collections$SynchronizedCollection;-><init>(Ljava/util/Collection;Ljava/lang/Object;)V (greylist-max-o, reflection, denied)
12-18 12:21:54.806 17328 17328 I CAR.GH  : Process: SHARED_SERVICE
12-18 12:21:54.815  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 17, msg_len = 21
12-18 12:21:54.886  1537  1614 I system_server: Background concurrent copying GC freed 194192(8799KB) AllocSpace objects, 41(11MB) LOS objects, 42% free, 27MB/47MB, paused 136us total 157.840ms
12-18 12:21:54.912  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 17, msg_len = 21
12-18 12:21:54.917 17328 17328 I CAR.GH  : onCreate completed
12-18 12:21:54.935 17328 17328 I GH.WifiBluetoothRcvr: Connection action: android.bluetooth.device.action.ACL_CONNECTED, device F0:5C:7C:7A:CB:15
12-18 12:21:54.947  2968  2968 E AbstractGmsTracer: Traced class shouldn't be obfuscated: PersistentTrustedChimeraReceiver [CONTEXT service_id=259 ]
12-18 12:21:54.947  1537  6138 I ActivityManager: Killing 14505:com.google.android.gm/u0a119 (adj 985): empty #17
12-18 12:21:54.951  3404  3404 E AbstractGmsTracer: Traced class shouldn't be obfuscated: GmsIntentOperationChimeraService [CONTEXT service_id=259 ]
12-18 12:21:54.956  2968  2968 E AbstractGmsTracer: Traced class shouldn't be obfuscated: PersistentIntentOperationChimeraService [CONTEXT service_id=259 ]
12-18 12:21:54.960  4403  5382 I bchi    : (REDACTED) bluetoothConnectionStateChanged. Action: %s
12-18 12:21:54.960  3404 17361 E AbstractGmsTracer: Traced class shouldn't be obfuscated: CarBluetoothReceiverOperation [CONTEXT service_id=259 ]
12-18 12:21:54.961  2968 17362 E AbstractGmsTracer: Traced class shouldn't be obfuscated: BluetoothDeviceIntentOperation [CONTEXT service_id=259 ]
12-18 12:21:54.962  3404 17361 E AbstractGmsTracer: Traced class shouldn't be obfuscated: BluetoothReceiverOperation [CONTEXT service_id=259 ]
12-18 12:21:54.962  2968 17362 I Nearby  : (REDACTED) is blocked device type %s, isAuto=%s, isIot=%s, isLatchsky=%s, isChinaWearable=%s, isTv=%s, isWearable=%s (supportWearOs=%s), isChromeOsDevice=%s (supportChromeOs=%s)
12-18 12:21:54.965  2968  2968 I NearbyDiscovery: (REDACTED) onAclChange: state=%s, %s
12-18 12:21:54.970  2968 10615 I NearbyDiscovery: (REDACTED) FastPair: lock scan rate if needed, %s, bondState=%s
12-18 12:21:54.971  2968 16473 I NearbyDiscovery: (REDACTED) FastPairBattery: No associated accountKey is found when query battery info, %s
12-18 12:21:54.990  4403  4702 I bchi    : (REDACTED) Failed to get bistoDeviceInfo %s
12-18 12:21:55.003 17328 17355 I GH.CarSvcDataStorage: Using DB version: 12
12-18 12:21:55.005  4403  4702 I atnw    : Not bonded or not refresh cache.
12-18 12:21:55.009  4403  4711 W bchi    : Failed to get bisto device info.
12-18 12:21:55.009  4403  4711 W bchi    : cfkr
12-18 12:21:55.009  4403  4711 W bchi    : 	at cftw.get(PG:1)
12-18 12:21:55.009  4403  4711 W bchi    : 	at j$.util.Optional.orElseThrow(SourceFile:2)
12-18 12:21:55.009  4403  4711 W bchi    : 	at cftx.apply(PG:3)
12-18 12:21:55.009  4403  4711 W bchi    : 	at hbvz.apply(PG:3)
12-18 12:21:55.009  4403  4711 W bchi    : 	at hsvk.e(PG:2)
12-18 12:21:55.009  4403  4711 W bchi    : 	at hsvl.run(PG:9)
12-18 12:21:55.009  4403  4711 W bchi    : 	at exhk.run(PG:1)
12-18 12:21:55.009  4403  4711 W bchi    : 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
12-18 12:21:55.009  4403  4711 W bchi    : 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
12-18 12:21:55.009  4403  4711 W bchi    : 	at exgp.run(PG:2)
12-18 12:21:55.009  4403  4711 W bchi    : 	at java.lang.Thread.run(Thread.java:919)
12-18 12:21:55.009  4403  4711 W bchi    : 	at exhp.run(PG:5)
12-18 12:21:55.010  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 17, msg_len = 7
12-18 12:21:55.010  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=3, s_handle=0x0001, e_handle=0x0009
12-18 12:21:55.013  2504  2610 D BtGatt.GattService: onClientConnUpdate() - connId=8, status=0
12-18 12:21:55.013 13688 17359 D BluetoothGatt: onConnectionUpdated() - Device=F0:5C:7C:7A:CB:15 interval=6 latency=0 timeout=500 status=0
12-18 12:21:55.018 17328 17367 I GH.ConnLoggerV2: Started session 3f85df64-e1f2-4f7f-a3d0-787e1d142981, start time = 11897483
12-18 12:21:55.023 17328 17367 I GH.ConnLoggerV2: Session 3f85df64-e1f2-4f7f-a3d0-787e1d142981, event 0, detail OptionalInt.empty, SESSION_STARTED, at 11897483
12-18 12:21:55.023 17328 17355 W CAR.BTCapsStore: Device not bonded, thus it's not currently AAW capable.
12-18 12:21:55.023 17328 17355 I CAR.BTCapsStore: AAW status (UNKNOWN_AND_DONT_TRY_RFCOMM).
12-18 12:21:55.031  1537  6137 D ConnectivityService: ConnectivityService NetworkRequestInfo binderDied(NetworkRequest [ LISTEN id=795, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10119] ], android.os.BinderProxy@3963821)
12-18 12:21:55.031  1537  6145 D ConnectivityService: ConnectivityService NetworkRequestInfo binderDied(NetworkRequest [ TRACK_DEFAULT id=794, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10119] ], android.os.BinderProxy@a1b1688)
12-18 12:21:55.032   970   970 I Zygote  : Process 14505 exited due to signal 9 (Killed)
12-18 12:21:55.032  1537  6137 D ConnectivityService: ConnectivityService NetworkRequestInfo binderDied(NetworkRequest [ TRACK_DEFAULT id=792, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10119] ], android.os.BinderProxy@6962446)
12-18 12:21:55.032  1537  3226 D ConnectivityService: ConnectivityService NetworkRequestInfo binderDied(NetworkRequest [ TRACK_DEFAULT id=793, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10119] ], android.os.BinderProxy@11ef607)
12-18 12:21:55.032  1537  2660 D ActivityManager: makeInactive, ProcessRecord{87f30a0 14505:com.google.android.gm/u0a119}, clear holder.state
12-18 12:21:55.032  1537  2473 D ConnectivityService: releasing NetworkRequest [ TRACK_DEFAULT id=792, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10119] ] (release request)
12-18 12:21:55.033  1537  2473 D ConnectivityService: releasing NetworkRequest [ TRACK_DEFAULT id=793, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10119] ] (release request)
12-18 12:21:55.034  1537  1831 I libprocessgroup: Successfully killed process cgroup uid 10119 pid 14505 in 85ms
12-18 12:21:55.034  1537  2473 D ConnectivityService: releasing NetworkRequest [ TRACK_DEFAULT id=794, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10119] ] (release request)
12-18 12:21:55.039 17328 17367 I GH.ConnLoggerV2: Session 3f85df64-e1f2-4f7f-a3d0-787e1d142981, event 1, detail OptionalInt.empty, USB_CHARGER_CONNECTED, at 11897483
12-18 12:21:55.039 17328 17367 I GH.ConnLoggerV2: Session 3f85df64-e1f2-4f7f-a3d0-787e1d142981, event 2, detail OptionalInt.empty, INTERNET_CONNECTED, at 11897493
12-18 12:21:55.040 17328 17367 I GH.ConnLoggerV2: Session 3f85df64-e1f2-4f7f-a3d0-787e1d142981, event 3, detail OptionalInt.empty, WIRELESS_WIFI_STATE_ENABLED, at 11897493
12-18 12:21:55.041 17328 17367 I GH.ConnLoggerV2: Session 3f85df64-e1f2-4f7f-a3d0-787e1d142981, event 4, detail OptionalInt.empty, GH_USB_CONFIGURED, at 11897495
12-18 12:21:55.069 17328 17328 I CAR.TOKEN: Connecting ksf@9c8d4a6 using class law@70462100/class laz@162615015 (cx attempt 1)
12-18 12:21:55.071 17328 17328 I GH.SharedService: Shared Service created
12-18 12:21:55.081  2504  2936 W bt_btm  : btm_read_remote_version_complete lmp_version 9 manufacturer 89 lmp_subversion 183
12-18 12:21:55.083   970   970 D Zygote  : Forked child process 17376
12-18 12:21:55.087  1537  1829 I ActivityManager: Start proc 17376:com.google.android.projection.gearhead:car/u0a240 for broadcast {com.google.android.projection.gearhead/com.google.android.apps.auto.carservice.gmscorecompat.CarBluetoothReceiver}
12-18 12:21:55.090 17328 17328 I GH.SharedServiceConnect: onServiceConnected(ComponentName:ComponentInfo{com.google.android.projection.gearhead/com.google.android.gearhead.service.SharedService}, service:hhs@33a693d)
12-18 12:21:55.097 17376 17376 E on.gearhead:ca: Unknown bits set in runtime_flags: 0x8000
12-18 12:21:55.104  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.104  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=4, s_handle=0x0001, e_handle=0x0009
12-18 12:21:55.105 17376 17376 E on.gearhead:ca: Not starting debugger since process cannot load the jdwp agent.
12-18 12:21:55.119  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 22
12-18 12:21:55.134  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 8
12-18 12:21:55.147 17376 17376 I on.gearhead:ca: The ClassLoaderContext is a special shared library.
12-18 12:21:55.149  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.149  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=3, s_handle=0x000a, e_handle=0x000d
12-18 12:21:55.164  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.164  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=4, s_handle=0x000a, e_handle=0x000d
12-18 12:21:55.179  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 8
12-18 12:21:55.209  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.209  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=5, s_handle=0x000d, e_handle=0x000d
12-18 12:21:55.216 17376 17376 I CAR.GH  : onCreate
12-18 12:21:55.224  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 5, msg_len = 5
12-18 12:21:55.224  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=3, s_handle=0x000e, e_handle=0x0015
12-18 12:21:55.239  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.239  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=4, s_handle=0x000e, e_handle=0x0015
12-18 12:21:55.249 17376 17376 I GH.PrimesMgr: transmitting to prod
12-18 12:21:55.254  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 22
12-18 12:21:55.255 17376 17397 W on.gearhead:ca: Accessing hidden field Ljava/util/Collections$SynchronizedCollection;->mutex:Ljava/lang/Object; (greylist-max-o, reflection, denied)
12-18 12:21:55.256 17376 17397 W on.gearhead:ca: Accessing hidden method Ljava/util/Collections$SynchronizedSet;-><init>(Ljava/util/Set;Ljava/lang/Object;)V (greylist-max-o, reflection, denied)
12-18 12:21:55.256 17376 17397 W on.gearhead:ca: Accessing hidden method Ljava/util/Collections$SynchronizedCollection;-><init>(Ljava/util/Collection;Ljava/lang/Object;)V (greylist-max-o, reflection, denied)
12-18 12:21:55.261 17376 17376 I CAR.GH  : Process: CAR
12-18 12:21:55.269  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 22
12-18 12:21:55.284  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 22
12-18 12:21:55.306  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.307  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=5, s_handle=0x0013, e_handle=0x0013
12-18 12:21:55.316 17376 17376 I CAR.GH  : onCreate completed
12-18 12:21:55.321 17376 17376 I GH.CAR  : onCreate
12-18 12:21:55.321  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 5, msg_len = 5
12-18 12:21:55.322  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=3, s_handle=0x0016, e_handle=0x001d
12-18 12:21:55.337  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.337  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=4, s_handle=0x0016, e_handle=0x001d
12-18 12:21:55.367  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 22
12-18 12:21:55.389  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 22
12-18 12:21:55.391 17376 17376 I GH.CAR  : gearheadCarServiceBinder in mainHandler: true
12-18 12:21:55.404  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.404  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=5, s_handle=0x0019, e_handle=0x001a
12-18 12:21:55.419  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 5, msg_len = 9
12-18 12:21:55.419  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=5, s_handle=0x001d, e_handle=0x001d
12-18 12:21:55.428 17376 17376 I GH.CAR  : Using GearheadCarServiceBinder in CarMessageService.
12-18 12:21:55.432 17376 17376 I GH.DelegateMngCarSvc: Retries remaining initialized to 20
12-18 12:21:55.432 17376 17376 I GH.CAR  : Using Gearhead for projection services. All aboard! 🚀
12-18 12:21:55.432 17376 17376 I GH.DelegateICarSupplier: Obtaining car service delegate from GMS Core via connectionless.
12-18 12:21:55.433 17376 17376 I GH.DelegateMngCarSvc: Skipping delegate acquisition on init().
12-18 12:21:55.433 17376 17376 I GH.CarService: Setting delegate: ejh@6d8b9a5
12-18 12:21:55.434  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 5, msg_len = 5
12-18 12:21:55.434  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=3, s_handle=0x001e, e_handle=0xffff
12-18 12:21:55.434 17376 17376 I CAR.SERVICE: Setting CSB delegate, previous value null updated to ffh@d75817a
12-18 12:21:55.434 17376 17376 I GH.CAR  : Setting validator car info suppliers
12-18 12:21:55.435 17376 17376 I GH.CAR  : ICar delegate chain:
12-18 12:21:55.435 17376 17376 I GH.CAR  : 	fgc@6d77d2b
12-18 12:21:55.435 17376 17376 I GH.CAR  : 	-> ejh@6d8b9a5
12-18 12:21:55.435 17376 17376 I GH.CAR  : 	-> ffh@d75817a
12-18 12:21:55.436 17376 17376 I GH.CAR  : GearheadCarStartupService.onBind
12-18 12:21:55.440 17376 17376 I CAR.BT_RCVR: Android is Q or below.
12-18 12:21:55.442  1537  2660 I ActivityManager: Killing 6840:com.google.process.gservices/u0a26 (adj 985): empty #17
12-18 12:21:55.447 17328 17406 I GH.GhCarClientCtor: Bound to startup service, got Car Service: ktk@4e95c39
12-18 12:21:55.449  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.449  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=4, s_handle=0x001e, e_handle=0xffff
12-18 12:21:55.451 17328 17328 I CAR.TOKEN: Successfully connected lbb@71f33df using class law@70462100/class laz@162615015 (cx attempt 1)
12-18 12:21:55.464  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 9, msg_len = 8
12-18 12:21:55.479  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.479  2504  2936 I bt_stack: [INFO:gatt_api.cc(635)] GATTC_Discover conn_id=0x0008, disc_type=5, s_handle=0x0021, e_handle=0xffff
12-18 12:21:55.482 17328 17328 I GH.CarClientManager: CarClientToken connected.
12-18 12:21:55.482 17328 17328 I GH.CarClientManager: Transition from UNINITIALIZED to CLIENT_CONNECTED.
12-18 12:21:55.499  1537  2660 D ActivityManager: makeInactive, ProcessRecord{2e5b01 6840:com.google.process.gservices/u0a26}, clear holder.state
12-18 12:21:55.502   970   970 I Zygote  : Process 6840 exited due to signal 9 (Killed)
12-18 12:21:55.503  1537  1831 I libprocessgroup: Successfully killed process cgroup uid 10026 pid 6840 in 60ms
12-18 12:21:55.509  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 5, msg_len = 5
12-18 12:21:55.516   970   970 D Zygote  : Forked child process 17413
12-18 12:21:55.521  1537  1829 I ActivityManager: Start proc 17413:com.google.process.gservices/u0a26 for content provider {com.google.android.gsf/com.google.android.gsf.gservices.GservicesProvider}
12-18 12:21:55.524  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 1, msg_len = 4
12-18 12:21:55.524  2504  2936 I bt_stack: [INFO:bta_gattc_cache.cc(183)] bta_gattc_explore_srvc_finished: service discovery finished
12-18 12:21:55.525  2504  2610 E bt_btif_gattc: btif_gattc_upstreams_evt: Unhandled event (8)!
12-18 12:21:55.534 17413 17413 E ocess.gservice: Not starting debugger since process cannot load the jdwp agent.
12-18 12:21:55.549  1537  6138 I ActivityManager: Killing 16008:com.google.android.apps.turbo:aab/u0a23 (adj 985): empty #17
12-18 12:21:55.554  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 3, msg_len = 2
12-18 12:21:55.555  2504  2936 W bt_l2cap: l2cble_set_fixed_channel_tx_data_length, request not supported
12-18 12:21:55.555  2504  2610 D BtGatt.GattService: onConfigureMTU() address=F0:5C:7C:7A:CB:15, status=0, mtu=247
12-18 12:21:55.556 13688 17359 D BluetoothGatt: onConfigureMTU() - Device=F0:5C:7C:7A:CB:15 mtu=247 status=0
12-18 12:21:55.563 13688 14889 I ReactNativeJS: 'StackLog: ', 'Connecting: BLE connection stablished…', '', '', '', '', '', '', '', ''
12-18 12:21:55.575 17413 17413 I ocess.gservice: The ClassLoaderContext is a special shared library.
12-18 12:21:55.584  2504  2610 D BtGatt.GattService: onClientConnUpdate() - connId=8, status=0
12-18 12:21:55.585 13688 17359 D BluetoothGatt: onConnectionUpdated() - Device=F0:5C:7C:7A:CB:15 interval=39 latency=0 timeout=500 status=0
12-18 12:21:55.619  1537  4048 D ActivityManager: makeInactive, ProcessRecord{d3f360e 16008:com.google.android.apps.turbo:aab/u0a23}, clear holder.state
12-18 12:21:55.620   970   970 I Zygote  : Process 16008 exited due to signal 9 (Killed)
12-18 12:21:55.634  1537  1831 I libprocessgroup: Successfully killed process cgroup uid 10023 pid 16008 in 84ms
12-18 12:21:55.665 17413 17413 I GservicesProvider: Gservices pushing to system: true; secure/global: true
12-18 12:21:55.781   969 17436 E ResolverController: No valid NAT64 prefix (100, <unspecified>/0)
12-18 12:21:56.502 13688 14889 I ReactNativeJS: 'ble.js: ', 'POST _on_Conn_ected-Device', true, '', '', '', '', '', '', ''
12-18 12:21:57.796   969 17440 E ResolverController: No valid NAT64 prefix (100, <unspecified>/0)
12-18 12:21:58.015 13688 14889 I ReactNativeJS: 'StackLog: ', 'Connecting: BLE creating channel…', '', '', '', '', '', '', '', ''
12-18 12:21:58.803     0     0 W swapper/0: type=1400 audit(0.0:1485): avc: denied { kill } for uid=0 capability=5 scontext=u:r:kernel:s0 tcontext=u:r:kernel:s0 tclass=capability permissive=0
12-18 12:21:58.917 13688 17245 D BluetoothGatt: discoverServices() - device: F0:5C:7C:7A:CB:15
12-18 12:21:58.918  2504  2521 D BtGatt.GattService: discoverServices() - address=F0:5C:7C:7A:CB:15, connId=8
12-18 12:21:58.919  2504  2610 D BtGatt.GattService: onSearchCompleted() - connId=8, status=0
12-18 12:21:58.921  2504  2610 D bt_bta_gattc: bta_gattc_get_gatt_db
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: onGetGattDb() - address=F0:5C:7C:7A:CB:15
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got service with UUID=00001800-0000-1000-8000-00805f9b34fb id: 1
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got characteristic with UUID=00002a00-0000-1000-8000-00805f9b34fb id: 3
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got characteristic with UUID=00002a01-0000-1000-8000-00805f9b34fb id: 5
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got characteristic with UUID=00002a04-0000-1000-8000-00805f9b34fb id: 7
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got characteristic with UUID=00002aa6-0000-1000-8000-00805f9b34fb id: 9
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got service with UUID=00001801-0000-1000-8000-00805f9b34fb id: 10
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got characteristic with UUID=00002a05-0000-1000-8000-00805f9b34fb id: 12
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got descriptor with UUID=00002902-0000-1000-8000-00805f9b34fb id: 13
12-18 12:21:58.923  2504  2610 D BtGatt.GattService: got service with UUID=00001530-1212-efde-1523-785feabcd123 id: 14
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got characteristic with UUID=00001532-1212-efde-1523-785feabcd123 id: 16
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got characteristic with UUID=00001531-1212-efde-1523-785feabcd123 id: 18
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got descriptor with UUID=00002902-0000-1000-8000-00805f9b34fb id: 19
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got characteristic with UUID=00001534-1212-efde-1523-785feabcd123 id: 21
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got service with UUID=6e400001-b5a3-f393-e0a9-e50e24dcca9e id: 22
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got characteristic with UUID=6e400003-b5a3-f393-e0a9-e50e24dcca9e id: 24
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got descriptor with UUID=00002902-0000-1000-8000-00805f9b34fb id: 25
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got descriptor with UUID=00002901-0000-1000-8000-00805f9b34fb id: 26
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got characteristic with UUID=6e400002-b5a3-f393-e0a9-e50e24dcca9e id: 28
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got descriptor with UUID=00002901-0000-1000-8000-00805f9b34fb id: 29
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got service with UUID=0000180f-0000-1000-8000-00805f9b34fb id: 30
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got characteristic with UUID=00002a19-0000-1000-8000-00805f9b34fb id: 32
12-18 12:21:58.924  2504  2610 D BtGatt.GattService: got descriptor with UUID=00002902-0000-1000-8000-00805f9b34fb id: 33
12-18 12:21:58.925 13688 17359 D BluetoothGatt: onSearchComplete() = Device=F0:5C:7C:7A:CB:15 Status=0
12-18 12:21:58.929 13688 14889 I ReactNativeJS: 'ble.js: ', 'Discover All Services And Characteristics OK', '', '', '', '', '', '', '', ''
12-18 12:21:58.939 13688 14889 I ReactNativeJS: 'StackLog: ', 'Connecting: BLE channel stablished…', '', '', '', '', '', '', '', ''
12-18 12:21:59.808   969 17444 E ResolverController: No valid NAT64 prefix (100, <unspecified>/0)
12-18 12:21:59.824 13688 14889 I ReactNativeJS: 'ble.js: ', 'uart channerl', true, 'doMonitor', true, '', '', '', '', ''
12-18 12:21:59.826 13688 14889 I ReactNativeJS: 'ble.js: ', 'send_Command', { charCode: '7237A1B5-790A-D044-0123-456789ABCDE0' }, '', '', '', '', '', '', ''
12-18 12:21:59.827 13688 14889 I ReactNativeJS: 'ble.js: ', 'check channel ', false, '', '', '', '', '', '', ''
12-18 12:21:59.828 13688 14889 I ReactNativeJS: 'ble.js: ', 'we have channel for ', 'F0:5C:7C:7A:CB:15', '', '', '', '', '', '', ''
12-18 12:21:59.828 13688 14890 D BluetoothGatt: setCharacteristicNotification() - uuid: 6e400003-b5a3-f393-e0a9-e50e24dcca9e enable: true
12-18 12:21:59.829 13688 14889 I ReactNativeJS: 'ble.js: ', 'is channel bussy? ', '', '', '', '', '', '', '', ''
12-18 12:21:59.829  2504  2521 D BtGatt.GattService: registerForNotification() - address=F0:5C:7C:7A:CB:15 enable: true
12-18 12:21:59.829 13688 14889 I ReactNativeJS: 'ble.js: ', 'Command STR = ', '7237A1B5-790A-D044-0123-456789ABCDE0', '', '', '', '', '', '', ''
12-18 12:21:59.829  2504  2610 D BtGatt.GattService: onRegisterForNotifications() - address=null, status=0, registered=1, handle=24
12-18 12:21:59.831 13688 14889 I ReactNativeJS: 'ble.js: ', 'send command', '7237A1B5-790A-D044-0123-456789ABCDE0', ' to ', 'F0:5C:7C:7A:CB:15', '', '', '', '', ''
12-18 12:21:59.832 13688 14889 I ReactNativeJS: 'ble.js: ', 'F0:5C:7C:7A:CB:15', [ 'F9:F2:19:9D:7A:BA', 'F0:5C:7C:7A:CB:15' ], '', '', '', '', '', '', ''
12-18 12:21:59.834 13688 14889 I ReactNativeJS: 'ble.js: ', 'message to write: ', 'NzIzN0ExQjUtNzkwQS1EMDQ0LTAxMjMtNDU2Nzg5QUJDREUw', '', '', '', '', '', '', ''
12-18 12:21:59.886  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 19, msg_len = 0
12-18 12:21:59.983  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 19, msg_len = 0
12-18 12:21:59.984  2504  2936 I bt_stack: [INFO:gatt_main.cc(919)] gatt_data_process op_code = 27, msg_len = 5
12-18 12:21:59.984  2504  2936 E bt_btif : bta_gattc_process_indicate, ignore HID ind/notificiation
12-18 12:21:59.990 13688 14889 I ReactNativeJS: 'ble.js: ', 'char write response:', 'NzIzN0ExQjUtNzkwQS1EMDQ0LTAxMjMtNDU2Nzg5QUJDREUw', 'with time_out of ', 8000, '', '', '', '', ''
12-18 12:21:59.995 13688 14889 I ReactNativeJS: 'StackLog: ', 'Connecting: Connection Successful!', '', '', '', '', '', '', '', ''
12-18 12:22:00.024  2524  2524 W View    : requestLayout() improperly called by com.android.systemui.statusbar.HeadsUpStatusBarView{f602a08 I.E...... ......ID 0,0-194,53 #7f0a01f7 app:id/heads_up_status_bar_view} during layout: running second layout pass
12-18 12:22:00.564  2504  2521 D BtGatt.GattService: getDeviceType() - device=F4:4E:FD:10:9A:59, type=1
12-18 12:22:00.564  2504  2521 D BtGatt.GattService: getDeviceType() - device=9C:19:C2:32:C6:5A, type=3
12-18 12:22:00.565 13688 17245 D BluetoothGatt: cancelOpen() - device: F0:5C:7C:7A:CB:15
12-18 12:22:00.566  2504  2521 D BtGatt.GattService: clientDisconnect() - address=F0:5C:7C:7A:CB:15, connId=8
12-18 12:22:00.566  2504  2936 I bt_stack: [INFO:gatt_api.cc(1237)] GATT_Disconnect conn_id=0x0008
12-18 12:22:00.567  2504  2936 E bt_stack: [ERROR:bta_gattc_utils.cc(458)] bta_gattc_mark_bg_conn unable to find the bg connection mask for bd_addr=f0:5c:7c:7a:cb:15
12-18 12:22:00.568  2504  2610 D BtGatt.GattService: onDisconnected() - clientIf=8, connId=8, address=F0:5C:7C:7A:CB:15
12-18 12:22:00.568 13688 17359 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=F0:5C:7C:7A:CB:15
12-18 12:22:00.570 13688 17359 D BluetoothGatt: setCharacteristicNotification() - uuid: 6e400003-b5a3-f393-e0a9-e50e24dcca9e enable: false
12-18 12:22:00.570  2504  2521 D BtGatt.GattService: registerForNotification() - address=F0:5C:7C:7A:CB:15 enable: false
12-18 12:22:00.570  2504 17445 D BluetoothMetrics: btclass1f00
12-18 12:22:00.570  2504  2521 E BtGatt.GattService: registerForNotification() - No connection for F0:5C:7C:7A:CB:15...
12-18 12:22:00.572  2504 17445 D Checkin : publish the event [tag = MOT_BT event name = DISC]
12-18 12:22:00.575 13688 17245 D BluetoothGatt: close()
12-18 12:22:00.575 13688 17245 D BluetoothGatt: unregisterApp() - mClientIf=8
@budowski
Copy link

Happens to me as well (only on Android). Works fine on version 2.0.3

@eliaslecomte
Copy link

I have the same issue 🤔.

@GerardoStella
Copy link

I have the same issue

@p4bl1t0
Copy link
Author

p4bl1t0 commented Jan 12, 2024

@dominik-czupryna-withintent @dimninik can you help us to find the issue?

@leoafarias
Copy link
Contributor

Don't want to do just a +1, but this seems like an important issue.

@andreyukD
Copy link

Same situation for me, Android 2.0.3 works fine, 3.1.2 gets disconnected after max 30s
apparently, disconnection time depends on timeout in the connectToDevice method

await bleManagerDevice.connectToDevice(device.id, { timeout: 15000 }); 
// disconnect will be after 15s. but increasing timeout to more than 30000 won't increase connection time 

@p4bl1t0
Copy link
Author

p4bl1t0 commented Feb 7, 2024

@andreyukD thats works for you?

@andreyukD
Copy link

@p4bl1t0 version 3.1.2 works only for a few seconds (max 30 seconds - if I set timeout: 30000), if I set timeout 5000 it will work for a 5s, but if I set for instance timeout: 60000 it will be disconnected after ~30 seconds

version 2.0.3. works fine

@macksal
Copy link

macksal commented Feb 17, 2024

I seem to be getting the same behaviour in 3.x: the connection always drops after an amount of time roughly equal to the timeout. Android 10 but it seems to be affecting many different devices in production.

@macksal
Copy link

macksal commented Feb 19, 2024

I found the disconnect originates from the onFinally clause here.

Observable<RxBleConnection> connect = device
.establishConnection(autoConnect)
.doOnSubscribe(disposable -> onConnectionStateChangedCallback.onEvent(ConnectionState.CONNECTING))
.doFinally(() -> {
safeExecutor.error(BleErrorUtils.cancelled());
onDeviceDisconnected(device);
onConnectionStateChangedCallback.onEvent(ConnectionState.DISCONNECTED);
});

The problem is that the timeout is added just below, constructed from the original observable.

I believe that when the observable made on L1260 errors, it will unsubscribe from the original one constructed on L1227, which triggers the doFinally and disconnects.

I don't know Rx for languages other than js. I suppose doFinally is meant to cancel the connection when the connection observable is unsubscribed from. I think the connection can be interrupted as the subscription made on L1264 can be disposed later through the replaceSubscription method, so something is needed there. I'm not sure doFinally is the right mechanism to do that, though.

#1135 is a duplicate.

Edit: Removing the timeout parameter on Android is a functional workaround for my app.

@p4bl1t0
Copy link
Author

p4bl1t0 commented Feb 19, 2024

Great find @macksal

It's a pitty that dotintent team is so silenced

@EmmaZachara
Copy link
Collaborator

EmmaZachara commented Feb 20, 2024

Hi @macksal, @p4bl1t0,
Thank you for reporting the issue. We are analyzing it and will get back to you with more information soon.

@dominik-czupryna-withintent
Copy link
Collaborator

dominik-czupryna-withintent commented Feb 25, 2024

Hi,
I have quite a big problem with this error, because I am unable to reproduce it, but it is present in couple issues. I also don't want the problem to be fixed blindly without example. In thread #1174 @joanmarcs mentioned that the problem occurs on Samsung s22 Ultra and One plus, unfortunately I do not have either of these devices. I tried to reproduce this problem on Xiaomi mi 6 and 10, Motorola g82 and Samsung M13 in both development and production applications, but unfortunately I was unable to do so. A certain problem is that the event appears in your logs: "BluetoothGatt: cancelOpen() - device: F0:5C:7C:7A:CB:15", which identifies that the connection should be terminated.
Following the android source https://android.googlesource.com/platform/frameworks/base/+/364ed4d/core/java/android/bluetooth/BluetoothGatt.java:

    * Disconnects an established connection, or cancels a connection attempt
    * currently in progress.
    *
    * <p>Requires {@link android.Manifest.permission#BLUETOOTH} permission.
    */
    public void disconnect() {
    if (DBG) Log.d(TAG, "cancelOpen() - device: " + mDevice.getAddress());
    if (mService == null \|\| mClientIf == 0) return;
     
    try {
    mService.clientDisconnect(mClientIf, mDevice.getAddress());
    } catch (RemoteException e) {
    Log.e(TAG,"",e);
    }
    }

This function is mainly called in two cases. The first one is when the cancelDeviceConnection function is called, and the second one is when the timeout (https://dotintent.github.io/react-native-ble-plx/#connectionoptions) time that you specify when connecting run out.

BluetoothGatt logs when timeout is set in v3:

2024-02-25 23:34:05.806 24239-24498 BluetoothGatt           com.i1157                            D  connect() - device: 55:D6:CF:22:13:7A, auto: false, eattSupport: false
2024-02-25 23:34:05.806 24239-24498 BluetoothGatt           com.i1157                            D  registerApp()
2024-02-25 23:34:05.806 24239-24498 BluetoothGatt           com.i1157                            D  registerApp() - UUID=b2e5621e-be0b-48f8-bc20-fc8f69b7f0a8
2024-02-25 23:34:05.810 24239-24259 BluetoothGatt           com.i1157                            D  onClientRegistered() - status=0 clientIf=9
2024-02-25 23:34:06.301 24239-24259 BluetoothGatt           com.i1157                            D  onClientConnectionState() - status=0 clientIf=9 device=55:D6:CF:22:13:7A
2024-02-25 23:34:06.697 24239-24259 BluetoothGatt           com.i1157                            D  onPhyUpdate() - status=0 address=55:D6:CF:22:13:7A txPhy=2 rxPhy=2
2024-02-25 23:34:06.745 24239-24259 BluetoothGatt           com.i1157                            D  onConnectionUpdated() - Device=55:D6:CF:22:13:7A interval=36 latency=0 timeout=500 status=59
2024-02-25 23:34:08.141 24239-24259 BluetoothGatt           com.i1157                            D  onConnectionUpdated() - Device=55:D6:CF:22:13:7A interval=6 latency=0 timeout=500 status=0
2024-02-25 23:34:25.918 24239-24498 BluetoothGatt           com.i1157                            D  discoverServices() - device: 55:D6:CF:22:13:7A
2024-02-25 23:34:25.921 24239-24329 BluetoothGatt           com.i1157                            D  onSearchComplete() = Device=55:D6:CF:22:13:7A Status=0
2024-02-25 23:35:06.343 24239-24498 BluetoothGatt           com.i1157                            D  cancelOpen() - device: 55:D6:CF:22:13:7A
2024-02-25 23:35:06.347 24239-24466 BluetoothGatt           com.i1157                            D  onClientConnectionState() - status=0 clientIf=9 device=55:D6:CF:22:13:7A
2024-02-25 23:35:06.350 24239-24498 BluetoothGatt           com.i1157                            D  close()
2024-02-25 23:35:06.350 24239-24498 BluetoothGatt           com.i1157                            D  unregisterApp() - mClientIf=9

BluetoothGatt logs when timeout is set in v2:

2024-02-25 23:56:24.045 28846-31711 BluetoothGatt           com.i1157                            D  connect() - device: 58:C1:3C:30:27:E0, auto: false, eattSupport: false
2024-02-25 23:56:24.045 28846-31711 BluetoothGatt           com.i1157                            D  registerApp()
2024-02-25 23:56:24.045 28846-31711 BluetoothGatt           com.i1157                            D  registerApp() - UUID=3efda5b8-4e31-48c1-b8d1-8d06573be3bf
2024-02-25 23:56:24.047 28846-29093 BluetoothGatt           com.i1157                            D  onClientRegistered() - status=0 clientIf=10
2024-02-25 23:56:24.053 28846-29093 BluetoothGatt           com.i1157                            D  onClientConnectionState() - status=0 clientIf=10 device=58:C1:3C:30:27:E0
2024-02-25 23:56:24.054 28846-29093 RxBle#BluetoothGatt$1   com.i1157                            D  onConnectionStateChange newState=2 status=0
2024-02-25 23:56:29.766 28846-31711 BluetoothGatt           com.i1157                            D  discoverServices() - device: 58:C1:3C:30:27:E0
2024-02-25 23:56:29.769 28846-29093 BluetoothGatt           com.i1157                            D  onSearchComplete() = Device=58:C1:3C:30:27:E0 Status=0
2024-02-25 23:56:29.770 28846-29093 RxBle#BluetoothGatt$1   com.i1157                            D  onServicesDiscovered status=0
2024-02-25 23:56:40.962 28846-29093 RxBle#BluetoothGatt$1   com.i1157                            D  onDescriptorWrite descriptor=0000290e-0000-1000-8000-00805f9b34fb status=0
2024-02-25 23:56:42.197 28846-28867 RxBle#Blue...ttCallback com.i1157                            D  onCharacteristicRead descriptor=0000290e-0000-1000-8000-00805f9b34fb status=0

I also checked error mentoned by @andreyukD that it is not possible to set a timeout longer than 30 seconds but on my devices it occurs after the time I declare (90 sec)

2024-02-26 00:25:56.043  7741-8238  BluetoothGatt           com.i1157                            D  connect() - device: 4B:30:1D:5D:DE:82, auto: false, eattSupport: false
2024-02-26 00:25:56.043  7741-8238  BluetoothGatt           com.i1157                            D  registerApp()
2024-02-26 00:25:56.043  7741-8238  BluetoothGatt           com.i1157                            D  registerApp() - UUID=7396792a-bc2b-432e-a695-90d26b1b667e
2024-02-26 00:25:56.045  7741-7823  BluetoothGatt           com.i1157                            D  onClientRegistered() - status=0 clientIf=9
2024-02-26 00:25:57.053  7741-7823  BluetoothGatt           com.i1157                            D  onClientConnectionState() - status=0 clientIf=9 device=4B:30:1D:5D:DE:82
2024-02-26 00:25:57.446  7741-7823  BluetoothGatt           com.i1157                            D  onPhyUpdate() - status=0 address=4B:30:1D:5D:DE:82 txPhy=2 rxPhy=2
2024-02-26 00:25:57.537  7741-7823  BluetoothGatt           com.i1157                            D  onConnectionUpdated() - Device=4B:30:1D:5D:DE:82 interval=36 latency=0 timeout=500 status=59
2024-02-26 00:25:58.935  7741-7823  BluetoothGatt           com.i1157                            D  onConnectionUpdated() - Device=4B:30:1D:5D:DE:82 interval=6 latency=0 timeout=500 status=0
2024-02-26 00:26:03.859  7741-8238  BluetoothGatt           com.i1157                            D  discoverServices() - device: 4B:30:1D:5D:DE:82
2024-02-26 00:26:03.862  7741-7823  BluetoothGatt           com.i1157                            D  onSearchComplete() = Device=4B:30:1D:5D:DE:82 Status=0
2024-02-26 00:27:27.091  7741-8238  BluetoothGatt           com.i1157                            D  cancelOpen() - device: 4B:30:1D:5D:DE:82
2024-02-26 00:27:27.095  7741-8480  BluetoothGatt           com.i1157                            D  onClientConnectionState() - status=0 clientIf=9 device=4B:30:1D:5D:DE:82
2024-02-26 00:27:27.099  7741-8238  BluetoothGatt           com.i1157                            D  close()
2024-02-26 00:27:27.099  7741-8238  BluetoothGatt           com.i1157                            D  unregisterApp() - mClientIf=9

Could you please show me the process you implemented to handle the connection and what devices you use? I'm stuck at the moment and don't know what I could do to get cancelOpen() called in different case.

@andreyukD
Copy link

andreyukD commented Feb 29, 2024

I've debugged both versions a bit, so I have two screens:

  1. ConnectionScreen (starts device scan -> connects to the BLE device -> navigates to ReadCharacteristicScreen)
  2. ReadCharacteristicScreen (every second reads from the BLE device a characteristic)

  1. Connection screen:
const processJoinBleQr = (
  data: BarCodeScannerResult,
  setBleDevices: React.Dispatch<React.SetStateAction<Device[]>>,
  navigation: UserStackScreenProps<Routes.AddFromQRScreen>['navigation']
) => {
  requestPermissions((isGranted) => {
    if (isGranted) {
      const onDeviceDisconnected = async (device: Device) => {
        const deviceId = device.id;
        if (device) {
          const subscription = device.onDisconnected((error, device) => {
            Alert.alert(translate('ui.bluetoothDevice.deviceWasDisconnected'), `ID: ${deviceId}`);
            setBleDevices((prev) => prev.filter((el) => el.id !== deviceId));
            subscription.remove();
          });
        }
      };

      const disconnectFromDevice = (id: string) => {
        bleManagerDevice.cancelDeviceConnection(id);
        setBleDevices((prev) => prev.filter((el) => el.id !== id));
      };

      const stopScanning = () => {
        bleManagerDevice.stopDeviceScan();
      };

      bleManagerDevice.startDeviceScan(undefined, null, async (error, device) => {
        if (error) {
          Alert.alert(error.message);
          return navigation.goBack();
        }

        if (
          device &&
          [device.localName, device.name].some((el) => el?.startsWith('BLE-MY-DEVICE-123'))
        ) {
          await stopScanning();

          try {
            const isConnected = await device.isConnected(); // check if device was previously connected

            const deviceConnection = isConnected
              ? device
              : await bleManagerDevice.connectToDevice(device.id, {
                  timeout: 15000,
                });

            setBleDevices((prev) =>
              !prev.find((el) => el.id === deviceConnection.id) ? [...prev, deviceConnection] : prev
            );
            await deviceConnection.discoverAllServicesAndCharacteristics();
            stopScanning();
            !isConnected && onDeviceDisconnected(deviceConnection);

            return navigation.replace(Routes.MainStack, {
              screen: Routes.ReadCharacteristicScreen,
              params: { deviceId: device.id },
            });
          } catch (e) {
            stopScanning();
            if (await device.isConnected()) disconnectFromDevice(device.id);
            Alert.alert(JSON.stringify(e, Object.getOwnPropertyNames(e)));
            return navigation.goBack();
          }
        }
      });
    } else {
      Alert.alert(
        translate('ui.bluetooth.notEnoughPermissions'),
        translate('ui.bluetooth.notEnoughPermissionsDescription')
      );
      return navigation.goBack();
    }
  });
};

type VoidCallback = (result: boolean) => void;
const requestPermissions = async (cb: VoidCallback) => {
  if (Platform.OS === 'android') {
    const apiLevel = await DeviceInfo.getApiLevel();

    if (apiLevel < 31) {
      const granted = await PermissionsAndroid.request(
        PermissionsAndroid.PERMISSIONS.ACCESS_FINE_LOCATION,
        {
          title: 'Location Permission',
          message: 'Bluetooth Low Energy requires Location',
          buttonNeutral: 'Ask Later',
          buttonNegative: 'Cancel',
          buttonPositive: 'OK',
        }
      );
      cb(granted === PermissionsAndroid.RESULTS.GRANTED);
    } else {
      const result = await requestMultiple([
        PERMISSIONS.ANDROID.BLUETOOTH_SCAN,
        PERMISSIONS.ANDROID.BLUETOOTH_CONNECT,
        PERMISSIONS.ANDROID.ACCESS_FINE_LOCATION,
      ]);

      const isGranted =
        result['android.permission.BLUETOOTH_CONNECT'] === PermissionsAndroid.RESULTS.GRANTED &&
        result['android.permission.BLUETOOTH_SCAN'] === PermissionsAndroid.RESULTS.GRANTED &&
        result['android.permission.ACCESS_FINE_LOCATION'] === PermissionsAndroid.RESULTS.GRANTED;

      cb(isGranted);
    }
  } else {
    cb(true);
  }
};
  1. ReadCharacteristicScreen
useInterval(
    async () => {
      handleGetBleData();
    },
    !isLoading ? 1000 : null
);

 const handleGetBleData = async () => {
    if (device?.id) {
      try {
        setIsLoading(true);
        setErrors([]);
        if (await device.isConnected()) {
          const lastUpdatedCharacteristic = await device.readCharacteristicForService(
           '00000000-0000-0000-0000-123400000000', 
           '00000000-0000-4000-0000-123456789012'
          );
          console.log(lastUpdatedCharacteristic);
        }
      } catch (error) {
        setErrors([error.message]);
      } finally {
        setIsLoading(false);
      }
    }
  };

Logs from 2.0.3 (working version)

2024-02-29 23:08:56.612 10297-21717 BluetoothGatt           com.foo                      D  connect() - device: 70:F7:84:E4:FC:9D, auto: false
2024-02-29 23:08:56.612 10297-21717 BluetoothGatt           com.foo                      D  registerApp()
2024-02-29 23:08:56.613 10297-21717 BluetoothGatt           com.foo                      D  registerApp() - UUID=df806afe-bc42-495e-92b7-e39d7d816796
2024-02-29 23:08:56.615 10297-19662 BluetoothGatt           com.foo                      D  onClientRegistered() - status=0 clientIf=10
2024-02-29 23:08:56.859 10297-19662 BluetoothGatt           com.foo                      D  onClientConnectionState() - status=0 clientIf=10 device=70:F7:84:E4:FC:9D
2024-02-29 23:08:57.223 10297-21717 BluetoothGatt           com.foo                      D  discoverServices() - device: 70:F7:84:E4:FC:9D
2024-02-29 23:08:57.267 10297-19662 BluetoothGatt           com.foo                      D  onConnectionUpdated() - Device=70:F7:84:E4:FC:9D interval=6 latency=0 timeout=500 status=0
2024-02-29 23:08:58.805 10297-19662 BluetoothGatt           com.foo                      D  onSearchComplete() = Device=70:F7:84:E4:FC:9D Status=0
2024-02-29 23:08:58.890 10297-20360 BluetoothGatt           com.foo                      D  onConnectionUpdated() - Device=70:F7:84:E4:FC:9D interval=39 latency=0 timeout=500 status=0

+

If I trigger manual disconnect

2024-02-29 23:10:16.042 10297-21717 BluetoothGatt           com.foo                      D  cancelOpen() - device: 70:F7:84:E4:FC:9D
2024-02-29 23:10:16.065 10297-20360 BluetoothGatt           com.foo                      D  onClientConnectionState() - status=0 clientIf=10 device=70:F7:84:E4:FC:9D
2024-02-29 23:10:16.070 10297-21717 BluetoothGatt           com.foo                      D  close()
2024-02-29 23:10:16.070 10297-21717 BluetoothGatt           com.foo                      D  unregisterApp() - mClientIf=10

Logs from 3.1.2 (auto disconnect)

2024-02-29 23:13:13.778 12979-6311  BluetoothGatt           com.foo                      D  connect() - device: 45:54:2A:33:14:1C, auto: false
2024-02-29 23:13:13.778 12979-6311  BluetoothGatt           com.foo                      D  registerApp()
2024-02-29 23:13:13.778 12979-6311  BluetoothGatt           com.foo                      D  registerApp() - UUID=b32a98f2-966d-4f38-b959-faea350bc154
2024-02-29 23:13:13.783 12979-5081  BluetoothGatt           com.foo                      D  onClientRegistered() - status=0 clientIf=10
2024-02-29 23:13:13.966 12979-6297  BluetoothGatt           com.foo                      D  onClientConnectionState() - status=0 clientIf=10 device=45:54:2A:33:14:1C
2024-02-29 23:13:14.373 12979-5089  BluetoothGatt           com.foo                      D  onConnectionUpdated() - Device=45:54:2A:33:14:1C interval=6 latency=0 timeout=500 status=0
2024-02-29 23:13:14.404 12979-6311  BluetoothGatt           com.foo                      D  discoverServices() - device: 45:54:2A:33:14:1C
2024-02-29 23:13:15.894 12979-6335  BluetoothGatt           com.foo                      D  onSearchComplete() = Device=45:54:2A:33:14:1C Status=0
2024-02-29 23:13:15.994 12979-5084  BluetoothGatt           com.foo                      D  onConnectionUpdated() - Device=45:54:2A:33:14:1C interval=39 latency=0 timeout=500 status=0
2024-02-29 23:13:29.035 12979-6311  BluetoothGatt           com.foo                      D  cancelOpen() - device: 45:54:2A:33:14:1C
2024-02-29 23:13:29.057 12979-5089  BluetoothGatt           com.foo                      D  onClientConnectionState() - status=0 clientIf=10 device=45:54:2A:33:14:1C
2024-02-29 23:13:29.062 12979-6311  BluetoothGatt           com.foo                      D  close()
2024-02-29 23:13:29.062 12979-6311  BluetoothGatt           com.foo                      D  unregisterApp() - mClientIf=10

Tested on device OPPO Reno5 Lite (CPH2205), Android 13

@dominik-czupryna-withintent
Copy link
Collaborator

@andreyukD

await bleManagerDevice.connectToDevice(device.id, {
                  timeout: 15000,
                })

timeout paramter works in 3.1.2 and doesn't work on 2.0.3 and you are declared that the device should be disconnected after 15 seconds and it is (29.035 - 13.778 = 15.257). So should it be autodisconnected or not?

@andreyukD
Copy link

@dominik-czupryna-withintent
I mentioned that in 3.1.2 disconnection time depends on timeout in the connectToDevice method
and logs confirm this (29 - 13 = ~15). But this is a bug and it shouldn't behave like that

@dominik-czupryna-withintent
Copy link
Collaborator

dominik-czupryna-withintent commented Mar 1, 2024

Okay, I understood, I was looking for the error in the wrong place. Bug confirmed. We're working on it.

@lucaslt89
Copy link

As stated by @macksal above, removing the timeout to the connection is a functional workaround and the connection doesn't drop.

@joanmarcs
Copy link

joanmarcs commented Jun 5, 2024

The problem persist in the new version 3.2.0 @dominik-czupryna-withintent , and removing the timeout is not a workaround for me. We found that issue in Android 14. In Android 12 is working perfect.

This is the error I'm receiving now:

LOG error valuesMonitor: {"message":"Device 0C:8B:95:40:14:A2 was disconnected","errorCode":201,"attErrorCode":0,"iosErrorCode":null,"androidErrorCode":null,"reason":"Disconnected from MAC='XX:XX:XX:XX:XX:XX' with status 0 (GATT_SUCCESS)","name":"BleError"} WARN Possible Unhandled Promise Rejection (id: 1): BleError: Device 0C:8B:95:40:14:A2 is not connected BleError: Device 0C:8B:95:40:14:A2 is not connected at construct (native) at Wrapper (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:20215:64) at construct (native) at _createSuperInternal (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:121006:322) at call (native) at BleError (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:121014:26) at parseBleError (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:121044:30) at ?anon_0_ (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:121310:82) at throw (native) at asyncGeneratorStep (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:21237:26) at _throw (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:21259:29) at tryCallOne (/root/react-native/ReactAndroid/hermes-engine/.cxx/Release/544q5p5d/arm64-v8a/lib/InternalBytecode/InternalBytecode.js:53:16) at anonymous (/root/react-native/ReactAndroid/hermes-engine/.cxx/Release/544q5p5d/arm64-v8a/lib/InternalBytecode/InternalBytecode.js:139:27) at apply (native) at anonymous (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:26778:26) at _callTimer (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:26697:17) at _callReactNativeMicrotasksPass (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:26727:17) at callReactNativeMicrotasks (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:26890:44) at __callReactNativeMicrotasks (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:5066:46) at anonymous (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:4878:45) at __guard (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:5050:15) at flushedQueue (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:4877:21) at invokeCallbackAndReturnFlushedQueue (http://localhost:8081/index.bundle//&platform=android&dev=true&minify=false&app=com.Simon.EVElectron&modulesOnly=false&runModule=true:4871:33)

@adumat
Copy link

adumat commented Sep 27, 2024

when this pr will be released?

@alex-freeaim
Copy link

This continues to be an issue in version 3.2.0.

@adumat
Copy link

adumat commented Oct 17, 2024

@alex-freeaim the pr is merged but no new release was made after the merge 😐

@tomaseliasm
Copy link

@adumat @alex-freeaim you can use the latest version pointing to the master branch
"react-native-ble-plx": "dotintent/react-native-ble-plx#master",

@alex-freeaim
Copy link

Okay, I made a fix already that I tested on android and ios, so I can wait until the next release. Below is my fix, where it will time out after 10 seconds.

                setTimeout(async () => {
                    const deviceConnected = await this.bleManager.isDeviceConnected(deviceId);
                    if(!deviceConnected) {
                        console.log("Timeout waiting for device to connect");
                        this.bleManager.cancelDeviceConnection(deviceId);
                    }
                }, 10000);
                this.connectedDevice = await this.bleManager.connectToDevice(deviceId);

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.