Bug 994268 - enabling autofs causes systemd ordering cycle
enabling autofs causes systemd ordering cycle
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: systemd (Show other bugs)
18
x86_64 Unspecified
unspecified Severity urgent
: ---
: ---
Assigned To: systemd-maint
Fedora Extras Quality Assurance
: Reopened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-08-06 19:00 EDT by Ray Mikkelson
Modified: 2013-11-12 21:25 EST (History)
10 users (show)

See Also:
Fixed In Version: systemd-201-2.fc18.9
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-11-12 21:25:00 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Ray Mikkelson 2013-08-06 19:00:43 EDT
Description of problem:

I have a fresh install of Fedora 18.  When I install (via yum) and enable (via systemctl) autofs, it causes systemd ordering cycle problems on system shutdown.

I feel that this problem is urgent since it results in many (most? all?) of the services to not be properly shut down, especially the local filesystems.



Version-Release number of selected component (if applicable):

autofs.x86_64                         1:5.0.7-16.fc18 
systemd.x86_64                        201-2.fc18.7
systemd-sysv.x86_64                   201-2.fc18.7



How reproducible:

Unknown.  It seems to be somewhat random on exactly what errors occur at shutdown, but I've not seen what I would consider a normal shutdown yet.


Steps to Reproduce:

1. Installed F18 from DVD using a kickstart file (with many packages included)
2. install autofs (yum install autofs)
3. enable & start autofs (systemctl enable autofs; systemctl start autofs)
4. ls an automounted directory
5. shutdown -h now


Actual results:

System seems to boot OK, although I have seen instances where some of the SysV init scripts do not start their processes (at least logs are missing from /var/log/messages)

On Shutdown (shutdown -h now), I don't see messages for most/all of the system services being shut down.



Expected results:

No ordering cycle found by systemd and all of the system services properly shut down.



Additional info:

From /var/log/messages:


1st shutdown produced (immediately after enabling, w/ autofs mounted dirs):

Aug  6 17:13:36 pot systemd[1]: Found ordering cycle on dbus.socket/stop
Aug  6 17:13:36 pot systemd[1]: Walked on cycle path to sysinit.target/stop
Aug  6 17:13:36 pot systemd[1]: Walked on cycle path to local-fs.target/stop
Aug  6 17:13:36 pot systemd[1]: Walked on cycle path to software-linux.mount/stop
Aug  6 17:13:36 pot systemd[1]: Walked on cycle path to network.target/stop
Aug  6 17:13:36 pot systemd[1]: Walked on cycle path to NetworkManager.service/stop
Aug  6 17:13:36 pot systemd[1]: Walked on cycle path to basic.target/stop
Aug  6 17:13:36 pot systemd[1]: Walked on cycle path to sockets.target/stop
Aug  6 17:13:36 pot systemd[1]: Walked on cycle path to dbus.socket/stop
Aug  6 17:13:36 pot systemd[1]: Breaking ordering cycle by deleting job sysinit.target/stop
Aug  6 17:13:36 pot rsyslogd: [origin software="rsyslogd" swVersion="7.2.6" x-pid="580" x-info="http://www.rsyslog.com"] exiting on signal 15.




2nd shutdown produced (no dirs autofs-mounted):

<<NOTE: no ordering cycle reported by systemd!!>>

Aug  6 17:24:34 pot systemd[1]: Starting Show Plymouth Power Off Screen...
Aug  6 17:24:34 pot systemd[1]: Deactivating swap /dev/dm-0...
Aug  6 17:24:34 pot systemd[1]: Deactivating swap /dev/dm-0...
Aug  6 17:24:34 pot systemd[1]: Deactivating swap /dev/dm-0...
Aug  6 17:24:34 pot systemd[1]: Deactivating swap /dev/dm-0...




3rd shutdown produced (w/ autofs-mounted dirs):

Aug  6 17:30:10 pot systemd[1]: Found ordering cycle on dbus.socket/stop
Aug  6 17:30:10 pot systemd[1]: Walked on cycle path to sysinit.target/stop
Aug  6 17:30:10 pot systemd[1]: Walked on cycle path to local-fs.target/stop
Aug  6 17:30:10 pot systemd[1]: Walked on cycle path to software-linux.mount/stop
Aug  6 17:30:10 pot systemd[1]: Walked on cycle path to network.target/stop
Aug  6 17:30:10 pot systemd[1]: Walked on cycle path to NetworkManager.service/stop
Aug  6 17:30:10 pot systemd[1]: Walked on cycle path to basic.target/stop
Aug  6 17:30:10 pot systemd[1]: Walked on cycle path to sockets.target/stop
Aug  6 17:30:10 pot systemd[1]: Walked on cycle path to dbus.socket/stop
Aug  6 17:30:10 pot systemd[1]: Breaking ordering cycle by deleting job sysinit.target/stop
Aug  6 17:30:10 pot systemd[1]: Job sysinit.target/stop deleted to break ordering cycle starting with dbus.socket/stop
Aug  6 17:30:10 pot systemd[1]: Starting Show Plymouth Power Off Screen...
Aug  6 17:30:10 pot systemd[1]: Deactivating swap /dev/dm-0...
Aug  6 17:30:10 pot systemd[1]: Deactivating swap /dev/dm-0...
Aug  6 17:30:10 pot systemd[1]: Stopping Load legacy module configuration...
Aug  6 17:30:10 pot systemd[1]: Stopped Load Kernel Modules.
Aug  6 17:30:10 pot systemd[1]: Stopping Daemon for power management...
Aug  6 17:30:10 pot rsyslogd: [origin software="rsyslogd" swVersion="7.2.6" x-pid="579" x-info="http://www.rsyslog.com"] exiting on signal 15.
Comment 1 Lennart Poettering 2013-09-12 15:37:27 EDT
How is software-linux.mount configured? Via fstab? Can you provide the precise line?
Comment 2 Ray Mikkelson 2013-09-12 16:40:33 EDT
Lennart,

No, /software/linux is automounted via NIS.  So, to walk down the tree....


/etc/auto.master has (I'm only including the pertinent lines for clarity):

/software       yp:auto_software      --timeout=0


Doing a ypcat -k auto_software shows:


Linux -rw,hard,retry=0,noatime,nodiratime    pie:/vol0/software/linux
linux -rw,hard,retry=0,noatime,nodiratime    pie:/vol0/software/linux

(I'm implementing an "alias" for Linux to "point to" linux)


My /etc/fstab has no entries related to /software/linux at all.


The output from mount | grep -i linux shows:

pie:/vol0/software/linux on /software/Linux type nfs4 (rw,noatime,nodiratime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=192.168.1.164,local_lock=none,addr=192.168.1.60)
pie:/vol0/software/linux on /software/linux type nfs4 (rw,noatime,nodiratime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=192.168.1.164,local_lock=none,addr=192.168.1.60)



Note that this all worked just fine in F16...
Comment 3 Zbigniew Jędrzejewski-Szmek 2013-10-06 22:15:37 EDT
This should be fixed by http://cgit.freedesktop.org/systemd/systemd/commit/?id=7700945. I guess we need to backport this here too.
Comment 4 Fedora Update System 2013-10-22 12:20:54 EDT
systemd-204-17.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/systemd-204-17.fc19
Comment 5 Ray Mikkelson 2013-10-22 14:46:36 EDT
Any chance that the fix will be ported back to F18?
Comment 6 Zbigniew Jędrzejewski-Szmek 2013-10-22 14:51:29 EDT
It should be. I'll try to produce an update, but because of the version gap, backporting stuff isn't easy.
Comment 7 Fedora Update System 2013-10-22 23:32:43 EDT
Package systemd-204-17.fc19:
* should fix your issue,
* was pushed to the Fedora 19 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing systemd-204-17.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-19730/systemd-204-17.fc19
then log in and leave karma (feedback).
Comment 8 Fedora Update System 2013-10-24 21:52:46 EDT
systemd-204-17.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 9 Fedora Update System 2013-10-29 12:05:37 EDT
systemd-201-2.fc18.9 has been submitted as an update for Fedora 18.
https://admin.fedoraproject.org/updates/systemd-201-2.fc18.9
Comment 10 Fedora Update System 2013-10-29 21:53:22 EDT
Package systemd-201-2.fc18.9:
* should fix your issue,
* was pushed to the Fedora 18 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing systemd-201-2.fc18.9'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-20267/systemd-201-2.fc18.9
then log in and leave karma (feedback).
Comment 11 Ray Mikkelson 2013-10-31 15:36:55 EDT
Tested with: 
systemd.x86_64                        201-2.fc18.9               @updates-testing

(Thanks for porting the fix back!!)

Fix does solve the ordering cycle problem, which is a big improvement.

However, being admittedly somewhat naive here, shouldn't the shutdown messages in /var/log/messages be the same each time?  I'm guessing that there might be timing issues with syslogd...  Is there a reliable place to see all of the messages output during shutdown?  What is stored in the messages file doesn't match what I see on the screen (momentarily) while the system shuts down.

Anyway, to document the testing that I did, here's the pertinent output from /var/log/messages, with my comments:



#
# Previous shutdown without fix
#

Oct 28 14:17:57 security systemd-logind[14668]: System is powering down.
Oct 28 14:17:57 security systemd[1]: Found ordering cycle on network.target/stop
Oct 28 14:17:57 security systemd[1]: Walked on cycle path to NetworkManager.service/stop
Oct 28 14:17:57 security systemd[1]: Walked on cycle path to dbus.socket/stop
Oct 28 14:17:57 security systemd[1]: Walked on cycle path to sysinit.target/stop
Oct 28 14:17:57 security systemd[1]: Walked on cycle path to local-fs.target/stop
Oct 28 14:17:57 security systemd[1]: Walked on cycle path to software-FedoraMirror.mount/stop
Oct 28 14:17:57 security systemd[1]: Walked on cycle path to network.target/stop
Oct 28 14:17:57 security systemd[1]: Breaking ordering cycle by deleting job NetworkManager.service/stop
Oct 28 14:17:57 security systemd[1]: Job NetworkManager.service/stop deleted to break ordering cycle starting with network.target/stop
Oct 28 14:17:57 security systemd[1]: Starting Show Plymouth Power Off Screen...
Oct 28 14:17:57 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 28 14:17:57 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 28 14:17:57 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 28 14:17:57 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 28 14:17:57 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 28 14:17:57 security systemd[1]: Stopping Sound Card.
Oct 28 14:17:57 security systemd[1]: Stopping Sockets.
Oct 28 14:17:57 security rsyslogd: [origin software="rsyslogd" swVersion="7.2.6" x-pid="606" x-info="http://www.rsyslog.com"] exiting on signal 15.

# 
# First shutdown immediately after installing new systemd packages
# NFS directories are automount'ed
#

Oct 31 13:11:35 security systemd-logind[26978]: System is powering down.
Oct 31 13:11:35 security systemd[1]: Starting Show Plymouth Power Off Screen...
Oct 31 13:11:35 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:11:35 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:11:35 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:11:35 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:11:35 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:11:35 security systemd[1]: Stopping Sound Card.
Oct 31 13:11:35 security systemd[1]: Stopped target Sound Card.
ct 31 13:11:35 security systemd[1]: Stopping Import network configuration from initramfs...
Oct 31 13:11:35 security systemd[1]: Stopped Import network configuration from initramfs.
Oct 31 13:11:35 security rsyslogd: [origin software="rsyslogd" swVersion="7.2.6" x-pid="731" x-info="http://www.rsyslog.com"] exiting on signal 15.

#
# 2nd shutdown after install, no NFS directories mounted
#

Oct 31 13:13:24 security systemd-logind[667]: System is powering down.
Oct 31 13:13:24 security systemd[1]: Starting Show Plymouth Power Off Screen...
Oct 31 13:13:24 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:13:24 security rsyslogd: [origin software="rsyslogd" swVersion="7.2.6" x-pid="726" x-info="http://www.rsyslog.com"] exiting on signal 15.

#
# 3rd shutdown after install, NFS directories are automount'ed
#

Oct 31 13:16:15 security systemd-logind[666]: System is powering down.
Oct 31 13:16:15 security systemd[1]: Starting Show Plymouth Power Off Screen...
Oct 31 13:16:15 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:16:15 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:16:15 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:16:15 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:16:15 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:16:15 security systemd[1]: Stopping Sound Card.
Oct 31 13:16:15 security systemd[1]: Stopped target Sound Card.
Oct 31 13:16:15 security systemd[1]: Stopping Import network configuration from initramfs...
Oct 31 13:16:15 security systemd[1]: Stopped Import network configuration from initramfs.
Oct 31 13:16:15 security systemd[1]: Stopping Stop Read-Ahead Data Collection 10s After Completed Startup.
Oct 31 13:16:15 security systemd[1]: Stopped Stop Read-Ahead Data Collection 10s After Completed Startup.
Oct 31 13:16:15 security systemd[1]: Stopping CUPS Printing Service...
Oct 31 13:16:15 security systemd[1]: Stopping Graphical Interface.
Oct 31 13:16:15 security systemd[1]: Stopped target Graphical Interface.
Oct 31 13:16:15 security rsyslogd: [origin software="rsyslogd" swVersion="7.2.6" x-pid="677" x-info="http://www.rsyslog.com"] exiting on signal 15.

#
# 4th shutdown, NFS directories automount'ed
#

Oct 31 13:23:22 security systemd-logind[674]: System is powering down.
Oct 31 13:23:22 security systemd[1]: Starting Show Plymouth Power Off Screen...
Oct 31 13:23:22 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:23:22 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:23:22 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:23:22 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:23:22 security systemd[1]: Deactivating swap /dev/dm-0...
Oct 31 13:23:22 security systemd[1]: Stopping Sound Card.
Oct 31 13:23:22 security systemd[1]: Stopped target Sound Card.
Oct 31 13:23:22 security systemd[1]: Stopping Import network configuration from initramfs...
Oct 31 13:23:22 security systemd[1]: Stopped Import network configuration from initramfs.
Oct 31 13:23:22 security systemd[1]: Stopping Stop Read-Ahead Data Collection 10s After Completed Startup.
Oct 31 13:23:22 security systemd[1]: Stopped Stop Read-Ahead Data Collection 10s After Completed Startup.
Oct 31 13:23:22 security systemd[1]: Stopping CUPS Printing Service...
Oct 31 13:23:22 security systemd[1]: Stopping Graphical Interface.
Oct 31 13:23:22 security systemd[1]: Stopped target Graphical Interface.
Oct 31 13:23:22 security systemd[1]: Stopping Restorecon maintaining path file context...
Oct 31 13:23:22 security systemd[1]: Stopping ACPI Event Daemon...
Oct 31 13:23:22 security systemd[1]: Stopping Console Mouse manager...
Oct 31 13:23:22 security systemd[1]: Stopping Virtualization daemon...
Oct 31 13:23:22 security systemd[1]: Stopping Kernel Samepage Merging (KSM) Tuning Daemon...
Oct 31 13:23:22 security rsyslogd: [origin software="rsyslogd" swVersion="7.2.6" x-pid="682" x-info="http://www.rsyslog.com"] exiting on signal 15.
Comment 12 Zbigniew Jędrzejewski-Szmek 2013-10-31 15:41:35 EDT
(In reply to Ray Mikkelson from comment #11)
> Tested with: 
> systemd.x86_64                        201-2.fc18.9              
> @updates-testing
> 
> (Thanks for porting the fix back!!)
> 
> Fix does solve the ordering cycle problem, which is a big improvement.
Great.
 
> However, being admittedly somewhat naive here, shouldn't the shutdown
> messages in /var/log/messages be the same each time?  I'm guessing that
> there might be timing issues with syslogd...  Is there a reliable place to
> see all of the messages output during shutdown?  What is stored in the
> messages file doesn't match what I see on the screen (momentarily) while the
> system shuts down.
No, messages can be lost. The problem is that because of a kernel limitation, the message queue length cannot be changed, and is on 10 packets long. This means that at times when many messages are logged (like shutdown), journald cannot keep up with the flow. We can either lose messages, or make the message passing blocking. In later versions, it is blocking, but the downside is that it slows things down, and can even dead-lock if important stuff is waiting for logging, so special care must be taken. And the same thing happens on the interface between journald and syslog. If syslog is slow for whatever reason, it'll lose messages.

You might have better luck with journalctl output.
Comment 13 Fedora Update System 2013-11-12 21:25:00 EST
systemd-201-2.fc18.9 has been pushed to the Fedora 18 stable repository.  If problems still persist, please make note of it in this bug report.

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