Bluetooth mouse breaks on -current

Eric Anderson anderson at centtech.com
Tue Oct 4 11:50:38 PDT 2005


Maksim Yevmenkin wrote:
> Eric,
> 
> [...]
> 
>>>> It's back at it again.  About 10-15 minutes into a buildworld, I 
>>>> started losing my mouse.  If I hit a button on the mouse, it would 
>>>> come back (it was just losing the connection, as if the mouse went 
>>>> to sleep, or had low batteries).  I did that a few times, until it 
>>>> finally stopped working altogether.  I swapped batteries thinking 
>>>> this was the problem, however the batteries were pretty fresh still, 
>>>> but the new batts did not make a difference.
> 
> 
> ok
> 
>>>> I noticed in /var/log/messages:
>>>> [beginning of problems]
>>>> Oct  1 19:58:41 neutrino bthidd[603]: Remote device 
>>>> 00:0c:55:01:bf:39 has closed interrupt connection
>>>> Oct  1 19:58:42 neutrino kernel: ng_l2cap_process_discon_req: 
>>>> ubt0l2cap - unexpected L2CAP_DisconnectReq message. Channel does not 
>>>> exist, cid=107
>>>> Oct  1 20:01:03 neutrino bthidd[603]: Accepted control connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:01:03 neutrino bthidd[603]: Accepted interrupt connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:09:47 neutrino bthidd[603]: Remote device 
>>>> 00:0c:55:01:bf:39 has closed control connection
>>>> Oct  1 20:09:48 neutrino bthidd[603]: Accepted control connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:09:48 neutrino bthidd[603]: Accepted interrupt connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:15:14 neutrino bthidd[603]: Remote device 
>>>> 00:0c:55:01:bf:39 has closed control connection
>>>> Oct  1 20:15:14 neutrino bthidd[603]: Accepted control connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:15:14 neutrino bthidd[603]: Accepted interrupt connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:15:22 neutrino bthidd[603]: Remote device 
>>>> 00:0c:55:01:bf:39 has closed control connection
>>>> Oct  1 20:15:22 neutrino bthidd[603]: Accepted control connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:15:22 neutrino bthidd[603]: Accepted interrupt connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:15:34 neutrino bthidd[603]: Remote device 
>>>> 00:0c:55:01:bf:39 has closed control connection
>>>> Oct  1 20:15:34 neutrino bthidd[603]: Accepted control connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:15:34 neutrino bthidd[603]: Accepted interrupt connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:15:40 neutrino bthidd[603]: Remote device 
>>>> 00:0c:55:01:bf:39 has closed control connection
>>>> Oct  1 20:15:41 neutrino bthidd[603]: Accepted control connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:15:41 neutrino bthidd[603]: Accepted interrupt connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:16:08 neutrino bthidd[603]: Remote device 
>>>> 00:0c:55:01:bf:39 has closed control connection
>>>> Oct  1 20:30:27 neutrino bthidd[603]: Accepted control connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:30:27 neutrino bthidd[603]: Accepted interrupt connection 
>>>> from 00:0c:55:01:bf:39
>>>> Oct  1 20:54:50 neutrino kernel: kbd1 at vkbd1
> 
> 
> this looks like the mouse is loosing the connection and trying to 
> re-connect.

Correct - the mouse would just stop working while I was using it, and 
this particular mouse needs a button click to tell it to re-connect (as 
if it was in power save mode).  The reconnects you see, are me clicking 
buttons to get it to come back alive.

>>>> [died completely at that vkbd message]
>>>>
>>>> Oct  1 21:01:16 neutrino su: anderson to root on /dev/ttyp2
>>>> Oct  1 21:06:22 neutrino kernel: ng_hci_process_command_timeout: 
>>>> ubt0hci - unable to complete HCI command OGF=0x1, OCF=0x1. Timeout
>>>> Oct  1 21:06:22 neutrino kernel: ubt_request_complete2: ubt0 - 
>>>> Control request failed. TIMEOUT (15)
>>>> Oct  1 21:07:39 neutrino kernel: ng_hci_process_command_timeout: 
>>>> ubt0hci - unable to complete HCI command OGF=0x3, OCF=0x3. Timeout
>>>> Oct  1 21:07:39 neutrino kernel: ubt_request_complete2: ubt0 - 
>>>> Control request failed. TIMEOUT (15)
> 
> 
> this is bad. something screwed up at usb level. basically we are trying 
> to send commands to the local device (not mouse) and it does not respond.

I agree - almost seems as though it's a faulty usb bluetooth adapter.


> what is the model/make of the local bluetooth device (not mouse)?

It's a built-in bluetooth adapter in my Sony laptop:

ubt0: ALPS UGX, rev 1.10/11.68, addr 3
ubt0: ALPS UGX, rev 1.10/11.68, addr 3
ubt0: Interface 0 endpoints: interrupt=0x81, bulk-in=0x82, bulk-out=0x2
ubt0: Interface 1 (alt.config 5) endpoints: isoc-in=0x83, isoc-out=0x3; 
wMaxPacketSize=49; nframes=6, buffer size=294


> was buildworld still running?

Yes

> if buildworld was running can you tell what the load was?

I can't recall what the load was at the time, but the CPU was close to 
100% utilized.

> what scheduler are you using BSD or ULE?

ULE

> are you running with WITNESS enabled?

No.

> also how fast is the cpu on your machine?

1500MHZ.

Full dmesg, and other info here:

http://www.googlebit.com/freebsd/

Look for the most recent date.

>>>> [those were me trying to do commands to find my own bd_addr so I 
>>>> could follow your instructions on what to do next, but I kept 
>>>> getting timeouts]
>>>>
>>>> Oct  1 21:08:34 neutrino bthidd[13548]: Got signal 15, total number 
>>>> of signals 1
>>>>
>>>> [so then I killed bthidd]
>>>>
>>>> Oct  1 21:09:33 neutrino kernel: ubt0: detached
> 
> 
> ok, this is really bad. usb device should not just detach by itself 
> (unless you pull it out).

Actually, that was me flipping the switch (enable/disable wireless, 
including bluetooth) on the laptop.

>>>> [and tried unloading the modules so I could reload them]
>>>>
>>>> The next step was a 'kldunload vkbd' which caused an instant reboot 
>>>> of my system.
> 
> 
> ok, i will look into this.
> 
>>>> Here's a typescript from what I was doing - it's truncated at the 
>>>> bottom because (I believe) it had not synced the blocks to disk 
>>>> before the instant reboot:
> 
> 
> it somewhat hard to read :(

Yea, sorry - with no mouse, I could not copy/paste the xterm session 
easily, so a cat | mail ... etc had to work. :)


>>>> hccontrol -n ubt0hci read_connection_list
>>>> Remote BD_ADDR    Handle Type Mode Role Encrypt Pending Queue State
>>>> mouse                 42  ACL    2 MAST    NONE       2     0 OPEN
> 
> 
> hmm... local device thinks that it still has connection to the mouse
> 
>>>> l2control -a hccontrol -n ubt0hci inquiry
>>>> l2control: hccontrol: Unknown host
> 
> 
> ?? i'm not really sure what were you trying to do here. to read BD_ADDR 
> of local device just do
> 
> hccontrol -n ubt0hci read_bd_addr

Ok - that's all I was trying to do. Thanks!


>>>> [ 21:06:52 root at neutrino 
>>>> ~/bt ]# -su: btcontrol: command not found
>>>> bash: -su:: command not found
> 
> 
> ???
> 
>>>> [ 21:06:52 root at neutrino 
>>>> ~/bt ]# [ 20:56:00 root at neutrino ~/bt ]# 
>>>> hccontrol -n ubt0hci read_connection_list
>>>> bash: [: missing `]'
> 
> 
> ???

It's a typescript, so you see all my mistakes too :)

>>>> hccontrol -n ubto0hci inquiry
>>>> Could not execute command "inquiry". Operation timed out
> 
> 
> seems like typo. 'ubto0hci' instead of 'ubt0hci'

Woops.  However, I think it gave a timeout error using the right name 
anyhow.

>>>> /etc/rc.bluetooth stop
>>>> Usage:
>>>>   /etc/rc.bluetooth start device
>>>> or
>>>>   /etc/rc.bluetooth stop device
> 
> 
> ???
> 
>>>> /etc/rc.bluetooth stop ubt0
>>>> /etc/rc.bluetooth stop ubt0
> 
> 
> why issue the command twice?

Thought possibly the second run would give me a warning that it wasn't 
started, if the stop had successfully worked the first time.


>>>> /etc/rc.bluetooth start ubt0
>>>> Could not execute command "reset". Operation timed out
> 
> 
> this usually mean that communication between local bluetooth device and 
> the local stack is broken. it could be that local device already 
> detached it self (as shown in your /var/log/messages).
> 
>>>> kldstat
>>>> Id Refs Address    Size     Name
>>>>  1   37 0xc0400000 4e3420   kernel
>>>>  2    1 0xc08e4000 56c8     vesa.ko
>>>>  3    2 0xc08ea000 1c6c8    linux.ko
>>>>  4    1 0xc0907000 5e28     snd_ich.ko
>>>>  5    2 0xc090d000 244e0    sound.ko
>>>>  6    7 0xc0932000 22258    usb.ko
>>>>  7    1 0xc0955000 5df8     ugen.ko
>>>>  8    1 0xc095b000 4098     ums.ko
>>>>  9    1 0xc0960000 7a38     umass.ko
>>>> 10    1 0xc0968000 4344     acpi_video.ko
>>>> 11    1 0xc096d000 1e530    radeon.ko
>>>> 12    2 0xc098c000 10eec    drm.ko
>>>> 13    1 0xc099d000 2720     acpi_sony.ko
>>>> 14    1 0xc09a0000 2d90     wlan_wep.ko
>>>> 15    1 0xc09a3000 942c     cpufreq.ko
>>>> 16    6 0xc09ad000 d900     netgraph.ko
>>>> 17    1 0xc09bb000 80c4     ng_ubt.ko
>>>> 18    1 0xc09c4000 68cc     vkbd.ko
>>>> 19    1 0xc2718000 6000     linprocfs.ko
>>>> 20    4 0xc2a34000 2000     ng_bluetooth.ko
>>>> 21    1 0xc2a36000 d000     ng_hci.ko
>>>> 22    1 0xc2a43000 10000    ng_l2cap.ko
>>>> 23    1 0xc2a5c000 19000    ng_btsocket.ko
>>>> 24    1 0xc2a77000 4000     ng_socket.ko
>>>> 25    1 0xc6cb8000 5000     geom_label.ko
> 
> 
> that looks fine
> 
>>>> kldunload ng_socket
>>>> kldunload: can't unload file: Device busy
> 
> 
>  >>> kldunload  ng_btsocket
>  >>> kldunload: can't unload file: Device busy
> 
> you can not unload ng_{k,bt}socket modules. freebsd does not yet allow 
> to unload protocol families.
> 
> the rest of the script is not very interesting. basically, you do not 
> have to kldunload/kldload modules. just rc.bluetooth stop/start should 
> be enough to reset stack to its default state.

Ok - however doing the stop/start didn't seem to do anything for me.


>>>> And now, even after reboot, I can no longer see by bluetooth mouse.
> 
> 
> strange. does BD_ADDR of the mouse appears in /var/db/bthidd.hids file? 
> if yes, then do

Yes, it is indeed in there, and I tried the 'forget', but got the timeout.

> 1) bthidcontrol -a BD_ADDR_of_the_mouse forget
> 2) press 'connect' button on your mouse
> 3) restart bthidd(8)
> 
> note: depending on your mouse you may or may not need to run hcsecd(8). 
> if your mouse requires authentication please look at mouse manual for 
> pin code etc.

Doesn't seem to need it.

>> I'm trying a different bluetooth mouse now, just in case.
> 
> 
> i doubt mouse is the problem
> 
>> However, I see this in my dmesg output, when I can't use bluetooth:
>>
>> ng_hci_process_command_timeout: ubt0hci - unable to complete HCI 
>> command OGF=0x3, OCF=0x3. Timeout
>>
>> Can you give me a clue as to what that is really telling me?
> 
> 
> the line above tells you that host (freebsd) tried to send hci command 
> with OGF=0x3 (group field) and OCF=0x3 (command field) to the bluetooth 
> device ubt0 via ubt0hci netgraph node and this request has timed out.
> 
> hci command with OGF=0x3 (group field) and OCF=0x3 means "Reset" which 
> is the first command rc.bluetooth script will send to the device. 
> possible reasons for timeout:
> 
> 1) device is not present
> 2) communication between device and the host is broken (at usb level)
> 3) stack was not setup correctly
> 
> you can run
> 
> # ngctl li
> 
> to see what netgraph nodes are present and if they are connected. for 
> example, on my system
> 
> # ngctl li
> There are 7 total nodes:
>   Name: ngctl19807      Type: socket          ID: 00000023   Num hooks: 0
>   Name: ubt0l2cap       Type: l2cap           ID: 0000001d   Num hooks: 3
>   Name: ubt0hci         Type: hci             ID: 00000019   Num hooks: 3
>   Name: ubt0            Type: ubt             ID: 00000015   Num hooks: 1
>   Name: btsock_l2c      Type: btsock_l2c      ID: 00000005   Num hooks: 1
>   Name: btsock_l2c_raw  Type: btsock_l2c_raw  ID: 00000004   Num hooks: 1
>   Name: btsock_hci_raw  Type: btsock_hci_raw  ID: 00000003   Num hooks: 1
> 
> "ubt0" node (type ubt) is the device driver node. if you see "num hooks" 
>  set to 1 then node is connected to the stack.
> 
> "ubt0hci" node (type hci) is the hci node for ubt0 device. if you see 
> "num hooks" set to 3 then everything should be fine.
> 
> "ubt0l2cap" is similar to "ubt0hci" except its l2cap node.
> 
> 
> so far, the only thing i see is that communication between bluetooth 
> device and the host was broken. at this point, i can not tell exactly 
> why this happened. the only thing i can suggest is to run
> 
> # hcidump -w dump.file
> 
> while doing buildword and using bluetooth mouse. then when things start 
> to go bad terminate hcidump and send me dump.file

Ok - I'll give this a try.

Thanks for the help!
Eric



-- 
------------------------------------------------------------------------
Eric Anderson        Sr. Systems Administrator        Centaur Technology
Anything that works is better than anything that doesn't.
------------------------------------------------------------------------


More information about the freebsd-bluetooth mailing list