system suspends immediately after wake

[Rob Hughes]

Binary package hint: devicekit-power

This is consistent on a intel P43 chipset system using a core 2 duo processor running KDE on Karmic w/ all updates as of 11 am Mar. 20th 2010. After setting the system to sleep after an idle period in the kde power settings, when the system wakes up it again sleeps after about 30 seconds or less. Occasionally, I get a notification that the system will sleep in 30 seconds, but sometimes it also sleeps again before I can unlock the screen. It should also be mentioned that at times the screen doesn't actually lock until this second sleep occurs. Additionally, waking the system up after the second sleep always allows me to unlock the screen and continue working. This appears somewhat similar to 425411, but I don't believe it's the same issue. I'm not removing power from the system while it sleeps nor is this a lap top, and this second suspend always happens. I also see the following crash after each attempt to wake the system:

[ 8041.111623] PM: Preparing system for mem sleep
[ 8041.111626] Freezing user space processes ... (elapsed 0.00 seconds) done.
[ 8041.112454] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
[ 8041.112505] PM: Entering mem sleep
[ 8041.112516] Suspending console(s) (use no_console_suspend to debug)
[ 8041.190207] sd 1:0:0:0: [sdb] Synchronizing SCSI cache
[ 8041.190526] sd 1:0:0:0: [sdb] Stopping disk
[ 8041.250034] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 8041.250144] sd 0:0:0:0: [sda] Stopping disk
[ 8041.270375] ACPI handle has no context!
[ 8041.270535] parport_pc 00:08: disabled
[ 8041.270651] serial 00:07: disabled
[ 8041.270780] pata_jmicron 0000:03:00.0: PCI INT A disabled
[ 8041.297069] SB-XFi 0000:02:00.0: PCI INT A disabled
[ 8041.297133] ACPI handle has no context!
[ 8041.480094] PM: suspend of drv:ahci dev:0000:00:1f.2 complete after 135.322 msecs
[ 8041.480109] ehci_hcd 0000:00:1d.7: PCI INT A disabled
[ 8041.480117] uhci_hcd 0000:00:1d.2: PCI INT C disabled
[ 8041.480125] uhci_hcd 0000:00:1d.1: PCI INT B disabled
[ 8041.480133] uhci_hcd 0000:00:1d.0: PCI INT A disabled
[ 8041.590140] HDA Intel 0000:00:1b.0: PCI INT A disabled
[ 8041.610086] PM: suspend of drv:HDA Intel dev:0000:00:1b.0 complete after 129.937 msecs
[ 8041.610095] ehci_hcd 0000:00:1a.7: PCI INT C disabled
[ 8041.610102] uhci_hcd 0000:00:1a.2: PCI INT C disabled
[ 8041.610110] uhci_hcd 0000:00:1a.1: PCI INT B disabled
[ 8041.610118] uhci_hcd 0000:00:1a.0: PCI INT A disabled
[ 8041.610259] PM: suspend of devices complete after 497.360 msecs
[ 8041.610261] PM: suspend devices took 0.500 seconds
[ 8041.610536] r8169 0000:04:00.0: PME# enabled
[ 8041.672330] PM: late suspend of devices complete after 62.065 msecs
[ 8041.672611] ACPI: Preparing to enter system sleep state S3
[ 8041.711111] Disabling non-boot CPUs ...
[ 8041.711129] CPU0 attaching NULL sched-domain.
[ 8041.711131] CPU1 attaching NULL sched-domain.
[ 8041.871117] CPU0 attaching NULL sched-domain.
[ 8041.872212] Broke affinity for irq 7
[ 8041.872230] Broke affinity for irq 12
[ 8041.983604] CPU 1 is now offline
[ 8041.983606] SMP alternatives: switching to UP code
[ 8041.988383] Back to C!
[ 8041.988383] CPU0: Thermal monitoring enabled (TM2)
[ 8041.988383] Enabling non-boot CPUs ...
[ 8041.988383] SMP alternatives: switching to SMP code
[ 8041.993064] Booting processor 1 APIC 0x1 ip 0x6000
[ 8041.988153] Initializing CPU#1
[ 8041.988153] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 8041.988153] CPU: L2 cache: 3072K
[ 8041.988153] CPU 1/0x1 -> Node 0
[ 8041.988153] CPU: Physical Processor ID: 0
[ 8041.988153] CPU: Processor Core ID: 1
[ 8041.988153] CPU1: Thermal monitoring enabled (TM2)
[ 8042.151176] CPU1: Intel(R) Core(TM)2 CPU E7500 @ 2.93GHz stepping 0a
[ 8042.151230] CPU0 attaching NULL sched-domain.
[ 8042.221119] CPU0 attaching sched-domain:
[ 8042.221121] domain 0: span 0-1 level MC
[ 8042.221123] groups: 0 1
[ 8042.221126] CPU1 attaching sched-domain:
[ 8042.221127] domain 0: span 0-1 level MC
[ 8042.221128] groups: 1 0
[ 8042.221431] CPU1 is up
[ 8042.221881] ACPI: Waking up from system sleep state S3
[ 8042.222580] HDA Intel 0000:00:1b.0: restoring config space at offset 0xf (was 0x100, writing 0x105)
[ 8042.222591] HDA Intel 0000:00:1b.0: restoring config space at offset 0x4 (was 0x4, writing 0xfdff8004)
[ 8042.222594] HDA Intel 0000:00:1b.0: restoring config space at offset 0x3 (was 0x0, writing 0x1)
[ 8042.222598] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100002)
[ 8042.222867] ahci 0000:00:1f.2: restoring config space at offset 0x8 (was 0xf001, writing 0xf501)
[ 8042.222914] nvidia 0000:01:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 8042.222920] nvidia 0000:01:00.0: restoring config space at offset 0x9 (was 0x1, writing 0xef01)
[ 8042.222923] nvidia 0000:01:00.0: restoring config space at offset 0x7 (was 0x4, writing 0xf8000004)
[ 8042.222927] nvidia 0000:01:00.0: restoring config space at offset 0x5 (was 0xc, writing 0xd000000c)
[ 8042.222930] nvidia 0000:01:00.0: restoring config space at offset 0x4 (was 0x0, writing 0xfa000000)
[ 8042.222934] nvidia 0000:01:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100007)
[ 8042.222975] SB-XFi 0000:02:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 8042.222988] SB-XFi 0000:02:00.0: restoring config space at offset 0x8 (was 0x4, writing 0xec000004)
[ 8042.222994] SB-XFi 0000:02:00.0: restoring config space at offset 0x6 (was 0x4, writing 0xf3c00004)
[ 8042.223000] SB-XFi 0000:02:00.0: restoring config space at offset 0x4 (was 0x4, writing 0xf3ff0004)
[ 8042.223005] SB-XFi 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x1)
[ 8042.223011] SB-XFi 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100002)
[ 8042.223045] pata_jmicron 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[ 8042.223059] pata_jmicron 0000:03:00.0: restoring config space at offset 0x8 (was 0x1, writing 0xdb01)
[ 8042.223064] pata_jmicron 0000:03:00.0: restoring config space at offset 0x7 (was 0x1, writing 0xdc01)
[ 8042.223068] pata_jmicron 0000:03:00.0: restoring config space at offset 0x6 (was 0x1, writing 0xdd01)
[ 8042.223073] pata_jmicron 0000:03:00.0: restoring config space at offset 0x5 (was 0x1, writing 0xde01)
[ 8042.223077] pata_jmicron 0000:03:00.0: restoring config space at offset 0x4 (was 0x1, writing 0xdf01)
[ 8042.223082] pata_jmicron 0000:03:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x1)
[ 8042.223088] pata_jmicron 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100007)
[ 8042.223133] r8169 0000:04:00.0: restoring config space at offset 0xf (was 0x1ff, writing 0x10e)
[ 8042.223145] r8169 0000:04:00.0: restoring config space at offset 0x8 (was 0xc, writing 0xfdce000c)
[ 8042.223150] r8169 0000:04:00.0: restoring config space at offset 0x6 (was 0xc, writing 0xfdcff00c)
[ 8042.223155] r8169 0000:04:00.0: restoring config space at offset 0x4 (was 0xfc01, writing 0xce01)
[ 8042.223160] r8169 0000:04:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x8)
[ 8042.223165] r8169 0000:04:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407)
[ 8042.223414] PM: early resume of devices complete after 1.020 msecs
[ 8042.223547] uhci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[ 8042.223551] uhci_hcd 0000:00:1a.0: setting latency timer to 64
[ 8042.223569] usb usb3: root hub lost power or was reset
[ 8042.223584] uhci_hcd 0000:00:1a.1: PCI INT B -> GSI 21 (level, low) -> IRQ 21
[ 8042.223588] uhci_hcd 0000:00:1a.1: setting latency timer to 64
[ 8042.223605] usb usb4: root hub lost power or was reset
[ 8042.223619] uhci_hcd 0000:00:1a.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[ 8042.223623] uhci_hcd 0000:00:1a.2: setting latency timer to 64
[ 8042.223639] usb usb5: root hub lost power or was reset
[ 8042.223654] ehci_hcd 0000:00:1a.7: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[ 8042.223658] ehci_hcd 0000:00:1a.7: setting latency timer to 64
[ 8042.223665] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[ 8042.223669] HDA Intel 0000:00:1b.0: setting latency timer to 64
[ 8042.381400] PM: resume of drv:HDA Intel dev:0000:00:1b.0 complete after 157.734 msecs
[ 8042.381411] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[ 8042.381415] uhci_hcd 0000:00:1d.0: setting latency timer to 64
[ 8042.381432] usb usb6: root hub lost power or was reset
[ 8042.381448] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[ 8042.381452] uhci_hcd 0000:00:1d.1: setting latency timer to 64
[ 8042.381469] usb usb7: root hub lost power or was reset
[ 8042.381485] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[ 8042.381489] uhci_hcd 0000:00:1d.2: setting latency timer to 64
[ 8042.381506] usb usb8: root hub lost power or was reset
[ 8042.381522] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[ 8042.381528] ehci_hcd 0000:00:1d.7: setting latency timer to 64
[ 8042.381536] pci 0000:00:1e.0: setting latency timer to 64
[ 8042.381545] ahci 0000:00:1f.2: setting latency timer to 64
[ 8042.791083] PM: resume of drv:nvidia dev:0000:01:00.0 complete after 409.459 msecs
[ 8042.791133] SB-XFi 0000:02:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[ 8042.791142] SB-XFi 0000:02:00.0: setting latency timer to 64
[ 8042.791278] ata4: SATA link down (SStatus 0 SControl 300)
[ 8042.831274] ata3: SATA link down (SStatus 0 SControl 300)
[ 8042.931272] ata6: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 8042.935511] ata6.00: configured for UDMA/100
[ 8042.991272] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[ 8042.995493] ata5.00: configured for UDMA/100
[ 8043.102192] PM: resume of drv:SB-XFi dev:0000:02:00.0 complete after 311.082 msecs
[ 8043.102203] pata_jmicron 0000:03:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[ 8043.102208] pata_jmicron 0000:03:00.0: setting latency timer to 64
[ 8043.102224] r8169 0000:04:00.0: PME# disabled
[ 8043.103199] serial 00:07: activated
[ 8043.103875] parport_pc 00:08: activated
[ 8043.240803] sd 0:0:0:0: [sda] Starting disk
[ 8048.850032] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 8048.851067] ata1.00: configured for UDMA/133
[ 8048.874589] PM: resume of drv:sd dev:0:0:0:0 complete after 5633.786 msecs
[ 8049.050535] sd 1:0:0:0: [sdb] Starting disk
[ 8052.430028] ata2: softreset failed (device not ready)
[ 8052.960032] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 8052.963147] ata2.00: configured for UDMA/133
[ 8053.003554] PM: resume of drv:sd dev:1:0:0:0 complete after 3953.018 msecs
[ 8053.241443] PM: resume of devices complete after 11018.003 msecs
[ 8053.241671] PM: resume devices took 11.020 seconds
[ 8053.241673] ------------[ cut here ]------------
[ 8053.241678] WARNING: at /build/buildd/linux-2.6.32/kernel/power/suspend_test.c:53 suspend_test_finish+0x88/0x90()
[ 8053.241680] Hardware name: EP43-UD3L
[ 8053.241681] Component: resume devices, time: 11020
[ 8053.241682] Modules linked in: nls_iso8859_1 nls_cp437 vfat fat snd_hda_codec_realtek ppdev snd_ctxfi snd_hda_intel snd_hda_codec snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi max6650 snd_seq_midi_event it87 hwmon_vid snd_seq coretemp snd_timer snd_seq_device joydev fbcon tileblit font bitblit softcursor snd parport_pc nvidia(P) psmouse serio_raw soundcore vga16fb vgastate intel_agp snd_page_alloc lp parport hid_logitech ff_memless dm_raid45 xor usbhid hid r8169 mii usb_storage
[ 8053.241709] Pid: 11602, comm: pm-suspend Tainted: P W 2.6.32-16-generic #25-Ubuntu
[ 8053.241710] Call Trace:
[ 8053.241715] [<ffffffff81064f8b>] warn_slowpath_common+0x7b/0xc0
[ 8053.241717] [<ffffffff81065031>] warn_slowpath_fmt+0x41/0x50
[ 8053.241719] [<ffffffff810a13b8>] suspend_test_finish+0x88/0x90
[ 8053.241721] [<ffffffff810a1161>] suspend_devices_and_enter+0xb1/0xe0
[ 8053.241723] [<ffffffff810a1268>] enter_state+0xd8/0x110
[ 8053.241725] [<ffffffff810a080a>] state_store+0x9a/0x100
[ 8053.241728] [<ffffffff812ae8d7>] kobj_attr_store+0x17/0x20
[ 8053.241731] [<ffffffff811aa225>] sysfs_write_file+0xe5/0x170
[ 8053.241734] [<ffffffff811400b8>] vfs_write+0xb8/0x1a0
[ 8053.241737] [<ffffffff81559868>] ? do_page_fault+0x148/0x380
[ 8053.241739] [<ffffffff81140951>] sys_write+0x51/0x80
[ 8053.241742] [<ffffffff810131f2>] system_call_fastpath+0x16/0x1b
[ 8053.241743] ---[ end trace 9c8aed93c0c7c2b5 ]---
[ 8053.241767] PM: Finishing wakeup.
[ 8053.241768] Restarting tasks ... done.
[ 8053.480698] r8169: eth0: link up