From owner-freebsd-bluetooth@FreeBSD.ORG Tue Oct 4 12:16:37 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 ED34216A41F for ; Tue, 4 Oct 2005 12:16:36 +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 705B043D4C for ; Tue, 4 Oct 2005 12:16:36 +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 j94CGZWL046876; Tue, 4 Oct 2005 07:16:35 -0500 (CDT) (envelope-from anderson@centtech.com) Message-ID: <43427296.6090404@centtech.com> Date: Tue, 04 Oct 2005 07:16:22 -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> In-Reply-To: <433F62F7.3060607@centtech.com> 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 12:16:37 -0000 Eric Anderson wrote: > Eric Anderson wrote: > >> Eric Anderson wrote: >> >>> Maksim Yevmenkin wrote: >>> >>>> Eric, >>>> >>>>>> Ok, I wish I could provide better information, but as of the last >>>>>> couple of weeks (2 weeks maybe?), I've had this weird problem with >>>>>> my bluetooth mouse (which had been working flawlessly until now). >>>>>> Right in the middle of use, my mouse will die. It will lose >>>>>> association (or whatever it's called). Actually, the mouse seems >>>>>> to be ok, as I've tried it on another computer and it works just >>>>>> fine with no changes. Once it dies, I have to muck with the >>>>>> bthidcontrol forget, reboot, etc, so I'm not sure what I do to fix >>>>>> it, but eventually it will be able to query the mouse again and >>>>>> then bthidd will connect and everything will be fine. >>>> >>>> >>>> >>>> >>>> >>>> very strange... i do not think i committed any significant change to >>>> the bluetooth code in a few months. >>>> >>>>>> One thing I've noticed, is that now, when doing an l2ping, I get >>>>>> this: >>>>>> # l2ping -a mouse >>>>>> 44 bytes from mouse seq_no=0 time=59990.660 ms result=0x23 >>>>>> Resource temporarily unavailable >>>>>> 44 bytes from mouse seq_no=1 time=59990.834 ms result=0x23 >>>>>> Resource temporarily unavailable >>>>>> 44 bytes from mouse seq_no=2 time=59990.821 ms result=0x23 >>>>>> Resource temporarily unavailable >>>>>> 44 bytes from mouse seq_no=3 time=59990.885 ms result=0x23 >>>>>> Resource temporarily unavailable >>>>>> 44 bytes from mouse seq_no=4 time=59990.879 ms result=0x23 >>>>>> Resource temporarily unavailable >>>>>> >>>>>> When my mouse is on or off. Also, pinging other devices, returns >>>>>> either the same result, or sometimes it will return ~5000ms >>>>>> returns, as if it can ping it, but it is slow - even when the >>>>>> device isn't powered on! >>>> >>>> >>>> >>>> >>>> >>>> i think its fine. what probably happens here is that bluetooth >>>> thinks there is an active baseband connection to the device, but for >>>> what ever reason no data is transferred (flow control issues?). >>>> l2ping has default timeout of 60 seconds (time=59990.879) after that >>>> msleep() call will timeout and return EAGAIN (35 decimal or 0x23) >>>> >>>>>> What do I need to do to help diagnose? >>>> >>>> >>>> >>>> >>>> >>>> when this happens please do >>>> >>>> # hccontrol -n ubt0hci read_connection_list >>>> >>>> # l2control -a read_connection_list >>>> >>>> # l2control -a read_channel_list >>>> >>>> # btsockstat >>>> >>>> and send me the output. note: means >>>> bd_addr of the device connected to the computer, not mouse. >>>> >>>>> Seems that rebooting my FreeBSD laptop clears it up - so I'm >>>>> thinking it has to do with the netgraph/bluetooth modules.. >>>> >>>> >>>> >>>> >>>> >>>> you probably right. if you have time, you could try to revert your >>>> src/ tree to, say, month ago and see if you still have the problem. >>>> using the few iterations you could find the date after which your >>>> mouse no longer works. this would help me a lot to figure out what >>>> change caused this. >>>> >>>> also i would like to know if anybody else has the same issues. >>> >>> >>> >>> >>> Just letting you know that I haven't had a problem since cvsuping src >>> and rebuilding world/kernel.. >> >> >> >> 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. >> >> 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 >> >> [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) >> >> [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 >> >> [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. >> >> 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: >> >> Script started on Sat Oct 1 20:56:25 2005 >> [ 20:56:25 root@neutrino >> ~/bt ]# 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 >> [ 20:56:37 root@neutrino >> ~/bt ]# l2control -a hccontrol -n ubt0hci >> inquiry >> l2control: hccontrol: Unknown host >> [ 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 `]' >> [ 21:06:52 root@neutrino >> ~/bt ]# hccontrol -n ubto0hci inquiry >> Could not execute command "inquiry". Operation timed out >> [ 21:07:14 root@neutrino >> ~/bt ]# /etc/rc.bluetooth stop >> Usage: >> /etc/rc.bluetooth start device >> or >> /etc/rc.bluetooth stop device >> [ 21:07:23 root@neutrino >> ~/bt ]# /etc/rc.bluetooth stop ubt0 >> [ 21:07:28 root@neutrino >> ~/bt ]# /etc/rc.bluetooth stop ubt0 >> [ 21:07:29 root@neutrino >> ~/bt ]# >> /etc/rc.bluetooth stop ubt0       art ubt0 >> Could not execute command "reset". Operation timed out >> [ 21:07:40 root@neutrino >> ~/bt ]# 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 >> [ 21:08:08 root@neutrino >> ~/bt ]# kldunload ng_socket >> kldunload: can't unload file: Device busy >> [ 21:08:24 root@neutrino >> ~/bt ]# kldunload ng_socket      >> btsocket >> kldunload: can't unload file: Device busy >> [ 21:08:29 root@neutrino >> ~/bt ]# killall bthidd >> [ 21:08:34 root@neutrino >> ~/bt ]# killall hcsed cd >> [ 21:08:38 root@neutrino >> ~/bt >> ]# killall >> hcsecdbthiddldunload ng_btsocketsocket >> kldunload: can't unload file: Device busy >> [ 21:08:40 root@neutrino >> ~/bt ]# >> kldunload ng_socketillall hcsecdbthiddldunload >> ng_btsocket >> kldunload: can't unload file: Device busy >> [ 21:08:42 root@neutrino >> ~/bt ]# kldunload ng_bluetooth >> [ 21:08:50 root@neutrino >> ~/bt ]# kldunload ng_bluetoothtsocketsocketillall >> hcsecdbthiddldunload ng_btsocketsocketstat >> >> Id Refs Address Size Name >> 1 >> >> [thats where it ends] >> >> And now, even after reboot, I can no longer see by bluetooth mouse. I'm trying a different bluetooth mouse now, just in case. 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? Eric -- ------------------------------------------------------------------------ Eric Anderson Sr. Systems Administrator Centaur Technology Anything that works is better than anything that doesn't. ------------------------------------------------------------------------