On 30/10/2018 5:15 PM, Oliver Neukum wrote:
On Sa, 2018-10-27 at 22:56 +0800, Morikazu Fumita wrote:
I always found error messages of
"Bluetooth: hci0: command 0x0406 tx timeout" and
The problem is likely shortly before that.
"dwc2 ffb40000.usb: --Host Channel x Interrupt: Frame Overrun--"
when this problem is happening.
Here's an example log:
[ 251.748320] pan: port 1(bnep0) entered disabled state
[ 251.752153] device bnep0 left promiscuous mode
[ 251.754541] pan: port 1(bnep0) entered disabled state
[ 257.879162] Bluetooth: hci0: command 0x0406 tx timeout
Oct 25 04:47:14 cyclone5 systemd-networkd[132]: bnep0: Lost carrier
Oct 25 04:47:14 cyclone5 kernel: pan: port 1(bnep0) entered disabled state
Oct 25 04:47:14 cyclone5 kernel: dwc2 ffb40000.usb: --Host Channel 15
Interrupt: Frame Overrun--
You need to find out under which circumstances the hang happens.
Is it always when leaving the promiscuous mode?
Regards
Oliver
Hello Oliver,
Thank you for your reply.
I narrowed the problem down a little bit.
This problem seems to happen after the virtual network interface which
is added
by Bluez for PAN-NAP service is down.
Turning promiscuous mode OFF is not the cause of the issue.
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?
This is the log from the USB Bluetooth dongle is detected and PAN-NAP is
started
to the timeout happened.
[ 705.813455] usb 1-1: new full-speed USB device number 2 using dwc2
[ 706.027240] usb 1-1: New USB device found, idVendor=0a12,
idProduct=0001,
bcdDevice= 1.00
[ 706.031407] usb 1-1: New USB device strings: Mfr=1, Product=2,
SerialNumber=0
[ 706.035859] usb 1-1: Product: Bluetooth V2.0 Dongle
[ 706.038304] usb 1-1: Manufacturer: Allcom Corp
[ 706.041282] device: '1-1': device_add
[ 706.041388] bus: 'usb': add device 1-1
[ 706.041426] PM: Adding info for usb:1-1
[ 706.043371] bus: 'usb': driver_probe_device: matched device 1-1 with
driver usb
[ 706.043389] bus: 'usb': really_probe: probing driver usb with device 1-1
[ 706.044501] usb 1-1: no default pinctrl state
[ 706.044554] devices_kset: Moving 1-1 to end of list
[ 706.044818] device: '1-1:1.0': device_add
[ 706.044872] bus: 'usb': add device 1-1:1.0
[ 706.044897] PM: Adding info for usb:1-1:1.0
[ 706.045823] bus: 'usb': driver_probe_device: matched device 1-1:1.0 with
driver btusb
[ 706.045841] bus: 'usb': really_probe: probing driver btusb with
device 1-1:1.0
[ 706.045861] btusb 1-1:1.0: no default pinctrl state
[ 706.045891] devices_kset: Moving 1-1:1.0 to end of list
[ 706.046024] device: 'hci0': device_add
[ 706.046082] PM: Adding info for No Bus:hci0
[ 706.046669] driver: 'btusb': driver_bound: bound to device '1-1:1.0'
[ 706.047243] bus: 'usb': really_probe: bound device 1-1:1.0 to driver
btusb
[ 706.047273] device: 'ep_81': device_add
[ 706.047340] PM: Adding info for No Bus:ep_81
[ 706.047356] device: 'ep_82': device_add
[ 706.047407] PM: Adding info for No Bus:ep_82
[ 706.047423] device: 'ep_02': device_add
[ 706.047504] PM: Adding info for No Bus:ep_02
[ 706.047517] device: '1-1:1.1': device_add
[ 706.047580] bus: 'usb': add device 1-1:1.1
[ 706.047600] PM: Adding info for usb:1-1:1.1
[ 706.048189] driver: 'btusb': driver_bound: bound to device '1-1:1.1'
[ 706.054130] device: 'ep_83': device_add
[ 706.054199] PM: Adding info for No Bus:ep_83
[ 706.054217] device: 'ep_03': device_add
[ 706.054271] PM: Adding info for No Bus:ep_03
[ 706.054283] device: '1-1:1.2': device_add
[ 706.054327] bus: 'usb': add device 1-1:1.2
[ 706.054346] PM: Adding info for usb:1-1:1.2
[ 706.054504] bus: 'usb': driver_probe_device: matched device 1-1:1.2 with
driver btusb
[ 706.054518] bus: 'usb': really_probe: probing driver btusb with
device 1-1:1.2
[ 706.054537] btusb 1-1:1.2: no default pinctrl state
[ 706.054564] devices_kset: Moving 1-1:1.2 to end of list
[ 706.054597] btusb: probe of 1-1:1.2 rejects match -19
[ 706.054620] device: 'ep_84': device_add
[ 706.054678] PM: Adding info for No Bus:ep_84
[ 706.054697] device: 'ep_04': device_add
[ 706.054748] PM: Adding info for No Bus:ep_04
[ 706.054758] device: '1-1:1.3': device_add
[ 706.054795] bus: 'usb': add device 1-1:1.3
[ 706.054813] PM: Adding info for usb:1-1:1.3
[ 706.054908] bus: 'usb': driver_probe_device: matched device 1-1:1.3 with
driver btusb
[ 706.054919] bus: 'usb': really_probe: probing driver btusb with
device 1-1:1.3
[ 706.054933] btusb 1-1:1.3: no default pinctrl state
[ 706.054956] devices_kset: Moving 1-1:1.3 to end of list
[ 706.054985] btusb: probe of 1-1:1.3 rejects match -19
[ 706.055004] driver: 'usb': driver_bound: bound to device '1-1'
[ 706.055061] bus: 'usb': really_probe: bound device 1-1 to driver usb
[ 706.055106] device: 'ep_00': device_add
[ 706.055165] PM: Adding info for No Bus:ep_00
[ 722.448492] device: 'hci0:11': device_add
[ 722.448556] PM: Adding info for No Bus:hci0:11
[ 723.324687] device: 'bnep0': device_add
[ 723.324896] PM: Adding info for No Bus:bnep0
[ 723.330830] pan: port 1(bnep0) entered blocking state
[ 723.333422] pan: port 1(bnep0) entered disabled state
[ 723.336516] device bnep0 entered promiscuous mode
[ 723.342652] pan: port 1(bnep0) entered blocking state
[ 723.345258] pan: port 1(bnep0) entered forwarding state
[ 729.468482] pan: port 1(bnep0) entered disabled state
[ 753.838286] Bluetooth: hci0: command 0x0c3a tx timeout
[ 755.878258] Bluetooth: hci0: command 0x0c1a tx timeout
Thank you,
Mori
