Bluetooth radio doesn´t reply to inquiry request

Bluetooth radio doesn´t reply to inquiry request

[Carles Cufi]

[-- Attachment #1: Type: text/plain, Size: 2824 bytes --]

Hi there,

I am currently developing a custom application and while debugging it
I have stumbled upon a problem that seems to be
related to some internal kernel problem, and hence I am sharing it
with you to see if anyone has any advice at all about
how to approach it.

I have a setup running:

* Ubuntu 8.10
* Linux 2.6.27-11-generic #1 SMP
* BlueZ 4.12 (from pkgconfig)
* Gnome with the bluetooth daemon running
* A High-speed USB hub with 3 Toshiba Bluetooth 2.0 dongles
(PA3455U-1BTM) each with a CSR BlueCore-4 inside.

What the application does:

My custom application performs inquiries (using the hci2 Host
Controller) periodically with bound raw HCI sockets (i.e.
hci_send_cmd (dd, OGF_LINK_CTL, OCF_INQUIRY, INQUIRY_CP_SIZE, &cp);)
and then receiving the inquiry responses by polling
the device descriptor and parsing the events that come from the Host
Controller (len = read(dd, hci_buffer,
sizeof(hci_buffer)) and then headerptr = (hci_event_hdr *) (hci_buffer
+ 1);). In the meantime, Host Controllers hci0
and hci1 send files over OBEX (using obexftp) to the devices discovered by hci2.

The problem:

The application runs fine for a while, inquiring and sending (or
trying to send) files over OBEX. But after a few
successful inquiries, the program stops after having sent an inquiry
request command and never receiving any response
for it (no command status and no inquiry result or inquiry complete events).
After that, the btusb subsystem seems to block completely, since I am
unable to contact
any of the HCs until I unload it and load it again (with rmmod and modprobe).

Logs attached:

hciconfig_dump: output of hciconfig -a
hciX_dump: output of sudo hcidump -i hciX -Vt
dmesg_dump: output of dmesg

Please note that to help me find out what was going on inside the
kernel I decided to recompile bluetooth.ko and
btusb.ko with the following flags enabled:
CONFIG_BT_HCIBTUSB_DEBUG
CONFIG_BT_HCI_CORE_DEBUG
CONFIG_BT_HCI_SOCK_DEBUG

What seems to be going on:

>From the last few lines of dmesg:

[  324.011911] hci_send_frame: hci2 type 1 len 8
[  324.011913] hci_send_to_sock: hdev edfe7800 len 8
[  324.011921] btusb_send_frame: hci2
[  324.011939] hci_sock_recvmsg: sock ec9aa900, sk eda5ee00
[  324.256140] __set_isoc_interface: hci1 setting interface failed (110)

and the last few lines of hci2_dump:

2009-02-27 13:23:49.377393 < HCI Command: Inquiry (0x01|0x0001) plen 5
   lap 0x9e8b33 len 16 num 0

The last inquiry request command seems to be being sent correctly
(btusb_send_frame: hci2) but just after that we see a
failure when calling __set_isoc_interface on hci1.

I do not currently have enough knowledge about the btusb subsystem to
find out what's happening, and so if someone has
any information about this, please let me know, it would be most useful.

Thanks in advance!

Carles

[-- Attachment #2: dmesg_dump.txt --]
[-- Type: text/plain, Size: 12838 bytes --]

  309.384117] hci_low_sent: conn 00000000 quote 0
[  309.391908] btusb_bulk_complete: hci1 urb ec131280 status 0 count 12
[  309.391928] hci_rx_task: hci1
[  309.391931] hci_send_to_sock: hdev f55dc000 len 12
[  309.391938] hci_rx_task: hci1 ACL data packet
[  309.391940] hci_acldata_packet: hci1 len 8 handle 0x2a flags 0x2
[  309.391943] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  309.391956] hci_send_acl: hci1 conn edbc8800 flags 0x0
[  309.391969] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  309.391983] hci_send_acl: hci1 nonfrag skb eda35cc0 len 22
[  309.391995] hci_tx_task: hci1 acl 8 sco 8
[  309.392006] hci_sched_acl: hci1
[  309.392011] hci_low_sent: conn edbc8800 quote 8
[  309.392018] hci_sched_acl: skb eda35cc0 len 22
[  309.392025] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  309.392033] hci_send_frame: hci1 type 2 len 22
[  309.392040] hci_send_to_sock: hdev f55dc000 len 22
[  309.392051] btusb_send_frame: hci1
[  309.392054] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  309.392070] hci_low_sent: conn 00000000 quote 0
[  309.392074] hci_sched_sco: hci1
[  309.392079] hci_low_sent: conn 00000000 quote 0
[  309.392085] hci_sched_esco: hci1
[  309.392091] hci_low_sent: conn 00000000 quote 0
[  309.392158] btusb_tx_complete: hci1 urb f566c280 status 0 count 22
[  309.396041] btusb_intr_complete: hci1 urb ec131f00 status 0 count 10
[  309.396063] hci_rx_task: hci1
[  309.396070] hci_send_to_sock: hdev f55dc000 len 10
[  309.396082] hci_remote_version_evt: hci1
[  309.396096] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  309.396115] hci_sock_recvmsg: sock ec9b7680, sk ec1abc00
[  309.396123] hci_sock_ioctl: cmd 800448d3 arg b8f3c250
[  309.396125] hci_dev_get: 1
[  309.396147] hci_sock_create: sock ec91d380
[  309.396161] hci_sock_ioctl: cmd 800448d2 arg b8f401c0
[  309.396164] hci_sock_ioctl: cmd 800448d3 arg bfe87a20
[  309.396166] hci_dev_get: 0
[  309.396169] hci_sock_ioctl: cmd 800448d3 arg bfe87a20
[  309.396171] hci_dev_get: 1
[  309.396175] hci_sock_release: sock ec91d380 sk edbc1a00
[  309.396182] hci_sock_ioctl: cmd 800448d4 arg b8f40118
[  309.396189] hci_dev_get: 1
[  309.399034] btusb_intr_complete: hci1 urb ec131f00 status 0 count 7
[  309.399045] hci_rx_task: hci1
[  309.399047] hci_send_to_sock: hdev f55dc000 len 7
[  309.399055] hci_num_comp_pkts_evt: hci1 num_hndl 1
[  309.399058] hci_tx_task: hci1 acl 8 sco 8
[  309.399059] hci_sched_acl: hci1
[  309.399060] hci_low_sent: conn 00000000 quote 0
[  309.399062] hci_sched_sco: hci1
[  309.399063] hci_low_sent: conn 00000000 quote 0
[  309.399064] hci_sched_esco: hci1
[  309.399065] hci_low_sent: conn 00000000 quote 0
[  309.399994] hci_sock_create: sock ec91d380
[  309.400006] hci_sock_bind: sock ec91d380 sk edbc1a00
[  309.400008] hci_dev_get: 1
[  309.400014] hci_sock_release: sock ec91d380 sk edbc1a00
[  309.400701] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  309.409916] btusb_bulk_complete: hci1 urb ec131400 status 0 count 21
[  309.409937] hci_rx_task: hci1
[  309.409939] hci_send_to_sock: hdev f55dc000 len 21
[  309.409946] hci_rx_task: hci1 ACL data packet
[  309.409948] hci_acldata_packet: hci1 len 17 handle 0x2a flags 0x2
[  309.409951] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  309.409963] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  309.411793] btusb_bulk_complete: hci1 urb ec131280 status 0 count 5
[  309.411808] hci_rx_task: hci1
[  309.411810] hci_send_to_sock: hdev f55dc000 len 5
[  309.411821] hci_rx_task: hci1 ACL data packet
[  309.411824] hci_acldata_packet: hci1 len 1 handle 0x2a flags 0x1
[  309.411827] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  309.411834] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  309.413760] hci_send_acl: hci1 conn edbc8800 flags 0x0
[  309.413769] hci_send_acl: hci1 nonfrag skb eda350c0 len 12
[  309.413773] hci_tx_task: hci1 acl 8 sco 8
[  309.413775] hci_sched_acl: hci1
[  309.413777] hci_low_sent: conn edbc8800 quote 8
[  309.413785] hci_sched_acl: skb eda350c0 len 12
[  309.413787] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  309.413790] hci_send_frame: hci1 type 2 len 12
[  309.413792] hci_send_to_sock: hdev f55dc000 len 12
[  309.413802] btusb_send_frame: hci1
[  309.413807] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  309.413808] hci_low_sent: conn 00000000 quote 0
[  309.413810] hci_sched_sco: hci1
[  309.413811] hci_low_sent: conn 00000000 quote 0
[  309.413813] hci_sched_esco: hci1
[  309.413814] hci_low_sent: conn 00000000 quote 0
[  309.413917] btusb_tx_complete: hci1 urb f566ca00 status 0 count 12
[  309.420049] btusb_intr_complete: hci1 urb ec131f00 status 0 count 7
[  309.420064] hci_rx_task: hci1
[  309.420066] hci_send_to_sock: hdev f55dc000 len 7
[  309.420071] hci_num_comp_pkts_evt: hci1 num_hndl 1
[  309.420074] hci_tx_task: hci1 acl 8 sco 8
[  309.420076] hci_sched_acl: hci1
[  309.420077] hci_low_sent: conn 00000000 quote 0
[  309.420079] hci_sched_sco: hci1
[  309.420081] hci_low_sent: conn 00000000 quote 0
[  309.420082] hci_sched_esco: hci1
[  309.420084] hci_low_sent: conn 00000000 quote 0
[  309.420091] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.200032] hci_send_acl: hci1 conn edbc8800 flags 0x0
[  317.200039] hci_send_acl: hci1 nonfrag skb ed9db180 len 12
[  317.200044] hci_tx_task: hci1 acl 8 sco 8
[  317.200046] hci_sched_acl: hci1
[  317.200047] hci_low_sent: conn edbc8800 quote 8
[  317.200049] hci_sched_acl: skb ed9db180 len 12
[  317.200052] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  317.200054] hci_send_frame: hci1 type 2 len 12
[  317.200057] hci_send_to_sock: hdev f55dc000 len 12
[  317.200066] btusb_send_frame: hci1
[  317.200073] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.200075] hci_low_sent: conn 00000000 quote 0
[  317.200077] hci_sched_sco: hci1
[  317.200079] hci_low_sent: conn 00000000 quote 0
[  317.200081] hci_sched_esco: hci1
[  317.200082] hci_low_sent: conn 00000000 quote 0
[  317.200216] btusb_tx_complete: hci1 urb ec131680 status 0 count 12
[  317.204971] btusb_intr_complete: hci1 urb ec131f00 status 0 count 7
[  317.204993] hci_rx_task: hci1
[  317.204995] hci_send_to_sock: hdev f55dc000 len 7
[  317.205004] hci_num_comp_pkts_evt: hci1 num_hndl 1
[  317.205008] hci_tx_task: hci1 acl 8 sco 8
[  317.205009] hci_sched_acl: hci1
[  317.205011] hci_low_sent: conn 00000000 quote 0
[  317.205013] hci_sched_sco: hci1
[  317.205014] hci_low_sent: conn 00000000 quote 0
[  317.205016] hci_sched_esco: hci1
[  317.205018] hci_low_sent: conn 00000000 quote 0
[  317.205534] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.226347] btusb_bulk_complete: hci1 urb ec131400 status 0 count 12
[  317.226375] hci_rx_task: hci1
[  317.226378] hci_send_to_sock: hdev f55dc000 len 12
[  317.226391] hci_rx_task: hci1 ACL data packet
[  317.226398] hci_acldata_packet: hci1 len 8 handle 0x2a flags 0x2
[  317.226400] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  317.226417] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.226421] hci_send_acl: hci1 conn edbc8800 flags 0x0
[  317.226433] hci_send_acl: hci1 nonfrag skb eda0d3c0 len 12
[  317.226446] hci_tx_task: hci1 acl 8 sco 8
[  317.226448] hci_sched_acl: hci1
[  317.226454] hci_low_sent: conn edbc8800 quote 8
[  317.226456] hci_sched_acl: skb eda0d3c0 len 12
[  317.226458] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  317.226461] hci_send_frame: hci1 type 2 len 12
[  317.226463] hci_send_to_sock: hdev f55dc000 len 12
[  317.226468] btusb_send_frame: hci1
[  317.226473] hci_low_sent: conn 00000000 quote 0
[  317.226475] hci_sched_sco: hci1
[  317.226477] hci_low_sent: conn 00000000 quote 0
[  317.226479] hci_sched_esco: hci1
[  317.226485] hci_low_sent: conn 00000000 quote 0
[  317.226492] hci_send_acl: hci1 conn edbc8800 flags 0x0
[  317.226494] hci_send_acl: hci1 nonfrag skb eda0d780 len 16
[  317.226497] hci_tx_task: hci1 acl 7 sco 8
[  317.226503] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.226515] hci_sched_acl: hci1
[  317.226516] hci_low_sent: conn edbc8800 quote 7
[  317.226518] hci_sched_acl: skb eda0d780 len 16
[  317.226520] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  317.226523] hci_send_frame: hci1 type 2 len 16
[  317.226525] hci_send_to_sock: hdev f55dc000 len 16
[  317.226535] btusb_send_frame: hci1
[  317.226538] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.226548] hci_low_sent: conn 00000000 quote 0
[  317.226558] hci_sched_sco: hci1
[  317.226560] hci_low_sent: conn 00000000 quote 0
[  317.226561] hci_sched_esco: hci1
[  317.226563] hci_low_sent: conn 00000000 quote 0
[  317.226598] btusb_tx_complete: hci1 urb f566c980 status 0 count 12
[  317.226605] btusb_tx_complete: hci1 urb f566c800 status 0 count 16
[  317.231974] btusb_intr_complete: hci1 urb ec131f00 status 0 count 7
[  317.231987] hci_rx_task: hci1
[  317.231991] hci_send_to_sock: hdev f55dc000 len 7
[  317.231997] hci_num_comp_pkts_evt: hci1 num_hndl 1
[  317.232000] hci_tx_task: hci1 acl 7 sco 8
[  317.232005] hci_sched_acl: hci1
[  317.232007] hci_low_sent: conn 00000000 quote 0
[  317.232013] hci_sched_sco: hci1
[  317.232015] hci_low_sent: conn 00000000 quote 0
[  317.232017] hci_sched_esco: hci1
[  317.232019] hci_low_sent: conn 00000000 quote 0
[  317.232029] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.232971] btusb_intr_complete: hci1 urb ec131f00 status 0 count 7
[  317.232981] hci_rx_task: hci1
[  317.232983] hci_send_to_sock: hdev f55dc000 len 7
[  317.232993] hci_num_comp_pkts_evt: hci1 num_hndl 1
[  317.232997] hci_tx_task: hci1 acl 8 sco 8
[  317.232999] hci_sched_acl: hci1
[  317.233000] hci_low_sent: conn 00000000 quote 0
[  317.233003] hci_sched_sco: hci1
[  317.233004] hci_low_sent: conn 00000000 quote 0
[  317.233006] hci_sched_esco: hci1
[  317.233008] hci_low_sent: conn 00000000 quote 0
[  317.233017] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.243845] btusb_bulk_complete: hci1 urb ec131280 status 0 count 12
[  317.243865] hci_rx_task: hci1
[  317.243867] hci_send_to_sock: hdev f55dc000 len 12
[  317.243873] hci_rx_task: hci1 ACL data packet
[  317.243876] hci_acldata_packet: hci1 len 8 handle 0x2a flags 0x2
[  317.243877] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  317.243882] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  317.246731] btusb_bulk_complete: hci1 urb ec131400 status 0 count 16
[  317.246754] hci_rx_task: hci1
[  317.246756] hci_send_to_sock: hdev f55dc000 len 16
[  317.246766] hci_rx_task: hci1 ACL data packet
[  317.246768] hci_acldata_packet: hci1 len 12 handle 0x2a flags 0x2
[  317.246772] hci_conn_enter_active_mode: conn edbc8800 mode 0
[  317.246797] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  319.245507] hci_conn_timeout: conn edbc8800 state 1
[  319.245513] hci_acl_disconn: edbc8800
[  319.245516] hci_send_cmd: hci1 opcode 0x406 plen 3
[  319.245518] hci_send_cmd: skb len 6
[  319.245618] hci_cmd_task: hci1 cmd 1
[  319.245622] hci_send_frame: hci1 type 1 len 6
[  319.245624] hci_send_to_sock: hdev f55dc000 len 6
[  319.245631] btusb_send_frame: hci1
[  319.245647] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  319.249986] btusb_tx_complete: hci1 urb f7c6a680 status 0 count 6
[  319.251992] btusb_intr_complete: hci1 urb ec131f00 status 0 count 6
[  319.252011] hci_rx_task: hci1
[  319.252017] hci_send_to_sock: hdev f55dc000 len 6
[  319.252035] hci_cmd_status_evt: hci1 opcode 0x406
[  319.252053] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  319.252068] hci_sock_recvmsg: sock ec9b7680, sk ec1abc00
[  319.252076] hci_sock_ioctl: cmd 800448d3 arg b8f3c250
[  319.252078] hci_dev_get: 1
[  319.256993] btusb_intr_complete: hci1 urb ec131f00 status 0 count 6
[  319.257014] hci_rx_task: hci1
[  319.257016] hci_send_to_sock: hdev f55dc000 len 6
[  319.257029] hci_disconn_complete_evt: hci1 status 0
[  319.257031] hci_conn_del_sysfs: conn edbc8800
[  319.257042] hci_conn_del: hci1 conn edbc8800 handle 42
[  319.257045] btusb_notify: hci1 evt 2
[  319.257058] hci_sock_recvmsg: sock ec91d080, sk edbc2000
[  319.257065] hci_sock_recvmsg: sock ec9b7680, sk ec1abc00
[  319.257075] hci_sock_ioctl: cmd 800448d3 arg b8f3c250
[  319.257078] hci_dev_get: 1
[  319.257237] btusb_bulk_complete: hci1 urb ec131400 status -2 count 0
[  319.257735] btusb_bulk_complete: hci1 urb ec131280 status -2 count 0
[  324.010181] hci_sock_create: sock ec9b6900
[  324.010522] hci_sock_bind: sock ec9b6900 sk edbdac00
[  324.010875] hci_dev_get: 2
[  324.011181] hci_sock_setsockopt: sk edbdac00, opt 2
[  324.011532] hci_sock_sendmsg: sock ec9b6900 sk edbdac00
[  324.011906] hci_cmd_task: hci2 cmd 1
[  324.011911] hci_send_frame: hci2 type 1 len 8
[  324.011913] hci_send_to_sock: hdev edfe7800 len 8
[  324.011921] btusb_send_frame: hci2
[  324.011939] hci_sock_recvmsg: sock ec9aa900, sk eda5ee00
[  324.256140] __set_isoc_interface: hci1 setting interface failed (110)

[-- Attachment #3: hci0_dump.txt --]
[-- Type: text/plain, Size: 584 bytes --]

HCI sniffer - Bluetooth packet analyzer ver 1.42
device: hci0 snap_len: 1028 filter: 0xffffffff
2009-02-27 13:23:09.891279 < HCI Command: Create Connection (0x01|0x0005) plen 13
    bdaddr 00:16:4E:5F:4D:CF ptype 0xcc18 rswitch 0x01 clkoffset 0x0000
    Packet type: DM1 DM3 DM5 DH1 DH3 DH5 
2009-02-27 13:23:09.897897 > HCI Event: Command Status (0x0f) plen 4
    Create Connection (0x01|0x0005) status 0x00 ncmd 1
2009-02-27 13:23:15.022480 > HCI Event: Connect Complete (0x03) plen 11
    status 0x04 handle 0 bdaddr 00:16:4E:5F:4D:CF type ACL encrypt 0x00
    Error: Page Timeout

[-- Attachment #4: hci1_dump.txt --]
[-- Type: text/plain, Size: 6746 bytes --]

HCI sniffer - Bluetooth packet analyzer ver 1.42
device: hci1 snap_len: 1028 filter: 0xffffffff
2009-02-27 13:23:34.569789 < HCI Command: Create Connection (0x01|0x0005) plen 13
    bdaddr 00:16:4E:5F:4D:CF ptype 0xcc18 rswitch 0x01 clkoffset 0x0000
    Packet type: DM1 DM3 DM5 DH1 DH3 DH5 
2009-02-27 13:23:34.575429 > HCI Event: Command Status (0x0f) plen 4
    Create Connection (0x01|0x0005) status 0x00 ncmd 1
2009-02-27 13:23:34.656470 > HCI Event: Connect Complete (0x03) plen 11
    status 0x00 handle 42 bdaddr 00:16:4E:5F:4D:CF type ACL encrypt 0x00
2009-02-27 13:23:34.656600 < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2
    handle 42
2009-02-27 13:23:34.661465 > HCI Event: Command Status (0x0f) plen 4
    Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 0
2009-02-27 13:23:34.664465 > HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
    bdaddr 00:16:4E:5F:4D:CF mode 1
2009-02-27 13:23:34.668465 > HCI Event: Max Slots Change (0x1b) plen 3
    handle 42 slots 5
2009-02-27 13:23:34.688479 > HCI Event: Command Status (0x0f) plen 4
    Unknown (0x00|0x0000) status 0x00 ncmd 1
2009-02-27 13:23:34.688522 < HCI Command: Remote Name Request (0x01|0x0019) plen 10
    bdaddr 00:16:4E:5F:4D:CF mode 2 clkoffset 0x0000
2009-02-27 13:23:34.696480 > HCI Event: Command Status (0x0f) plen 4
    Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
2009-02-27 13:23:34.699492 > HCI Event: Read Remote Supported Features (0x0b) plen 11
    status 0x00 handle 42
    Features: 0xbf 0xee 0x0f 0x00 0x00 0x00 0x00 0x00
2009-02-27 13:23:34.699586 < ACL data: handle 42 flags 0x02 dlen 10
    L2CAP(s): Info req: type 2
2009-02-27 13:23:34.705487 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:34.714501 > ACL data: handle 42 flags 0x02 dlen 16
    L2CAP(s): Info rsp: type 2 result 0
      Extended feature mask 0x0000
2009-02-27 13:23:34.714558 < ACL data: handle 42 flags 0x02 dlen 12
    L2CAP(s): Connect req: psm 3 scid 0x0040
2009-02-27 13:23:34.730372 > ACL data: handle 42 flags 0x02 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0040 result 0 status 0
      Connection successful
2009-02-27 13:23:34.730453 < ACL data: handle 42 flags 0x02 dlen 16
    L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
      MTU 1013 
2009-02-27 13:23:34.733246 > ACL data: handle 42 flags 0x02 dlen 16
    L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
      MTU 32772 
2009-02-27 13:23:34.733318 < ACL data: handle 42 flags 0x02 dlen 18
    L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 4
      MTU 32772 
2009-02-27 13:23:34.733508 > HCI Event: Remote Name Req Complete (0x07) plen 255
    status 0x00 bdaddr 00:16:4E:5F:4D:CF name 'Nokia 6230'
2009-02-27 13:23:34.734495 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:34.736418 < HCI Command: Read Remote Version Information (0x01|0x001d) plen 2
    handle 42
2009-02-27 13:23:34.737500 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:34.740513 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:34.742251 > ACL data: handle 42 flags 0x02 dlen 18
    L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 4
      MTU 1013 
2009-02-27 13:23:34.742768 < ACL data: handle 42 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): SABM: cr 1 dlci 0 pf 1 ilen 0 fcs 0x1c 
2009-02-27 13:23:34.748516 > HCI Event: Command Status (0x0f) plen 4
    Read Remote Version Information (0x01|0x001d) status 0x00 ncmd 1
2009-02-27 13:23:34.749511 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:34.757389 > ACL data: handle 42 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7 
2009-02-27 13:23:34.757514 < ACL data: handle 42 flags 0x02 dlen 18
    L2CAP(d): cid 0x0040 len 14 [psm 3]
      RFCOMM(s): PN CMD: cr 1 dlci 0 pf 0 ilen 10 fcs 0x70 mcc_len 8
      dlci 18 frame_type 0 credit_flow 15 pri 7 ack_timer 0
      frame_size 1008 max_retrans 0 credits 7
2009-02-27 13:23:34.761526 > HCI Event: Read Remote Ver Info Complete (0x0c) plen 8
    status 0x00 handle 42
    LMP Version: 1.1 (0x1) LMP Subversion: 0x382
    Manufacturer: Cambridge Silicon Radio (10)
2009-02-27 13:23:34.764515 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:34.775395 > ACL data: handle 42 flags 0x02 dlen 17
2009-02-27 13:23:34.777275 > ACL data: handle 42 flags 0x01 dlen 1
    L2CAP(d): cid 0x0040 len 14 [psm 3]
      RFCOMM(s): PN RSP: cr 0 dlci 0 pf 0 ilen 10 fcs 0xaa mcc_len 8
      dlci 18 frame_type 0 credit_flow 14 pri 7 ack_timer 0
      frame_size 329 max_retrans 0 credits 0
2009-02-27 13:23:34.779270 < ACL data: handle 42 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): SABM: cr 1 dlci 18 pf 1 ilen 0 fcs 0x32 
2009-02-27 13:23:34.785528 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:42.565530 < ACL data: handle 42 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): DISC: cr 1 dlci 18 pf 1 ilen 0 fcs 0xd3 
2009-02-27 13:23:42.570454 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:42.591829 > ACL data: handle 42 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): UA: cr 1 dlci 18 pf 1 ilen 0 fcs 0xf9 
2009-02-27 13:23:42.591937 < ACL data: handle 42 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): DISC: cr 1 dlci 0 pf 1 ilen 0 fcs 0xfd 
2009-02-27 13:23:42.591999 < ACL data: handle 42 flags 0x02 dlen 12
    L2CAP(s): Disconn req: dcid 0x0040 scid 0x0040
2009-02-27 13:23:42.597451 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:42.598448 > HCI Event: Number of Completed Packets (0x13) plen 5
    handle 42 packets 1
2009-02-27 13:23:42.609328 > ACL data: handle 42 flags 0x02 dlen 8
    L2CAP(d): cid 0x0040 len 4 [psm 3]
      RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7 
2009-02-27 13:23:42.612217 > ACL data: handle 42 flags 0x02 dlen 12
    L2CAP(s): Disconn rsp: dcid 0x0040 scid 0x0040
2009-02-27 13:23:44.611098 < HCI Command: Disconnect (0x01|0x0006) plen 3
    handle 42 reason 0x13
    Reason: Remote User Terminated Connection
2009-02-27 13:23:44.617476 > HCI Event: Command Status (0x0f) plen 4
    Disconnect (0x01|0x0006) status 0x00 ncmd 1
2009-02-27 13:23:44.622475 > HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 42 reason 0x16
    Reason: Connection Terminated by Local Host

[-- Attachment #5: hci2_dump.txt --]
[-- Type: text/plain, Size: 10353 bytes --]

009-02-27 13:23:30.798524 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9C:A3 mode 1 clkoffset 0x0328 class 0x3e0100 rssi -94
2009-02-27 13:23:30.831542 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9C:FE mode 1 clkoffset 0x177b class 0x3e0100 rssi -75
2009-02-27 13:23:30.849547 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:08:2E:FE mode 1 clkoffset 0x2488 class 0x1c010c rssi -53
2009-02-27 13:23:30.853566 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:81:19 mode 1 clkoffset 0x01ba class 0x3e0100 rssi -86
2009-02-27 13:23:30.858556 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:6C:72 mode 1 clkoffset 0x0c8a class 0x3e0100 rssi -73
2009-02-27 13:23:30.862552 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:AE:8D mode 1 clkoffset 0x7d87 class 0x3e0100 rssi -64
2009-02-27 13:23:30.919592 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:83:4A mode 1 clkoffset 0x6b60 class 0x3e0100 rssi -82
2009-02-27 13:23:31.175712 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9B:C0 mode 1 clkoffset 0x1377 class 0x3e0100 rssi -51
2009-02-27 13:23:31.199731 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:83:4A mode 1 clkoffset 0x6b5f class 0x3e0100 rssi -76
2009-02-27 13:23:31.206728 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:0C:41:E2:0A:10 mode 1 clkoffset 0x57ac class 0x020104 rssi -70
2009-02-27 13:23:31.212728 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:AE:8D mode 1 clkoffset 0x7d87 class 0x3e0100 rssi -73
2009-02-27 13:23:31.246747 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1F:F3:AD:1C:F0 mode 1 clkoffset 0x3aee class 0x380104 rssi -67
2009-02-27 13:23:31.269759 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:83:4A mode 1 clkoffset 0x6b60 class 0x3e0100 rssi -85
2009-02-27 13:23:31.273763 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:81:19 mode 1 clkoffset 0x01ba class 0x3e0100 rssi -86
2009-02-27 13:23:31.370819 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:08:2E:FE mode 1 clkoffset 0x2488 class 0x1c010c rssi -57
2009-02-27 13:23:31.376820 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:6A:1F mode 1 clkoffset 0x72aa class 0x3e0100 rssi -60
2009-02-27 13:23:31.411829 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:08:2E:FE mode 1 clkoffset 0x2488 class 0x1c010c rssi -62
2009-02-27 13:23:31.426835 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:F6:82 mode 1 clkoffset 0x3775 class 0x3e0100 rssi -57
2009-02-27 13:23:31.446852 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:F6:D1 mode 1 clkoffset 0x3775 class 0x3e0100 rssi -53
2009-02-27 13:23:31.467865 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1D:98:06:DB:D8 mode 1 clkoffset 0x7c89 class 0x5a0204 rssi -85
2009-02-27 13:23:31.491876 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:83:4A mode 1 clkoffset 0x6b5f class 0x3e0100 rssi -90
2009-02-27 13:23:31.527888 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:0A:94:F5:58:A4 mode 1 clkoffset 0x0951 class 0x1c0104 rssi -82
2009-02-27 13:23:31.656952 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1F:F3:AD:1C:F0 mode 1 clkoffset 0x3aee class 0x380104 rssi -71
2009-02-27 13:23:31.666965 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:19:4F:BE:FB:34 mode 1 clkoffset 0x7b70 class 0x50020c rssi -70
2009-02-27 13:23:31.686975 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:F6:82 mode 1 clkoffset 0x3775 class 0x3e0100 rssi -63
2009-02-27 13:23:31.706977 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:F6:D1 mode 1 clkoffset 0x3775 class 0x3e0100 rssi -56
2009-02-27 13:23:31.798026 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:6C:7B mode 1 clkoffset 0x0d74 class 0x3e0100 rssi -86
2009-02-27 13:23:31.863068 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9C:FE mode 1 clkoffset 0x177c class 0x3e0100 rssi -78
2009-02-27 13:23:31.919093 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:ED:4F mode 1 clkoffset 0x42c4 class 0x000100 rssi -80
2009-02-27 13:23:31.948109 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:19:4F:BE:FB:34 mode 1 clkoffset 0x7b70 class 0x50020c rssi -71
2009-02-27 13:23:31.968110 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:F6:82 mode 1 clkoffset 0x3775 class 0x3e0100 rssi -56
2009-02-27 13:23:31.979114 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9B:C0 mode 1 clkoffset 0x1377 class 0x3e0100 rssi -48
2009-02-27 13:23:31.983114 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:83:4A mode 1 clkoffset 0x6b5f class 0x3e0100 rssi -79
2009-02-27 13:23:31.989118 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:F6:D1 mode 1 clkoffset 0x3775 class 0x3e0100 rssi -55
2009-02-27 13:23:31.994123 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:AE:8D mode 1 clkoffset 0x7d87 class 0x3e0100 rssi -75
2009-02-27 13:23:32.261256 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:19:2D:41:54:C5 mode 1 clkoffset 0x307c class 0x5a020c rssi -50
2009-02-27 13:23:32.425346 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9B:B8 mode 1 clkoffset 0x0954 class 0x3e0100 rssi -54
2009-02-27 13:23:32.447350 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:08:2E:FE mode 1 clkoffset 0x2488 class 0x1c010c rssi -60
2009-02-27 13:23:32.697477 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:08:2E:FE mode 1 clkoffset 0x2488 class 0x1c010c rssi -65
2009-02-27 13:23:32.751511 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:19:2D:41:54:C5 mode 1 clkoffset 0x307c class 0x5a020c rssi -45
2009-02-27 13:23:32.779517 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:07:98:75 mode 1 clkoffset 0x3976 class 0x1c010c rssi -79
2009-02-27 13:23:32.895576 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:C2:99:0F:09 mode 1 clkoffset 0x29c1 class 0x380104 rssi -73
2009-02-27 13:23:32.953606 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:16:4E:5F:4D:CF mode 1 clkoffset 0x038a class 0x520204 rssi -51
2009-02-27 13:23:33.066660 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:22:41:FE:F2:DD mode 1 clkoffset 0x641f class 0x380104 rssi -62
2009-02-27 13:23:33.183728 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:17:E6:A1:73:B9 mode 1 clkoffset 0x4e10 class 0x50020c rssi -80
2009-02-27 13:23:33.351814 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:07:98:75 mode 1 clkoffset 0x3976 class 0x1c010c rssi -75
2009-02-27 13:23:33.357807 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9C:FE mode 1 clkoffset 0x177c class 0x3e0100 rssi -77
2009-02-27 13:23:33.433845 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:17:E6:A1:73:B9 mode 1 clkoffset 0x4e10 class 0x50020c rssi -80
2009-02-27 13:23:33.437850 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:6A:4C mode 1 clkoffset 0x72b2 class 0x3e0100 rssi -60
2009-02-27 13:23:33.533903 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:19:2D:41:54:C5 mode 1 clkoffset 0x307c class 0x5a020c rssi -48
2009-02-27 13:23:33.565923 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:16:4E:5F:4D:CF mode 1 clkoffset 0x038a class 0x520204 rssi -43
2009-02-27 13:23:33.578922 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9C:FE mode 1 clkoffset 0x177b class 0x3e0100 rssi -80
2009-02-27 13:23:33.591935 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:07:98:75 mode 1 clkoffset 0x3976 class 0x1c010c rssi -92
2009-02-27 13:23:33.636947 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:16:4E:5F:4D:CF mode 1 clkoffset 0x038a class 0x520204 rssi -50
2009-02-27 13:23:33.699979 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:81:19 mode 1 clkoffset 0x01ba class 0x3e0100 rssi -87
2009-02-27 13:23:33.726992 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:6A:4C mode 1 clkoffset 0x72b2 class 0x3e0100 rssi -64
2009-02-27 13:23:33.748002 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:AE:8D mode 1 clkoffset 0x7d87 class 0x3e0100 rssi -75
2009-02-27 13:23:33.940105 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9C:FE mode 1 clkoffset 0x177c class 0x3e0100 rssi -74
2009-02-27 13:23:34.051164 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:08:2E:FE mode 1 clkoffset 0x2488 class 0x1c010c rssi -59
2009-02-27 13:23:34.178233 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:0C:6C:72 mode 1 clkoffset 0x0c89 class 0x3e0100 rssi -80
2009-02-27 13:23:34.190226 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9C:FE mode 1 clkoffset 0x177b class 0x3e0100 rssi -79
2009-02-27 13:23:34.242252 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:08:2E:FE mode 1 clkoffset 0x2488 class 0x1c010c rssi -70
2009-02-27 13:23:34.531409 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:C0:1B:08:9C:FE mode 1 clkoffset 0x177b class 0x3e0100 rssi -85
2009-02-27 13:23:34.532352 < HCI Command: Inquiry Cancel (0x01|0x0002) plen 0
2009-02-27 13:23:34.535402 > HCI Event: Inquiry Result with RSSI (0x22) plen 15
    bdaddr 00:1E:3D:07:98:75 mode 1 clkoffset 0x3976 class 0x1c010c rssi -85
2009-02-27 13:23:34.541410 > HCI Event: Command Complete (0x0e) plen 4
    Inquiry Cancel (0x01|0x0002) ncmd 1
    status 0x00
2009-02-27 13:23:49.377393 < HCI Command: Inquiry (0x01|0x0001) plen 5
    lap 0x9e8b33 len 16 num 0

[-- Attachment #6: hciconfig_dump.txt --]
[-- Type: text/plain, Size: 1758 bytes --]

hci0:	Type: USB
	BD Address: 00:0A:94:F5:53:58 ACL MTU: 384:8 SCO MTU: 64:8
	UP RUNNING 
	RX bytes:1036 acl:0 sco:0 events:36 errors:0
	TX bytes:403 acl:0 sco:0 commands:35 errors:0
	Features: 0xff 0xff 0x8f 0xfe 0x9b 0xf9 0x00 0x80
	Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3 
	Link policy: RSWITCH HOLD SNIFF PARK 
	Link mode: SLAVE ACCEPT 
	Name: 'bloomy-0'
	Class: 0x0a0104
	Service Classes: Networking, Capturing
	Device Class: Computer, Desktop workstation
	HCI Ver: 2.0 (0x3) HCI Rev: 0x6e6 LMP Ver: 2.0 (0x3) LMP Subver: 0x6e6
	Manufacturer: Cambridge Silicon Radio (10)

hci1:	Type: USB
	BD Address: 00:0A:94:F5:58:86 ACL MTU: 384:8 SCO MTU: 64:8
	UP RUNNING 
	RX bytes:1007 acl:0 sco:0 events:31 errors:0
	TX bytes:370 acl:0 sco:0 commands:30 errors:0
	Features: 0xff 0xff 0x8f 0xfe 0x9b 0xf9 0x00 0x80
	Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3 
	Link policy: RSWITCH HOLD SNIFF PARK 
	Link mode: SLAVE ACCEPT 
	Name: 'bloomy-1'
	Class: 0x0a0104
	Service Classes: Networking, Capturing
	Device Class: Computer, Desktop workstation
	HCI Ver: 2.0 (0x3) HCI Rev: 0x6e6 LMP Ver: 2.0 (0x3) LMP Subver: 0x6e6
	Manufacturer: Cambridge Silicon Radio (10)

hci2:	Type: USB
	BD Address: 00:0A:94:F5:58:D8 ACL MTU: 384:8 SCO MTU: 64:8
	UP RUNNING 
	RX bytes:1007 acl:0 sco:0 events:31 errors:0
	TX bytes:370 acl:0 sco:0 commands:30 errors:0
	Features: 0xff 0xff 0x8f 0xfe 0x9b 0xf9 0x00 0x80
	Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3 
	Link policy: RSWITCH HOLD SNIFF PARK 
	Link mode: SLAVE ACCEPT 
	Name: 'bloomy-2'
	Class: 0x0a0104
	Service Classes: Networking, Capturing
	Device Class: Computer, Desktop workstation
	HCI Ver: 2.0 (0x3) HCI Rev: 0x6e6 LMP Ver: 2.0 (0x3) LMP Subver: 0x6e6
	Manufacturer: Cambridge Silicon Radio (10)

Re: Bluetooth radio doesn´t reply to inquiry request

[Marcel Holtmann]

Hi Charles,

> I am currently developing a custom application and while debugging it
> I have stumbled upon a problem that seems to be
> related to some internal kernel problem, and hence I am sharing it
> with you to see if anyone has any advice at all about
> how to approach it.
> 
> I have a setup running:
> 
> * Ubuntu 8.10
> * Linux 2.6.27-11-generic #1 SMP
> * BlueZ 4.12 (from pkgconfig)
> * Gnome with the bluetooth daemon running
> * A High-speed USB hub with 3 Toshiba Bluetooth 2.0 dongles
> (PA3455U-1BTM) each with a CSR BlueCore-4 inside.
> 
> What the application does:
> 
> My custom application performs inquiries (using the hci2 Host
> Controller) periodically with bound raw HCI sockets (i.e.
> hci_send_cmd (dd, OGF_LINK_CTL, OCF_INQUIRY, INQUIRY_CP_SIZE, &cp);)
> and then receiving the inquiry responses by polling
> the device descriptor and parsing the events that come from the Host
> Controller (len = read(dd, hci_buffer,
> sizeof(hci_buffer)) and then headerptr = (hci_event_hdr *) (hci_buffer
> + 1);). In the meantime, Host Controllers hci0
> and hci1 send files over OBEX (using obexftp) to the devices discovered by hci2.
> 
> The problem:
> 
> The application runs fine for a while, inquiring and sending (or
> trying to send) files over OBEX. But after a few
> successful inquiries, the program stops after having sent an inquiry
> request command and never receiving any response
> for it (no command status and no inquiry result or inquiry complete events).
> After that, the btusb subsystem seems to block completely, since I am
> unable to contact
> any of the HCs until I unload it and load it again (with rmmod and modprobe).
> 
> Logs attached:
> 
> hciconfig_dump: output of hciconfig -a
> hciX_dump: output of sudo hcidump -i hciX -Vt
> dmesg_dump: output of dmesg
> 
> Please note that to help me find out what was going on inside the
> kernel I decided to recompile bluetooth.ko and
> btusb.ko with the following flags enabled:
> CONFIG_BT_HCIBTUSB_DEBUG
> CONFIG_BT_HCI_CORE_DEBUG
> CONFIG_BT_HCI_SOCK_DEBUG
> 
> What seems to be going on:
> 
> From the last few lines of dmesg:
> 
> [  324.011911] hci_send_frame: hci2 type 1 len 8
> [  324.011913] hci_send_to_sock: hdev edfe7800 len 8
> [  324.011921] btusb_send_frame: hci2
> [  324.011939] hci_sock_recvmsg: sock ec9aa900, sk eda5ee00
> [  324.256140] __set_isoc_interface: hci1 setting interface failed (110)
> 
> and the last few lines of hci2_dump:
> 
> 2009-02-27 13:23:49.377393 < HCI Command: Inquiry (0x01|0x0001) plen 5
>    lap 0x9e8b33 len 16 num 0
> 
> The last inquiry request command seems to be being sent correctly
> (btusb_send_frame: hci2) but just after that we see a
> failure when calling __set_isoc_interface on hci1.
> 
> I do not currently have enough knowledge about the btusb subsystem to
> find out what's happening, and so if someone has
> any information about this, please let me know, it would be most useful.

why don't you use periodic inquiry instead and let the controller handle
the timing.

Also should try the bluetooth-testing.git tree since it contains an
updated btusb.ko driver.

Regards

Marcel

Re: Bluetooth radio doesn´t reply to inquiry request

[Carles Cufi]

Hi Marcel,

Thanks for your reply.

>
> why don't you use periodic inquiry instead and let the controller  
> handle
> the timing.
>

Because the specific bit I am working on is a C++ library capable of  
doing (among other things) asynchronous discovery while avoiding any  
intermediate caches (that's why I don't use the D-Bus interface or the  
ioctl call) and I do not have control over the periodicity of the  
inquiry nor know when it is going to be cancelled or started again.  
The API requirements were to provide an fast, not cached inquiry that  
can be started and cancelled at will by the application.
Having examined the logs the amount of inquiry requests I am sending  
is fairly low (every 30 seconds or so) and so I thought it wouldn't be  
a problem for the HCI or USB layers to handle in terms of data volume.

> Also should try the bluetooth-testing.git tree since it contains an
> updated btusb.ko driver.

I will try it and let you know about the results.
Does this imply that it looks like a problem in the btusb driver? The  
only other explanations that occurred me until now were:

- The problem is in the hardware (USB hub or BlueCores): I discarded  
this possibility because I took a different hub and 3 dongles  
containing Broadcom modules and reproduced it immediately.
- The problem could be the library sending commands directlly to the  
HC and therefore conflicting with another source of commands  
(bluetooth daemon or other): This seems unlikely given that the logs  
show that on hci2 the only commands are the inquiry requests and  
cancels being sent by the library.

Thanks!

Carles

Re: Bluetooth radio doesn´t reply to inquiry request

[Marcel Holtmann]

Hi Carles,

> > why don't you use periodic inquiry instead and let the controller  
> > handle
> > the timing.
> >
> 
> Because the specific bit I am working on is a C++ library capable of  
> doing (among other things) asynchronous discovery while avoiding any  
> intermediate caches (that's why I don't use the D-Bus interface or the  
> ioctl call) and I do not have control over the periodicity of the  
> inquiry nor know when it is going to be cancelled or started again.  
> The API requirements were to provide an fast, not cached inquiry that  
> can be started and cancelled at will by the application.
> Having examined the logs the amount of inquiry requests I am sending  
> is fairly low (every 30 seconds or so) and so I thought it wouldn't be  
> a problem for the HCI or USB layers to handle in terms of data volume.

do me favor and read the Bluetooth specification, because periodic
inquiry is a low-level HCI command.

> > Also should try the bluetooth-testing.git tree since it contains an
> > updated btusb.ko driver.
> 
> I will try it and let you know about the results.
> Does this imply that it looks like a problem in the btusb driver? The  
> only other explanations that occurred me until now were:

With btusb we were trying to send as less URBs as possible, but it could
be that not having bulk URB running the chips behave funny. At least
that is what we have seen with some hardware. So that could be an issue
here. Nobody knows for sure.

Regards

Marcel

Re: Bluetooth radio doesn´t reply to inquiry request

[Carles Cufi]

Hi Marcel,

> do me favor and read the Bluetooth specification, because periodic
> inquiry is a low-level HCI command.

I believe you may have misunderstood my earlier post. I do know about
the HCI Period Inquiry Mode command, but this is a large, multi-person
project, and I am in charge of writing a library that provides an
Inquiry() and InquiryCancel() methods. Someone else writes the
application that uses those methods, and so it happens that some of
the time they are using them to periodically launch inquiries, but
then not always. I cannot use the above mentioned HCI command because
I do not receive anything resembling a period as a parameter, since my
API only allows the application to start and stop inquiries, no to
provide periodicity information to the underlying library
implementation. Unfortunately I cannot change the API requirements nor
have control over what the application does with my library.

> With btusb we were trying to send as less URBs as possible, but it could
> be that not having bulk URB running the chips behave funny. At least
> that is what we have seen with some hardware. So that could be an issue
> here. Nobody knows for sure.

So if I understand this correctly, at some point (apparently when
BlueZ transitioned from hci_usb to btusb?) you removed support for
bulk URBs and that causes problems with some chipsets. I will try the
bluetooth-testing.git repository, but could you confirm what I just
stated and let me know at which point did the transition you are
talking about happened?

Thanks very much again!

Regards,

Carles

Re: Bluetooth radio doesn´t reply to inquiry request

[Carles Cufi]

Hi Marcel,

> Also should try the bluetooth-testing.git tree since it contains an
> updated btusb.ko driver.

I took the btusb.c from bluetooth-testing.git and compiled it into my
kernel. The symptoms remain exactly the same, the output of dmesg
looks identical, with the call to  __set_isoc_interface still failing.
Is there anything else I can try? Do you believe this problem has been
introduced recently into the kernel?

Thanks again!

Regards,

Carles

Re: Bluetooth radio doesn´t reply to inquiry request

[Carles Cufi]

Hi Marcel,

> Also should try the bluetooth-testing.git tree since it contains an
> updated btusb.ko driver.

I tried bluetooth-testing.git, this time building the whole thing and
not just btusb.ko and now everything seems to work fine. Any idea on
what kernels are affected by the problem? Is it only 2.6.27, or may
earlier (or older) kernels have the same issue too?

Thanks in advance!

Regards,

Carles