Date: Thu, 12 Jan 2006 11:24:12 -0800 From: Maksim Yevmenkin <maksim.yevmenkin@savvis.net> To: scycoon@internode.on.net Cc: freebsd-bluetooth@freebsd.org Subject: Re: Bluetooth Device Failing to Initialize Message-ID: <43C6ACDC.10802@savvis.net> In-Reply-To: <1137051315.613.7.camel@bigboy.scycoon.soho.on.net> References: <43c59d92.36a.33a6.26043@internode.on.net> <43C5A551.8000206@savvis.net> <1137051315.613.7.camel@bigboy.scycoon.soho.on.net>
next in thread | previous in thread | raw e-mail | index | archive | help
Chriso,
> I have included the requested output below,
thanks. lets see...
[...]
>>>Could not execute command "initialize". Device not
>>>configured
>>
>>this is *very* strange.
>>
>>1) did you check your /var/log/messages to see if device has detached?
>
> This is in the messages after I run /etc/rc.bluetooth after a fresh
> reboot;
>
> Jan 12 17:54:28 bigboy kernel: ng_hci_process_command_timeout: ubt0hci -
> unable to complete HCI command OGF=0x3, OCF=0x3. Timeout
> Jan 12 17:54:28 bigboy kernel: ng_hci_process_event: ubt0hci - got HCI
> event=0xe, length=4
> Jan 12 17:54:28 bigboy kernel: complete_command: ubt0hci - no pending
> command, state=0x1
> Jan 12 17:54:28 bigboy kernel: ubt_request_complete2: ubt0 - Control
> request failed. TIMEOUT (15)
hmm... this does not make much sense to me :( what it means is that the
hci node tried to send command to the device, but it did not get any
response back from the device in time (timed out). what happened next is
that the hci node received response back from the device, but it did
throw it away because it already timed out.
i'm also concern about "ubt_request_complete2" error. it might indicate
that something is wrong at usb level.
> Jan 12 17:54:33 bigboy kernel: ng_hci_process_command_timeout: ubt0hci -
> unable to complete HCI command OGF=0x4, OCF=0x9. Timeout
> Jan 12 17:54:33 bigboy kernel: ng_hci_process_event: ubt0hci - got HCI
> event=0xe, length=10
> Jan 12 17:54:33 bigboy kernel: complete_command: ubt0hci - no pending
> command, state=0x1
> Jan 12 17:54:33 bigboy kernel: ubt_request_complete2: ubt0 - Control
> request failed. TIMEOUT (15)
here is the same sequence for another command (READ_BD_ADDR)
> Jan 12 17:54:38 bigboy kernel: ng_hci_process_command_timeout: ubt0hci -
> unable to complete HCI command OGF=0x4, OCF=0x3. Timeout
> Jan 12 17:54:38 bigboy kernel: ng_hci_process_event: ubt0hci - got HCI
> event=0xe, length=12
> Jan 12 17:54:38 bigboy kernel: complete_command: ubt0hci - no pending
> command, state=0x1
> Jan 12 17:54:38 bigboy kernel: ubt_request_complete2: ubt0 - Control
> request failed. TIMEOUT (15)
and again (READ_LOCAL_FEATURES)
> Jan 12 17:54:43 bigboy kernel: ng_hci_process_command_timeout: ubt0hci -
> unable to complete HCI command OGF=0x4, OCF=0x5. Timeout
> Jan 12 17:54:43 bigboy kernel: ng_hci_process_event: ubt0hci - got HCI
> event=0xe, length=11
> Jan 12 17:54:43 bigboy kernel: complete_command: ubt0hci - no pending
> command, state=0x1
> Jan 12 17:54:43 bigboy kernel: ubt_request_complete2: ubt0 - Control
> request failed. TIMEOUT (15)
and again (READ_BUFFER_SIZE)
> Jan 12 17:54:48 bigboy kernel: ng_hci_process_command_timeout: ubt0hci -
> unable to complete HCI command OGF=0x3, OCF=0x1a. Timeout
> Jan 12 17:54:48 bigboy kernel: ng_hci_process_event: ubt0hci - got HCI
> event=0xe, length=4
> Jan 12 17:54:48 bigboy kernel: complete_command: ubt0hci - no pending
> command, state=0x1
> Jan 12 17:54:48 bigboy kernel: ubt_request_complete2: ubt0 - Control
> request failed. TIMEOUT (15)
and again (WRITE_SCAN_ENABLE)
> Jan 12 17:54:53 bigboy kernel: ng_hci_process_command_timeout: ubt0hci -
> unable to complete HCI command OGF=0x3, OCF=0x24. Timeout
> Jan 12 17:54:53 bigboy kernel: ng_hci_process_event: ubt0hci - got HCI
> event=0xe, length=4
> Jan 12 17:54:53 bigboy kernel: complete_command: ubt0hci - no pending
> command, state=0x1
> Jan 12 17:54:53 bigboy kernel: ubt_request_complete2: ubt0 - Control
> request failed. TIMEOUT (15)
and again (WRITE_UNIT_CLASS)
> Jan 12 17:54:58 bigboy kernel: ng_hci_process_command_timeout: ubt0hci -
> unable to complete HCI command OGF=0x3, OCF=0x13. Timeout
> Jan 12 17:54:58 bigboy kernel: ng_hci_process_event: ubt0hci - got HCI
> event=0xe, length=4
> Jan 12 17:54:58 bigboy kernel: complete_command: ubt0hci - no pending
> command, state=0x1
> Jan 12 17:54:58 bigboy kernel: ubt_request_complete2: ubt0 - Control
> request failed. TIMEOUT (15)
and again (CHANGE_LOCAL_NAME)
also note interval between each chunks of errors - its 5 second. which
is a hci command timeout.
>>2) can you please run as root the following commands
>
> bash-2.05b# ngctl types
> There are 7 total types:
> Type name Number of living nodes
> --------- ----------------------
> socket 1
> btsock_l2c 1
> btsock_l2c_raw 1
> btsock_hci_raw 1
> l2cap 1
> hci 1
> ubt 1
>
> bash-2.05b# ngctl li
> There are 7 total nodes:
> Name: ngctl704 Type: socket ID: 00000013 Num hooks: 0
> Name: ubt0l2cap Type: l2cap ID: 0000000c Num hooks: 3
> Name: ubt0hci Type: hci ID: 00000008 Num hooks: 3
> Name: btsock_l2c Type: btsock_l2c ID: 00000004 Num hooks: 1
> Name: btsock_l2c_raw Type: btsock_l2c_raw ID: 00000003 Num hooks: 1
> Name: btsock_hci_raw Type: btsock_hci_raw ID: 00000002 Num hooks: 1
> Name: ubt0 Type: ubt ID: 00000001 Num hooks: 1
good. all nodes are still present and connected.
> bash-2.05b# ngctl status ubt0:
> Status for "ubt0:":
> Hook: hook
> Flags: 0x30
> Debug: 3
> CMD queue: [have:0,max:12]
> ACL queue: [have:0,max:12]
> SCO queue: [have:0,max:12]
looks good.
> bash-2.05b# ngctl status ubt0hci:
> Status for "ubt0hci:":
> bdaddr 0:0:0:0:0:0
> Hooks drv acl raw
> State 0x1
> Queue cmd:0
> Buffer cmd:1,acl:1,1,17,sco:1,1,10
aha! this is why "initialize" command failed. as i said above, the hci
node did not get any response back from the device in time for every
command in the initialization sequence. so, as far as the hci node is
concerned the device was _not_ initialized correctly, i.e. note that
bdaddr is 0:0:0:0:0:0 etc.
the reason you see correct output on the screen is because data,
received from the device, is copied to the "raw" hook (where socket gets
connected) _before_ they processed by the hci node.
this is a very strange failure mode that i have never seen before.
you could try to do a couple of things
1) comment out "reset" command in the rc.bluetooth script, unplug/replug
your device and run rc.bluetooth again.
## ${hccontrol} -n ${dev}hci reset || exit 1
2) try to adjust the command timeout, i.e. add a couple of lines before
"reset" command
${sysctl} net.bluetooth.hci.command_timeout=10
${sysctl} net.bluetooth.hci.sockets.raw.ioctl_timeout=10
also, just to be on the safe side, could you please check your
/etc/devd.conf file and make sure you do not call anything in response
to ubt(4) attach/detach events.
also it would be nice if you could run hcidump (with timestamp option)
while you are running rc.bluetooth, i.e.
# hcidump -tX
thanks,
max
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?43C6ACDC.10802>