[systemd-devel] Failed to mark scope session-20.scope as abandoned

[Garry T. Williams]

On 5-12-14 15:11:46 Michal Sekletar wrote:
> On Sat, May 10, 2014 at 05:12:21PM -0400, Garry T. Williams wrote:
> > This recently stated showing up in the journal on Fedora F20 here:
> > 
> >     May 10 17:01:01 vfr systemd[1]: Failed to mark scope session-20.scope as abandoned : Stale file handle
> 
> I suspect this is caused by race between systemd realizing that
> cgroup for a scope is empty, thus changing its state, and
> dispatching dbus message coming from logind where it asks systemd to
> mark scope as abandoned. I don't think this is a big deal so we
> could log this only if debug is on.
> 
> To make sure if it is the case can you try to reproduce with systemd
> and logind debug turned on. Thanks!

Heh.  Reproducing was an interesting problem.

Based on your suspicion, I created a crontab to run a couple of
logger(1) commands every minute and then tried to create a lot of I/O
on the system in the hope that I could recreate the race.  Luckily, I
caught it.

I see

    systemd[1]: session-45.scope changed running -> dead
    systemd[1]: Collecting session-45.scope

happening in the log before

    systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Scope.Abandon() on /org/freedesktop/systemd1/unit/session_2d45_2escope
    systemd[1]: Failed to mark scope session-45.scope as abandoned : Stale file handle

Is that the race?

systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
systemd-logind[654]: Got message: org.freedesktop.DBus org.freedesktop.DBus NameOwnerChanged
systemd-logind[654]: Got message: :1.117 org.freedesktop.login1.Manager CreateSession
systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartTransientUnit() on /org/freedesktop/systemd1
systemd[1]: Failed to load configuration for session-45.scope: No such file or directory
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:system_r:init_t:s0 tclass=service perm=start path=(null) cmdline=(null): 0
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=start path=/run/systemd/system/session-45.scope cmdline=(null): 0
systemd[1]: Trying to enqueue job session-45.scope/start/fail
systemd[1]: Installed new job session-45.scope/start as 3401
systemd[1]: Enqueued job session-45.scope/start as 3401
systemd[1]: Starting Session 45 of user garry.
systemd[1]: session-45.scope changed dead -> running
systemd[1]: Job session-45.scope/start finished, result=done
systemd[1]: Started Session 45 of user garry.
systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
systemd-logind[654]: New session 45 of user garry.
systemd-logind[654]: Got message: org.freedesktop.DBus org.freedesktop.DBus NameOwnerChanged
systemd-logind[654]: Got message: :1.118 org.freedesktop.login1.Manager CreateSession
systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartTransientUnit() on /org/freedesktop/systemd1
systemd[1]: Failed to load configuration for session-44.scope: No such file or directory
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:system_r:init_t:s0 tclass=service perm=start path=(null) cmdline=(null): 0
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=start path=/run/systemd/system/session-44.scope cmdline=(null): 0
systemd[1]: Trying to enqueue job session-44.scope/start/fail
systemd[1]: Installed new job session-44.scope/start as 3407
systemd[1]: Enqueued job session-44.scope/start as 3407
systemd[1]: Starting Session 44 of user garry.
systemd-logind[654]: New session 44 of user garry.
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager JobRemoved
systemd[1]: session-44.scope changed dead -> running
systemd[1]: Job session-44.scope/start finished, result=done
systemd[1]: Started Session 44 of user garry.
systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
systemd-logind[654]: Got message: org.freedesktop.DBus org.freedesktop.DBus NameOwnerChanged
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager JobRemoved
systemd-logind[654]: Got message: org.freedesktop.DBus org.freedesktop.DBus NameOwnerChanged
systemd-logind[654]: Got message: org.freedesktop.DBus org.freedesktop.DBus NameOwnerChanged
systemd-logind[654]: Got message: :1.119 org.freedesktop.login1.Manager ReleaseSession
systemd-logind[654]: Got message: org.freedesktop.DBus org.freedesktop.DBus NameOwnerChanged
systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Scope.Abandon() on /org/freedesktop/systemd1/unit/session_2d44_2escope
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=status path=/run/systemd/system/session-44.scope cmdline=(null): 0
systemd[1]: session-44.scope: cgroup is empty
systemd[1]: session-44.scope changed running -> dead
systemd[1]: Collecting session-44.scope
systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
systemd[1]: Received SIGCHLD from PID 5846 (logger).
systemd-logind[654]: Got message: org.freedesktop.DBus org.freedesktop.DBus NameOwnerChanged
systemd-logind[654]: Got message: :1.120 org.freedesktop.login1.Manager ReleaseSession
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager UnitRemoved
systemd[1]: Child 5846 (logger) died (code=exited, status=0/SUCCESS)
systemd[1]: Accepted connection on private bus.
systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/session_2d44_2escope
systemd[1]: Failed to load configuration for session-44.scope: No such file or directory
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:system_r:init_t:s0 tclass=service perm=status path=(null) cmdline=(null): 0
systemd[1]: Collecting session-44.scope
systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
systemd[1]: Accepted connection on private bus.
systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/session_2d44_2escope
systemd[1]: Failed to load configuration for session-44.scope: No such file or directory
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:system_r:init_t:s0 tclass=service perm=status path=(null) cmdline=(null): 0
systemd[1]: Collecting session-44.scope
systemd-logind[654]: Removed session 44.
systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
systemd-logind[654]: Got message: org.freedesktop.DBus org.freedesktop.DBus NameOwnerChanged
systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager UnitRemoved
systemd[1]: session-45.scope: cgroup is empty
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager UnitRemoved
systemd[1]: session-45.scope changed running -> dead
systemd[1]: Collecting session-45.scope
systemd[1]: Failed to load configuration for session-45.scope: No such file or directory
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:system_r:init_t:s0 tclass=service perm=status path=(null) cmdline=(null): 0
CROND[5843]: (garry) CMD (exec logger 'this is a test 2'&)
CROND[5845]: (garry) CMD (exec logger 'this is a test'&)
garry[5846]: this is a test
garry[5844]: this is a test 2
systemd[1]: Child 5844 (logger) died (code=exited, status=0/SUCCESS)
systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Scope.Abandon() on /org/freedesktop/systemd1/unit/session_2d45_2escope
systemd[1]: Failed to mark scope session-45.scope as abandoned : Stale file handle
systemd[1]: Collecting session-45.scope
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager UnitRemoved
systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/session_2d45_2escope
systemd[1]: Failed to load configuration for session-45.scope: No such file or directory
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:system_r:init_t:s0 tclass=service perm=status path=(null) cmdline=(null): 0
systemd[1]: Collecting session-45.scope
systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/session_2d45_2escope
systemd[1]: Failed to load configuration for session-45.scope: No such file or directory
systemd[1]: SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:system_r:init_t:s0 tclass=service perm=status path=(null) cmdline=(null): 0
systemd[1]: Collecting session-45.scope
systemd-logind[654]: Removed session 45.
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager UnitRemoved
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager UnitRemoved
systemd-logind[654]: Got message: :1.2 org.freedesktop.systemd1.Manager UnitRemoved

-- 
Garry T. Williams