search

jeroen1602 / lighthouse_pm

A Flutter app for controlling the power state of Valve Index® lighthouses
Other
152 stars 8 forks source link

Bluetooth Read Characteristic fails #32

Open JoseJX opened 4 years ago

JoseJX commented 4 years ago

This is on a cheap Samsung J3 Orbit (SM-S367VL) running Android 9. I can read the Characteristic using BLE Scanner, so the hardware appears to be working fine. When I scan for available lighthouses using the latest code ( commit 331ddd3 ) it successfully finds the available V2 Lighthouse devices, but does not succeed in reading the power state. The backtrace below is generated when reading the Bluetooth characteristic is attempted:

2020-09-03 12:55:30.068 15945-15945/com.jeroen1602.lighthouse_pm D/ViewRootImpl@66b9cb1[MainActivity]: Relayout returned: old=[0,0][720,1280] new=[0,0][720,1280] result=0x1 surface={true 3576477696} changed=false
2020-09-03 12:55:31.171 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: STATE_ON
2020-09-03 12:55:31.174 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: STATE_ON
2020-09-03 12:55:31.174 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothLeScanner: could not find callback wrapper
2020-09-03 12:55:31.403 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: STATE_ON
2020-09-03 12:55:31.405 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: STATE_ON
2020-09-03 12:55:31.603 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: STATE_ON
2020-09-03 12:55:31.605 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: BLE support array set: 010011
2020-09-03 12:55:31.606 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothLeScanner: Start Scan with callback
2020-09-03 12:55:32.166 15945-15968/com.jeroen1602.lighthouse_pm D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=10 mScannerId=0
2020-09-03 12:55:32.488 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: Trying to connect to device with name: LHB-DEEEFEE0
2020-09-03 12:55:32.497 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: Trying to connect to device with name: LHB-241D89DB
2020-09-03 12:55:32.507 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: Connecting to device: C3:8B:5A:87:2B:94
2020-09-03 12:55:32.522 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: Connecting to device: E9:8E:B8:0E:80:E5
2020-09-03 12:55:32.534 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectedDevices
2020-09-03 12:55:32.549 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: STATE_ON
2020-09-03 12:55:32.557 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothGatt: connect() - device: C3:8B:5A:87:2B:94, auto: true
2020-09-03 12:55:32.558 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: isSecureModeEnabled
2020-09-03 12:55:32.560 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothGatt: registerApp()
2020-09-03 12:55:32.561 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothGatt: registerApp() - UUID=51e59be4-bc6a-4e50-8196-753924c441a9
2020-09-03 12:55:32.575 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectedDevices
2020-09-03 12:55:32.575 15945-15970/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onClientRegistered() - status=0 clientIf=11
2020-09-03 12:55:32.593 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: STATE_ON
2020-09-03 12:55:32.598 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothGatt: connect() - device: E9:8E:B8:0E:80:E5, auto: true
2020-09-03 12:55:32.598 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothAdapter: isSecureModeEnabled
2020-09-03 12:55:32.599 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothGatt: registerApp()
2020-09-03 12:55:32.600 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothGatt: registerApp() - UUID=b2a1407a-33e4-43fe-95bc-243b196d7aaa
2020-09-03 12:55:32.608 15945-15968/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onClientRegistered() - status=0 clientIf=12
2020-09-03 12:55:32.631 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectionState()
2020-09-03 12:55:32.631 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectedDevices
2020-09-03 12:55:32.644 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectionState()
2020-09-03 12:55:32.644 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectedDevices
2020-09-03 12:55:33.572 15945-15970/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=11 device=C3:8B:5A:87:2B:94
2020-09-03 12:55:33.578 15945-15970/com.jeroen1602.lighthouse_pm D/FlutterBluePlugin: [onConnectionStateChange] status: 0 newState: 2
2020-09-03 12:55:33.648 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: Finding service for device: C3:8B:5A:87:2B:94
2020-09-03 12:55:33.657 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectionState()
2020-09-03 12:55:33.657 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectedDevices
2020-09-03 12:55:33.673 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothGatt: discoverServices() - device: C3:8B:5A:87:2B:94
2020-09-03 12:55:33.853 15945-15970/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onConnectionUpdated() - Device=C3:8B:5A:87:2B:94 interval=6 latency=0 timeout=500 status=0
2020-09-03 12:55:34.315 15945-15970/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onSearchComplete() = Device=C3:8B:5A:87:2B:94 Status=0
2020-09-03 12:55:34.317 15945-15970/com.jeroen1602.lighthouse_pm D/FlutterBluePlugin: [onServicesDiscovered] count: 6 status: 0
2020-09-03 12:55:34.371 15945-15970/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onConnectionUpdated() - Device=C3:8B:5A:87:2B:94 interval=36 latency=0 timeout=500 status=0
2020-09-03 12:55:34.952 15945-15970/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=12 device=E9:8E:B8:0E:80:E5
2020-09-03 12:55:34.961 15945-15970/com.jeroen1602.lighthouse_pm D/FlutterBluePlugin: [onConnectionStateChange] status: 0 newState: 2
2020-09-03 12:55:34.981 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: Finding service for device: E9:8E:B8:0E:80:E5
2020-09-03 12:55:34.990 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectionState()
2020-09-03 12:55:34.990 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectedDevices
2020-09-03 12:55:35.004 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothGatt: discoverServices() - device: E9:8E:B8:0E:80:E5
2020-09-03 12:55:35.247 15945-15970/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onConnectionUpdated() - Device=E9:8E:B8:0E:80:E5 interval=6 latency=0 timeout=500 status=0
2020-09-03 12:55:35.560 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectionState()
2020-09-03 12:55:35.560 15945-15945/com.jeroen1602.lighthouse_pm D/BluetoothManager: getConnectedDevices
2020-09-03 12:55:35.605 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: remoteId: C3:8B:5A:87:2B:94 characteristicUuid: 00001525-1212-efde-1523-785feabcd124 serviceUuid: 00001523-1212-efde-1523-785feabcd124
2020-09-03 12:55:35.627 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: PlatformException(read_characteristic_error, unknown reason, may occur if readCharacteristic was called before last read finished., null)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #0      StandardMethodCodec.decodeEnvelope (package:flutter/src/services/message_codecs.dart:572:7)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #1      MethodChannel._invokeMethod (package:flutter/src/services/platform_channel.dart:161:18)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: <asynchronous suspension>
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #2      MethodChannel.invokeMethod (package:flutter/src/services/platform_channel.dart:334:12)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #3      BluetoothCharacteristic.read (package:flutter_blue/src/bluetooth_characteristic.dart:83:10)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #4      LighthouseV2Device.getCurrentState (package:lighthouse_pm/lighthouseProvider/devices/LighthouseV2Device.dart:28:45)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: <asynchronous suspension>
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #5      LighthouseDevice._startPowerStateStream.<anonymous closure> (package:lighthouse_pm/lighthouseProvider/LighthouseDevice.dart:122:11)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #6      _rootRunUnary (dart:async/zone.dart:1198:47)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #7      _CustomZone.runUnary (dart:async/zone.dart:1100:19)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #8      _CustomZone.runUnaryGuarded (dart:async/zone.dart:1005:7)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #9      _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:357:11)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #10     _BufferingStreamSubscription._add (dart:async/stream_impl.dart:285:7)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #11     _SyncStreamControllerDispatch._sendData (dart:async/stream_controller.dart:808:19)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #12     _StreamController._add (dart:async/stream_controller.dart:682:7)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #13     _StreamController.add (dart:async/stream_controller.dart:624:5)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #14     new Stream.periodic.<anonymous closure>.sendEvent (dart:async/stream.dart:358:22)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #15     _rootRunUnary (dart:async/zone.dart:1198:47)
2020-09-03 12:55:35.631 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #16     _CustomZone.runUnary (dart:async/zone.dart:1100:19)
2020-09-03 12:55:35.632 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #17     _CustomZone.runUnaryGuarded (dart:async/zone.dart:1005:7)
2020-09-03 12:55:35.632 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #18     _CustomZone.bindUnaryCallbackGuarded.<anonymous closure> (dart:async/zone.dart:1042:26)
2020-09-03 12:55:35.632 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #19     _rootRunUnary (dart:async/zone.dart:1206:13)
2020-09-03 12:55:35.632 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #20     _CustomZone.runUnary (dart:async/zone.dart:1100:19)
2020-09-03 12:55:35.632 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #21     _CustomZone.bindUnaryCallback.<anonymous closure> (dart:async/zone.dart:1026:26)
2020-09-03 12:55:35.632 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #22     _Timer._runTimers (dart:isolate-patch/timer_impl.dart:397:19)
2020-09-03 12:55:35.632 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #23     _Timer._handleMessage (dart:isolate-patch/timer_impl.dart:428:5)
2020-09-03 12:55:35.632 15945-15998/com.jeroen1602.lighthouse_pm I/flutter: #24     _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:168:12)
2020-09-03 12:55:35.738 15945-15970/com.jeroen1602.lighthouse_pm D/BluetoothGatt: onSearchComplete() = Device=E9:8E:B8:0E:80:E5 Status=0
jeroen1602 commented 4 years ago

Hmm, it should only allow the second power state read when the first one has finished.

I do know that this sometimes happens when an old device is still reading while a new scan is happening. But the error is handled and I don't think it is the problem.

What I'm wondering is. Is it spamming this stack trace or is it just once (for every device)? If this is not the case then I think the problem might be that the older firmware revisions don't report back their power-state. Or have different values for their states.

JoseJX commented 4 years ago

It's once per read, per lighthouse device.

Both of my lighthouses have firmware 3002. I haven't figured out a way to update them yet without a working Windows setup. I might be able to borrow a laptop from a friend in a week or so, but it isn't something I can do right away.

I am able to use the CLI version of lighthouse-v2-manager to turn them on/off from my PC. If there's any other information I could provide that might help, please let me know!

jeroen1602 commented 4 years ago

According to this Stackoverflow post this happens when another transaction is still going on.

Though I can't find in the code where this transaction may hang. If you want to also try and have a look then you should take a look in lib/lighthouseProvider/devices/BLEDevice.dart and/ or lib/lighthouseProvider/devices/LighthouseV2Device.dart. That is where all the communication happens.

However I do see that I should probably use atomic locks for this instead of a boolean since write operation is also supposed to wait.

jeroen1602 commented 4 years ago

I've implemented an actual Mutex lock (#37) can you check if the problem still persists?

I'm also adding a work-around in case this error ever pops up again see: #38

JoseJX commented 4 years ago

I've pulled and built 01eaceb, but unfortunately, it still persists with the same unknown value and error in logcat. Mutex locking was a good idea though! I'll try this on another android phone this weekend to try to figure out if it's the lighthouses themselves or the phone's BT implementation that might be causing the issue.

jeroen1602 commented 3 years ago

I hope the new Play store release that has been released today can help with this problem. Maybe not the state not working but at least making the app usable.

JoseJX commented 3 years ago

Sorry, I've been busy with work and haven't had a chance to respond. I did test the latest version and can confirm that even though the state is still 0xFF, I can now turn on and off the lighthouses with this app.

Thanks!