From owner-freebsd-bluetooth@FreeBSD.ORG Tue Oct 4 18:50:38 2005 Return-Path: X-Original-To: freebsd-bluetooth@freebsd.org Delivered-To: freebsd-bluetooth@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 8031716A422 for ; Tue, 4 Oct 2005 18:50:38 +0000 (GMT) (envelope-from anderson@centtech.com) Received: from mh1.centtech.com (moat3.centtech.com [207.200.51.50]) by mx1.FreeBSD.org (Postfix) with ESMTP id 7E89843D45 for ; Tue, 4 Oct 2005 18:50:33 +0000 (GMT) (envelope-from anderson@centtech.com) Received: from [10.177.171.220] (neutrino.centtech.com [10.177.171.220]) by mh1.centtech.com (8.13.1/8.13.1) with ESMTP id j94IoWat056519; Tue, 4 Oct 2005 13:50:32 -0500 (CDT) (envelope-from anderson@centtech.com) Message-ID: <4342CEEB.5010501@centtech.com> Date: Tue, 04 Oct 2005 13:50:19 -0500 From: Eric Anderson User-Agent: Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.7.11) Gecko/20050914 X-Accept-Language: en-us, en MIME-Version: 1.0 To: Maksim Yevmenkin 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> <4342BC20.8000001@savvis.net> In-Reply-To: <4342BC20.8000001@savvis.net> Content-Type: text/plain; charset=us-ascii; format=flowed Content-Transfer-Encoding: 7bit X-Virus-Scanned: ClamAV 0.82/1109/Mon Oct 3 17:06:28 2005 on mh1.centtech.com X-Virus-Status: Clean Cc: freebsd-bluetooth@freebsd.org Subject: Re: Bluetooth mouse breaks on -current X-BeenThere: freebsd-bluetooth@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Using Bluetooth in FreeBSD environments List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 04 Oct 2005 18:50:38 -0000 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@neutrino >>>> ~/bt ]# -su: btcontrol: command not found >>>> bash: -su:: command not found > > > ??? > >>>> [ 21:06:52 root@neutrino >>>> ~/bt ]# [ 20:56:00 root@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. ------------------------------------------------------------------------