On 31/10/2018 4:49 PM, Oliver Neukum wrote:
On Mi, 2018-10-31 at 12:32 +0800, Morikazu Fumita wrote:My test procedure is below (assuming Bluetooth devices are already paired). 1. Adding a network bridge for PAN using "brctl". 2. Link the bridge up. 3. Run "hciconfig hci0 up" to power the USB Bluetooth dongle up. 4. Register "nap" service and the network bridge to "org.bluez.NetworkServer1" via d-bus using a Python script. 5. Bluez makes "bnep0" virtual network interface automatically. 6. Connect to the PAN-NAP server from the client. Network is working fine at this point. (Note: The hang does not happen even if turning promiscuous mode off at this point by running "ip link set bnep0 promisc off") 7. Disconnect PAN from the client or make the "bnep0" virtual network adapter down by running "ip link set bnep0 down". 8. The hang happens with "Bluetooth: hci0: command 0xXXXX tx timeout" errors. 9. No response from the USB Bluetooth dongle anymore. For example, running "discoverable on" from "bluetoothctl" fails with error message of "Failed to set discoverable on: org.bluez.Error.Failed". The timeout error is logged in "dmesg" as well. From this fact, I believe this issue is related to Bluez but not to USB. What do you think?Hi, you are using a slightly less common HC, are you not? Anyway, it seems to me that you can narrow this down a bit further. You are using bridging. You can try to remove that. And after that you can take an usbmon trace right as you give the command that crashes the device. The procedure is described in the kernel's Documentation directory. That will allow to determine which exact command is the problem. HTH Oliver
Hello Oliver,I got rid of the network bridge but the timeout error still happens so I can rule out the bridge now.
I also got USB packet dump and found that the error is happening regardless of HCI commands.
One example is below. I just inserted the USB dongle when I got the following errors.
[ 145.046503] Bluetooth: hci0: command 0x1002 tx timeout [ 147.086503] Bluetooth: hci0: command 0x0c52 tx timeout [ 149.121499] Bluetooth: hci0: command 0x0c45 tx timeout [ 151.166503] Bluetooth: hci0: command 0x0c58 tx timeout Please find the USB packet dump attached.In frame no. 161, the host sent HCI command 0x1002 (Read Local Supported Commands). Then the USB dongle tried to respond to that from frame no. 163 but it did not sent all fragment packets. It seems to stop response in the middle.
Finally, above "0x1002 tx timeout" happened.As for frame no. 165, the host sent 0x0c52 (Write Extended Inquiry Response) but there was no response to it then above "0x0c52 tx timeout" happened.
This is just one example. The USB dongle can be successfully inserted and working for a while but suddenly stops response to HCI commands like this example.
It seems there is no specific HCI commands to cause the problem. I do not find out what is the trigger of it yet. Do you have any thoughts from this point? Here is log from inserting the USB dongle. [ 141.811511] usb 1-1: new full-speed USB device number 2 using dwc2 [ 142.001509] usb 1-1: device descriptor read/64, error -71[ 142.373525] usb 1-1: New USB device found, idVendor=0a12, idProduct=0001, bcdDevice=88.91 [ 142.377642] usb 1-1: New USB device strings: Mfr=0, Product=2, SerialNumber=0
[ 142.381204] usb 1-1: Product: CSR8510 A10 [ 142.385718] device: '1-1': device_add [ 142.385829] bus: 'usb': add device 1-1 [ 142.385866] PM: Adding info for usb:1-1[ 142.386066] bus: 'usb': driver_probe_device: matched device 1-1 with driver usb
[ 142.386081] bus: 'usb': really_probe: probing driver usb with device 1-1 [ 142.386101] usb 1-1: no default pinctrl state [ 142.386128] devices_kset: Moving 1-1 to end of list [ 142.392785] device: '1-1:1.0': device_add [ 142.392837] bus: 'usb': add device 1-1:1.0 [ 142.392860] PM: Adding info for usb:1-1:1.0 [ 142.392997] device: 'ep_81': device_add [ 142.393068] PM: Adding info for No Bus:ep_81 [ 142.393087] device: 'ep_02': device_add [ 142.393138] PM: Adding info for No Bus:ep_02 [ 142.393153] device: 'ep_82': device_add [ 142.393202] PM: Adding info for No Bus:ep_82 [ 142.393212] device: '1-1:1.1': device_add [ 142.393259] bus: 'usb': add device 1-1:1.1 [ 142.393280] PM: Adding info for usb:1-1:1.1 [ 142.393380] device: 'ep_03': device_add [ 142.393434] PM: Adding info for No Bus:ep_03 [ 142.393448] device: 'ep_83': device_add [ 142.393495] PM: Adding info for No Bus:ep_83 [ 142.393512] driver: 'usb': driver_bound: bound to device '1-1' [ 142.393577] bus: 'usb': really_probe: bound device 1-1 to driver usb [ 142.393630] device: 'ep_00': device_add [ 142.393694] PM: Adding info for No Bus:ep_00 [ 142.724485] Bluetooth: Core ver 2.22 [ 142.726310] device class 'bluetooth': registering [ 142.726384] NET: Registered protocol family 31 [ 142.729838] Bluetooth: HCI device and connection manager initialized [ 142.733199] Bluetooth: HCI socket layer initialized [ 142.735649] Bluetooth: L2CAP socket layer initialized [ 142.738395] Bluetooth: SCO socket layer initialized [ 142.814694] bus: 'usb': add driver btusb[ 142.814738] bus: 'usb': driver_probe_device: matched device 1-1:1.0 with driver btusb [ 142.814752] bus: 'usb': really_probe: probing driver btusb with device 1-1:1.0
[ 142.814769] btusb 1-1:1.0: no default pinctrl state [ 142.814795] devices_kset: Moving 1-1:1.0 to end of list [ 142.814838] driver: 'btusb': driver_bound: bound to device '1-1:1.1' [ 142.815490] device: 'hci0': device_add [ 142.815555] PM: Adding info for No Bus:hci0 [ 142.815908] driver: 'btusb': driver_bound: bound to device '1-1:1.0'[ 142.816575] bus: 'usb': really_probe: bound device 1-1:1.0 to driver btusb
[ 142.818233] usbcore: registered new interface driver btusb [ 143.004182] Bluetooth: BNEP (Ethernet Emulation) ver 1.3 [ 143.007009] Bluetooth: BNEP filters: protocol multicast [ 143.009670] Bluetooth: BNEP socket layer initialized [ 143.040749] device: 'lo': device_add [ 143.040952] PM: Adding info for No Bus:lo [ 143.041379] device: 'sit0': device_add [ 143.042079] PM: Adding info for No Bus:sit0 [ 145.046503] Bluetooth: hci0: command 0x1002 tx timeout [ 147.086503] Bluetooth: hci0: command 0x0c52 tx timeout [ 149.121499] Bluetooth: hci0: command 0x0c45 tx timeout [ 151.166503] Bluetooth: hci0: command 0x0c58 tx timeout [ 153.201501] Bluetooth: hci0: command tx timeout [ 173.227275] PM: Removing info for No Bus:sit0 [ 173.252443] PM: Removing info for No Bus:lo Thank you always, Mori
Attachment:
bt_timeout_when_connect.pcapng
Description: Binary data
