WARNING: at /build/buildd/linux-2.6.28/kernel/power/main.c:177 suspend_test_finish+0x7c/0x80()

[Fernando Miguel]

my syslog is getting filed with call traces.

ProblemType: Bug
Architecture: amd64
DistroRelease: Ubuntu 9.04
NonfreeKernelModules: nvidia
Package: linux-image-2.6.28-7-generic 2.6.28-7.20
ProcCmdLine: root=UUID=a8aa4adb-b3e6-4e1d-b4ad-e6cd704788b2 ro bootchart=nostop profile
ProcEnviron:
 SHELL=/bin/bash
 PATH=(custom, no user)
 LANG=en_US.UTF-8
ProcVersionSignature: Ubuntu 2.6.28-7.20-generic
SourcePackage: linux

[Fernando Miguel (fernandomiguel)]

$ apt-cache policy network-manager
network-manager:
  Installed: 0.7-0ubuntu1
  Candidate: 0.7-0ubuntu1
  Version table:
 *** 0.7-0ubuntu1 0
        500 ftp://darkstar.ist.utl.pt jaunty/main Packages
        500 ftp://archive.ubuntu.com jaunty/main Packages
        100 /var/lib/dpkg/status
     0.7-0ubuntu1~nm1 0
        500 http://ppa.launchpad.net jaunty/main Packages

[Fernando Miguel (fernandomiguel)]

I'm now getting comm: s2ram Tainted: P 2.6.28-7-generic #20-Ubuntu
I think it is related to my webcam driver (http://ubuntuforums.org/showthread.php?p=6748916) bug 215604

Feb 17 01:16:17 blubug kernel: [14970.176071] usb 2-2: USB disconnect, address 2
Feb 17 01:16:22 blubug kernel: [14974.784051] sky2 eth0: disabling interface
Feb 17 01:16:24 blubug kernel: [14976.826284] PM: Marking nosave pages: 000000000009f000 - 0000000000100000
Feb 17 01:16:24 blubug kernel: [14976.826290] PM: Marking nosave pages: 00000000bffb0000 - 0000000100000000
Feb 17 01:16:24 blubug kernel: [14976.834060] PM: Basic memory bitmaps created
Feb 17 01:16:24 blubug kernel: [14976.978442] Syncing filesystems ... done.
Feb 17 01:16:24 blubug kernel: [14977.057044] Freezing user space processes ... (elapsed 0.00 seconds) done.
Feb 17 01:16:24 blubug kernel: [14977.058023] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
Feb 17 01:16:24 blubug kernel: [14977.058213] s2disk[14904]: segfault at 0 ip 0000000000000000 sp 00007fff7da51ee8 error 14 in s2disk[400000+8000]
Feb 17 01:16:24 blubug kernel: [14977.058237] Core dump to |/usr/share/apport/apport pipe failed
Feb 17 01:16:24 blubug kernel: [14977.097023] PM: Basic memory bitmaps freed
Feb 17 01:16:24 blubug kernel: [14977.097025] Restarting tasks ... done.
Feb 17 01:16:24 blubug kernel: [14977.369746] sky2 eth0: enabling interface
Feb 17 01:16:24 blubug kernel: [14977.373284] ADDRCONF(NETDEV_UP): eth0: link is not ready
Feb 17 01:16:24 blubug kernel: [14977.582085] Registered led device: iwl-phy0::radio
Feb 17 01:16:24 blubug kernel: [14977.582110] Registered led device: iwl-phy0::assoc
Feb 17 01:16:24 blubug kernel: [14977.582124] Registered led device: iwl-phy0::RX
Feb 17 01:16:24 blubug kernel: [14977.582137] Registered led device: iwl-phy0::TX
Feb 17 01:16:24 blubug kernel: [14977.612144] ADDRCONF(NETDEV_UP): wlan2: link is not ready
Feb 17 01:16:37 blubug kernel: [14990.196065] sky2 eth0: disabling interface
Feb 17 01:16:39 blubug kernel: [14992.075159] PM: Marking nosave pages: 000000000009f000 - 0000000000100000
Feb 17 01:16:39 blubug kernel: [14992.075165] PM: Marking nosave pages: 00000000bffb0000 - 0000000100000000
Feb 17 01:16:39 blubug kernel: [14992.080952] PM: Basic memory bitmaps created
Feb 17 01:16:39 blubug kernel: [14992.206596] Syncing filesystems ... done.
Feb 17 01:16:39 blubug kernel: [14992.283867] Freezing user space processes ... (elapsed 0.00 seconds) done.
Feb 17 01:16:39 blubug kernel: [14992.284967] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
Feb 17 01:16:39 blubug kernel: [14992.285176] s2disk[15423]: segfault at 0 ip 0000000000000000 sp 00007fffefd1f9d8 error 14 in s2disk[400000+8000]
Feb 17 01:16:39 blubug kernel: [14992.285200] Core dump to |/usr/share/apport/apport pipe failed
Feb 17 01:16:39 blubug kernel: [14992.308912] PM: Basic memory bitmaps freed
Feb 17 01:16:39 blubug kernel: [14992.308914] Restarting tasks ... done.
Feb 17 01:16:39 blubug kernel: [14992.428258] sky2 eth0: enabling interface
Feb 17 01:16:39 blubug kernel: [14992.431774] ADDRCONF(NETDEV_UP): eth0: link is not ready
Feb 17 01:16:39 blubug kernel: [14992.642815] ...

[Fernando Miguel (fernandomiguel)]

Leann i unloaded the driver, rebooted, and then tried it again.
suspend and resume work;
hibernate will fail, and wake in a few sec.

Feb 18 02:26:47 blubug kernel: [21442.513954] PM: Syncing filesystems ... done.
Feb 18 02:26:47 blubug kernel: [21442.589665] PM: Preparing system for mem sleep
Feb 18 02:26:47 blubug kernel: [21442.589669] Freezing user space processes ... (elapsed 0.00 seconds) done.
Feb 18 02:26:47 blubug kernel: [21442.590524] Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
Feb 18 02:26:47 blubug kernel: [21442.590560] PM: Entering mem sleep
Feb 18 02:26:47 blubug kernel: [21442.590574] Suspending console(s) (use no_console_suspend to debug)
Feb 18 02:26:47 blubug kernel: [21442.696044] gl860: Genesys USB2.0 Camera disconnected
Feb 18 02:26:47 blubug kernel: [21442.696094] gl860: Genesys USB2.0 Camera release resources video device /dev/video0
Feb 18 02:26:47 blubug kernel: [21443.460764] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Feb 18 02:26:47 blubug kernel: [21443.460963] sd 0:0:0:0: [sda] Stopping disk
Feb 18 02:26:47 blubug kernel: [21444.088770] ricoh-mmc: Suspending.
Feb 18 02:26:47 blubug kernel: [21444.088777] ricoh-mmc: Controller is now re-enabled.
Feb 18 02:26:47 blubug kernel: [21444.088822] ACPI handle has no context!
Feb 18 02:26:47 blubug kernel: [21444.088827] sdhci-pci 0000:07:01.1: PCI INT B disabled
Feb 18 02:26:47 blubug kernel: [21444.088831] ACPI handle has no context!
Feb 18 02:26:47 blubug kernel: [21444.109052] ACPI handle has no context!
Feb 18 02:26:47 blubug kernel: [21444.124043] sky2 eth0: disabling interface
Feb 18 02:26:47 blubug kernel: [21444.125464] ACPI handle has no context!
Feb 18 02:26:47 blubug kernel: [21444.125469] ACPI handle has no context!
Feb 18 02:26:47 blubug kernel: [21444.156170] ahci 0000:03:00.0: PCI INT A disabled
Feb 18 02:26:47 blubug kernel: [21444.188074] NVRM: RmPowerManagement: 4
Feb 18 02:26:47 blubug kernel: [21444.332150] ata6: port disabled. ignoring.
Feb 18 02:26:47 blubug kernel: [21444.332195] ata_piix 0000:00:1f.1: PCI INT A disabled
Feb 18 02:26:47 blubug kernel: [21444.332289] ehci_hcd 0000:00:1d.7: PCI INT A disabled
Feb 18 02:26:47 blubug kernel: [21444.348061] uhci_hcd 0000:00:1d.2: PCI INT C disabled
Feb 18 02:26:47 blubug kernel: [21444.348094] uhci_hcd 0000:00:1d.1: PCI INT B disabled
Feb 18 02:26:47 blubug kernel: [21444.348125] uhci_hcd 0000:00:1d.0: PCI INT A disabled
Feb 18 02:26:47 blubug kernel: [21444.380058] HDA Intel 0000:00:1b.0: PCI INT A disabled
Feb 18 02:26:47 blubug kernel: [21444.380108] ACPI handle has no context!
Feb 18 02:26:47 blubug kernel: [21444.396077] ehci_hcd 0000:00:1a.7: PCI INT C disabled
Feb 18 02:26:47 blubug kernel: [21444.412071] uhci_hcd 0000:00:1a.1: PCI INT B disabled
Feb 18 02:26:47 blubug kernel: [21444.412103] uhci_hcd 0000:00:1a.0: PCI INT A disabled
Feb 18 02:26:47 blubug kernel: [21444.412201] PM: suspend devices took 1.824 seconds
Feb 18 02:26:47 blubug kernel: [21444.412555] ACPI: Preparing to enter system sleep state S3
Feb 18 02:26:47 blubug kernel: [21444.413967] Disabling non-boot CPUs ...
Feb 18 02:26:47 blubug kernel: [21444.416361] CPU 1 is now offline
Feb 18 02:26:47 blubug ker...

[Fernando Miguel (fernandomiguel)]

disabled the driver, installed a new driver (Linux blubug 2.6.28-8-generic #23-Ubuntu SMP Wed Feb 18 04:22:10 UTC 2009 x86_64 GNU/Linux), and remove the entrie in /etc/module, so that the webcam was not the cause.

I can suspend and then resume, but hibernate will not work.

[Fernando Miguel (fernandomiguel)]

I wonder if has anything to do with the changes made to detect fail in resume, and call apport

[Andy Whitcroft (apw)]

@BUGabundo -- the changes for that in the suspend/hibernate cycle are limited to creating and removing a single file. So are unlikely to be realted to this issue.

As for the original message. This is triggered when resuming the system too over 5 seconds from the time it started resume to when the resume is deemed complete. Although it comes with a back trace, it is mearly informational and indicative of a relativly slow resume. The kernel still carries on in the same manner. In your case it is tellng us that your resume took approximatly 8s, which isn't mad slow:

    Feb 17 01:17:00 blubug kernel: [15010.424230] PM: resume devices took 8.112 seconds

As this message is benign I will close this one off.

[Andy Whitcroft (apw)]

This is a benign kernel message indicating that the resume time was higher than expected. No action is required. Closing.

[Nol (o-lorin)]

Just to be sure: no trouble with the gl860 driver?

[Fernando Miguel (fernandomiguel)]

Sorry Nol... forgot to update the forum.
AFAICT it is not caused (at least alone) by your driver.

[Andres Mujica (andres.mujica)]

this seems as dupe from bug #350609 .. failed to IDENTIFY (I/O Error...

Feb 13 21:06:09 blubug kernel: [ 963.713392] sd 0:0:0:0: [sda] Starting disk
Feb 13 21:06:09 blubug kernel: [ 963.928189] ata4: SATA link down (SStatus 0 SControl 300)
Feb 13 21:06:09 blubug kernel: [ 964.181340] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x1)
Feb 13 21:06:09 blubug kernel: [ 964.181341] ata5.00: revalidation failed (errno=-5)
Feb 13 21:06:09 blubug kernel: [ 966.065176] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Feb 13 21:06:09 blubug kernel: [ 966.079720] ata1.00: configured for UDMA/133
Feb 13 21:06:09 blubug kernel: [ 966.092226] sd 0:0:0:0: [sda] 625142448 512-byte hardware sectors: (320 GB/298 GiB)
Feb 13 21:06:09 blubug kernel: [ 966.092250] sd 0:0:0:0: [sda] Write Protect is off
Feb 13 21:06:09 blubug kernel: [ 966.092253] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Feb 13 21:06:09 blubug kernel: [ 966.092283] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Feb 13 21:06:09 blubug kernel: [ 967.140178] usb 7-6: reset high speed USB device using ehci_hcd and address 3
Feb 13 21:06:09 blubug kernel: [ 967.396176] usb 1-1: reset full speed USB device using uhci_hcd and address 2
Feb 13 21:06:09 blubug kernel: [ 967.660175] usb 5-1: reset full speed USB device using uhci_hcd and address 2
Feb 13 21:06:09 blubug kernel: [ 967.881391] gl860: Release: 0103
Feb 13 21:06:09 blubug kernel: [ 967.881393] gl860: Number of interfaces : 1
Feb 13 21:06:09 blubug kernel: [ 967.881394] gl860: Version Hulkie/Iceman/Soro (c)
Feb 13 21:06:09 blubug kernel: [ 967.881395] gl860: Genesys USB2.0 - GL860 based webcam found.
Feb 13 21:06:09 blubug kernel: [ 967.881396] gl860: Genesys USB2.0 2.0M WebCam - Product ID 0x0503.
Feb 13 21:06:09 blubug kernel: [ 969.344373] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x1)
Feb 13 21:06:09 blubug kernel: [ 969.344375] ata5.00: revalidation failed (errno=-5)