Bluetooth Device Failing to Initialize

[Maksim Yevmenkin]

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