Re: [systemd-devel] Failed to mark scope session-20.scope as abandoned
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
Re: [systemd-devel] Failed to mark scope session-20.scope as abandoned
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:
Re: [systemd-devel] Failed to mark scope session-20.scope as abandoned
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. [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
Re: [systemd-devel] Failed to mark scope session-20.scope as abandoned
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]: Starting Session 20 of user root. May 10 17:01:01 vfr systemd[1]: Started Session 20 of user root. May 10 17:01:01 vfr CROND[5035]: (root) CMD (run-parts /etc/cron.hourly) May 10 17:01:01 vfr run-parts[5039]: (/etc/cron.hourly) starting 0anacron May 10 17:01:01 vfr run-parts[5052]: (/etc/cron.hourly) finished 0anacron May 10 17:01:01 vfr run-parts[5054]: (/etc/cron.hourly) starting ghc-doc-index May 10 17:01:01 vfr run-parts[5065]: (/etc/cron.hourly) finished ghc-doc-index May 10 17:01:01 vfr run-parts[5067]: (/etc/cron.hourly) starting mcelog.cron May 10 17:01:01 vfr run-parts[5071]: (/etc/cron.hourly) finished mcelog.cron May 10 17:01:01 vfr systemd[1]: Failed to mark scope session-20.scope as abandoned : Stale file handle It seems benign. I just haven't seen it before and thought it may be worth reporting here. garry@vfr$ journalctl|grep 'Failed to mark scope' Apr 19 19:01:02 vfr systemd[1]: Failed to mark scope session-2.scope as abandoned : Stale file handle May 05 22:01:02 vfr systemd[1]: Failed to mark scope session-59.scope as abandoned : Stale file handle May 10 17:01:01 vfr systemd[1]: Failed to mark scope session-20.scope as abandoned : Stale file handle garry@vfr$ /usr/lib/systemd/systemd --version systemd 208 +PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ 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! Michal -- 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] Failed to mark scope session-20.scope as abandoned
This recently stated showing up in the journal on Fedora F20 here: May 10 17:01:01 vfr systemd[1]: Starting Session 20 of user root. May 10 17:01:01 vfr systemd[1]: Started Session 20 of user root. May 10 17:01:01 vfr CROND[5035]: (root) CMD (run-parts /etc/cron.hourly) May 10 17:01:01 vfr run-parts[5039]: (/etc/cron.hourly) starting 0anacron May 10 17:01:01 vfr run-parts[5052]: (/etc/cron.hourly) finished 0anacron May 10 17:01:01 vfr run-parts[5054]: (/etc/cron.hourly) starting ghc-doc-index May 10 17:01:01 vfr run-parts[5065]: (/etc/cron.hourly) finished ghc-doc-index May 10 17:01:01 vfr run-parts[5067]: (/etc/cron.hourly) starting mcelog.cron May 10 17:01:01 vfr run-parts[5071]: (/etc/cron.hourly) finished mcelog.cron May 10 17:01:01 vfr systemd[1]: Failed to mark scope session-20.scope as abandoned : Stale file handle It seems benign. I just haven't seen it before and thought it may be worth reporting here. garry@vfr$ journalctl|grep 'Failed to mark scope' Apr 19 19:01:02 vfr systemd[1]: Failed to mark scope session-2.scope as abandoned : Stale file handle May 05 22:01:02 vfr systemd[1]: Failed to mark scope session-59.scope as abandoned : Stale file handle May 10 17:01:01 vfr systemd[1]: Failed to mark scope session-20.scope as abandoned : Stale file handle garry@vfr$ /usr/lib/systemd/systemd --version systemd 208 +PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -- Garry T. Williams ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
