Closed RobHumphris closed 4 years ago
RobHumphris
commented
6 years ago It specifically sticks at the line:
if n, err := h.skt.Write(b[:4+c.Len()]); err != nil {
In the function:
func (h *HCI) send(c Command) ([]byte, error)
of the file
linux/hci/hci.go
There are no messages in syslog, and it fails at the same point at the same time - everytime.
estutzenberger
commented
6 years ago One thing I might suggest, is to stop scanning before you connect to the devices. Once connected, scanning can be re-enabled. Not all controllers support scanning while initiating a connection so you may be running into that issue.
RobHumphris
commented
6 years ago Thanks. This is done without scanning, I have the whitelist of BLE devices that I want to connect to. If I run the program each time with a single MAC I can connect without problem - as work around I may end up spawning a new process for each connection that I need to make, but there must be a neater way. I'll keep trying.
estutzenberger
commented
6 years ago Ahh, I see that in the example now.
RobHumphris
commented
6 years ago I have a way round it, it involves bringing the d, err := NewDevice(...) call inside the for loop, and the addition of d.Stop() in the closing go routine:
go func() {
<-cln.Disconnected()
fmt.Printf("[ %s ] is disconnected \n", cln.Addr())
d.Stop() // <--- this is the key to multiple connections
close(done)
}()Does this mean that there's a tight coupling between the Bluetooth interface on the host and the Bluetooth peripheral? I was hoping to be able to initiate the Bluetooth interface, then use it to find, and communicate with peripherals in range.
func main() {
flag.Parse()
addresses := []string{"c1:85:1f:60:83:f8", "c7:7f:04:8d:ee:59", "c9:35:97:07:94:e1", "e6:2d:89:8c:49:6c", "e6:bd:57:4e:20:df", "e9:1e:0e:18:d0:92", "eb:d6:c9:6c:ef:87", "ed:24:62:72:24:9b", "f4:64:fb:60:22:cb"}
for _, a := range addresses {
d, err := dev.NewDevice(*device)
if err != nil {
log.Fatalf("can't new device : %s", err)
}
ble.SetDefaultDevice(d)
filter := filter(a)
ctx := ble.WithSigHandler(context.WithTimeout(context.Background(), *sd))
cln, err := ble.Connect(ctx, filter)
if err != nil {
log.Fatalf("can't connect : %s", err)
}
done := make(chan struct{})
go func() {
<-cln.Disconnected()
fmt.Printf("[ %s ] is disconnected \n", cln.Addr())
d.Stop()
close(done)
}()
fmt.Printf("Discovering profile...\n")
_, err = cln.DiscoverProfile(true)
if err != nil {
log.Fatalf("can't discover profile: %s", err)
}
// Disconnect the connection. (On OS X, this might take a while.)
fmt.Printf("Disconnecting [ %s ]... (this might take up to few seconds on OS X)\n", cln.Addr())
cln.CancelConnection()
<-done
}
}@RobHumphris Are you able to capture the output of btmon when the issue occurs? I'd be curious to see what is actually going back and forth at the HCI layer.
RobHumphris
commented
6 years ago I'm on a pretty tight deadline with this at the moment, but I will take a look in a week or so.
RobHumphris
commented
5 years ago Okay so I am back looking at this, with a slightly different test case, but with the same issue. If I run the following code I get to attempt 7 and the 'bd.Scan(...)` never returns. It always gets to 7 attempts and then it always exhibits the same behaviour.
Bluez version: 5.50 Ubuntu 18.04 and 16 Core.
func TestScanningMethod(t *testing.T) {
timeout := 2 * time.Second
global.Debugf("Creating Bluetooth Device %s", global.BluetoothDevice)
bd, err := dev.NewDevice(global.BluetoothDevice)
if err != nil {
t.Fatalf("error creating device %v\n", err)
}
ble.SetDefaultDevice(bd)
global.Debugf("Scanning for %s...\n", timeout)
for i := 0; i < 30; i++ {
fmt.Println("Starting discovery attempt: ", i)
ctx := ble.WithSigHandler(context.WithTimeout(context.Background(), timeout))
err = errorHandler(bd.Scan(ctx, true, advHandler))
if err != nil {
t.Errorf("scan error err: %v\n", err)
}
time.Sleep(5 * time.Second)
}
bd.Stop()
}
btmon shows that there's a load of scanning going on. I never see MGMT Event: Command Complete
HCI Event: LE Meta Event (0x3e) plen 42 34798 [hci0] 533.357150
LE Advertising Report (0x02)
Num reports: 1
Event type: Connectable undirected - ADV_IND (0x00)
Address type: Random (0x01)
Address: 65:5C:9B:40:B0:5F (Resolvable)
Data length: 30
Flags: 0x1a
LE General Discoverable Mode
Simultaneous LE and BR/EDR (Controller)
Simultaneous LE and BR/EDR (Host)
Company: Apple, Inc. (76)
Type: iBeacon (2)
UUID: bbe3ea63-c0d1-e0ba-c240-ec511a9f6406
Version: 14336.10512
TX power: -59 dB
RSSI: -78 dBm (0xb2)
HCI Event: LE Meta Event (0x3e) plen 43 34799 [hci0] 533.365212
LE Advertising Report (0x02)
Num reports: 1
Event type: Non connectable undirected - ADV_NONCONN_IND (0x03)
Address type: Random (0x01)
Address: 39:E1:67:07:1E:44 (Non-Resolvable)
Data length: 31
Company: Microsoft (6)
Data: 010920026ef32f40e9bd9784a7239e5f01870347fc35eff165522d
RSSI: -35 dBm (0xdd)
HCI Event: LE Meta Event (0x3e) plen 43 34800 [hci0] 533.386206
LE Advertising Report (0x02)
Num reports: 1
Event type: Connectable undirected - ADV_IND (0x00)
Address type: Random (0x01)
Address: FB:9D:81:6B:D1:2D (Static)
Data length: 31
Flags: 0x06
LE General Discoverable Mode
BR/EDR Not Supported
Company: Anhui Huami Information Technology Co., Ltd. (343)
Data: 0014151471b544330e8dbf5d8a4480948102fb9d816bd12d
RSSI: -79 dBm (0xb1)
HCI Event: LE Meta Event (0x3e) plen 42 #34801 [hci0] 533.388135
LE Advertising Report (0x02)
Num reports: 1
Event type: Connectable undirected - ADV_IND (0x00)
Address type: Random (0x01)
Address: 65:5C:9B:40:B0:5F (Resolvable)
Data length: 30
Flags: 0x1a
LE General Discoverable Mode
Simultaneous LE and BR/EDR (Controller)
Simultaneous LE and BR/EDR (Host)
Company: Apple, Inc. (76)
Type: iBeacon (2)
UUID: bbe3ea63-c0d1-e0ba-c240-ec511a9f6406
Version: 14336.10512
TX power: -59 dB
RSSI: -79 dBm (0xb1)
HCI Event: LE Meta Event (0x3e) plen 26 #34802 [hci0] 533.424127
LE Advertising Report (0x02)
Num reports: 1
Event type: Connectable undirected - ADV_IND (0x00)
Address type: Random (0x01)
Address: 56:D2:0D:03:A6:44 (Resolvable)
Data length: 14
Flags: 0x1a
LE General Discoverable Mode
Simultaneous LE and BR/EDR (Controller)
Simultaneous LE and BR/EDR (Host)
Company: Apple, Inc. (76)
Type: Unknown (16)
Data: 031c806bc0
RSSI: -73 dBm (0xb7)
...Changing matters slightly, I get past 7 attempts in fact all 30 run.
func TestScanningMethodTwo(t *testing.T) {
timeout := 2 * time.Second
for i := 0; i < 30; i++ {
global.Debugf("Creating Bluetooth Device %s", global.BluetoothDevice)
bd, err := dev.NewDevice(global.BluetoothDevice)
if err != nil {
t.Fatalf("error creating device %v\n", err)
}
ble.SetDefaultDevice(bd)
global.Debugf("Scanning for %s...\n", timeout)
fmt.Println("Starting discovery attempt: ", i)
ctx := ble.WithSigHandler(context.WithTimeout(context.Background(), timeout))
err = errorHandler(bd.Scan(ctx, true, advHandler))
if err != nil {
t.Errorf("scan error err: %v\n", err)
}
bd.Stop()
time.Sleep(5 * time.Second)
}
}But if I run this multiple times I eventually get: can't accept: skt: EOF (error emerged at like 274 of hci.go n, err := h.skt.Read(b)
Subsequent attempts to open a device give:
error creating device can't init hci: no devices available: (hci0: can't up device: connection timed out)
And btmon shows the key error bluetoothd: Loading LTKs timed out for hci0
The LTKs error is also shown in the syslog journalctl -b --no-pager | grep -i blue
The only way to get back out of this issue is to reboot the machine.
@ USER Close: debug.test {0x0002} [hci0] 1368.456145
< HCI Command: Read BD ADDR (0x04|0x0009) plen 0 #63402 [hci0] 1368.456147
= Close Index: AC:2B:6E:F3:E7:3C [hci0] 1368.456253
@ MGMT Event: Index Added (0x0004) plen 0 {0x0003} [hci0] 1368.456447
@ MGMT Event: Index Added (0x0004) plen 0 {0x0001} [hci0] 1368.456447
@ MGMT Command: Read Controller Information (0x0004) plen 0 {0x0001} [hci0] 1368.456574
@ MGMT Event: Command Complete (0x0001) plen 283 {0x0001} [hci0] 1368.456591
Read Controller Information (0x0004) plen 280
Status: Success (0x00)
Address: AC:2B:6E:F3:E7:3C (Intel Corporate)
Version: Bluetooth 4.2 (0x08)
Manufacturer: Intel Corp. (2)
Supported settings: 0x0000ffff
Powered
Connectable
Fast Connectable
Discoverable
Bondable
Link Security
Secure Simple Pairing
BR/EDR
High Speed
Low Energy
Advertising
Secure Connections
Debug Keys
Privacy
Controller Configuration
Static Address
Current settings: 0x00000ada
Connectable
Discoverable
Bondable
Secure Simple Pairing
BR/EDR
Low Energy
Secure Connections
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
Name: rob-Inspiron-15-5568
Short name:
@ MGMT Command: Remove UUID (0x0011) plen 16 {0x0001} [hci0] 1368.457850
UUID: 00000000-0000-0000-0000-000000000000
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1368.457867
Remove UUID (0x0011) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Remove Device (0x0034) plen 7 {0x0001} [hci0] 1368.457943
BR/EDR Address: 00:00:00:00:00:00 (OUI 00-00-00)
@ MGMT Event: Command Complete (0x0001) plen 10 {0x0001} [hci0] 1368.457957
Remove Device (0x0034) plen 7
Status: Success (0x00)
BR/EDR Address: 00:00:00:00:00:00 (OUI 00-00-00)
@ MGMT Command: Set Privacy (0x002f) plen 17 {0x0001} [hci0] 1368.458021
Privacy: Disabled (0x00)
Key: 00000000000000000000000000000000
@ MGMT Event: Command Complete (0x0001) plen 7 {0x0001} [hci0] 1368.458026
Set Privacy (0x002f) plen 4
Status: Success (0x00)
Current settings: 0x00000ada
Connectable
Discoverable
Bondable
Secure Simple Pairing
BR/EDR
Low Energy
Secure Connections
@ MGMT Command: Read Advertising Features (0x003d) plen 0 {0x0001} [hci0] 1368.458084
@ MGMT Event: Command Complete (0x0001) plen 11 {0x0001} [hci0] 1368.458089
Read Advertising Features (0x003d) plen 8
Status: Success (0x00)
Flags: 0x0000007f
Switch into Connectable mode
Advertise as Discoverable
Advertise as Limited Discoverable
Add Flags field to Advertising Data
Add TX Power field to Advertising Data
Add Appearance field to Scan Response
Add Local Name in Scan Response
Advertising data length: 31
Scan response length: 31
Max instances: 5
Instances: 0
@ MGMT Command: Set Powered (0x0005) plen 1 {0x0001} [hci0] 1368.458146
Powered: Enabled (0x01)
= Open Index: AC:2B:6E:F3:E7:3C [hci0] 1368.458185
< HCI Command: Reset (0x03|0x0003) plen 0 #63403 [hci0] 1368.458220
= bluetoothd: Endpoint registered: sender=:1.83 path=/MediaEndpoint/A2DPSource 1368.468080
= bluetoothd: Endpoint registered: sender=:1.83 path=/MediaEndpoint/A2DPSink 1368.468143
= bluetoothd: Loading LTKs timed out for hci0 [hci0] 1370.479477
@ RAW Open: debug.test (privileged) version 2.22 {0x0002} 1373.456821
= Close Index: AC:2B:6E:F3:E7:3C [hci0] 1373.456991
@ MGMT Event: Command Status (0x0002) plen 3 {0x0001} [hci0] 1373.457312
Set Powered (0x0005)
Status: Failed (0x03)
= Open Index: AC:2B:6E:F3:E7:3C [hci0] 1373.457435
< HCI Command: Reset (0x03|0x0003) plen 0 #63404 [hci0] 1373.457482
= bluetoothd: Failed to set mode: Failed (0x03) [hci0] 1373.457664
@ MGMT Command: Set Local Name (0x000f) plen 260 {0x0001} [hci0] 1373.457731
Name: rob-Inspiron-15-5568
Short name:
@ MGMT Event: Command Complete (0x0001) plen 263 {0x0001} [hci0] 1373.457770
Set Local Name (0x000f) plen 260
Status: Success (0x00)
Name: rob-Inspiron-15-5568
Short name:
@ MGMT Command: Set Device Class (0x000e) plen 2 {0x0001} [hci0] 1373.457862
Major class: 0x01
Minor class: 0x0c
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.457867
Set Device Class (0x000e) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Add UUID (0x0010) plen 17 {0x0001} [hci0] 1373.457937
UUID: 0000110e-0000-1000-8000-00805f9b34fb
Service class: 0x00
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.457942
Add UUID (0x0010) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Add UUID (0x0010) plen 17 {0x0001} [hci0] 1373.458030
UUID: 0000110c-0000-1000-8000-00805f9b34fb
Service class: 0x00
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.458035
Add UUID (0x0010) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Add UUID (0x0010) plen 17 {0x0001} [hci0] 1373.458114
UUID: 00001112-0000-1000-8000-00805f9b34fb
Service class: 0x00
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.458120
Add UUID (0x0010) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Add UUID (0x0010) plen 17 {0x0001} [hci0] 1373.458189
UUID: 00001108-0000-1000-8000-00805f9b34fb
Service class: 0x00
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.458194
Add UUID (0x0010) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Unblock Device (0x0027) plen 7 {0x0001} [hci0] 1373.458262
BR/EDR Address: 00:00:00:00:00:00 (OUI 00-00-00)
@ MGMT Event: Device Unblocked (0x0015) plen 7 {0x0003} [hci0] 1373.458267
BR/EDR Address: 00:00:00:00:00:00 (OUI 00-00-00)
@ MGMT Event: Command Complete (0x0001) plen 10 {0x0001} [hci0] 1373.458273
Unblock Device (0x0027) plen 7
Status: Success (0x00)
BR/EDR Address: 00:00:00:00:00:00 (OUI 00-00-00)
@ MGMT Command: Load Link Keys (0x0012) plen 3 {0x0001} [hci0] 1373.458339
Debug keys: Disabled (0x00)
Keys: 0
@ MGMT Event: Command Complete (0x0001) plen 3 {0x0001} [hci0] 1373.458343
Load Link Keys (0x0012) plen 0
Status: Success (0x00)
@ MGMT Command: Load Identity Resolving Keys (0x0030) plen 2 {0x0001} [hci0] 1373.458408
Keys: 0
@ MGMT Event: Command Complete (0x0001) plen 3 {0x0001} [hci0] 1373.458413
Load Identity Resolving Keys (0x0030) plen 0
Status: Success (0x00)
@ MGMT Command: Load Connection Parameters (0x0035) plen 2 {0x0001} [hci0] 1373.458476
Parameters: 0
@ MGMT Event: Command Complete (0x0001) plen 3 {0x0001} [hci0] 1373.458481
Load Connection Parameters (0x0035) plen 0
Status: Success (0x00)
@ MGMT Command: Add UUID (0x0010) plen 17 {0x0001} [hci0] 1373.458546
UUID: 00001200-0000-1000-8000-00805f9b34fb
Service class: 0x00
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.458552
Add UUID (0x0010) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Set Device ID (0x0028) plen 8 {0x0001} [hci0] 1373.458621
Device ID: USB Implementer's Forum assigned (0x0002)
Vendor: Linux Foundation (0x1d6b)
Product: 0x0246
Version: 5.3.2 (0x0532)
@ MGMT Event: Command Complete (0x0001) plen 3 {0x0001} [hci0] 1373.458627
Set Device ID (0x0028) plen 0
Status: Success (0x00)
@ MGMT Command: Set Device Class (0x000e) plen 2 {0x0001} [hci0] 1373.458692
Major class: 0x01
Minor class: 0x0c
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.458696
Set Device Class (0x000e) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Set Local Name (0x000f) plen 260 {0x0001} [hci0] 1373.458762
Name: rob-Inspiron-15-5568
Short name:
@ MGMT Event: Command Complete (0x0001) plen 263 {0x0001} [hci0] 1373.458768
Set Local Name (0x000f) plen 260
Status: Success (0x00)
Name: rob-Inspiron-15-5568
Short name:
@ MGMT Command: Set Connectable (0x0007) plen 1 {0x0001} [hci0] 1373.458834
Connectable: Disabled (0x00)
@ MGMT Event: Command Complete (0x0001) plen 7 {0x0001} [hci0] 1373.458838
Set Connectable (0x0007) plen 4
Status: Success (0x00)
Current settings: 0x00000ad0
Bondable
Secure Simple Pairing
BR/EDR
Low Energy
Secure Connections
@ MGMT Event: New Settings (0x0006) plen 4 {0x0003} [hci0] 1373.458865
Current settings: 0x00000ad0
Bondable
Secure Simple Pairing
BR/EDR
Low Energy
Secure Connections
@ MGMT Command: Set Connectable (0x0007) plen 1 {0x0001} [hci0] 1373.462455
Connectable: Enabled (0x01)
@ MGMT Event: Command Complete (0x0001) plen 7 {0x0001} [hci0] 1373.462472
Set Connectable (0x0007) plen 4
Status: Success (0x00)
Current settings: 0x00000ad2
Connectable
Bondable
Secure Simple Pairing
BR/EDR
Low Energy
Secure Connections
@ MGMT Event: New Settings (0x0006) plen 4 {0x0003} [hci0] 1373.462483
Current settings: 0x00000ad2
Connectable
Bondable
Secure Simple Pairing
BR/EDR
Low Energy
Secure Connections
@ MGMT Command: Set Discoverable (0x0006) plen 3 {0x0001} [hci0] 1373.462566
Discoverable: General (0x01)
Timeout: 0
@ MGMT Event: Command Complete (0x0001) plen 7 {0x0001} [hci0] 1373.462572
Set Discoverable (0x0006) plen 4
Status: Success (0x00)
Current settings: 0x00000ada
Connectable
Discoverable
Bondable
Secure Simple Pairing
BR/EDR
Low Energy
Secure Connections
@ MGMT Event: New Settings (0x0006) plen 4 {0x0003} [hci0] 1373.462575
Current settings: 0x00000ada
Connectable
Discoverable
Bondable
Secure Simple Pairing
BR/EDR
Low Energy
Secure Connections
@ MGMT Command: Add UUID (0x0010) plen 17 {0x0001} [hci0] 1373.465298
UUID: 0000110a-0000-1000-8000-00805f9b34fb
Service class: 0x08
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.465315
Add UUID (0x0010) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Add UUID (0x0010) plen 17 {0x0001} [hci0] 1373.465394
UUID: 0000110b-0000-1000-8000-00805f9b34fb
Service class: 0x04
@ MGMT Event: Command Complete (0x0001) plen 6 {0x0001} [hci0] 1373.465399
Add UUID (0x0010) plen 3
Status: Success (0x00)
Class: 0x000000
Major class: Miscellaneous
Minor class: 0x00
@ MGMT Command: Set Powered (0x0005) plen 1 {0x0001} [hci0] 1373.465462
Powered: Enabled (0x01)@estutzenberger I was debugging this on a different machine (Dell Edge 3001 Gateway) which seemed more stable, but the same issue occured, this time I was monitoring syslog and saw:
ATT request failed: input channel closed: io: read/write on closed pipe
A google of this showed me this: https://github.com/balena-io/edge-node-manager/issues/115 where the issue is "resolved" by waiting a second for the disconnect to complete.
This issue appears to be happening across libraries - I'm guessing that the issue is around synchronisation and that we're assuming a disconnect happens rather than seeing an event or signal raised on disconnect.
estutzenberger
commented
5 years ago Regarding https://github.com/go-ble/ble/issues/34#issuecomment-446158917, have you tried a local fix with time.Sleep? I am finally getting back to working on more software using this library as well.
RobHumphris
commented
5 years ago Sleep improved stability, but after running for 2-3 days Bluetooth would stop working. I was happy to reset the hardware but could not find a way of doing it.I
My concerns are that on Linux the stability is too variable across hardware and bluez versions. My development machine crashes almost instantly, the test machine works for an hour or two, the target platform works for a couple of days.
As the application needs to run remotely for long periods of time I'm now rewriting our protocol for a ublox NINA board using AT commands, as this uses their embedded Bluetooth stack which exposes a function to reboot the hardware.
estutzenberger
commented
4 years ago Closing this for now since the thread seems dead.
shakahl
commented
4 years ago The solution is to restart the bluetooth service if you are using Raspberry Pi
#!/bin/bash
while :
do
echo "$(date) restarting bluetooth service"
sudo systemctl restart bluetooth.service
sleep 1
doneROFL
Running on Ubuntu 18.04, although the same issue appears on Ubuntu 16 Core I've found an issue in an app I'm writing, where I scan the Bluetooth devices in range, filter out any devices that are not the sensors I'm interested in, then connect to each in turn in order to obtain information from them. After 4 successful connections connections lock up in Scan it seems.
I've modified the main function in examples/basic/explorer to distill the issue into something that I hope makes sense. This will connect to the first few devices, then it will never come out of
dev.NewDevice(...)