xl crashes on resume from S3 sleep

[marmarek]

Reported by joanna on 3 Jul 2011 08:31 UTC
getting this in dmesg (but besides that, all is fine!):

[xl[18035](45464.256046]): segfault at fffffffffffffffb ip 00007f0c7e85c83c sp 00007fff2d6a70a8 error 4 in libc-2.12.so[xl[18039](7f0c7e7e2000+175000]
[45464.262491]): segfault at fffffffffffffffb ip 00007f1a667bc83c sp 00007ffffa1069d8 error 4 in libc-2.12.so[xl[18042](7f1a66742000+175000]
[45464.268788]): segfault at fffffffffffffffb ip 00007fa3d886483c sp 00007fff040813b8 error 4 in libc-2.12.so[xl[18045](7fa3d87ea000+175000]
[45464.278045]): segfault at fffffffffffffffb ip 00007fbbca4bd83c sp 00007fffce36ddf8 error 4 in libc-2.12.so[PM: Syncing filesystems ... done.
[45466.751348](7fbbca443000+175000]
[45466.750797]) PM: Preparing system for mem sleep
[Freezing user space processes ... (elapsed 0.01 seconds) done.
[45467.136206](45467.120413]) Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[PM: Entering mem sleep
[45467.152248](45467.152202]) Suspending console(s) (use no_console_suspend to debug)
[sd 2:0:0:0: [sdb](45467.152999]) Synchronizing SCSI cache
[sd 0:0:0:0: [sda](45467.153439]) Synchronizing SCSI cache
[sd 2:0:0:0: [sdb](45467.156638]) Stopping disk
[sd 0:0:0:0: [sda](45467.156926]) Stopping disk
[pciback 0000:02:00.0: PCI INT A disabled
[45467.296408](45467.296381]) pci 0000:00:1f.6: PCI INT C disabled
[pci 0000:00:1f.3: PCI INT B disabled
[45467.296473](45467.296419]) pciback 0000:00:1d.0: PCI INT A disabled
[ACPI handle has no context!
[45467.296707](45467.296682]) sdhci-pci 0000:03:00.4: PCI INT C disabled
[sdhci-pci 0000:03:00.0: PCI INT A disabled
[45467.296751](45467.296742]) ACPI handle has no context!
[ehci_hcd 0000:00:1a.0: PCI INT A disabled
[45467.297424](45467.297408]) pciback 0000:00:19.0: PCI INT A disabled
[i915 0000:00:02.0: power state changed by ACPI to D3
[45467.400338](45467.336205]) HDA Intel 0000:00:1b.0: PCI INT A disabled
[PM: suspend of devices complete after 303.503 msecs
[45467.472371](45467.456197]) PM: late suspend of devices complete after 16.166 msecs
[ACPI: Preparing to enter system sleep state S3
[45467.484285](45467.472562]) PM: Saving platform NVS memory
[Disabling non-boot CPUs ...
[45467.813321](45467.484291]) SMP alternatives: switching to UP code
[Extended CMOS year: 2000
[45467.850851](45467.850352]) Back to C!
[PM: Restoring platform NVS memory
[45467.851105](45467.850857]) Extended CMOS year: 2000
[Enabling non-boot CPUs ...
[45467.851373](45467.851127]) SMP alternatives: switching to SMP code
[Switched to NOHz mode on CPU #1
[45467.884788](45467.884187]) CPU1 is up
[Switched to NOHz mode on CPU #2
[45467.940646](45467.888089]) CPU2 is up
[Switched to NOHz mode on CPU #3
[45467.996785](45467.944163]) CPU3 is up
[ACPI: Waking up from system sleep state S3
[45468.054579](45467.996788]) i915 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007, writing 0x900407)
[pciback 0000:00:19.0: restoring config space at offset 0x1 (was 0x100007, writing 0x100003)
[45468.054959](45468.054831]) ehci_hcd 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)
[HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)
[45468.055699](45468.055138]) pciback 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900006, writing 0x2900002)
[pci 0000:00:1e.0: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)
[45468.056016](45468.055777]) ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407)
[pci 0000:00:1f.6: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)
[45468.056539](45468.056322]) pciback 0000:02:00.0: restoring config space at offset 0x1 (was 0x100006, writing 0x100002)
[sdhci-pci 0000:03:00.0: restoring config space at offset 0xf (was 0x100, writing 0x10b)
[45468.056732](45468.056676]) sdhci-pci 0000:03:00.0: restoring config space at offset 0x4 (was 0x0, writing 0xb4400a00)
[sdhci-pci 0000:03:00.0: restoring config space at offset 0x3 (was 0x800000, writing 0x800010)
[45468.056761](45468.056744]) sdhci-pci 0000:03:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100006)
[pci 0000:03:00.1: restoring config space at offset 0xf (was 0x200, writing 0x20a)
[45468.056916](45468.056861]) pci 0000:03:00.1: restoring config space at offset 0x4 (was 0x0, writing 0xb4400900)
[pci 0000:03:00.1: restoring config space at offset 0x3 (was 0x800000, writing 0x800010)
[45468.056945](45468.056929]) pci 0000:03:00.1: restoring config space at offset 0x1 (was 0x100000, writing 0x100006)
[sdhci-pci 0000:03:00.4: restoring config space at offset 0xf (was 0x300, writing 0x305)
[45468.057099](45468.057043]) sdhci-pci 0000:03:00.4: restoring config space at offset 0x4 (was 0x0, writing 0xb4400800)
[sdhci-pci 0000:03:00.4: restoring config space at offset 0x3 (was 0x800000, writing 0x800010)
[45468.057128](45468.057112]) sdhci-pci 0000:03:00.4: restoring config space at offset 0x1 (was 0x100000, writing 0x100006)
[PM: early resume of devices complete after 3.175 msecs
[45468.058005](45468.057609]) i915 0000:00:02.0: power state changed by ACPI to D0
[i915 0000:00:02.0: power state changed by ACPI to D0
[45468.058028](45468.058014]) i915 0000:00:02.0: setting latency timer to 64
[pciback 0000:00:19.0: PCI INT A -> GSI 18 (level, low) -> IRQ 18
[45468.059887](45468.059870]) pciback 0000:00:19.0: setting latency timer to 64
[ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[45468.059922](45468.059908]) ehci_hcd 0000:00:1a.0: setting latency timer to 64
[HDA Intel 0000:00:1b.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[45468.059990](45468.059976]) HDA Intel 0000:00:1b.0: setting latency timer to 64
[pciback 0000:00:1d.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[45468.060179](45468.060146]) pci 0000:00:1e.0: setting latency timer to 64
[pciback 0000:00:1d.0: setting latency timer to 64
[45468.060208](45468.060187]) pci 0000:00:1f.3: PCI INT B -> GSI 22 (level, low) -> IRQ 22
[pci 0000:00:1f.6: PCI INT C -> GSI 22 (level, low) -> IRQ 22
[45468.060232](45468.060226]) ahci 0000:00:1f.2: setting latency timer to 64
[HDA Intel 0000:00:1b.0: irq 49 (277) for MSI/MSI-X
[45468.060244](45468.060239]) pciback 0000:02:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[pciback 0000:02:00.0: setting latency timer to 64
[45468.060321](45468.060286]) sdhci-pci 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[sdhci-pci 0000:03:00.4: PCI INT C -> GSI 19 (level, low) -> IRQ 19
[45468.060528](45468.060388]) sd 0:0:0:0: [Starting disk
[45468.061392](sda]) sd 2:0:0:0: [Starting disk
[45468.069771](sdb]) power_supply BAT1: parent PNP0C0A:00 should not be sleeping
[ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[45468.380211](45468.380171]) ata5: SATA link down (SStatus 0 SControl 300)
[ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[45468.380277](45468.380248]) ata4: SATA link down (SStatus 0 SControl 300)
[ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[45468.380658](45468.380316]) ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
[ata3.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
[45468.381110](45468.380815]) ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
[ata3.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
[45468.381295](45468.381284]) ata1.00: configured for UDMA/100
[ata3.00: configured for UDMA/100
[45468.381959](45468.381379]) ata2.00: unexpected _GTF length (8)
[ata2.00: unexpected _GTF length (8)
[45468.387774](45468.387768]) ata2.00: configured for UDMA/100
[sdhci-pci 0000:03:00.0: Will use DMA mode even though HW doesn't fully claim to support it.
[45468.564137](45468.564130]) sdhci-pci 0000:03:00.4: Will use DMA mode even though HW doesn't fully claim to support it.
[sdhci-pci 0000:03:00.0: setting latency timer to 64
[45468.564163](45468.564159]) sdhci-pci 0000:03:00.4: setting latency timer to 64
[PM: resume of devices complete after 677.028 msecs
[45468.735289](45468.734883]) PM: Finishing wakeup.
[Restarting tasks ... done.
[45468.737919](45468.735293]) video LNXVIDEO:00: Restoring backlight state
[xl[18296](45470.380329]): segfault at fffffffffffffffb ip 00007f5abdf7a83c sp 00007fff88b26fd8 error 4 in libc-2.12.so[xl[18299](7f5abdf00000+175000]
[45470.389353]): segfault at fffffffffffffffb ip 00007fe8782b583c sp 00007fff97459838 error 4 in libc-2.12.so[xl[18302](7fe87823b000+175000]
[45470.396370]): segfault at fffffffffffffffb ip 00007fa49cd7d83c sp 00007fff5b424a38 error 4 in libc-2.12.so[xl[18305](7fa49cd03000+175000]
[45470.405777]): segfault at fffffffffffffffb ip 00007f3a9472b83c sp 00007fff0d9288b8 error 4 in libc-2.12.so[7f3a946b1000+175000]

This seems likely triggered by our pm-utils scripts.

Migrated-From: https://wiki.qubes-os.org/ticket/267

[marmarek]

Comment by marmarek on 6 Jul 2011 21:53 UTC
Yes, this is bug in xl pci-list (SEGV when VM has no PCI devices). I've send patch for this to xen-devel, but forgot to include in our xen repo...
Fixed now (finally by different patch).

http://git.qubes-os.org/gitweb/?p=marmarek/xen.git;a=commit;h=40277c7619f922808b972e132332af5c6bb8ea3b

[marmarek]

Comment by marmarek on 6 Jul 2011 21:53 UTC
Yes, this is bug in xl pci-list (SEGV when VM has no PCI devices). I've send patch for this to xen-devel, but forgot to include in our xen repo...
Fixed now (finally by different patch).

http://git.qubes-os.org/gitweb/?p=marmarek/xen.git;a=commit;h=40277c7619f922808b972e132332af5c6bb8ea3b