Re: When connecting to NAP bnep0 can not go up

[Ferry Toth <ftoth@exalondelft.nl>]

Marcel,

Op 18-02-19 om 16:36 schreef Ferry Toth:
> Adding Andy, Marcel, Johan to CC
>
> Op 16-02-19 om 18:38 schreef Ferry Toth:
>> I'm trying to make a connection from my Edison (linux 4.19) to my 
>> android
>> phone (nap), but it seems Edison bnep0 gets removed immediately after
>> creation. How can help me diagnose this?
>
> Actually, this is using Andy's kernel 4.20 (not 4.19).
>
> I didn't mention that other BT functionality seems to be working fine. 
> And building with Yocto Thud (bluez 5.50).
>
> Everything is fairly up-to-date (compared to Edison factory image).
>
>> Initially I tried connman. The bluetooth service appears, but when I 
>> try to
>> connect I get:
>>
>> connmanctl> connect bluetooth_43341B001FAC_C462EA01AF74
>> Error /net/connman/service/bluetooth_43341B001FAC_C462EA01AF74:
>> Input/output error
>>
>> For testing I switched to the bluez test-network.py script:
>>
>> root@edison:~# python3 ./test-network.py C4:62:EA:01:AF:74 nap
>> Traceback (most recent call last):
>>   File "./test-network.py", line 42, in <module>
>>     iface = network.Connect(service)
>>   File "/usr/lib/python3.5/site-packages/dbus/proxies.py", line 70, in
>> __call__
>>     return self._proxy_method(*args, **keywords)
>>   File "/usr/lib/python3.5/site-packages/dbus/proxies.py", line 145, in
>> __call__
>>     **keywords)
>>   File "/usr/lib/python3.5/site-packages/dbus/connection.py", line 
>> 651, in
>> call_blocking
>>     message, timeout)
>> dbus.exceptions.DBusException: org.bluez.Error.Failed: Input/output 
>> error
>>
>> Using btmon to log while running above script:
>>
>> < ACL Data TX: Handle 12 flags 0x00 dlen 11
>> #96 [hci0] 2974.047858
>>       Channel: 78 len 7 [PSM 15 mode 0] {chan 0}
>>       BNEP: Control (0x01|0)
>>          Setup Conn Req (0x01)
>>            Size: 0x02
>>            Dst: 0x1116(NAP)
>>            Src: 0x1115(PANU)
>>> HCI Event: Number of Completed Packets (0x13) plen 5
>> #97 [hci0] 2974.049982
>>         Num handles: 1
>>         Handle: 12
>>         Count: 2
>>> ACL Data RX: Handle 12 flags 0x02 dlen 8
>> #98 [hci0] 2974.052464
>>       Channel: 64 len 4 [PSM 15 mode 0] {chan 0}
>>       BNEP: Control (0x01|0)
>>          Setup Conn Rsp (0x02)
>>            Rsp msg: Operation Successful(0x0000)
>> = bluetoothd: bnep: Could not bring up bnep0: Cannot assign requested
>> address(99)
>> = bluetoothd: connect failed Input/output error
>>
>> And logging with udevadm monitor:
>> KERNEL add /devices/pci..../serial0-0/bluetooth/hci0/hci0:12 (bluetooth)
>> UDEV   add /devices/pci..../serial0-0/bluetooth/hci0/hci0:12 (bluetooth)
>> KERNEL add 
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0 (net)
>> KERNEL add
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0/queues/rx-0
>> (queues)
>> KERNEL add
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0/queues/tx-0
>> (queues)
>> KERNEL remove
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0/queues/rx-0
>> (queues)
>> KERNEL[146116.687930] remove
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0/queues/tx-0
>> (queues)
>> KERNEL 
>> remove   /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0
>> (net)
>
> Note the KERNEL already issues a remove before UDEV add
>
>> UDEV   add      /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0 
>>
>> (net)
>> UDEV   add
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0/queues/rx-0
>> (queues)
>> UDEV   add
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0/queues/tx-0
>> (queues)
>> UDEV   remove
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0/queues/rx-0
>> (queues)
>> UDEV  [146116.776687] remove
>> /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0/queues/tx-0
>> (queues)
>> UDEV   remove   /devices/pci..../serial0-0/bluetooth/hci0/hci0:12/net/bnep0 
>>
>> (net)
>> KERNEL remove   /devices/pci..../serial0-0/bluetooth/hci0/hci0:12
>> (bluetooth)
>> UDEV   remove   /devices/pci..../serial0-0/bluetooth/hci0/hci0:12
>> (bluetooth)
>>
>> To me it looks like the kernel already removes the bnep0 device, 
>> before user
>> space can bring it up.
>>
>> And indeed, doing the same from another computer (Ubuntu linux 4.18) 
>> I get
>> only the kernel and udev add events, the connection is established 
>> and the
>> remove events appear only after pressing Ctrl-C
>>
>> What could this be?
>>
To check my kernel configuration I now added btusb kernel module, no 
other changes. Then I attach:

root@edison:~# lsusb
..
Bus 001 Device 004: ID 050d:0131 Belkin Components Bluetooth Device with 
trace filter

..

Which gives me 2 bt controllers. The Edison uses btbcm:


root@edison:~# journalctl -b 0 | grep -i bcm
Jan 25 21:13:35 edison kernel: Bluetooth: hci0: BCM: chip id 82
Jan 25 21:13:35 edison kernel: Bluetooth: hci0: BCM: features 0x2f
Jan 25 21:13:35 edison kernel: Bluetooth: hci0: BCM43341B0
Jan 25 21:13:35 edison kernel: Bluetooth: hci0: BCM43341B0 (002.001.014) 
build 0000

Jan 25 21:13:36 edison kernel: Bluetooth: hci0: BCM43341B0 (002.001.014) 
build 0176


Connman shows now 2 bt controllers, on using btbcm and one using btusb. 
Connecting using btusb using the Belkin works fine.


Connecting and disconnecting while watching with udevadm monitor:

(BTUSB connect)

KERNEL[11332.104716] add 
/devices/pci0000:00/0000:00:11.0/dwc3.0.auto/xhci-hcd.1.auto/usb1/1-1/1-1.4/1-1.4:1.0/bluetooth/hci1/hci1:12 
(bluetooth)
UDEV  [11332.114629] add      " (bluetooth)
KERNEL[11332.432039] add      "/net/bnep0 (net)
KERNEL[11332.432255] add      "/net/bnep0/queues/rx-0 (queues)
KERNEL[11332.432431] add      "/net/bnep0/queues/tx-0 (queues)
UDEV  [11332.489620] add      "/net/bnep0 (net)
UDEV  [11332.506436] add      "/net/bnep0/queues/rx-0 (queues)
UDEV  [11332.517584] add      "/net/bnep0/queues/tx-0 (queues)

(BTUSB disconnect)

KERNEL[11351.254976] remove   "/net/bnep0/queues/rx-0 (queues)
KERNEL[11351.255204] remove   "/net/bnep0/queues/tx-0 (queues)
KERNEL[11351.255483] remove   "/net/bnep0 (net)
UDEV  [11351.268731] remove   "/net/bnep0/queues/rx-0 (queues)
UDEV  [11351.270734] remove   "/net/bnep0/queues/tx-0 (queues)
UDEV  [11351.285370] remove   "/net/bnep0 (net)
KERNEL[11353.494377] remove   " (bluetooth)
UDEV  [11353.498291] remove   " (bluetooth)

(BTBCM connect)

KERNEL[11368.188073] add 
/devices/pci0000:00/0000:00:04.1/serial0/serial0-0/bluetooth/hci0/hci0:12 
(bluetooth)
UDEV  [11368.194174] add      " (bluetooth)
KERNEL[11368.292190] add      "/net/bnep0 (net)
KERNEL[11368.292411] add      "/net/bnep0/queues/rx-0 (queues)
KERNEL[11368.292588] add      "/net/bnep0/queues/tx-0 (queues)
KERNEL[11368.299872] remove   "/net/bnep0/queues/rx-0 (queues)
KERNEL[11368.301253] remove   "/net/bnep0/queues/tx-0 (queues)
KERNEL[11368.302775] remove   "/net/bnep0 (net)
UDEV  [11368.359215] add      "/net/bnep0 (net)
UDEV  [11368.373121] add      "/net/bnep0/queues/rx-0 (queues)
UDEV  [11368.381030] remove   "/net/bnep0/queues/rx-0 (queues)
UDEV  [11368.387723] add      "/net/bnep0/queues/tx-0 (queues)
UDEV  [11368.388807] remove   "/net/bnep0/queues/tx-0 (queues)
UDEV  [11368.395210] remove   "/net/bnep0 (net)
KERNEL[11370.651209] remove   " (bluetooth)
UDEV  [11370.655569] remove   " (bluetooth)


Using btmon is still see for BTBCM:

= bluetoothd: bnep: Could not bring up bnep0: Cannot assign requested 
address(99)
= bluetoothd: connect failed Input/output error

And for BSUSB:

= bluetoothd: bnep0 connected


Is there something wrong with the btbcm driver?