Bug 749962 - systemd-logind - session removed after resume from ram (suspend to ram, polkitd)
Summary: systemd-logind - session removed after resume from ram (suspend to ram, polkitd)
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 16
Hardware: i686
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-10-29 09:16 UTC by Thomas Meyer
Modified: 2012-01-29 15:44 UTC (History)
8 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2012-01-29 15:44:36 UTC
Type: ---
Embargoed:

Attachments (Terms of Use)

Description Thomas Meyer 2011-10-29 09:16:13 UTC 
Description of problem:
Sometimes after resume from ram, systemd seems to remove my current X session and I'm forced to login again in gdm. I suspended to ram via ssh and did a "sudo pm-suspend" with the same user as the current gdm session user.

here some log:

/var/log/messages:

Oct 29 10:31:41 localhost kernel: [76411.299154] Freezing user space processes ... (elapsed 0.03 seconds) done.
Oct 29 10:31:41 localhost kernel: [76411.339070] Freezing remaining freezable tasks ... (elapsed 0.24 seconds) done.
Oct 29 10:31:41 localhost kernel: [76411.579185] Suspending console(s) (use no_console_suspend to debug)
Oct 29 10:31:41 localhost kernel: [76411.581778] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Oct 29 10:31:41 localhost kernel: [76411.581875] sd 0:0:0:0: [sda] Stopping disk
Oct 29 10:31:41 localhost kernel: [76411.632738] uhci_hcd 0000:00:1d.2: PCI INT D disabled
Oct 29 10:31:41 localhost kernel: [76411.632750] uhci_hcd 0000:00:1d.1: PCI INT B disabled
Oct 29 10:31:41 localhost kernel: [76411.632761] uhci_hcd 0000:00:1d.0: PCI INT A disabled
Oct 29 10:31:41 localhost kernel: [76411.633497] ehci_hcd 0000:00:1a.7: PCI INT D disabled
Oct 29 10:31:41 localhost kernel: [76411.633514] uhci_hcd 0000:00:1a.0: PCI INT A disabled
Oct 29 10:31:41 localhost kernel: [76411.645723] ehci_hcd 0000:00:1d.7: PCI INT A disabled
Oct 29 10:31:41 localhost kernel: [76411.735783] snd_hda_intel 0000:00:1b.0: PCI INT A disabled
Oct 29 10:31:41 localhost kernel: [76412.262385] PM: suspend of devices complete after 683.006 msecs
Oct 29 10:31:41 localhost kernel: [76412.315773] PM: late suspend of devices complete after 53.381 msecs
Oct 29 10:31:41 localhost kernel: [76412.316373] ACPI: Preparing to enter system sleep state S3
Oct 29 10:31:41 localhost kernel: [76412.316501] PM: Saving platform NVS memory
Oct 29 10:31:41 localhost kernel: [76412.316501] ACPI: Low-level resume complete
Oct 29 10:31:41 localhost kernel: [76412.316501] PM: Restoring platform NVS memory
Oct 29 10:31:41 localhost kernel: [76412.316501] ACPI: Waking up from system sleep state S3
Oct 29 10:31:41 localhost kernel: [76412.434512] PM: early resume of devices complete after 1.151 msecs
Oct 29 10:31:41 localhost kernel: [76412.508558] uhci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
Oct 29 10:31:41 localhost kernel: [76412.508595] usb usb3: root hub lost power or was reset
Oct 29 10:31:41 localhost kernel: [76412.508612] ehci_hcd 0000:00:1a.7: PCI INT D -> GSI 19 (level, low) -> IRQ 19
Oct 29 10:31:41 localhost kernel: [76412.508650] snd_hda_intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
Oct 29 10:31:41 localhost kernel: [76412.508764] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
Oct 29 10:31:41 localhost kernel: [76412.508798] usb usb4: root hub lost power or was reset
Oct 29 10:31:41 localhost kernel: [76412.508812] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19
Oct 29 10:31:41 localhost kernel: [76412.508846] usb usb5: root hub lost power or was reset
Oct 29 10:31:41 localhost kernel: [76412.508859] uhci_hcd 0000:00:1d.2: PCI INT D -> GSI 16 (level, low) -> IRQ 16
Oct 29 10:31:41 localhost kernel: [76412.508893] usb usb6: root hub lost power or was reset
Oct 29 10:31:41 localhost kernel: [76412.508908] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23
Oct 29 10:31:41 localhost kernel: [76412.509469] sd 0:0:0:0: [sda] Starting disk
Oct 29 10:31:41 localhost kernel: [76412.513236] power_supply BAT1: parent PNP0C0A:00 should not be sleeping
Oct 29 10:31:41 localhost kernel: [76412.851968] usb 2-4: reset high speed USB device number 3 using ehci_hcd
Oct 29 10:31:41 localhost kernel: [76412.879066] ata2: SATA link down (SStatus 0 SControl 300)
Oct 29 10:31:41 localhost kernel: [76412.889062] ata6: SATA link down (SStatus 0 SControl 300)
Oct 29 10:31:41 localhost kernel: [76412.942194] ata5: SATA link down (SStatus 0 SControl 300)
Oct 29 10:31:41 localhost kernel: [76413.175723] usb 2-5: reset high speed USB device number 4 using ehci_hcd
Oct 29 10:31:41 localhost kernel: [76413.925735] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Oct 29 10:31:41 localhost kernel: [76413.927251] ata1.00: configured for UDMA/100
Oct 29 10:31:41 localhost kernel: [76413.996010] iwlagn 0000:02:00.0: L1 Enabled; Disabling L0S
Oct 29 10:31:41 localhost kernel: [76413.999060] iwlagn 0000:02:00.0: Radio type=0x1-0x2-0x0
Oct 29 10:31:41 localhost kernel: [76414.049107] PM: resume of devices complete after 1614.522 msecs
Oct 29 10:31:41 localhost kernel: [76414.049236] Restarting tasks ... done.
Oct 29 10:31:41 localhost kernel: [76414.064643] video LNXVIDEO:00: Restoring backlight state
Oct 29 10:31:41 localhost kernel: [76414.144992] cfg80211: Calling CRDA to update world regulatory domain
Oct 29 10:31:42 localhost NetworkManager[20553]: NetworkManager[20553]: <info> (wlan0): supplicant interface state: completed -> disconnected
Oct 29 10:31:42 localhost NetworkManager[20553]: <info> (wlan0): supplicant interface state: completed -> disconnected
Oct 29 10:31:42 localhost NetworkManager[20553]: NetworkManager[20553]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Oct 29 10:31:42 localhost NetworkManager[20553]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Oct 29 10:31:43 localhost dbus-daemon[605]: dbus[605]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Oct 29 10:31:43 localhost dbus[605]: [system] Activating service name='org.freedesktop.PackageKit' (using servicehelper)
Oct 29 10:31:43 localhost dbus-daemon[605]: (upowerd:22644): UPower-Linux-WARNING **: energy 50.616000 bigger than full 50.616000
Oct 29 10:31:44 localhost dbus-daemon[605]: (upowerd:22644): UPower-Linux-WARNING **: energy 50.616000 bigger than full 50.616000
Oct 29 10:31:45 localhost NetworkManager[20553]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Oct 29 10:31:45 localhost NetworkManager[20553]: NetworkManager[20553]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Oct 29 10:31:45 localhost NetworkManager[20553]: <info> (wlan0): supplicant interface state: authenticating -> associating
Oct 29 10:31:45 localhost NetworkManager[20553]: NetworkManager[20553]: <info> (wlan0): supplicant interface state: authenticating -> associating
Oct 29 10:31:45 localhost NetworkManager[20553]: <info> (wlan0): supplicant interface state: associating -> completed
Oct 29 10:31:45 localhost NetworkManager[20553]: NetworkManager[20553]: <info> (wlan0): supplicant interface state: associating -> completed
Oct 29 10:31:45 localhost kernel: [76418.189638] cfg80211: World regulatory domain updated:
Oct 29 10:31:45 localhost kernel: [76418.189643] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Oct 29 10:31:45 localhost kernel: [76418.189648] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Oct 29 10:31:45 localhost kernel: [76418.189652] cfg80211:     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Oct 29 10:31:45 localhost kernel: [76418.189656] cfg80211:     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Oct 29 10:31:45 localhost kernel: [76418.189660] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Oct 29 10:31:45 localhost kernel: [76418.189664] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Oct 29 10:31:45 localhost kernel: [76418.189678] cfg80211: Calling CRDA for country: DE
Oct 29 10:31:45 localhost kernel: [76418.194568] cfg80211: Regulatory domain changed to country: DE
Oct 29 10:31:45 localhost kernel: [76418.194572] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Oct 29 10:31:45 localhost kernel: [76418.194576] cfg80211:     (2400000 KHz - 2483500 KHz @ 40000 KHz), (N/A, 2000 mBm)
Oct 29 10:31:45 localhost kernel: [76418.194580] cfg80211:     (5150000 KHz - 5250000 KHz @ 40000 KHz), (N/A, 2000 mBm)
Oct 29 10:31:45 localhost kernel: [76418.194584] cfg80211:     (5250000 KHz - 5350000 KHz @ 40000 KHz), (N/A, 2000 mBm)
Oct 29 10:31:45 localhost kernel: [76418.194587] cfg80211:     (5470000 KHz - 5725000 KHz @ 40000 KHz), (N/A, 2698 mBm)
Oct 29 10:31:46 localhost kernel: [76418.337539] sd 6:0:0:0: [sdb] No Caching mode page present
Oct 29 10:31:46 localhost kernel: [76418.337546] sd 6:0:0:0: [sdb] Assuming drive cache: write through
Oct 29 10:31:46 localhost kernel: [76418.339663] sd 6:0:0:0: [sdb] No Caching mode page present
Oct 29 10:31:46 localhost kernel: [76418.339668] sd 6:0:0:0: [sdb] Assuming drive cache: write through
Oct 29 10:31:46 localhost kernel: [76418.341424]  sdb: unknown partition table
Oct 29 10:31:47 localhost systemd-logind[581]: Removed session 21.
Oct 29 10:31:48 localhost dbus-daemon[605]: dbus[605]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Oct 29 10:31:48 localhost dbus[605]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Oct 29 10:31:57 localhost systemd-logind[581]: New session 24 of user gdm.
Oct 29 10:31:57 localhost systemd-logind[581]: Linked /tmp/.X11-unix/X0 to /run/user/gdm/X11/display.
Oct 29 10:31:57 localhost gnome-session[29053]: DEBUG(+): Enabling debugging

/var/log/secure:
Oct 29 10:31:42 localhost polkitd(authority=local): Unregistered Authentication Agent for unix-session:/org/freedesktop/ConsoleKit/Session5 (system bus name :1.262, object path /org/gnome/PolicyKit1/AuthenticationAgent, locale de_DE.utf8) (disconnected from bus)
Oct 29 10:31:47 localhost gdm-password][20749]: pam_unix(gdm-password:session): session closed for user thomas
Oct 29 10:31:57 localhost gdm-welcome][29049]: pam_unix(gdm-welcome:session): session opened for user gdm by (uid=0)
Oct 29 10:32:10 localhost polkitd(authority=local): Registered Authentication Agent for unix-session:/org/freedesktop/ConsoleKit/Session6 (system bus name :1.380 [gnome-shell --gdm-mode], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale de_DE.UTF-8)
Oct 29 10:32:20 localhost gdm-password][29101]: pam_unix(gdm-password:session): session opened for user thomas by (uid=0)
Oct 29 10:32:20 localhost polkitd(authority=local): Unregistered Authentication Agent for unix-session:/org/freedesktop/ConsoleKit/Session6 (system bus name :1.380, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale de_DE.UTF-8) (disconnected from bus)
Oct 29 10:32:40 localhost polkitd(authority=local): Registered Authentication Agent for unix-session:/org/freedesktop/ConsoleKit/Session7 (system bus name :1.400 [/usr/libexec/polkit-gnome-authentication-agent-1], object path /org/gnome/PolicyKit1/AuthenticationAgent, locale de_DE.utf8)

/var/log/ConsoleKit/history:
1319877106.427 type=SEAT_ACTIVE_SESSION_CHANGED : seat-id='Seat1' session-id=''
1319877117.597 type=SEAT_SESSION_ADDED : seat-id='Seat1' session-id='Session6' session-type='LoginWindow' session-x11-display=':0' session-x11-display-device='/dev/tty8' session-display-device='' session-remote-host-name='' session-is-local=TRUE session-unix-user=42 session-creation-time='2011-10-29T08:31:57.597150Z'
1319877117.598 type=SEAT_ACTIVE_SESSION_CHANGED : seat-id='Seat1' session-id='Session6'
1319877140.895 type=SEAT_SESSION_REMOVED : seat-id='Seat1' session-id='Session6' session-type='LoginWindow' session-x11-display=':0' session-x11-display-device='/dev/tty8' session-display-device='' session-remote-host-name='' session-is-local=TRUE session-unix-user=42 session-creation-time='2011-10-29T08:31:57.597150Z'
1319877140.896 type=SEAT_ACTIVE_SESSION_CHANGED : seat-id='Seat1' session-id=''
1319877140.991 type=SEAT_SESSION_ADDED : seat-id='Seat1' session-id='Session7' session-type='' session-x11-display=':0' session-x11-display-device='/dev/tty8' session-display-device='' session-remote-host-name='' session-is-local=TRUE session-unix-user=1000 session-creation-time='2011-10-29T08:32:20.990759Z'
1319877140.992 type=SEAT_ACTIVE_SESSION_CHANGED : seat-id='Seat1' session-id='Session7'

the first message in above cut&paste of the secure log may indicate a polkitd problem. I don't know how polkitd, gdm and systemd-logind interact.

any ideas what is going on here?
Comment 1 Lennart Poettering 2011-11-01 21:51:53 UTC 
What makes you think systemd is involved or even responsible here? Right now systemd has no role in suspending the system.
Comment 2 Thomas Meyer 2011-11-02 22:31:40 UTC 
correct, systemd has no role in suspending. but after suspending the machine via a ssh connection with "sudo pm-suspend" with the same user as the current X session user, in the resume phase I see this message:

"Oct 29 10:31:47 localhost systemd-logind[581]: Removed session 21."

and my X session is thrown away and I need to login again.

I don't know if this is always the case when suspending via a remote ssh session. I will test this. It hit me twice since the fedora 16 upgrade. and when I remember correctly both times I did a remote suspend via ssh. normal local suspend to ram via works correctly and doesn't kill my X session.
Comment 3 Lennart Poettering 2011-11-03 13:07:59 UTC 
Well, the "Removed session 21" messages is probably more symptom than reason of your problem. My guess is that X crashes or something like that, so please check if you find any log messages pointing to something like that.

Also, was session 21 in that case an X session, or the ssh session? If it's the SSH session and you suspended from remote, then it's kinda expected that it goes away as soon as you resume.
Comment 4 Thomas Meyer 2011-11-04 18:15:14 UTC 
Session 21 was the X session:

Oct 27 22:10:08 localhost systemd-logind[581]: New session 21 of user thomas.
Oct 27 22:10:08 localhost systemd-logind[581]: Linked /tmp/.X11-unix/X0 to /run/user/thomas/X11/display.

and Session 23 was probably the ssh session:

Oct 29 00:45:11 localhost systemd-logind[581]: New session 23 of user thomas.
Oct 29 00:45:26 localhost kernel: [76410.689259] PM: Syncing filesystems ... done.
Oct 29 10:31:41 localhost kernel: [76411.299154] Freezing user space processes ... (elapsed 0.03 seconds) done.

I grep'ed for backtraces in the Xorg log, but found nothing . also no crashes captured by abrtd.

I just suspended from a ssh session, but resume didn't kill my X session, but I didn't wait many hours, just a few minutes. I will try again with a few hours gap between a ssh remote suspend and resume and see if this happens again.

"Xorg.0.old" log file also indicates no crash:

startup:
[ 44582.231] (==) Log file: "/var/log/Xorg.0.log", Time: Thu Oct 27 22:09:42 2011

->which matches above login time.

closure, i.e. last entry in log file:
[ 76424.698] Server terminated successfully (0). Closing log file.
Comment 5 Jóhann B. Guðmundsson 2012-01-29 15:44:36 UTC 
Closing this as notabug feel free to reopen this if this a still an issue and is relevant to systemd

Thanks
Note You need to log in before you can comment on or make changes to this bug.