[clug] bluetooth drops out

[Eyal Lebedinsky]

Looking again I see another sequence very often leading to this device
going down:

Jul 23 17:29:20 e7 kernel: [1933460.704052] hub 5-0:1.0: port 1 disabled by hub (EMI?), re-enabling...
Jul 23 17:29:20 e7 kernel: [1933460.704057] usb 5-1: USB disconnect, device number 125
Jul 23 17:29:20 e7 bluetoothd[1102]: HCI dev 0 down
Jul 23 17:29:20 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 down
... etc.

Possibly the 're-enabling...' does not always succeed.

Other times the disconnect is the first message in this event.

Eyal

On 07/23/12 19:31, eyal at pcug.org.au wrote:
> Every so often my bluetooth device drops out, and the only way to bring it
> back
> it to dis/re-connect it physically. This is a problem when I am not at
> home as
> happened recently when I way away for six weeks.
>
> I attach below the relevant log entries for a recent failure, as well as an
> example of a case where the device was automatically reconnected (happens
> a few
> time a day). Both cases were unattended,
>
> Is there a way to revive the system unattended? A cold usb bus re-scan maybe?
>
> This is a server (not a laptop) with a small USB bluetooth module running
> f16.
>
> TIA
>      Eyal
>
> === Here is a log from last night. This time the connection was
> re-established OK.
> Jul 22 22:18:56 e7 kernel: [1864436.954042] usb 5-1: USB disconnect, device number 123
> Jul 22 22:18:57 e7 kernel: [1864437.660024] usb 5-1: new full-speed USB device number 124 using uhci_hcd
> Jul 22 22:18:57 e7 bluetoothd[1102]: HCI dev 0 down
> Jul 22 22:18:57 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 down
> Jul 22 22:18:57 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been disabled
> Jul 22 22:18:57 e7 bluetoothd[1102]: HCI dev 0 unregistered
> Jul 22 22:18:57 e7 bluetoothd[1102]: Stopping hci0 event socket
> Jul 22 22:18:57 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been disabled
> Jul 22 22:18:57 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 unregistered
> Jul 22 22:18:57 e7 bluetoothd[1102]: bluetoothd[1102]: Stopping hci0 event socket
> Jul 22 22:18:57 e7 bluetoothd[1102]: Unregister path: /org/bluez/1102/hci0
> Jul 22 22:18:57 e7 bluetoothd[1102]: bluetoothd[1102]: Unregister path: /org/bluez/1102/hci0
> Jul 22 22:18:57 e7 kernel: [1864437.824282] usb 5-1: New USB device found, idVendor=0a12, idProduct=0001
> Jul 22 22:18:57 e7 kernel: [1864437.824286] usb 5-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> Jul 22 22:18:57 e7 bluetoothd[1102]: HCI dev 0 registered
> Jul 22 22:18:57 e7 bluetoothd[1102]: Listening for HCI events on hci0
> Jul 22 22:18:57 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 registered
> Jul 22 22:18:57 e7 bluetoothd[1102]: bluetoothd[1102]: Listening for HCI events on hci0
> Jul 22 22:18:57 e7 bluetoothd[1102]: HCI dev 0 up
> Jul 22 22:18:57 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 up
> Jul 22 22:18:58 e7 bluetoothd[1102]: Parsing /etc/bluetooth/serial.conf failed: No such file or directory
> Jul 22 22:18:58 e7 bluetoothd[1102]: bluetoothd[1102]: Parsing /etc/bluetooth/serial.conf failed: No such file or directory
> Jul 22 22:18:58 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been enabled
> Jul 22 22:18:58 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been enabled
> Jul 22 22:18:59 e7 dbus[1140]: [system] Rejected send message, 3 matched rules; type="error", sender=":1.71" (uid=500 pid=3232 comm="bluetooth-applet ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.0" (uid=0 pid=1102 comm="/usr/sbin/bluetoothd -n ")
> Jul 22 22:18:59 e7 dbus-daemon[1140]: dbus[1140]: [system] Rejected send message, 3 matched rules; type="error", sender=":1.71" (uid=500 pid=3232 comm="bluetooth-applet ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.0" (uid=0 pid=1102 comm="/usr/sbin/bluetoothd -n ")
> Jul 22 22:18:59 e7 systemd[1]: Service bluetooth.target is not needed > anymore. Stopping.
> Jul 22 22:20:05 e7 mythbackend[30508]: 2012-07-22 22:20:05.077308 WTFW(/var/lib/mythtv/2002_20120722215900.mpg:60): write(57528) cnt 19 total 1113148 -- took a long time, 1493 ms
> Jul 22 22:21:21 e7 dhcpd: DHCPREQUEST for 192.168.2.22 from 50:cc:f8:a4:5e:7d via eth1
> Jul 22 22:21:21 e7 dhcpd: DHCPACK on 192.168.2.22 to 50:cc:f8:a4:5e:7d via eth1
> Jul 22 22:23:15 e7 bluetoothd[1102]: HCI dev 0 down
> Jul 22 22:23:15 e7 kernel: [1864695.704059] usb 5-1: USB disconnect, device number 124
> Jul 22 22:23:15 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 down
> Jul 22 22:23:15 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been disabled
> Jul 22 22:23:15 e7 bluetoothd[1102]: HCI dev 0 unregistered
> Jul 22 22:23:15 e7 bluetoothd[1102]: Stopping hci0 event socket
> Jul 22 22:23:15 e7 bluetoothd[1102]: Unregister path: /org/bluez/1102/hci0
> Jul 22 22:23:15 e7 systemd[1]: Service bluetooth.target is not needed anymore. Stopping.
> Jul 22 22:23:15 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been disabled
> Jul 22 22:23:15 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 unregistered
> Jul 22 22:23:15 e7 bluetoothd[1102]: bluetoothd[1102]: Stopping hci0 event socket
> Jul 22 22:23:15 e7 bluetoothd[1102]: bluetoothd[1102]: Unregister path: /org/bluez/1102/hci0
> Jul 22 22:23:15 e7 dbus-daemon[1140]: dbus[1140]: [system] Rejected send message, 3 matched rules; type="error", sender=":1.71" (uid=500 pid=3232 comm="bluetooth-applet ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.0" (uid=0 pid=1102 comm="/usr/sbin/bluetoothd -n ")
> Jul 22 22:23:15 e7 dbus[1140]: [system] Rejected send message, 3 matched rules; type="error", sender=":1.71" (uid=500 pid=3232 comm="bluetooth-applet ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.0" (uid=0 pid=1102 comm="/usr/sbin/bluetoothd -n ")
> Jul 22 22:23:15 e7 kernel: [1864695.989015] usb 5-1: new full-speed USB device number 125 using uhci_hcd
> Jul 22 22:23:15 e7 kernel: [1864696.153265] usb 5-1: New USB device found, idVendor=0a12, idProduct=0001
> Jul 22 22:23:15 e7 kernel: [1864696.153270] usb 5-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> Jul 22 22:23:15 e7 bluetoothd[1102]: HCI dev 0 registered
> Jul 22 22:23:15 e7 bluetoothd[1102]: Listening for HCI events on hci0
> Jul 22 22:23:15 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 registered
> Jul 22 22:23:15 e7 bluetoothd[1102]: bluetoothd[1102]: Listening for HCI events on hci0
> Jul 22 22:23:16 e7 bluetoothd[1102]: HCI dev 0 up
> Jul 22 22:23:16 e7 bluetoothd[1102]: Parsing /etc/bluetooth/serial.conf failed: No such file or directory
> Jul 22 22:23:16 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 up
> Jul 22 22:23:16 e7 bluetoothd[1102]: bluetoothd[1102]: Parsing /etc/bluetooth/serial.conf failed: No such file or directory
> Jul 22 22:23:16 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been enabled
> Jul 22 22:23:16 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been enabled
> ============================
>
> === This is a log of a failure earlier this evening, after which I needed
> to un/plug the device.
> Jul 23 17:29:20 e7 kernel: [1933460.704052] hub 5-0:1.0: port 1 disabled
> by hub (EMI?), re-enabling...
> Jul 23 17:29:20 e7 kernel: [1933460.704057] usb 5-1: USB disconnect,
> device number 125
> Jul 23 17:29:20 e7 bluetoothd[1102]: HCI dev 0 down
> Jul 23 17:29:20 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 down
> Jul 23 17:29:20 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been
> disabled
> Jul 23 17:29:20 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter
> /org/bluez/1102/hci0 has been disabled
> Jul 23 17:29:20 e7 bluetoothd[1102]: HCI dev 0 unregistered
> Jul 23 17:29:20 e7 bluetoothd[1102]: Stopping hci0 event socket
> Jul 23 17:29:20 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 unregistered
> Jul 23 17:29:20 e7 bluetoothd[1102]: bluetoothd[1102]: Stopping hci0 event
> socket
> Jul 23 17:29:20 e7 systemd[1]: Service bluetooth.target is not needed
> anymore. Stopping.
> Jul 23 17:29:20 e7 kernel: [1933460.912028] usb 5-1: new full-speed USB
> device number 126 using uhci_hcd
> Jul 23 17:29:20 e7 bluetoothd[1102]: Unregister path: /org/bluez/1102/hci0
> Jul 23 17:29:20 e7 bluetoothd[1102]: bluetoothd[1102]: Unregister path:
> /org/bluez/1102/hci0
> Jul 23 17:29:20 e7 kernel: [1933461.076639] usb 5-1: New USB device found,
> idVendor=0a12, idProduct=0001
> Jul 23 17:29:20 e7 kernel: [1933461.076644] usb 5-1: New USB device
> strings: Mfr=0, Product=0, SerialNumber=0
> Jul 23 17:29:20 e7 bluetoothd[1102]: HCI dev 0 registered
> Jul 23 17:29:20 e7 bluetoothd[1102]: Listening for HCI events on hci0
> Jul 23 17:29:20 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 registered
> Jul 23 17:29:20 e7 bluetoothd[1102]: bluetoothd[1102]: Listening for HCI
> events on hci0
> Jul 23 17:29:21 e7 bluetoothd[1102]: HCI dev 0 up
> Jul 23 17:29:21 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 up
> Jul 23 17:29:21 e7 bluetoothd[1102]: Parsing /etc/bluetooth/serial.conf
> failed: No such file or directory
> Jul 23 17:29:21 e7 bluetoothd[1102]: bluetoothd[1102]: Parsing
> /etc/bluetooth/serial.conf failed: No such file or directory
> Jul 23 17:29:21 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been
> enabled
> Jul 23 17:29:21 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter
> /org/bluez/1102/hci0 has been enabled
> Jul 23 17:29:22 e7 kernel: [1933462.204050] usb 5-1: USB disconnect,
> device number 126
> Jul 23 17:29:22 e7 bluetoothd[1102]: HCI dev 0 down
> Jul 23 17:29:22 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been
> disabled
> Jul 23 17:29:22 e7 bluetoothd[1102]: HCI dev 0 unregistered
> Jul 23 17:29:22 e7 bluetoothd[1102]: Stopping hci0 event socket
> Jul 23 17:29:22 e7 bluetoothd[1102]: Unregister path: /org/bluez/1102/hci0
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 down
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter
> /org/bluez/1102/hci0 has been disabled
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 unregistered
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Stopping hci0 event
> socket
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Unregister path:
> /org/bluez/1102/hci0
> Jul 23 17:29:22 e7 systemd[1]: Service bluetooth.target is not needed
> anymore. Stopping.
> Jul 23 17:29:22 e7 kernel: [1933462.411027] usb 5-1: new full-speed USB
> device number 127 using uhci_hcd
> Jul 23 17:29:22 e7 kernel: [1933462.567669] usb 5-1: New USB device found,
> idVendor=0a12, idProduct=0001
> Jul 23 17:29:22 e7 kernel: [1933462.567673] usb 5-1: New USB device
> strings: Mfr=0, Product=0, SerialNumber=0
> Jul 23 17:29:22 e7 bluetoothd[1102]: HCI dev 0 registered
> Jul 23 17:29:22 e7 bluetoothd[1102]: Listening for HCI events on hci0
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 registered
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Listening for HCI
> events on hci0
> Jul 23 17:29:22 e7 bluetoothd[1102]: HCI dev 0 up
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 up
> Jul 23 17:29:22 e7 bluetoothd[1102]: Parsing /etc/bluetooth/serial.conf
> failed: No such file or directory
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Parsing
> /etc/bluetooth/serial.conf failed: No such file or directory
> Jul 23 17:29:22 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been
> enabled
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter
> /org/bluez/1102/hci0 has been enabled
> Jul 23 17:29:22 e7 kernel: [1933463.126053] usb 5-1: USB disconnect,
> device number 127
> Jul 23 17:29:22 e7 bluetoothd[1102]: HCI dev 0 down
> Jul 23 17:29:22 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been
> disabled
> Jul 23 17:29:22 e7 bluetoothd[1102]: HCI dev 0 unregistered
> Jul 23 17:29:22 e7 bluetoothd[1102]: Stopping hci0 event socket
> Jul 23 17:29:22 e7 bluetoothd[1102]: Unregister path: /org/bluez/1102/hci0
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 down
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter
> /org/bluez/1102/hci0 has been disabled
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 unregistered
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Stopping hci0 event
> socket
> Jul 23 17:29:22 e7 bluetoothd[1102]: bluetoothd[1102]: Unregister path:
> /org/bluez/1102/hci0
> Jul 23 17:29:22 e7 systemd[1]: Service bluetooth.target is not needed
> anymore. Stopping.
> Jul 23 17:29:23 e7 kernel: [1933463.670013] usb 5-1: new full-speed USB
> device number 2 using uhci_hcd
> Jul 23 17:29:23 e7 dbus[1140]: [system] Rejected send message, 3 matched
> rules; type="error", sender=":1.71" (uid=500 pid=3232
> comm="bluetooth-applet ") interface="(unset)" member="(unset)" error
> name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0"
> destination=":1.0" (uid=0 pid=1102 comm="/usr/sbin/bluetoothd -n ")
> Jul 23 17:29:23 e7 dbus-daemon[1140]: dbus[1140]: [system] Rejected send
> message, 3 matched rules; type="error", sender=":1.71" (uid=500 pid=3232
> comm="bluetooth-applet ") interface="(unset)" member="(unset)" error
> name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0"
> destination=":1.0" (uid=0 pid=1102 comm="/usr/sbin/bluetoothd -n ")
> Jul 23 17:29:23 e7 kernel: [1933464.186016] usb 5-1: device not accepting
> address 2, error -71
> Jul 23 17:29:24 e7 kernel: [1933464.288019] usb 5-1: new full-speed USB
> device number 3 using uhci_hcd
> Jul 23 17:29:24 e7 kernel: [1933464.444709] usb 5-1: New USB device found,
> idVendor=0a12, idProduct=0001
> Jul 23 17:29:24 e7 kernel: [1933464.444713] usb 5-1: New USB device
> strings: Mfr=0, Product=0, SerialNumber=0
> Jul 23 17:29:24 e7 bluetoothd[1102]: HCI dev 0 registered
> Jul 23 17:29:24 e7 bluetoothd[1102]: Listening for HCI events on hci0
> Jul 23 17:29:24 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 registered
> Jul 23 17:29:24 e7 bluetoothd[1102]: bluetoothd[1102]: Listening for HCI
> events on hci0
> Jul 23 17:29:44 e7 bluetoothd[21249]: Can't init device hci0: Connection
> timed out (110)
> Jul 23 17:29:44 e7 bluetoothd[1102]: bluetoothd[21249]: Can't init device
> hci0: Connection timed out (110)
> === later a plug-out
> Jul 23 17:46:57 e7 bluetoothd[1102]: HCI dev 0 unregistered
> Jul 23 17:46:57 e7 bluetoothd[1102]: Stopping hci0 event socket
> Jul 23 17:46:57 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 unregistered
> Jul 23 17:46:57 e7 bluetoothd[1102]: bluetoothd[1102]: Stopping hci0 event
> socket
> Jul 23 17:46:57 e7 kernel: [1934517.454042] usb 5-1: USB disconnect,
> device number 3
> Jul 23 17:46:57 e7 systemd[1]: Service bluetooth.target is not needed
> anymore. Stopping.
> === and a plug-in
> Jul 23 17:47:01 e7 kernel: [1934521.876018] usb 5-1: new full-speed USB
> device number 4 using uhci_hcd
> Jul 23 17:47:01 e7 kernel: [1934522.134050] usb 5-1: New USB device found,
> idVendor=0a12, idProduct=0001
> Jul 23 17:47:01 e7 kernel: [1934522.134055] usb 5-1: New USB device
> strings: Mfr=0, Product=0, SerialNumber=0
> Jul 23 17:47:01 e7 bluetoothd[1102]: HCI dev 0 registered
> Jul 23 17:47:01 e7 bluetoothd[1102]: Listening for HCI events on hci0
> Jul 23 17:47:01 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 registered
> Jul 23 17:47:01 e7 bluetoothd[1102]: bluetoothd[1102]: Listening for HCI
> events on hci0
> Jul 23 17:47:02 e7 bluetoothd[1102]: HCI dev 0 up
> Jul 23 17:47:02 e7 bluetoothd[1102]: bluetoothd[1102]: HCI dev 0 up
> Jul 23 17:47:02 e7 bluetoothd[1102]: Parsing /etc/bluetooth/serial.conf
> failed: No such file or directory
> Jul 23 17:47:02 e7 bluetoothd[1102]: bluetoothd[1102]: Parsing
> /etc/bluetooth/serial.conf failed: No such file or directory
> Jul 23 17:47:02 e7 bluetoothd[1102]: Adapter /org/bluez/1102/hci0 has been
> enabled
> Jul 23 17:47:02 e7 bluetoothd[1102]: bluetoothd[1102]: Adapter
> /org/bluez/1102/hci0 has been enabled
> ============================
>
>

-- 
Eyal Lebedinsky	(eyal at eyal.emu.id.au)