Ubuntu
linux package

thinkpad x301 (2777) fails to suspend with kernels 3.0.{2,3}

Bug #810652 reported by Chad Miller
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
linux (Ubuntu)
Incomplete
Undecided
Leann Ogasawara

Bug Description

This may have started earlier, in 3.0.1 or .0. Not sure.

I close the lid, and it seems to be trying to suspend, but resumes running with lid closed. If I open the lid, and close it again, it suspends (so far, every time).

linux-image-3.0-3-generic 3.0-3.4

Ubuntu 3.0-3.4-generic 3.0.0-rc5

syslog

Jul 14 12:27:24 localhost bluetoothd[1537]: HCI dev 0 down
Jul 14 12:27:24 localhost bluetoothd[1537]: Adapter /org/bluez/1531/hci0 has been disabled
Jul 14 12:27:24 localhost kernel: [11168.104141] usb 4-2: USB disconnect, device number 2
Jul 14 12:27:24 localhost kernel: [11168.104878] btusb_intr_complete: hci0 urb f6ea1d00 failed to resubmit (19)
Jul 14 12:27:24 localhost kernel: [11168.104899] btusb_bulk_complete: hci0 urb f6ea1200 failed to resubmit (19)
Jul 14 12:27:24 localhost kernel: [11168.105902] btusb_bulk_complete: hci0 urb f6ea1100 failed to resubmit (19)
Jul 14 12:27:24 localhost kernel: [11168.105963] btusb_send_frame: hci0 urb eda07e00 submission failed
Jul 14 12:27:24 localhost kernel: [11168.275973] type=1400 audit(1310660844.358:15481): apparmor="STATUS" operation="profile_replace" name="/usr/lib/cups/backend/cups-pdf" pid=15722 comm="apparmor_parser"
Jul 14 12:27:24 localhost kernel: [11168.277915] type=1400 audit(1310660844.362:15482): apparmor="STATUS" operation="profile_replace" name="/usr/sbin/cupsd" pid=15722 comm="apparmor_parser"
Jul 14 12:27:24 localhost kernel: [11168.290118] type=1400 audit(1310660844.374:15483): apparmor="DENIED" operation="chown" parent=1 profile="/usr/sbin/cupsd" name="/run/cups/" pid=15723 comm="cupsd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
Jul 14 12:27:24 localhost kernel: [11168.290206] type=1400 audit(1310660844.374:15484): apparmor="DENIED" operation="chown" parent=1 profile="/usr/sbin/cupsd" name="/run/cups/certs/" pid=15723 comm="cupsd" requested_mask="w" denied_mask="w" fsuid=0 ouid=0
Jul 14 12:27:24 localhost kernel: [11168.294659] type=1400 audit(1310660844.378:15485): apparmor="DENIED" operation="mknod" parent=1 profile="/usr/sbin/cupsd" name="/run/cups/printcap" pid=15723 comm="cupsd" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
Jul 14 12:27:24 localhost kernel: [11168.298338] type=1400 audit(1310660844.382:15486): apparmor="DENIED" operation="mknod" parent=1 profile="/usr/sbin/cupsd" name="/run/cups/cups.sock" pid=15723 comm="cupsd" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
Jul 14 12:27:24 localhost kernel: [11168.298504] type=1400 audit(1310660844.382:15487): apparmor="DENIED" operation="mknod" parent=1 profile="/usr/sbin/cupsd" name="/run/cups/cupsd.pid" pid=15723 comm="cupsd" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
Jul 14 12:27:24 localhost kernel: [11168.299299] init: cups main process (15723) terminated with status 1
Jul 14 12:27:24 localhost kernel: [11168.299346] init: cups main process ended, respawning
Jul 14 12:27:24 localhost bluetoothd[1537]: HCI dev 0 unregistered
Jul 14 12:27:24 localhost bluetoothd[1537]: Stopping hci0 event socket
Jul 14 12:27:24 localhost bluetoothd[1537]: Unregister path: /org/bluez/1531/hci0
Jul 14 12:27:24 localhost kernel: [11168.627556] PM: Syncing filesystems ... done.
Jul 14 12:27:24 localhost kernel: [11168.672540] PM: Preparing system for mem sleep
Jul 14 12:27:25 localhost kernel: [11169.020209] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jul 14 12:27:25 localhost kernel: [11169.036179] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jul 14 12:27:25 localhost kernel: [11169.052138] PM: Entering mem sleep
Jul 14 12:27:25 localhost kernel: [11169.052224] Suspending console(s) (use no_console_suspend to debug)
Jul 14 12:27:25 localhost kernel: [11169.053062] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Jul 14 12:27:25 localhost kernel: [11169.068116] sd 0:0:0:0: [sda] Stopping disk
Jul 14 12:27:25 localhost kernel: [11169.128328] ehci_hcd 0000:00:1d.7: PCI INT D disabled
Jul 14 12:27:25 localhost kernel: [11169.128343] uhci_hcd 0000:00:1d.2: PCI INT C disabled
Jul 14 12:27:25 localhost kernel: [11169.128358] uhci_hcd 0000:00:1d.1: PCI INT B disabled
Jul 14 12:27:25 localhost kernel: [11169.128373] uhci_hcd 0000:00:1d.0: PCI INT A disabled
Jul 14 12:27:25 localhost kernel: [11169.128393] pciehp 0000:00:1c.1:pcie04: pciehp_suspend ENTRY
Jul 14 12:27:25 localhost kernel: [11169.128409] pciehp 0000:00:1c.0:pcie04: pciehp_suspend ENTRY
Jul 14 12:27:25 localhost kernel: [11169.128594] ehci_hcd 0000:00:1a.7: PCI INT D disabled
Jul 14 12:27:25 localhost kernel: [11169.128611] uhci_hcd 0000:00:1a.2: PCI INT C disabled
Jul 14 12:27:25 localhost kernel: [11169.128624] uhci_hcd 0000:00:1a.1: PCI INT B disabled
Jul 14 12:27:25 localhost kernel: [11169.128637] uhci_hcd 0000:00:1a.0: PCI INT A disabled
Jul 14 12:27:25 localhost kernel: [11169.128841] e1000e 0000:00:19.0: PCI INT A disabled
Jul 14 12:27:25 localhost kernel: [11169.128850] e1000e 0000:00:19.0: PME# enabled
Jul 14 12:27:25 localhost kernel: [11169.128865] e1000e 0000:00:19.0: wake-up capability enabled by ACPI
Jul 14 12:27:25 localhost kernel: [11169.129700] pci_pm_suspend(): mei_pci_suspend+0x0/0xa0 [mei] returns 2500
Jul 14 12:27:25 localhost kernel: [11169.129709] pm_op(): pci_pm_suspend+0x0/0x110 returns 2500
Jul 14 12:27:25 localhost kernel: [11169.129714] PM: Device 0000:00:03.0 failed to suspend async: error 2500
Jul 14 12:27:25 localhost kernel: [11169.144060] i915 0000:00:02.0: power state changed by ACPI to D3
Jul 14 12:27:25 localhost kernel: [11169.232397] HDA Intel 0000:00:1b.0: PCI INT B disabled
Jul 14 12:27:25 localhost kernel: [11169.248025] PM: suspend of drv:HDA Intel dev:0000:00:1b.0 complete after 119.605 msecs
Jul 14 12:27:25 localhost kernel: [11169.417293] PM: suspend of drv:sd dev:0:0:0:0 complete after 364.239 msecs
Jul 14 12:27:25 localhost kernel: [11169.417343] PM: Some devices failed to suspend
Jul 14 12:27:25 localhost kernel: [11169.417387] i915 0000:00:02.0: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.417589] uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.417594] uhci_hcd 0000:00:1a.0: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.417602] uhci_hcd 0000:00:1a.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
Jul 14 12:27:25 localhost kernel: [11169.417617] uhci_hcd 0000:00:1a.0: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.417660] uhci_hcd 0000:00:1a.1: PCI INT B -> GSI 21 (level, low) -> IRQ 21
Jul 14 12:27:25 localhost kernel: [11169.417669] uhci_hcd 0000:00:1a.1: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.417700] uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.417733] uhci_hcd 0000:00:1a.2: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.417740] uhci_hcd 0000:00:1a.2: PCI INT C -> GSI 22 (level, low) -> IRQ 22
Jul 14 12:27:25 localhost kernel: [11169.417750] uhci_hcd 0000:00:1a.2: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.417796] ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.417804] ehci_hcd 0000:00:1a.7: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.417813] ehci_hcd 0000:00:1a.7: PCI INT D -> GSI 23 (level, low) -> IRQ 23
Jul 14 12:27:25 localhost kernel: [11169.417824] ehci_hcd 0000:00:1a.7: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.418074] pciehp 0000:00:1c.0:pcie04: pciehp_resume ENTRY
Jul 14 12:27:25 localhost kernel: [11169.418085] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.418089] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.418097] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
Jul 14 12:27:25 localhost kernel: [11169.418110] uhci_hcd 0000:00:1d.0: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.418114] pciehp 0000:00:1c.1:pcie04: pciehp_resume ENTRY
Jul 14 12:27:25 localhost kernel: [11169.418131] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17
Jul 14 12:27:25 localhost kernel: [11169.418142] uhci_hcd 0000:00:1d.1: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.418146] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
Jul 14 12:27:25 localhost kernel: [11169.418158] uhci_hcd 0000:00:1d.2: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.418180] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.418189] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.418200] ehci_hcd 0000:00:1d.7: PCI INT D -> GSI 19 (level, low) -> IRQ 19
Jul 14 12:27:25 localhost kernel: [11169.418203] pci 0000:00:1e.0: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.418211] ehci_hcd 0000:00:1d.7: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.421355] sd 0:0:0:0: [sda] Starting disk
Jul 14 12:27:25 localhost kernel: [11169.432060] i915 0000:00:02.0: BAR 0: set to [mem 0xf0000000-0xf03fffff 64bit] (PCI address [0xf0000000-0xf03fffff])
Jul 14 12:27:25 localhost kernel: [11169.432069] i915 0000:00:02.0: BAR 2: set to [mem 0xd0000000-0xdfffffff 64bit pref] (PCI address [0xd0000000-0xdfffffff])
Jul 14 12:27:25 localhost kernel: [11169.432076] i915 0000:00:02.0: BAR 4: set to [io 0x1800-0x1807] (PCI address [0x1800-0x1807])
Jul 14 12:27:25 localhost kernel: [11169.432083] i915 0000:00:02.0: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.432106] i915 0000:00:02.0: restoring config space at offset 0x1 (was 0x900403, writing 0x900407)
Jul 14 12:27:25 localhost kernel: [11169.432127] i915 0000:00:02.0: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.432133] i915 0000:00:02.0: power state changed by ACPI to D0
Jul 14 12:27:25 localhost kernel: [11169.432140] i915 0000:00:02.0: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.436043] e1000e 0000:00:19.0: BAR 0: set to [mem 0xf0600000-0xf061ffff] (PCI address [0xf0600000-0xf061ffff])
Jul 14 12:27:25 localhost kernel: [11169.436052] e1000e 0000:00:19.0: BAR 1: set to [mem 0xf0625000-0xf0625fff] (PCI address [0xf0625000-0xf0625fff])
Jul 14 12:27:25 localhost kernel: [11169.436061] e1000e 0000:00:19.0: BAR 2: set to [io 0x1840-0x185f] (PCI address [0x1840-0x185f])
Jul 14 12:27:25 localhost kernel: [11169.436082] e1000e 0000:00:19.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
Jul 14 12:27:25 localhost kernel: [11169.436112] e1000e 0000:00:19.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100107)
Jul 14 12:27:25 localhost kernel: [11169.436139] e1000e 0000:00:19.0: wake-up capability disabled by ACPI
Jul 14 12:27:25 localhost kernel: [11169.436145] e1000e 0000:00:19.0: PME# disabled
Jul 14 12:27:25 localhost kernel: [11169.436242] e1000e 0000:00:19.0: irq 42 for MSI/MSI-X
Jul 14 12:27:25 localhost kernel: [11169.439343] HDA Intel 0000:00:1b.0: BAR 0: set to [mem 0xf0620000-0xf0623fff 64bit] (PCI address [0xf0620000-0xf0623fff])
Jul 14 12:27:25 localhost kernel: [11169.439377] HDA Intel 0000:00:1b.0: restoring config space at offset 0xf (was 0x200, writing 0x20b)
Jul 14 12:27:25 localhost kernel: [11169.439404] HDA Intel 0000:00:1b.0: restoring config space at offset 0x3 (was 0x0, writing 0x10)
Jul 14 12:27:25 localhost kernel: [11169.439449] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100102)
Jul 14 12:27:25 localhost kernel: [11169.439477] HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
Jul 14 12:27:25 localhost kernel: [11169.439486] HDA Intel 0000:00:1b.0: setting latency timer to 64
Jul 14 12:27:25 localhost kernel: [11169.439538] HDA Intel 0000:00:1b.0: irq 46 for MSI/MSI-X
Jul 14 12:27:25 localhost kernel: [11169.455557] legacy_resume(): pnp_bus_resume+0x0/0x70 returns -19
Jul 14 12:27:25 localhost kernel: [11169.455563] PM: Device 00:0a failed to resume: error -19
Jul 14 12:27:25 localhost kernel: [11169.648649] PM: resume of drv:i915 dev:0000:00:02.0 complete after 231.275 msecs
Jul 14 12:27:25 localhost kernel: [11169.650677] PM: resume of devices complete after 233.327 msecs
Jul 14 12:27:25 localhost kernel: [11169.650888] PM: resume devices took 0.232 seconds
Jul 14 12:27:25 localhost kernel: [11169.650927] PM: Finishing wakeup.
Jul 14 12:27:25 localhost kernel: [11169.650929] Restarting tasks ... done.
Jul 14 12:27:25 localhost kernel: [11169.681870] video LNXVIDEO:00: Restoring backlight state
Jul 14 12:27:25 localhost acpid: client 1061[0:0] has disconnected
Jul 14 12:27:25 localhost acpid: client connected from 1061[0:0]
Jul 14 12:27:25 localhost acpid: 1 client rule loaded
Jul 14 12:27:25 localhost anacron[15874]: Anacron 2.3 started on 2011-07-14
Jul 14 12:27:25 localhost anacron[15874]: Normal exit (0 jobs run)

Tags: oneiric
Revision history for this message
Chad Miller (cmiller) wrote :
Revision history for this message
Chad Miller (cmiller) wrote :
Revision history for this message
Chad Miller (cmiller) wrote :

Here's a successful suspension. Note, there are some troubling lines.

Jul 14 14:14:13 localhost kernel: [17560.364892] WARNING: at /build/buildd/linux-3.0/kernel/irq/manage.c:1147 __free_irq+0x91/0x180()
Jul 14 14:14:13 localhost kernel: [17560.364895] Hardware name: 2777CTO
Jul 14 14:14:13 localhost kernel: [17560.364898] Trying to free already-free IRQ 16
Jul 14 14:14:13 localhost kernel: [17560.364900] Modules linked in: cryptd aes_i586 aes_generic rfcomm bnep vboxnetadp vboxnetflt vboxdrv kvm_intel kvm parport_pc ppdev binfmt_misc joydev snd_hda_codec_conexant btusb bluetooth appletalk ipx p8023 arc4 uvcvideo videodev snd_hda_intel snd_hda_codec snd_hwdep snd_pcm snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq iwlagn psmouse snd_timer serio_raw snd_seq_device mac80211 tpm_tis cfg80211 thinkpad_acpi tpm nvram i915 snd tpm_bios drm_kms_helper drm soundcore snd_page_alloc mei(C) i2c_algo_bit video lp parport ahci libahci e1000e
Jul 14 14:14:13 localhost kernel: [17560.364956] Pid: 10041, comm: kworker/u:4 Tainted: G C 3.0-3-generic #4-Ubuntu
Jul 14 14:14:13 localhost kernel: [17560.364959] Call Trace:
Jul 14 14:14:13 localhost kernel: [17560.364968] [<c1047492>] warn_slowpath_common+0x72/0xa0
Jul 14 14:14:13 localhost kernel: [17560.364973] [<c10a91b1>] ? __free_irq+0x91/0x180
Jul 14 14:14:13 localhost kernel: [17560.364977] [<c10a91b1>] ? __free_irq+0x91/0x180
Jul 14 14:14:13 localhost kernel: [17560.364982] [<c1047563>] warn_slowpath_fmt+0x33/0x40
Jul 14 14:14:13 localhost kernel: [17560.364986] [<c10a91b1>] __free_irq+0x91/0x180
Jul 14 14:14:13 localhost kernel: [17560.364991] [<c10a92fd>] free_irq+0x3d/0x90
Jul 14 14:14:13 localhost kernel: [17560.365000] [<f8153141>] mei_pci_suspend+0x61/0xa0 [mei]
Jul 14 14:14:13 localhost kernel: [17560.365007] [<c129734d>] pci_pm_suspend+0x4d/0x110
Jul 14 14:14:13 localhost kernel: [17560.365013] [<c1531ded>] ? _raw_spin_lock+0xd/0x10
Jul 14 14:14:13 localhost kernel: [17560.365019] [<c1341c1d>] pm_op+0x14d/0x1a0
Jul 14 14:14:13 localhost kernel: [17560.365023] [<c1341e1b>] __device_suspend+0x14b/0x190
Jul 14 14:14:13 localhost kernel: [17560.365028] [<c1341e7e>] async_suspend+0x1e/0x50
Jul 14 14:14:13 localhost kernel: [17560.365034] [<c106d119>] async_run_entry_fn+0x69/0x170
Jul 14 14:14:13 localhost kernel: [17560.365039] [<c1060ce1>] process_one_work+0x101/0x3a0
Jul 14 14:14:13 localhost kernel: [17560.365043] [<c106156a>] ? maybe_create_worker+0xda/0xe0
Jul 14 14:14:13 localhost kernel: [17560.365048] [<c106d0b0>] ? async_schedule+0x20/0x20
Jul 14 14:14:13 localhost kernel: [17560.365052] [<c10617a4>] worker_thread+0x124/0x2d0
Jul 14 14:14:13 localhost kernel: [17560.365056] [<c1061680>] ? manage_workers.isra.28+0x110/0x110
Jul 14 14:14:13 localhost kernel: [17560.365062] [<c10652bd>] kthread+0x6d/0x80
Jul 14 14:14:13 localhost kernel: [17560.365066] [<c1065250>] ? flush_kthread_worker+0x80/0x80
Jul 14 14:14:13 localhost kernel: [17560.365072] [<c153947e>] kernel_thread_helper+0x6/0x10

Brad Figg (brad-figg)
tags: added: oneiric
Brad Figg (brad-figg)
Changed in linux (Ubuntu):
status: New → Confirmed
Revision history for this message
Leann Ogasawara (leannogasawara) wrote :

Hi Chad,

This sounds like a duplicate of bug 811214. If you remove the iwlagn driver prior to suspending, does this help? If so, we'll mark this as a duplicate of 811214 and track this issue at that report. Thanks.

Changed in linux (Ubuntu):
assignee: nobody → Leann Ogasawara (leannogasawara)
status: Confirmed → Incomplete
Revision history for this message
Leann Ogasawara (leannogasawara) wrote :

I've posted a test kernel to bug 811214, see https://bugs.launchpad.net/ubuntu/+source/linux/+bug/811214/comments/48 . It would be good to know if that resolves the issue you are seeing here. Thanks.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.