[Pkg-bluetooth-maintainers] Bug#632960: bluetooth: Bluetoothd dies after restoring from hibernate PM

Thu Jul 7 11:49:19 UTC 2011

Package: bluetooth
Version: 4.94-2
Severity: important

Hi,

I'm experimenting sometime trouble with bluetoothd...

As I'm using a bluetooth mouse, I need it most of the time !

I'm using hibernation feature to turn my computer off.

After restarting, the bluetooth doesn't work anymore unless I restart
bluetoothd manually ! It does not happen every time, but 1-2 time for 3 restarts...

There are no significant log as you can see or I missed something :
[17123.943571] wlan0: deauthenticating from 00:21:29:ec:72:b1 by local choice
(reason=3)
[17123.968150] cfg80211: Calling CRDA to update world regulatory domain
[17127.316422] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[17137.486305] sky2 0000:04:00.0: eth0: disabling interface
[17138.762071] EXT4-fs (sda3): re-mounted. Opts: errors=remount-ro,commit=0
[17139.098872] EXT4-fs (sda6): re-mounted. Opts: acl,commit=0
[17139.260058] EXT4-fs (sda5): re-mounted. Opts: commit=0
[17140.974547] PM: Marking nosave pages: 000000000009e000 - 0000000000100000
[17140.974551] PM: Marking nosave pages: 00000000cee7a000 - 0000000100000000
[17140.975567] PM: Basic memory bitmaps created
[17140.975569] PM: Syncing filesystems ... done.
[17141.091426] Freezing user space processes ... (elapsed 0.01 seconds) done.
[17141.108069] Freezing remaining freezable tasks ... (elapsed 0.01 seconds)
done.
[17141.124188] PM: Preallocating image memory... done (allocated 1378208 pages)
[17141.817556] PM: Allocated 5512832 kbytes in 0.69 seconds (7989.61 MB/s)
[17141.817558] Suspending console(s) (use no_console_suspend to debug)
[17141.818222] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[17141.818577] sdhci-pci 0000:03:00.4: PCI INT C disabled
[17141.818654] sdhci-pci 0000:03:00.0: PCI INT A disabled
[17141.820340] pci 0000:00:1f.6: PCI INT C disabled
[17141.822975] ACPI handle has no context!
[17141.922753] HDA Intel 0000:00:1b.0: PCI INT A disabled
[17142.150276] HDA Intel 0000:01:00.1: PCI INT A disabled
[17142.150336] ACPI handle has no context!
[17142.166241] PM: freeze of devices complete after 349.078 msecs
[17142.166773] PM: late freeze of devices complete after 0.530 msecs
[17142.166913] ACPI: Preparing to enter system sleep state S4
[17142.167366] PM: Saving platform NVS memory
[17142.168099] Disabling non-boot CPUs ...
[17142.270070] CPU 1 is now offline
[17142.425774] CPU 2 is now offline
[17142.561540] CPU 3 is now offline
[17142.562124] Extended CMOS year: 2000
[17142.562233] PM: Creating hibernation image:
[17142.662767] PM: Need to copy 605529 pages
[17142.662769] PM: Normal pages needed: 605529 + 1024, available pages: 1486880
[17142.562266] PM: Restoring platform NVS memory
[17142.562784] CPU0: Thermal monitoring handled by SMI
[17142.562842] Extended CMOS year: 2000
[17142.562885] Enabling non-boot CPUs ...
[17142.563054] Booting Node 0 Processor 1 APIC 0x4
[17142.563055] smpboot cpu 1: start_ip = 99000
[17142.650127] CPU1: Thermal monitoring handled by SMI
[17142.670321] NMI watchdog enabled, takes one hw-pmu counter.
[17142.670625] CPU1 is up
[17142.670768] Booting Node 0 Processor 2 APIC 0x1
[17142.670770] smpboot cpu 2: start_ip = 99000
[17142.674068] Switched to NOHz mode on CPU #1
[17142.757941] CPU2: Thermal monitoring handled by SMI
[17142.778370] NMI watchdog enabled, takes one hw-pmu counter.
[17142.778746] CPU2 is up
[17142.778921] Booting Node 0 Processor 3 APIC 0x5
[17142.778923] smpboot cpu 3: start_ip = 99000
[17142.781884] Switched to NOHz mode on CPU #2
[17142.869753] CPU3: Thermal monitoring handled by SMI
[17142.893692] Switched to NOHz mode on CPU #3
[17142.898172] NMI watchdog enabled, takes one hw-pmu counter.
[17142.898542] CPU3 is up
[17142.900296] ACPI: Waking up from system sleep state S4
[17143.305595] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1
(was 0x100006, writing 0x100002)
[17143.305969] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was
0x2b00403, writing 0x2b00407)
[17143.306057] pci 0000:00:1f.6: restoring config space at offset 0x1 (was
0x100006, writing 0x100002)
[17143.306087] nvidia 0000:01:00.0: restoring config space at offset 0xc (was
0xe3000000, writing 0x0)
[17143.306097] nvidia 0000:01:00.0: restoring config space at offset 0x3 (was
0x800010, writing 0x800000)
[17143.306140] HDA Intel 0000:01:00.1: restoring config space at offset 0x1
(was 0x100006, writing 0x100002)
[17143.320971] sdhci-pci 0000:03:00.0: BAR 0: set to [mem
0xe6603000-0xe66030ff] (PCI address [0xe6603000-0xe66030ff])
[17143.321027] sdhci-pci 0000:03:00.0: restoring config space at offset 0x1
(was 0x100002, writing 0x100006)
[17143.336940] firewire_ohci 0000:03:00.3: BAR 0: set to [mem
0xe6601000-0xe66017ff] (PCI address [0xe6601000-0xe66017ff])
[17143.352909] sdhci-pci 0000:03:00.4: BAR 0: set to [mem
0xe6600000-0xe66000ff] (PCI address [0xe6600000-0xe66000ff])
[17143.352965] sdhci-pci 0000:03:00.4: restoring config space at offset 0x1
(was 0x100002, writing 0x100006)
[17143.353194] PM: early restore of devices complete after 47.857 msecs
[17143.518944] ehci_hcd 0000:00:1a.0: setting latency timer to 64
[17143.518976] usb usb1: root hub lost power or was reset
[17143.522912] ehci_hcd 0000:00:1a.0: cache line size of 64 is not supported
[17143.522915] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ
22
[17143.522930] HDA Intel 0000:00:1b.0: setting latency timer to 64
[17143.522933] ehci_hcd 0000:00:1d.0: setting latency timer to 64
[17143.522936] pci 0000:00:1e.0: setting latency timer to 64
[17143.522945] ahci 0000:00:1f.2: setting latency timer to 64
[17143.522953] pci 0000:00:1f.6: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[17143.522956] usb usb2: root hub lost power or was reset
[17143.526849] ehci_hcd 0000:00:1d.0: cache line size of 64 is not supported
[17143.526875] sdhci-pci 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ
17
[17143.526942] HDA Intel 0000:00:1b.0: irq 43 for MSI/MSI-X
[17143.526968] sdhci-pci 0000:03:00.4: PCI INT C -> GSI 19 (level, low) -> IRQ
19
[17143.527055] HDA Intel 0000:01:00.1: PCI INT A -> GSI 16 (level, low) -> IRQ
16
[17143.527060] HDA Intel 0000:01:00.1: setting latency timer to 64
[17143.527199] sd 0:0:0:0: [sda] Starting disk
[17143.580632] firewire_ohci 0000:03:00.3: irq 44 for MSI/MSI-X
[17143.580740] firewire_core: skipped bus generations, destroying all nodes
[17143.844169] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[17143.844234] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[17143.845072] ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK)
filtered out
[17143.846494] ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK)
filtered out
[17143.846937] ata1.00: configured for UDMA/133
[17143.866185] ata2.00: configured for UDMA/100
[17143.872036] usb 1-1: reset high speed USB device number 2 using ehci_hcd
[17144.027752] sdhci-pci 0000:03:00.4: Will use DMA mode even though HW doesn't
fully claim to support it.
[17144.027765] sdhci-pci 0000:03:00.4: setting latency timer to 64
[17144.027811] sdhci-pci 0000:03:00.0: Will use DMA mode even though HW doesn't
fully claim to support it.
[17144.027822] sdhci-pci 0000:03:00.0: setting latency timer to 64
[17144.115608] usb 2-1: reset high speed USB device number 2 using ehci_hcd
[17144.319354] usb 1-1.6: reset full speed USB device number 4 using ehci_hcd
[17144.413348] btusb 1-1.6:1.0: no reset_resume for driver btusb?
[17144.413350] btusb 1-1.6:1.1: no reset_resume for driver btusb?
[17144.483066] usb 1-1.2: reset high speed USB device number 3 using ehci_hcd
[17144.730473] firewire_core: rediscovered device fw0
[17144.730996] PM: restore of devices complete after 1214.199 msecs
[17144.731238] PM: Image restored successfully.
[17144.731239] Restarting tasks ... done.
[17144.741550] PM: Basic memory bitmaps freed
[17144.741556] video LNXVIDEO:01: Restoring backlight state
[17145.644226] EXT4-fs (sda3): re-mounted. Opts: errors=remount-ro,commit=600
[17145.817782] EXT4-fs (sda6): re-mounted. Opts: acl,commit=600
[17145.964515] EXT4-fs (sda5): re-mounted. Opts: commit=600
[17146.189370] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[17146.194226] sky2 0000:04:00.0: eth0: enabling interface
[17146.194947] ADDRCONF(NETDEV_UP): eth0: link is not ready
[17147.614557] EXT4-fs (sda3): re-mounted. Opts: errors=remount-ro,commit=600
[17147.911440] EXT4-fs (sda6): re-mounted. Opts: acl,commit=600
[17147.918845] EXT4-fs (sda5): re-mounted. Opts: commit=600
[17291.991000] sky2 0000:04:00.0: eth0: Link is up at 1000 Mbps, full duplex,
flow control rx
[17291.992330] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[17295.074992] EXT4-fs (sda3): re-mounted. Opts: errors=remount-ro,commit=0
[17295.154472] EXT4-fs (sda6): re-mounted. Opts: acl,commit=0
[17295.160058] EXT4-fs (sda5): re-mounted. Opts: commit=0
[17302.962403] eth0: no IPv6 routers present

I you need more information, I could try to make more tests...

Regards

Mourad

-- System Information:
Debian Release: wheezy/sid
   APT prefers testing
   APT policy: (990, 'testing'), (500, 'unstable'), (500, 'stable'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 2.6.39-2-amd64 (SMP w/4 CPU cores)
Locale: LANG=fr_FR.UTF-8, LC_CTYPE=fr_FR.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash

Versions of packages bluetooth depends on:
ii  bluez                         4.94-2     Bluetooth tools and daemons

Versions of packages bluetooth recommends:
ii  bluez-alsa                    4.94-2     Bluetooth ALSA support
ii  bluez-cups                    4.94-2     Bluetooth printer driver for CUPS
ii  bluez-gstreamer               4.94-2     Bluetooth GStreamer support

bluetooth suggests no packages.

-- no debconf information