On Wed, May 14, 2014 at 07:51:01AM +0200, Michal Sekletar wrote: > On Tue, May 13, 2014 at 11:54:49PM -0400, Garry T. Williams wrote: > > 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? > > That would be it! As you can see [0] we proceed in execution of handler code > for > Abandon() only for scopes which are either running or already abandoned. > However > scope here is, at the time systemd gets to processing D-Bus request, already > in a dead > state. > > I'll wait a bit and if no one objects I'll go ahead and change log level for a > message and also change it to something more sensible so it actually makes > sense to people.
I went ahead and committed fix. If anybody disagrees, feel free to revert. Michal http://cgit.freedesktop.org/systemd/systemd-stable/commit/?id=f517790db5277fa71d6ae3617244f1acc4b62572 > > [0] > http://cgit.freedesktop.org/systemd/systemd-stable/tree/src/core/scope.c#n433 > > Cheers, > > Michal > > > > > 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 > > > > _______________________________________________ > > systemd-devel mailing list > > systemd-devel@lists.freedesktop.org > > http://lists.freedesktop.org/mailman/listinfo/systemd-devel > _______________________________________________ > systemd-devel mailing list > systemd-devel@lists.freedesktop.org > http://lists.freedesktop.org/mailman/listinfo/systemd-devel _______________________________________________ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel