Date: Tue, 04 Oct 2005 10:30:08 -0700 From: Maksim Yevmenkin <maksim.yevmenkin@savvis.net> To: Eric Anderson <anderson@centtech.com> Cc: freebsd-bluetooth@freebsd.org Subject: Re: Bluetooth mouse breaks on -current Message-ID: <4342BC20.8000001@savvis.net> In-Reply-To: <43427296.6090404@centtech.com> References: <431F388E.2010204@centtech.com> <43217D56.3050508@centtech.com> <4321D6C4.6050300@savvis.net> <432AC7E9.5060206@centtech.com> <433F4B50.1050108@centtech.com> <433F62F7.3060607@centtech.com> <43427296.6090404@centtech.com>
next in thread | previous in thread | raw e-mail | index | archive | help
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.
>>> [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.
what is the model/make of the local bluetooth device (not mouse)?
was buildworld still running?
if buildworld was running can you tell what the load was?
what scheduler are you using BSD or ULE?
are you running with WITNESS enabled?
also how fast is the cpu on your machine?
>>> [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).
>>> [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 :(
>>> 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
>>> [1;1m[ [0m[1;32m21:06:52 [0m[1;1mroot@neutrino
>>> [0m[1;32m~/bt[0m[1;1m ]#[0m -su: btcontrol: command not found
>>> bash: -su:: command not found
???
>>> [1;1m[ [0m[1;32m21:06:52 [0m[1;1mroot@neutrino
>>> [0m[1;32m~/bt[0m[1;1m ]#[0m [ 20:56:00 root@neutrino ~/bt ]#
>>> hccontrol -n ubt0hci read_connection_list
>>> bash: [: missing `]'
???
>>> hccontrol -n ubto0hci inquiry
>>> Could not execute command "inquiry". Operation timed out
seems like typo. 'ubto0hci' instead of 'ubt0hci'
>>> /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?
>>> /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.
>>> 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
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.
> 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
thanks,
max
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?4342BC20.8000001>