Summary: | >=net-wireless/bluez-5: bluetooth is not automatically initialized (?) | ||
---|---|---|---|
Product: | Gentoo Linux | Reporter: | P Purkayastha <ppurka> |
Component: | [OLD] Core system | Assignee: | Pacho Ramos <pacho> |
Status: | RESOLVED UPSTREAM | ||
Severity: | normal | CC: | manday, openhs |
Priority: | Normal | ||
Version: | unspecified | ||
Hardware: | All | ||
OS: | Linux | ||
URL: | https://wiki.archlinux.org/index.php/bluetooth#hcitool_scan:_Device_not_found | ||
Whiteboard: | |||
Package list: | Runtime testing required: | --- | |
Attachments: | dmesg output |
Description
P Purkayastha
2014-03-22 16:16:20 UTC
Created attachment 373268 [details]
dmesg output
This gets worse. There is no initialization even on suspend/resume. The previous instance I had this problem was fixed several months ago by this kernel patch: http://www.spinics.net/lists/linux-usb/msg94547.html Here is some more info. 1. the output of udevadm --debug test before and after initialization /tmp» udevadm --debug test /sys/class/bluetooth # BEFORE INITIALIZATION ....<snip>.... read rules file: /lib64/udev/rules.d/99-pcscd-hotplug.rules rules contain 393216 bytes tokens (32768 * 12 bytes), 26696 bytes strings 25419 strings (206728 bytes), 22442 de-duplicated (183010 bytes), 2978 trie nodes used device 0x206f8c0 has devpath '/class/bluetooth' no db file to read /run/udev/data/+subsystem:bluetooth: No such file or directory unload module index This program is for debugging only, it does not run any program specified by a RUN key. It may show incorrect results, because some values may be different, or not available at a simulation run. ACTION=add DEVPATH=/class/bluetooth SUBSYSTEM=subsystem UDEV_LOG=7 USEC_INITIALIZED=53715772187 /tmp» udevadm --debug test /sys/class/bluetooth # AFTER INITIALIZATION ... <snip>... read rules file: /lib64/udev/rules.d/99-pcscd-hotplug.rules rules contain 393216 bytes tokens (32768 * 12 bytes), 26696 bytes strings 25419 strings (206728 bytes), 22442 de-duplicated (183010 bytes), 2978 trie nodes used device 0x79c8c0 has devpath '/class/bluetooth' no db file to read /run/udev/data/+subsystem:bluetooth: No such file or directory unload module index This program is for debugging only, it does not run any program specified by a RUN key. It may show incorrect results, because some values may be different, or not available at a simulation run. ACTION=add DEVPATH=/class/bluetooth SUBSYSTEM=subsystem UDEV_LOG=7 USEC_INITIALIZED=54501558297 2. The output of the same when run on hidraw before and after. /tmp» udevadm --debug test /sys/class/hidraw/hidraw0 # BEFORE INITIALIZATION ...<snip rules files>... read rules file: /lib64/udev/rules.d/99-pcscd-hotplug.rules rules contain 393216 bytes tokens (32768 * 12 bytes), 26696 bytes strings 25419 strings (206728 bytes), 22442 de-duplicated (183010 bytes), 2978 trie nodes used unable to open device '/sys/class/hidraw/hidraw0' unload module index /tmp» udevadm --debug test /sys/class/hidraw/hidraw0 # AFTER INITIALIZATION ...<snip rules files>... read rules file: /lib64/udev/rules.d/99-pcscd-hotplug.rules rules contain 393216 bytes tokens (32768 * 12 bytes), 26696 bytes strings 25419 strings (206728 bytes), 22442 de-duplicated (183010 bytes), 2978 trie nodes used device 0x6578c0 has devpath '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/0005:046D:B009.0005/hidraw/hidraw0' device 0x64ddc0 filled with db file data device 0x68ab70 has devpath '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/0005:046D:B009.0005' device 0x689890 has devpath '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35' device 0x68b1d0 has devpath '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0' device 0x68b5b0 has devpath '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0' device 0x68b990 has devpath '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5' device 0x68bd70 has devpath '/devices/pci0000:00/0000:00:1d.0/usb2/2-1' device 0x68c150 has devpath '/devices/pci0000:00/0000:00:1d.0/usb2' device 0x68c530 has devpath '/devices/pci0000:00/0000:00:1d.0' device 0x68c910 has devpath '/devices/pci0000:00' handling device node '/dev/hidraw0', devnum=c249:0, mode=0600, uid=0, gid=0 preserve permissions /dev/hidraw0, 020600, uid=0, gid=0 preserve already existing symlink '/dev/char/249:0' to '../hidraw0' created empty file '/run/udev/data/c249:0' for '/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/0005:046D:B009.0005/hidraw/hidraw0' unload module index This program is for debugging only, it does not run any program specified by a RUN key. It may show incorrect results, because some values may be different, or not available at a simulation run. ACTION=add DEVNAME=/dev/hidraw0 DEVPATH=/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/0005:046D:B009.0005/hidraw/hidraw0 MAJOR=249 MINOR=0 SUBSYSTEM=hidraw UDEV_LOG=7 USEC_INITIALIZED=54414889105 3. The output of udevadm monitor during the add of device: /tmp» udevadm monitor |& tee -i -a udevadm.log ^Cmonitor will print the received events for: UDEV - the event which udev sends out after rule processing KERNEL - the kernel uevent KERNEL[54294.932123] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35 (bluetooth) UDEV [54294.933384] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35 (bluetooth) KERNEL[54294.977262] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/0005:046D:B009.0005 (hid) KERNEL[54294.977593] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/input27 (input) KERNEL[54294.977707] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/input27/mouse1 (input) KERNEL[54294.977772] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/input27/event13 (input) KERNEL[54294.977827] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/0005:046D:B009.0005/hidraw/hidraw0 (hidraw) UDEV [54294.978245] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/0005:046D:B009.0005 (hid) UDEV [54294.978799] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/input27 (input) UDEV [54294.978910] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/0005:046D:B009.0005/hidraw/hidraw0 (hidraw) UDEV [54294.979590] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/input27/mouse1 (input) UDEV [54294.979938] add /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.5/2-1.5:1.0/bluetooth/hci0/hci0:35/input27/event13 (input) 4. The output of dmesg on suspend-resume cycle: [52690.370497] usb 3-1: USB disconnect, device number 3 [52697.333180] wlp1s0: deauthenticating from e8:40:f2:48:3b:39 by local choice (reason=3) [52697.358817] cfg80211: Calling CRDA to update world regulatory domain [52697.361116] cfg80211: World regulatory domain updated: [52697.361120] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) [52697.361123] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) [52697.361126] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) [52697.361128] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) [52697.361130] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) [52697.361132] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) [52697.717659] usbcore: deregistering interface driver uvcvideo [52698.034252] PM: Syncing filesystems ... done. [52698.045875] PM: Preparing system for mem sleep [52698.045952] Freezing user space processes ... (elapsed 0.001 seconds) done. [52698.047292] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done. [52698.048432] PM: Entering mem sleep [52698.048479] Suspending console(s) (use no_console_suspend to debug) [52698.048701] sd 0:0:0:0: [sda] Synchronizing SCSI cache [52698.048732] sd 0:0:0:0: [sda] Stopping disk [52698.261271] mei_me 0000:00:16.0: suspend [52699.477092] PM: suspend of devices complete after 1426.907 msecs [52699.477206] PM: late suspend of devices complete after 0.112 msecs [52699.477701] ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI [52699.490473] ehci-pci 0000:00:1a.0: System wakeup enabled by ACPI [52699.517084] xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI [52699.530426] PM: noirq suspend of devices complete after 53.155 msecs [52699.531316] ACPI: Preparing to enter system sleep state S3 [52699.532041] PM: Saving platform NVS memory [52699.532429] Disabling non-boot CPUs ... [52699.633818] smpboot: CPU 1 is now offline [52699.737303] smpboot: CPU 2 is now offline [52699.840734] smpboot: CPU 3 is now offline [52699.842214] ACPI: Low-level resume complete [52699.842259] PM: Restoring platform NVS memory [52699.842677] CPU0: Thermal monitoring handled by SMI [52699.842685] Enabling non-boot CPUs ... [52699.842719] smpboot: Booting Node 0 Processor 1 APIC 0x1 [52699.854351] CPU1: Thermal monitoring handled by SMI [52699.856580] Intel pstate controlling: cpu 1 [52699.856630] CPU1 is up [52699.856643] smpboot: Booting Node 0 Processor 2 APIC 0x2 [52699.868243] CPU2: Thermal monitoring handled by SMI [52699.870488] Intel pstate controlling: cpu 2 [52699.870519] CPU2 is up [52699.870532] smpboot: Booting Node 0 Processor 3 APIC 0x3 [52699.882132] CPU3: Thermal monitoring handled by SMI [52699.884288] Intel pstate controlling: cpu 3 [52699.884318] CPU3 is up [52699.888316] ACPI: Waking up from system sleep state S3 [52699.922559] xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI [52699.949260] ehci-pci 0000:00:1a.0: System wakeup disabled by ACPI [52699.975951] ehci-pci 0000:00:1d.0: System wakeup disabled by ACPI [52699.989715] PM: noirq resume of devices complete after 92.026 msecs [52699.989821] PM: early resume of devices complete after 0.083 msecs [52699.989858] i915 0000:00:02.0: setting latency timer to 64 [52699.989861] xhci_hcd 0000:00:14.0: setting latency timer to 64 [52699.989879] mei_me 0000:00:16.0: irq 41 for MSI/MSI-X [52699.989949] ahci 0000:00:1f.2: setting latency timer to 64 [52699.990009] ehci-pci 0000:00:1a.0: setting latency timer to 64 [52699.990092] snd_hda_intel 0000:00:1b.0: irq 44 for MSI/MSI-X [52699.990139] ehci-pci 0000:00:1d.0: setting latency timer to 64 [52700.096085] dpm_run_callback(): pnp_bus_resume+0x0/0xa0 returns -19 [52700.096086] PM: Device 00:06 failed to resume: error -19 [52700.193018] usb 2-1.5: reset full-speed USB device number 3 using ehci-pci [52700.279214] btusb 2-1.5:1.0: no reset_resume for driver btusb? [52700.279218] btusb 2-1.5:1.1: no reset_resume for driver btusb? [52700.309662] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300) [52700.312552] ata1.00: configured for UDMA/133 [52700.323041] sd 0:0:0:0: [sda] Starting disk [52700.343107] usb 1-1.5: reset high-speed USB device number 3 using ehci-pci [52700.780305] usb 3-2: reset high-speed USB device number 2 using xhci_hcd [52700.793913] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802353b1a80 [52700.793915] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802353b1ac0 [52700.794142] PM: resume of devices complete after 803.399 msecs [52701.185442] PM: Finishing wakeup. [52701.185444] Restarting tasks ... done. [52701.192313] video LNXVIDEO:00: Restoring backlight state [52701.206755] uvcvideo: Found UVC 1.00 device Laptop_Integrated_Webcam_1.3M (1bcf:288f) [52701.287634] input: Laptop_Integrated_Webcam_1.3M as /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.5/1-1.5:1.0/input/input21 [52701.288071] usbcore: registered new interface driver uvcvideo [52701.288076] USB Video Class driver (1.1.1) [52701.303126] Intel(R) Wireless WiFi driver for Linux, in-tree:d [52701.303129] Copyright(c) 2003-2013 Intel Corporation [52701.303284] iwlwifi 0000:01:00.0: can't disable ASPM; OS doesn't have ASPM control [52701.303460] iwlwifi 0000:01:00.0: irq 45 for MSI/MSI-X [52701.304595] iwlwifi 0000:01:00.0: loaded firmware version 18.168.6.1 op_mode iwldvm [52701.306353] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEBUG enabled [52701.306359] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEBUGFS disabled [52701.306363] iwlwifi 0000:01:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled [52701.306367] iwlwifi 0000:01:00.0: Detected Intel(R) Centrino(R) Advanced-N 6235 AGN, REV=0xB0 [52701.306501] iwlwifi 0000:01:00.0: L1 Enabled; Disabling L0S [52701.311691] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input22 [52701.322599] ieee80211 phy2: Selected rate control algorithm 'iwl-agn-rs' [52701.344223] systemd-udevd[6503]: renamed network interface wlan0 to wlp1s0 [52701.389527] iwlwifi 0000:01:00.0: L1 Enabled; Disabling L0S [52701.396515] iwlwifi 0000:01:00.0: Radio type=0x2-0x1-0x0 [52701.534379] [drm] Enabling RC6 states: RC6 on, RC6p on, RC6pp off [52701.676840] iwlwifi 0000:01:00.0: L1 Enabled; Disabling L0S [52701.683857] iwlwifi 0000:01:00.0: Radio type=0x2-0x1-0x0 [52708.142814] wlp1s0: authenticate with e8:40:f2:48:3b:39 [52708.145621] wlp1s0: send auth to e8:40:f2:48:3b:39 (try 1/3) [52708.148303] wlp1s0: authenticated [52708.148559] wlp1s0: associate with e8:40:f2:48:3b:39 (try 1/3) [52708.152359] wlp1s0: RX AssocResp from e8:40:f2:48:3b:39 (capab=0x411 status=0 aid=8) [52708.174294] wlp1s0: associated I have this usb<->bluetooth dongle, and a Nokia phone, and I just tried plugging it in and then enabling the phone with BlueZ 5, and I immediately got results I expected, and was able to transfer the files as normal I really don't understand what you tried to say with those examples. What exactly are you expecting udev to do here? > What exactly are you expecting udev to do here? I am expecting udev to behave the same as earlier, before the update. In my case, the earlier behavior was: 1. I boot the machine (or I resume the machine from suspend). It has inbuilt bluetooth. 2. My bluetooth mouse, that is already turned on and paired a year ago, starts working immediately in X without *any* need for me to do further configuration or interaction. Current behavior is: 1. I boot the machine (or resume from suspend). 2. The bluetooth mouse doesn't work because it is not visible to the system. 3. I have to manually enter the command "hciconfig hci0 up" and then the mouse starts working within 2-3 seconds. I paired the mouse with this machine a year ago, and this is the second time it doesn't automatically work - the previous instance was a problem with the kernel. I documented my bluetooth mouse setup here: https://plus.google.com/115114386497793444118/posts/WbpwLnR9kdY I wonder if this is related to bug 461828 (In reply to Samuli Suominen from comment #5) > I wonder if this is related to bug 461828 I don't think that is relevant. I do not have that variable, but there is a different one: ~» zgrep -i uevent /proc/config.gz CONFIG_UEVENT_HELPER_PATH="/sbin/hotplug" # CONFIG_DM_UEVENT is not set ~» uname -r 3.12.13-gentoo ~» l /sbin/hotplug ls: cannot access /sbin/hotplug: No such file or directory ~ [2] » eix -e udev [I] sys-fs/udev Available versions: 208^t 212-r1^t **9999^t {acl doc +firmware-loader gudev introspection +kmod +openrc selinux static-libs ABI_MIPS="n32 n64 o32" ABI_X86="32 64 x32"} Installed versions: 212-r1^t(12:25:51 AM 05/11/2014)(acl firmware-loader gudev kmod -doc -introspection -selinux -static-libs ABI_MIPS="-n32 -n64 -o32" ABI_X86="64 -32 -x32") Homepage: http://www.freedesktop.org/wiki/Software/systemd Description: Linux dynamic and persistent device naming support (aka userspace devfs) [I] virtual/udev Available versions: 208-r1 ~208-r2 {gudev introspection +kmod selinux static-libs ABI_MIPS="n32 n64 o32" ABI_X86="32 64 x32"} Installed versions: 208-r1(09:51:09 AM 03/22/2014)(gudev kmod -introspection -selinux -static-libs ABI_MIPS="-n32 -n64 -o32" ABI_X86="64 -32 -x32") Description: Virtual to select between sys-fs/udev and sys-fs/eudev Found 2 matches. I am now convinced this is a bug in bluez-5. 1. First, I downgraded to bluez-4 and everything worked just like before - there was no need to run hciconfig. (However, I can not use bluez4 because of other problems with getting audio to work over bluetooth). 2. According to this arch wiki link: https://wiki.archlinux.org/index.php/Bluetooth_Headset#Pairing_works.2C_but_connecting_does_not we need to add a udev rule to make sure that the bluetooth device is initialized: ----------------- After a reboot, your bluetooth adapter will not power on by default. You need to add a udev rule to power it on: /etc/udev/rules.d/10-local.rules # Set bluetooth power up ACTION=="add", SUBSYSTEM=="bluetooth", KERNEL=="hci[0-9]*", RUN+="/usr/bin/hciconfig %k up" ------------------ Doesn't such a global rule imply that our battery users will get bluetooth up even if they don't want to use it? (In reply to Michał Górny from comment #8) > Doesn't such a global rule imply that our battery users will get bluetooth > up even if they don't want to use it? Not really. If you don't want to enable bluetooth, then simply blacklist the bluetooth module. The above "global rule" was the default earlier. It looks like a regression in bluez5 to me at present. such rule should be part of net-wireless/bluez as the rule would be bluez specific, so reassigning to bluez maintainers This should be discussed and suggested to upstream directly: http://www.bluez.org/development/lists/ As they are really involved with systemd/udev world and we are using their "canonical" way of starting bluetoothd It would have been useful if I could actually post to the mailing list. I sent a long email more than a day ago and it never came up in the mailing list. Now, looking at gmane, I see the following: http://dir.gmane.org/gmane.linux.bluez.kernel Address linux-bluetooth@... Status posting isn't allowed And yet, the bluez page lists this very mailing list as the place to contact the developers. Frustrating, to say the least. Did you subscribe to the list? That would explain why wasn't sent :/ Yes. I subscribed to the list. Waited a couple of days, and then sent the email. Anyway, I asked in #bluez-users, and there seems to be no interest in fixing this. Transcript follows: ppurka: Can some developer please look at this Gentoo bug report? https://bugs.gentoo.org/show_bug.cgi?id=505362 ppurka: Basically, bluez5 does not initialize the hardware of system boot or after a suspend/resume cycle. ppurka: I tried emailing the linux-bluetooth ML, but it never appeared on the ML. My system configuration and other details are present in the bug report. This is a regression with respect to bluez4. jhe: ppurka1: it won't help much to report this as it's not something that'd be news to the project jhe: ppurka1: moving the power on/off responsibility outside of BlueZ was a conscious choice, and most GUIs supporting BlueZ 5 (e.g. GNOME and KDE) handle this just fine ppurka: jhe: actually, KDE's bluedevil simply complains that bluetooth is not completely initialized, and offers to "fix" it. This is still a manual process. ppurka: jhe: http://i.imgur.com/6ZWHOxE.jpg this is what I mean by "manual process" jhe: ppurka: no idea what KDE means by "not completely enabled" or how it pretends to fix it, however the logs you referred to earlier showed nothing else except a properly initialized adapter that just wasn't powered on yet Try reporting to: https://bugzilla.kernel.org/enter_bug.cgi?product=Drivers (Component -> bluetooth) (In reply to Pacho Ramos from comment #15) > Try reporting to: > https://bugzilla.kernel.org/enter_bug.cgi?product=Drivers > > (Component -> bluetooth) I am not sure I want to do that. This does not seem like a kernel level bug. It appears to be a conscious decision by bluez devs to leave it up to the DE (it's possible they don't think beyond KDE and Gnome) to handle the initialization. Well, I remember bugs from that bugtracker are seen in bluetooth devel mailing list and I have seen them handled by the same developers (one of them is Bastien Nocera, that takes care of gnome-bluetooth and is also a bluez dev) My common sense is saying that bluetooth should be powered on by "/etc/init.d/bluetooth start" command and powered off by corresponding "stop" command. Perhaps it could be implemented in the init script as a configurable option for those who does not have DE that handles bluetooth. If that breaks the "canonical" way of starting bluetoothd then it can be mentioned in the comment above the configuration option and disabled by default. This will not solve suspend/resume scenario but I would say it is in responsibility of particular s/r helper to handle it. (For example hibernate-script should be adapted (by upstream) to handle powering on/off. Until then users can configure hibernate-script to simply restart the bluetooth service.) *** Bug 533832 has been marked as a duplicate of this bug. *** |