I'm writing a multiplayer game for up to 6 players. I implemented code for reconnection - in other words if someone is connected with all of the other players and he is disconnected and then tries to reconnect. I read everything about Nearby Connections 2.0, but still I have some problems and I believe it's connected with the device (LG Nexus 5 with Android 6.0) and with the NearBy Connections API / Bluetooth. Sometimes the reconnection can't be done. Here are some of the log containing NearBy word:
07-31 16:30:33.053 23437-24092/? E/BluetoothAdapter: BT is in BLE_ON State
07-31 16:30:33.053 2135-2150/? D/BluetoothAdapterState: Current state: BLE ON, message: 1
07-31 16:30:33.053 2135-2150/? D/BluetoothAdapterProperties: Setting state to 11
07-31 16:30:33.053 2135-2150/? I/BluetoothAdapterState: Bluetooth adapter state changed: 15-> 11
07-31 16:30:33.055 2135-2135/? D/BluetoothAdapterService: getAdapterService() - returning com.android.bluetooth.btservice.AdapterService@912c26c
07-31 16:30:33.057 2135-2135/? D/HeadsetService: Received start request. Starting profile...
07-31 16:30:33.057 2135-2135/? D/HeadsetStateMachine: make
07-31 16:30:33.065 784-802/? I/ActivityManager: Start proc 626:com.android.settings/1000 for broadcast com.android.settings/.bluetooth.DockEventReceiver
07-31 16:30:33.067 2135-2135/? D/HeadsetStateMachine: max_hf_connections = 1
07-31 16:30:33.067 2135-2135/? I/bt_bluedroid: get_profile_interface handsfree
07-31 16:30:33.068 2135-2154/? I/bt_btif_storage: btif_storage_get_adapter_property service_mask:0x20000040
07-31 16:30:33.068 2135-2154/? E/bt_btif: btif_hf_upstreams_evt: Invalid index -1
07-31 16:30:33.078 2135-2135/? D/BluetoothAdapterService: getAdapterService() - returning com.android.bluetooth.btservice.AdapterService@912c26c
07-31 16:30:33.078 2135-2135/? D/A2dpService: Received start request. Starting profile...
07-31 16:30:33.078 2135-2135/? I/bt_bluedroid: get_profile_interface avrcp
07-31 16:30:33.080 2135-2150/? I/BluetoothAdapterState: Entering PendingCommandState
07-31 16:30:33.090 2135-2135/? E/RemoteController: Cannot set synchronization mode on an unregistered RemoteController
07-31 16:30:33.090 2135-2135/? D/A2dpStateMachine: make
07-31 16:30:33.109 2135-2135/? I/bt_bluedroid: get_profile_interface a2dp
07-31 16:30:33.110 2135-2154/? I/bt_btif_storage: btif_storage_get_adapter_property service_mask:0x20000048
07-31 16:30:33.110 2135-2135/? D/BluetoothAdapterService: getAdapterService() - returning com.android.bluetooth.btservice.AdapterService@912c26c
07-31 16:30:33.111 2135-2135/? D/HidService: Received start request. Starting profile...
07-31 16:30:33.111 2135-2135/? I/bt_bluedroid: get_profile_interface hidhost
07-31 16:30:33.111 2135-2135/? D/HidService: setHidService(): set to: null
07-31 16:30:33.111 2135-2154/? I/bt_bta_hh: BTA_HhEnable sec_mask:0x36 p_cback:0xb39102ad
07-31 16:30:33.111 2135-2135/? D/BluetoothAdapterService: getAdapterService() - returning com.android.bluetooth.btservice.AdapterService@912c26c
07-31 16:30:33.111 2135-2154/? I/bt_btif_storage: btif_storage_get_adapter_property service_mask:0x20100048
07-31 16:30:33.111 2135-625/? D/HeadsetPhoneState: sendDeviceStateChanged. mService=0 mSignal=0 mRoam=0 mBatteryCharge=3
07-31 16:30:33.111 2135-2135/? D/HealthService: Received start request. Starting profile...
07-31 16:30:33.112 2135-641/? D/A2dpStateMachine: Enter Disconnected: -2
07-31 16:30:33.117 545-545/com.project.testconnections W/art: Before Android 4.1, method int android.support.v7.widget.DropDownListView.lookForSelectablePosition(int, boolean) would have incorrectly overridden the package-private method in android.widget.ListView
07-31 16:30:33.121 2135-2135/? I/bt_bluedroid: get_profile_interface health
07-31 16:30:33.122 2135-2135/? V/BluetoothAdapterState: isTurningOff()=false
07-31 16:30:33.122 2135-2135/? V/BluetoothAdapterState: isTurningOn()=true
07-31 16:30:33.122 2135-2135/? V/BluetoothAdapterState: isBleTurningOn()=false
07-31 16:30:33.122 2135-2135/? V/BluetoothAdapterState: isBleTurningOff()=false
07-31 16:30:33.123 2135-2135/? D/BluetoothAdapterService: getAdapterService() - returning com.android.bluetooth.btservice.AdapterService@912c26c
07-31 16:30:33.123 2135-2135/? D/PanService: Received start request. Starting profile...
07-31 16:30:33.123 2135-2135/? D/BluetoothPanServiceJni: initializeNative(L110): pan
07-31 16:30:33.123 2135-2135/? I/bt_bluedroid: get_profile_interface pan
07-31 16:30:33.124 2135-2135/? D/BluetoothAdapterService: getAdapterService() - returning com.android.bluetooth.btservice.AdapterService@912c26c
07-31 16:30:33.124 2135-2135/? D/BluetoothMapService: Received start request. Starting profile...
07-31 16:30:33.124 2135-2135/? D/BluetoothMapService: start()
07-31 16:30:33.125 2135-2154/? D/BluetoothPanServiceJni: control_state_callback(L61): state:0, local_role:3, ifname:bt-pan
07-31 16:30:33.126 2135-2135/? D/BluetoothMapAccountLoader: Found 0 application(s) with intent android.bluetooth.action.BLUETOOTH_MAP_PROVIDER
07-31 16:30:33.126 2135-2135/? D/BluetoothMapAccountLoader: Found 0 application(s) with intent android.bluetooth.action.BLUETOOTH_MAP_IM_PROVIDER
07-31 16:30:33.126 2135-2135/? D/BluetoothMapAppObserver: createReceiver()
07-31 16:30:33.127 2135-2135/? D/BluetoothMapAppObserver: initObservers()
07-31 16:30:33.127 2135-2135/? D/BluetoothMapAppObserver: getEnabledAccountItems()
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isTurningOff()=false
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isTurningOn()=true
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isBleTurningOn()=false
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isBleTurningOff()=false
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isTurningOff()=false
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isTurningOn()=true
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isBleTurningOn()=false
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isBleTurningOff()=false
07-31 16:30:33.128 2135-2135/? V/BluetoothAdapterState: isTurningOff()=false
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isTurningOn()=true
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isBleTurningOn()=false
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isBleTurningOff()=false
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isTurningOff()=false
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isTurningOn()=true
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isBleTurningOn()=false
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isBleTurningOff()=false
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isTurningOff()=false
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isTurningOn()=true
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isBleTurningOn()=false
07-31 16:30:33.129 2135-2135/? V/BluetoothAdapterState: isBleTurningOff()=false
07-31 16:30:33.130 2135-2150/? D/BluetoothAdapterState: Current state: PENDING_COMMAND, message: 2
07-31 16:30:33.130 2135-2150/? D/BluetoothAdapterProperties: ScanMode = 20
07-31 16:30:33.130 2135-2150/? D/BluetoothAdapterProperties: State = 11
07-31 16:30:33.130 2135-2150/? D/BluetoothAdapterProperties: Setting state to 12
07-31 16:30:33.130 2135-2150/? I/BluetoothAdapterState: Bluetooth adapter state changed: 11-> 12
07-31 16:30:33.131 1721-1870/? D/BluetoothHeadset: onBluetoothStateChange: up=true
07-31 16:30:33.131 2135-2150/? I/BluetoothAdapterState: Entering OnState
07-31 16:30:33.132 923-935/? D/BluetoothInputDevice: onBluetoothStateChange: up=true
07-31 16:30:33.135 784-806/? D/BluetoothHeadset: onBluetoothStateChange: up=true
07-31 16:30:33.135 923-1345/? D/BluetoothMap: onBluetoothStateChange: up=true
07-31 16:30:33.137 923-923/? D/BluetoothInputDevice: Proxy object connected
07-31 16:30:33.137 2135-2154/? D/BluetoothAdapterProperties: Scan Mode:21
07-31 16:30:33.137 923-923/? D/HidProfile: Bluetooth service connected
07-31 16:30:33.138 2135-2154/? D/BluetoothAdapterProperties: Discoverable Timeout:120
07-31 16:30:33.138 923-947/? D/BluetoothPbap: onBluetoothStateChange: up=true
07-31 16:30:33.140 923-923/? D/BluetoothMap: Proxy object connected
07-31 16:30:33.140 923-923/? D/MapProfile: Bluetooth service connected
07-31 16:30:33.140 923-923/? D/BluetoothMap: getConnectedDevices()
07-31 16:30:33.140 923-6809/? D/BluetoothA2dp: onBluetoothStateChange: up=true
07-31 16:30:33.142 923-923/? D/BluetoothA2dp: Proxy object connected
07-31 16:30:33.142 784-806/? D/BluetoothHeadset: onBluetoothStateChange: up=true
07-31 16:30:33.142 784-806/? D/BluetoothHeadset: onBluetoothStateChange: up=true
07-31 16:30:33.142 784-806/? D/BluetoothA2dp: onBluetoothStateChange: up=true
07-31 16:30:33.143 784-784/? D/BluetoothA2dp: Proxy object connected
07-31 16:30:33.143 923-935/? D/BluetoothPan: onBluetoothStateChange on: true
07-31 16:30:33.146 923-947/? D/BluetoothHeadset: onBluetoothStateChange: up=true
07-31 16:30:33.149 784-784/? I/Telecom: BluetoothPhoneService: queryPhoneState
07-31 16:30:33.151 923-923/? D/BluetoothPan: BluetoothPAN Proxy object connected
07-31 16:30:33.151 923-923/? D/PanProfile: Bluetooth service connected
07-31 16:30:33.151 2135-2135/? D/BluetoothMapMasInstance10: Map Service startRfcommSocketListener
07-31 16:30:33.151 2135-2135/? D/ObexServerSockets: create(rfcomm = -2, l2capPsm = -2)
07-31 16:30:33.151 1349-1349/? I/BeaconBle: Resetting - new scanner available: true
07-31 16:30:33.153 2135-2135/? W/BluetoothAdapter: getBluetoothService() called with no BluetoothManagerCallback
07-31 16:30:33.154 1349-1349/? I/BeaconBle: ZERO_POWER is disabled.
07-31 16:30:33.154 1349-1349/? I/BeaconBle: 'L' hardware scan: scan stopped, no powered clients
07-31 16:30:33.155 1349-1349/? I/GCoreUlr: Caught bluetooth enabled event, re-enabling ULR BLE scanner
07-31 16:30:33.155 2135-2135/? W/BluetoothAdapter: getBluetoothService() called with no BluetoothManagerCallback
07-31 16:30:33.156 2135-2135/? D/ObexServerSockets: Succeed to create listening sockets
07-31 16:30:33.156 2135-2135/? D/ObexServerSockets10: startAccept()
07-31 16:30:33.156 2135-2135/? D/ObexServerSockets10: prepareForNewConnect()
07-31 16:30:33.156 2135-2135/? D/BluetoothSdpJni: sdpCreateMapMasRecordNative:
07-31 16:30:33.157 2135-2135/? D/BluetoothSdpJni: SDP Create record success - handle: 10
07-31 16:30:33.157 2135-2135/? D/BluetoothMapService: onReceive
07-31 16:30:33.157 2135-2135/? D/BluetoothMapService: onReceive: android.bluetooth.adapter.action.STATE_CHANGED
07-31 16:30:33.157 2135-2135/? D/BluetoothMapService: STATE_ON
07-31 16:30:33.157 2135-687/? D/ObexServerSockets10: Accepting socket connection...
07-31 16:30:33.158 2135-688/? D/ObexServerSockets10: Accepting socket connection...
07-31 16:30:33.159 1349-1349/? I/BeaconBle: Resetting - new scanner available: true
07-31 16:30:33.163 1349-1349/? I/BeaconBle: ZERO_POWER is disabled.
07-31 16:30:33.163 1349-1349/? I/BeaconBle: 'L' hardware scan: scan stopped, no powered clients
07-31 16:30:33.177 2135-2135/? D/BluetoothMapMasInstance10: Map Service startRfcommSocketListener
07-31 16:30:33.177 2135-2135/? D/ObexServerSockets10: prepareForNewConnect()
07-31 16:30:33.169 3005-3005/? W/Binder_C: type=1400 audit(0.0:547): avc: denied { ioctl } for path="socket:[96740]" dev="sockfs" ino=96740 ioctlcmd=7704 scontext=u:r:system_server:s0 tcontext=u:r:system_server:s0 tclass=unix_stream_socket permissive=0
07-31 16:30:33.169 3005-3005/? W/Binder_C: type=1400 audit(0.0:548): avc: denied { ioctl } for path="socket:[96740]" dev="sockfs" ino=96740 ioctlcmd=7704 scontext=u:r:system_server:s0 tcontext=u:r:system_server:s0 tclass=unix_stream_socket permissive=0
07-31 16:30:33.182 626-626/? W/System: ClassLoader referenced unknown path: /system/priv-app/Settings/lib/arm
07-31 16:30:33.169 2052-2052/? W/Binder_7: type=1400 audit(0.0:549): avc: denied { ioctl } for path="socket:[96739]" dev="sockfs" ino=96739 ioctlcmd=7704 scontext=u:r:system_server:s0 tcontext=u:r:system_server:s0 tclass=unix_stream_socket permissive=0
07-31 16:30:33.169 2052-2052/? W/Binder_7: type=1400 audit(0.0:550): avc: denied { ioctl } for path="socket:[96739]" dev="sockfs" ino=96739 ioctlcmd=7704 scontext=u:r:system_server:s0 tcontext=u:r:system_server:s0 tclass=unix_stream_socket permissive=0
07-31 16:30:33.183 1678-1678/? I/GoogleInputMethod: onFinishInput() : Dummy InputConnection bound
07-31 16:30:33.183 1678-1678/? I/GoogleInputMethod: onStartInput() : Dummy InputConnection bound
07-31 16:30:33.186 784-807/? I/ActivityManager: Displayed com.project.testconnections/.MainActivity: +1s730ms
07-31 16:30:33.207 784-891/? D/WifiService: New client listening to asynchronous messages
07-31 16:30:33.229 626-626/? W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1221 android.content.ContextWrapper.startService:581 android.content.ContextWrapper.startService:581 com.android.settings.bluetooth.DockEventReceiver.beginStartingService:134 com.android.settings.bluetooth.DockEventReceiver.onReceive:115
07-31 16:30:33.229 1349-1349/? W/ChimeraUtils: Non Chimera context
07-31 16:30:33.238 923-923/? D/BluetoothPbap: Proxy object connected
07-31 16:30:33.238 923-923/? D/PbapServerProfile: Bluetooth service connected
07-31 16:30:33.239 784-806/? D/BluetoothManagerService: Added callback: android.bluetooth.IBluetoothManagerCallback$Stub$Proxy@5b0fa31:true
07-31 16:30:33.240 2135-694/? W/BluetoothAdapter: getBluetoothService() called with no BluetoothManagerCallback
07-31 16:30:33.253 626-626/? D/LocalBluetoothProfileManager: Adding local A2DP profile
07-31 16:30:33.257 626-626/? D/LocalBluetoothProfileManager: Adding local HEADSET profile
07-31 16:30:33.269 1349-1349/? W/Nearby: Bind call too late - someone already tried to get: interface biol [CONTEXT service_id=49 ]
07-31 16:30:33.292 626-626/? D/LocalBluetoothProfileManager: Adding local MAP profile
07-31 16:30:33.292 626-626/? D/BluetoothMap: Create BluetoothMap proxy object
07-31 16:30:33.297 626-626/? D/LocalBluetoothProfileManager: LocalBluetoothProfileManager construction complete
07-31 16:30:33.300 626-626/? D/DockEventReceiver: finishStartingService: stopping service
07-31 16:30:33.319 626-626/? D/BluetoothA2dp: Proxy object connected
07-31 16:30:33.323 626-626/? D/BluetoothInputDevice: Proxy object connected
07-31 16:30:33.323 626-626/? D/HidProfile: Bluetooth service connected
07-31 16:30:33.326 626-626/? D/BluetoothPan: BluetoothPAN Proxy object connected
07-31 16:30:33.327 626-626/? D/PanProfile: Bluetooth service connected
07-31 16:30:33.328 626-626/? D/BluetoothMap: Proxy object connected
07-31 16:30:33.328 626-626/? D/MapProfile: Bluetooth service connected
07-31 16:30:33.328 626-626/? D/BluetoothMap: getConnectedDevices()
07-31 16:30:33.328 2135-704/? W/BluetoothAdapter: getBluetoothService() called with no BluetoothManagerCallback
07-31 16:30:33.330 2135-704/? I/BtOppRfcommListener: Accept thread started.
07-31 16:30:33.330 2135-2180/? E/bt_btif: bta_jv_rfcomm_start_server, run out of sec_id
07-31 16:30:33.330 2135-2203/? E/bt_btif_sock_rfcomm: find_rfc_slot_by_id unable to find RFCOMM slot id: 60
07-31 16:30:33.330 2135-704/? E/BtOppRfcommListener: Error accept connection java.io.IOException: read failed, socket might closed or timeout, read ret: -1
I'm showing this log because it's the start before the thing that I think is the reason of my problem - the non-stop looping of this in my log:
BtOppRfcommListener: Error accept connection java.io.IOException: read failed, socket might closed or timeout, read ret: -1
I can stop this loop only if I restart my device. Do you know any way how to fix it somehow using reflection or other way?
@Xlythe, could you give any idea how to fix my problem(without restarting my phone, but programmatically)? Is the reason for this problem that both players try to connect to each other at the same time?
Thanks.
Creating 5 BluetoothSockets (since you have 6 players) is something that is very much teetering on the edge of undefined behavior in implementations of the Bluetooth stack on Android -- if you can reliably sustain 4 BluetoothSockets, you should consider yourself very lucky. :)
Also, connecting to each other simultaneously is not a problem, and is supported in Nearby Connections -- at the end of that simultaneous attempt between 2 devices, only 1 of the 2 connections will remain established (with one arbitrarily being sacrificed).
Finally, to get better log messages from Nearby Connections, turn on VERBOSE logging for the NearbyConnections and NearbyMediums log tags -- as it stands, your logs have 1 mention of the word nearby, and it's not relevant to Nearby Connections.