Attachment 892424 Details for Bug 1094111 – /var/log/messages from manually triggered and successfully completed (and restored) hibernate

/var/log/messages from manually triggered and successfully completed (and restored) hibernate

1094111-success-hibernation-var_log_messages.txt (text/plain), 15.11 KB, created by japa-fi on 2014-05-05 06:06:03 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: japa-fi

Created: 2014-05-05 06:06:03 UTC

Size: 15.11 KB

patch

obsolete

>May  4 19:17:40 myhost NetworkManager[882]: <info> sleep requested (sleeping: no  enabled: yes)
>May  4 19:17:40 myhost NetworkManager[882]: <info> sleeping or disabling...
>May  4 19:17:40 myhost NetworkManager[882]: <info> (em1): device state change: activated -> unmanaged (reason 'sleeping') [100 10 37]
>May  4 19:17:40 myhost NetworkManager[882]: <info> (em1): deactivating device (reason 'sleeping') [37]
>May  4 19:17:40 myhost NetworkManager[882]: <info> (em1): canceled DHCP transaction, DHCP client pid 1487
>May  4 19:17:40 myhost NetworkManager[882]: <info> (em1): cleaning up...
>May  4 19:17:40 myhost NetworkManager[882]: <info> (em1): taking down device.
>May  4 19:17:41 myhost NetworkManager[882]: <info> NetworkManager state is now ASLEEP
>May  4 19:17:41 myhost NetworkManager[882]: <info> (wlp3s0): device state change: disconnected -> unmanaged (reason 'sleeping') [30 10 37]
>May  4 19:17:41 myhost NetworkManager[882]: <info> (wlp3s0): cleaning up...
>May  4 19:17:41 myhost NetworkManager[882]: <info> (wlp3s0): taking down device.
>May  4 19:17:41 myhost dbus[754]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop
>.nm-dispatcher.service'
>May  4 19:17:41 myhost dbus-daemon[754]: dbus[754]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='db
>us-org.freedesktop.nm-dispatcher.service'
>May  4 19:17:41 myhost systemd[1]: Starting Network Manager Script Dispatcher Service...
>May  4 19:17:41 myhost dbus-daemon[754]: dbus[754]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
>May  4 19:17:41 myhost dbus[754]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
>May  4 19:17:41 myhost systemd[1]: Started Network Manager Script Dispatcher Service.
>May  4 19:17:41 myhost systemd[1]: Starting Sleep.
>May  4 19:17:41 myhost systemd[1]: Reached target Sleep.
>May  4 19:17:41 myhost systemd[1]: Starting Hibernate...
>May  4 19:17:41 myhost chronyd[752]: Source 81.22.244.161 offline
>May  4 19:17:41 myhost chronyd[752]: Source 194.100.2.194 offline
>May  4 19:17:41 myhost chronyd[752]: Source 77.86.199.2 offline
>May  4 19:17:41 myhost chronyd[752]: Source 62.237.86.234 offline
>May  4 19:17:41 myhost systemd-sleep[2201]: Suspending system...
>May  4 19:17:41 myhost kernel: [  215.248316] PM: Syncing filesystems ... done.
>May  4 19:18:54 myhost kernel: [  215.708837] Freezing user space processes ... (elapsed 0.001 seconds) done.
>May  4 19:18:54 myhost kernel: [  215.711037] PM: Preallocating image memory... done (allocated 712621 pages)
>May  4 19:18:54 myhost kernel: [  216.029584] PM: Allocated 2850484 kbytes in 0.31 seconds (9195.10 MB/s)
>May  4 19:18:54 myhost kernel: [  216.029585] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
>May  4 19:18:54 myhost kernel: [  216.030969] Suspending console(s) (use no_console_suspend to debug)
>May  4 19:18:54 myhost kernel: [  216.084602] PM: freeze of devices complete after 53.591 msecs
>May  4 19:18:54 myhost kernel: [  216.084699] PM: late freeze of devices complete after 0.082 msecs
>May  4 19:18:54 myhost kernel: [  216.085360] PM: noirq freeze of devices complete after 0.659 msecs
>May  4 19:18:54 myhost kernel: [  216.085533] ACPI: Preparing to enter system sleep state S4
>May  4 19:18:54 myhost kernel: [  216.087677] PM: Saving platform NVS memory
>May  4 19:18:54 myhost kernel: [  216.088278] Disabling non-boot CPUs ...
>May  4 19:18:54 myhost kernel: [  216.089845] kvm: disabling virtualization on CPU1
>May  4 19:18:54 myhost kernel: [  216.089857] smpboot: CPU 1 is now offline
>May  4 19:18:54 myhost kernel: [  216.090361] Broke affinity for irq 48
>May  4 19:18:54 myhost kernel: [  216.091374] kvm: disabling virtualization on CPU2
>May  4 19:18:54 myhost kernel: [  216.091381] smpboot: CPU 2 is now offline
>May  4 19:18:54 myhost kernel: [  216.092832] kvm: disabling virtualization on CPU3
>May  4 19:18:54 myhost kernel: [  216.092845] smpboot: CPU 3 is now offline
>May  4 19:18:54 myhost kernel: [  216.093242] PM: Creating hibernation image:
>May  4 19:18:54 myhost kernel: [  216.269361] PM: Need to copy 711357 pages
>May  4 19:18:54 myhost kernel: [  216.093899] PM: Restoring platform NVS memory
>May  4 19:18:54 myhost kernel: [  216.094376] microcode: CPU0 sig=0x306a9, pf=0x10, revision=0x19
>May  4 19:18:54 myhost kernel: [  216.094397] Enabling non-boot CPUs ...
>May  4 19:18:54 myhost kernel: [  216.094427] x86: Booting SMP configuration:
>May  4 19:18:54 myhost kernel: [  216.094428] smpboot: Booting Node 0 Processor 1 APIC 0x1
>May  4 19:18:54 myhost kernel: [  216.106314] kvm: enabling virtualization on CPU1
>May  4 19:18:54 myhost kernel: [  216.108679] Intel pstate controlling: cpu 1
>May  4 19:18:54 myhost kernel: [  216.108750] microcode: CPU1 sig=0x306a9, pf=0x10, revision=0x16
>May  4 19:18:54 myhost kernel: [  216.109411] microcode: CPU1 updated to revision 0x19, date = 2013-06-13
>May  4 19:18:54 myhost kernel: [  216.109435] CPU1 is up
>May  4 19:18:54 myhost kernel: [  216.109452] smpboot: Booting Node 0 Processor 2 APIC 0x2
>May  4 19:18:54 myhost kernel: [  216.120821] kvm: enabling virtualization on CPU2
>May  4 19:18:54 myhost kernel: [  216.123054] Intel pstate controlling: cpu 2
>May  4 19:18:54 myhost kernel: [  216.123089] microcode: CPU2 sig=0x306a9, pf=0x10, revision=0x16
>May  4 19:18:54 myhost kernel: [  216.123388] microcode: CPU2 updated to revision 0x19, date = 2013-06-13
>May  4 19:18:54 myhost kernel: [  216.123395] CPU2 is up
>May  4 19:18:54 myhost kernel: [  216.123408] smpboot: Booting Node 0 Processor 3 APIC 0x3
>May  4 19:18:54 myhost kernel: [  216.134766] kvm: enabling virtualization on CPU3
>May  4 19:18:54 myhost kernel: [  216.137021] Intel pstate controlling: cpu 3
>May  4 19:18:54 myhost kernel: [  216.137055] microcode: CPU3 sig=0x306a9, pf=0x10, revision=0x19
>May  4 19:18:54 myhost kernel: [  216.137062] CPU3 is up
>May  4 19:18:54 myhost kernel: [  216.139796] ACPI: Waking up from system sleep state S4
>May  4 19:18:54 myhost kernel: [  216.152218] thinkpad_acpi: EC reports that Thermal Table has changed
>May  4 19:18:54 myhost kernel: [  216.176896] sdhci-pci 0000:02:00.0: MMC controller base frequency changed to 50Mhz.
>May  4 19:18:54 myhost kernel: [  216.177366] PM: noirq restore of devices complete after 22.828 msecs
>May  4 19:18:54 myhost kernel: [  216.177459] PM: early restore of devices complete after 0.068 msecs
>May  4 19:18:54 myhost kernel: [  216.307388] usb usb3: root hub lost power or was reset
>May  4 19:18:54 myhost kernel: [  216.307390] usb usb4: root hub lost power or was reset
>May  4 19:18:54 myhost kernel: [  216.307459] xhci_hcd 0000:00:14.0: Slot 1 endpoint 2 not removed from BW list!
>May  4 19:18:54 myhost kernel: [  216.307460] xhci_hcd 0000:00:14.0: Slot 1 endpoint 4 not removed from BW list!
>May  4 19:18:54 myhost kernel: [  216.307621] usb usb1: root hub lost power or was reset
>May  4 19:18:54 myhost kernel: [  216.308140] usb usb2: root hub lost power or was reset
>May  4 19:18:54 myhost kernel: [  216.311650] iwlwifi 0000:03:00.0: RF_KILL bit toggled to enable radio.
>May  4 19:18:54 myhost kernel: [  216.615669] usb 2-1: reset high-speed USB device number 2 using ehci-pci
>May  4 19:18:54 myhost kernel: [  216.620661] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>May  4 19:18:54 myhost kernel: [  216.620685] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
>May  4 19:18:54 myhost kernel: [  216.621785] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
>May  4 19:18:54 myhost kernel: [  216.621787] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
>May  4 19:18:54 myhost kernel: [  216.622656] ata5: SATA link down (SStatus 0 SControl 300)
>May  4 19:18:54 myhost kernel: [  216.624347] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
>May  4 19:18:54 myhost kernel: [  216.624350] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
>May  4 19:18:54 myhost kernel: [  216.625333] ata1.00: configured for UDMA/133
>May  4 19:18:54 myhost kernel: [  216.625439] sd 0:0:0:0: [sda] Starting disk
>May  4 19:18:54 myhost kernel: [  216.625470] ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
>May  4 19:18:54 myhost kernel: [  216.633848] ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
>May  4 19:18:54 myhost kernel: [  216.634129] ata2.00: configured for UDMA/100
>May  4 19:18:54 myhost kernel: [  216.831824] usb 1-1: reset high-speed USB device number 2 using ehci-pci
>May  4 19:18:54 myhost kernel: [  217.198128] usb 3-2: reset low-speed USB device number 2 using xhci_hcd
>May  4 19:18:54 myhost kernel: [  217.212655] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880405e12e40
>May  4 19:18:54 myhost kernel: [  217.212658] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880405e12e80
>May  4 19:18:54 myhost kernel: [  217.212664] usb 3-2: ep 0x81 - rounding interval to 64 microframes, ep desc says 80 microframes
>May  4 19:18:54 myhost kernel: [  217.212670] usb 3-2: ep 0x82 - rounding interval to 64 microframes, ep desc says 80 microframes
>May  4 19:18:54 myhost kernel: [  217.222897] input input6: event field not found
>May  4 19:18:54 myhost kernel: [  217.222899] input input6: event field not found
>May  4 19:18:54 myhost kernel: [  217.222900] input input6: event field not found
>May  4 19:18:54 myhost kernel: [  217.222901] input input6: event field not found
>May  4 19:18:54 myhost kernel: [  217.222902] input input6: event field not found
>May  4 19:18:54 myhost kernel: [  217.222903] input input6: event field not found
>May  4 19:18:54 myhost kernel: [  217.222904] input input6: event field not found
>May  4 19:18:54 myhost kernel: [  217.222930] input input7: event field not found
>May  4 19:18:54 myhost kernel: [  217.222930] input input7: event field not found
>May  4 19:18:54 myhost kernel: [  217.222931] input input7: event field not found
>May  4 19:18:54 myhost kernel: [  217.222931] input input7: event field not found
>May  4 19:18:54 myhost kernel: [  217.222932] input input7: event field not found
>May  4 19:18:54 myhost kernel: [  217.222932] input input7: event field not found
>May  4 19:18:54 myhost kernel: [  217.222933] input input7: event field not found
>May  4 19:18:54 myhost kernel: [  217.283512] usb 1-1.1: reset full-speed USB device number 3 using ehci-pci
>May  4 19:18:54 myhost kernel: [  217.421415] usb 1-1.4: reset full-speed USB device number 4 using ehci-pci
>May  4 19:18:54 myhost kernel: [  217.569474] usb 1-1.6: reset high-speed USB device number 5 using ehci-pci
>May  4 19:18:54 myhost kernel: [  217.652080] PM: restore of devices complete after 1343.914 msecs
>May  4 19:18:54 myhost systemd[1]: Time has been changed
>May  4 19:18:54 myhost kernel: [  217.653641] Restarting tasks ... done.
>May  4 19:18:54 myhost kernel: [  217.661079] video LNXVIDEO:00: Restoring backlight state
>May  4 19:18:54 myhost systemd-sleep[2201]: System resumed.
>May  4 19:18:54 myhost systemd[1]: Service bluetooth.target is not needed anymore. Stopping.
>May  4 19:18:54 myhost systemd[1]: Stopping Bluetooth.
>May  4 19:18:54 myhost systemd[1]: Stopped target Bluetooth.
>May  4 19:18:54 myhost systemd[1]: Starting Bluetooth.
>May  4 19:18:54 myhost systemd[1]: Reached target Bluetooth.
>May  4 19:18:54 myhost kernel: [  217.705305] [drm] Enabling RC6 states: RC6 on, RC6p on, RC6pp off
>May  4 19:18:54 myhost systemd[1]: Started Hibernate.
>May  4 19:18:54 myhost systemd[1]: Service sleep.target is not needed anymore. Stopping.
>May  4 19:18:54 myhost systemd[1]: Stopping Sleep.
>May  4 19:18:54 myhost systemd[1]: Stopped target Sleep.
>May  4 19:18:54 myhost systemd[1]: Starting Hibernate.
>May  4 19:18:54 myhost systemd[1]: Reached target Hibernate.
>May  4 19:18:54 myhost systemd-logind[755]: Operation finished.
>May  4 19:18:54 myhost NetworkManager[882]: <info> wake requested (sleeping: yes  enabled: yes)
>May  4 19:18:54 myhost NetworkManager[882]: <info> waking up and re-enabling...
>May  4 19:18:54 myhost NetworkManager[882]: <info> WWAN now enabled by management service
>May  4 19:18:54 myhost NetworkManager[882]: <info> (em1): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
>May  4 19:18:54 myhost NetworkManager[882]: <info> (em1): bringing up device.
>May  4 19:18:54 myhost NetworkManager[882]: <info> (em1): preparing device.
>May  4 19:18:54 myhost kernel: [  217.977880] IPv6: ADDRCONF(NETDEV_UP): em1: link is not ready
>May  4 19:18:54 myhost NetworkManager[882]: <info> (em1): deactivating device (reason 'managed') [2]
>May  4 19:18:54 myhost NetworkManager[882]: <info> NetworkManager state is now DISCONNECTED
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0): bringing up device.
>May  4 19:18:54 myhost kernel: [  217.979250] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
>May  4 19:18:54 myhost kernel: [  217.985967] iwlwifi 0000:03:00.0: Radio type=0x1-0x2-0x0
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0): preparing device.
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0): deactivating device (reason 'managed') [2]
>May  4 19:18:54 myhost kernel: [  218.067724] IPv6: ADDRCONF(NETDEV_UP): wlp3s0: link is not ready
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0) supports 5 scan SSIDs
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0): supplicant interface state: starting -> ready
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
>May  4 19:18:54 myhost NetworkManager[882]: <warn> Trying to remove a non-existant call id.
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0): supplicant interface state: ready -> disconnected
>May  4 19:18:54 myhost NetworkManager[882]: <info> (wlp3s0) supports 5 scan SSIDs
>May  4 19:18:56 myhost kernel: [  219.581436] e1000e: em1 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx
>May  4 19:18:56 myhost kernel: [  219.581442] e1000e 0000:00:19.0 em1: 10/100 speed: disabling TSO
>May  4 19:18:56 myhost kernel: [  219.581485] IPv6: ADDRCONF(NETDEV_CHANGE): em1: link becomes ready
>May  4 19:18:56 myhost NetworkManager[882]: <info> (em1): carrier now ON (device state 20)
>May  4 19:18:56 myhost NetworkManager[882]: <info> (em1): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
>May  4 19:18:56 myhost NetworkManager[882]: <info> Auto-activating connection 'Auto Ethernet'.
>May  4 19:18:56 myhost NetworkManager[882]: <info> Activation (em1) starting connection 'Auto Ethernet'
>May  4 19:18:56 myhost NetworkManager[882]: <info> (em1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
>May  4 19:18:56 myhost NetworkManager[882]: <info> NetworkManager state is now CONNECTING
>May  4 19:18:56 myhost NetworkManager[882]: <info> Activation (em1) Stage 1 of 5 (Device Prepare) scheduled...
>May  4 19:18:56 myhost NetworkManager[882]: <info> Activation (em1) Stage 1 of 5 (Device Prepare) started...
>May  4 19:18:56 myhost NetworkManager[882]: <info> Activation (em1) Stage 2 of 5 (Device Configure) scheduled...
>May  4 19:18:56 myhost NetworkManager[882]: <info> Activation (em1) Stage 1 of 5 (Device Prepare) complete.
>

Actions: View

Attachments on bug 1094111: 892420 | 892422 | 892424