Bug 1378135

Summary: [fdBeta] [OVS] systemd ordering of OVS service causes hang during restart when there is NFS mount over OVS
Product: Red Hat Enterprise Linux 7 Reporter: Flavio Leitner <fleitner>
Component: openvswitchAssignee: Aaron Conole <aconole>
Status: CLOSED CURRENTRELEASE QA Contact: Rick Alongi <ralongi>
Severity: high Docs Contact:
Priority: high    
Version: 7.3CC: aconole, atelang, atragler, eparis, erich, fbaudin, fleitner, lxin, qding, rhowe, sukulkar, systemd-maint-list, systemd-maint
Target Milestone: rc   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: openvswitch-2.5.0-19.git20160727.el7fdb Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1397049 (view as bug list) Environment:
Last Closed: 2017-01-12 15:08:14 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1267746, 1393481, 1397049    
Attachments:
Description Flags
shutdown-log.txt none

Description Flavio Leitner 2016-09-21 14:47:27 UTC 
Description of problem:

This is intended to fix the problem reported in bz#1304823 for OVS 2.5 (FD-Beta) which the system hangs for 1/2 hour to shutdown or restart if there is a mounted NFS share over OVS bridges.

The following commits need to be backported from upstream:
c416eaf8c247225f0ebeb22b6ca5c473e96a53d2
7fc28c50c0128a0c72853f8f243fd5045bcb9917
0cfd47f9dcc3914db8d266ed834d6e2c8fc1a11d
48458307b52d13d37d8f88d91385b732af12939f
4f6218739ec6ed33b71e5127fe619db13605602d
84ad120834919c3e0945e3e58e0f96c07efa0316

Upstream request:
http://openvswitch.org/pipermail/dev/2016-September/079193.html


Version-Release number of selected component (if applicable):
2.5.0
Comment 3 Flavio Leitner 2016-09-21 20:37:15 UTC 
ovs: openvswitch-2.5.1-1.fc24.x86_64
kernel: 3.10.0-327.36.1.el7.x86_64

From http://github.com/orgcandman/ovs, branch backports_requested_upstream,
 $ git log --oneline -3
59f420c rhel: Improved Systemd Integration
cdcf1b1 rhel/ovsdb-server.service: Rename the nonetwork service
336349b utilities/ovs-ctl.in: Allow non-monitoring daemons


This is the config:

# cat /etc/sysconfig/network-scripts/ifcfg-eth0 
# Generated by dracut initrd
NAME="eth0"
HWADDR=52:54:00:04:7A:39 
ONBOOT=yes
NETBOOT=yes
TYPE=OVSPort
OVS_BRIDGE=ovsbr0
HOTPLUG=no
NM_CONTROLLED=no

[root@localhost ~]# cat /etc/sysconfig/network-scripts/ifcfg-ovsbr0 
DEVICE=ovsbr0
ONBOOT=yes
DEVICETYPE=ovs
TYPE=OVSBridge
HOTPLUG=no
NM_CONTROLLED=no

# cat /etc/sysconfig/network-scripts/ifcfg-int0
DEVICE=int0
ONBOOT=yes
DEVICETYPE=ovs
TYPE=OVSIntPort
OVS_BRIDGE=ovsbr0
HOTPLUG=no
NM_CONTROLLED=no
BOOTPROTO=dhcp


[root@localhost ~]# ovs-vsctl show
bb0468de-056f-457b-9479-9618861f9949
    Bridge "ovsbr0"
        Port "int0"
            Interface "int0"
                type: internal
        Port "ovsbr0"
            Interface "ovsbr0"
                type: internal
        Port "eth0"
            Interface "eth0"
    ovs_version: "2.5.1"
[root@localhost ~]# 


# ip -4 a show dev int0 
5: int0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN 
    inet 192.168.122.22/24 brd 192.168.122.255 scope global dynamic int0
       valid_lft 3404sec preferred_lft 3404sec


NFS config:
# grep nfs /etc/fstab 
192.168.1.9:/home/fleitner/Music /mnt nfs _netdev 0 0

# mount | grep mnt | grep netdev
192.168.1.9:/home/fleitner/Music on /mnt type nfs4 (rw,relatime,vers=4.0,rsize=262144,wsize=262144,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=192.168.122.22,local_lock=none,addr=192.168.1.9,_netdev)

Test host connectivity:
# ping 192.168.1.9 -c 1
PING 192.168.1.9 (192.168.1.9) 56(84) bytes of data.
64 bytes from 192.168.1.9: icmp_seq=1 ttl=63 time=0.950 ms

--- 192.168.1.9 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.950/0.950/0.950/0.000 ms


Test NFS:
[root@localhost ~]# ls /mnt | wc  -l 
68
[root@localhost ~]# df -h /mnt
Filesystem                        Size  Used Avail Use% Mounted on
192.168.1.9:/home/fleitner/Music  197G   83G  105G  45% /mnt



# shutdown -h now
 [...]
 [   55.205458] systemd[1]: Stopped ABRT Automated Bug Reporting Tool.
 [   55.209402] systemd[1]: Stopped LSB: Starts the Spacewalk Daemon.
 [   55.210613] systemd[1]: Stopped Permit User Sessions.
 [   55.211318] systemd[1]: Stopped target Remote File Systems.
 [   55.211881] systemd[1]: Stopping Remote File Systems.
>[   55.212702] systemd[1]: Unmounting /mnt...
 [   55.228320] systemd[1]: Stopped Network Manager.
 [   55.240789] systemd[1]: Stopped Postfix Mail Transport Agent.
 [   55.258083] systemd[1]: Stopped Login Service.
 [   55.263484] systemd[1]: Received SIGRTMIN+20 from PID 9594 (plymouthd).
 [   55.265381] systemd[1]: Started Show Plymouth Power Off Screen.
 [  OK  ] Started Show Plymouth Power Off Screen.
 [   55.466154] systemd[1]: Stopped Open vSwitch Forwarding Unit.
 [   55.468479] systemd[1]: Stopping Open vSwitch Database Unit...
 [  OK  ] Stopped Open vSwitch Forwarding Unit.
          Stopping Open vSwitch Database Unit...
 [   55.590629] systemd[1]: Stopped Open vSwitch Database Unit.
 [  OK  ] Stopped Open vSwitch Database Unit.
 [  145.344145] systemd[1]: mnt.mount unmounting timed out. Stopping.
 [  235.603012] systemd[1]: mnt.mount unmounting timed out. Stopping.
 [  280.478707] nfs: server 192.168.1.9 not responding, timed out
 [  325.861889] systemd[1]: mnt.mount unmounting timed out. Stopping.
 [  416.120775] systemd[1]: mnt.mount unmounting timed out. Stopping.
[...]

The same issue happens with F23. It doesn't matter if mounting manually, or manually -o _netdev or using fstab as above.
Comment 4 Flavio Leitner 2016-09-21 21:06:45 UTC 
Giving that the service ordering looks correct, I will reassign this bug to systemd.

# rpm -q systemd
systemd-219-19.el7_2.13.x86_64
Comment 5 Lukáš Nykrýn 2016-09-22 08:28:51 UTC 
Can you try to reproduce it with latest build of rhel-7.3? There was plenty of changes in systemd and NM.

Also could you post here systemctl cat and systemctl show for mnt.mount? Also log from shutdown with systemd set to debug would be nice.
https://freedesktop.org/wiki/Software/systemd/Debugging/ the part "Shutdown Completes Eventually"
Comment 6 Flavio Leitner 2016-09-22 19:24:24 UTC 
Updated to latest 7.3 nightly build.  It doesn't happen all the time now, but still happens.

# uname -r
3.10.0-509.el7.x86_64

# rpm -q systemd
systemd-219-30.el7.x86_64

# rpm -q openvswitch
openvswitch-2.5.1-1.fc24.x86_64

# cat /proc/cmdline
BOOT_IMAGE=/boot/vmlinuz-3.10.0-509.el7.x86_64 root=UUID=1aa5c5ea-ee54-4143-a994-584c51f341ce ro console=tty0 rd_NO_PLYMOUTH crashkernel=auto console=ttyS0,115200 systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M enforcing=0

# systemctl cat mnt.mount
# /run/systemd/generator/mnt.mount
# Automatically generated by systemd-fstab-generator

[Unit]
SourcePath=/etc/fstab
Documentation=man:fstab(5) man:systemd-fstab-generator(8)
Before=remote-fs.target
After=network.target
Requires=network.target

[Mount]
What=192.168.1.9:/home/fleitner/Music
Where=/mnt
Type=nfs
Options=x-systemd.requires=network.target

[root@localhost ~]# systemctl show mnt.mount
Where=/mnt
What=192.168.1.9:/home/fleitner/Music
Options=rw,relatime,vers=4.0,rsize=262144,wsize=262144,namlen=255,hard,proto=tcp
Type=nfs4
TimeoutUSec=1min 30s
ControlPID=0
DirectoryMode=0755
SloppyOptions=no
Result=success
ExecMount={ path=/bin/mount ; argv[]=/bin/mount 192.168.1.9:/home/fleitner/Music
Slice=system.slice
ControlGroup=/system.slice/mnt.mount
MemoryCurrent=18446744073709551615
Delegate=no
CPUAccounting=no
CPUShares=18446744073709551615
StartupCPUShares=18446744073709551615
CPUQuotaPerSecUSec=infinity
BlockIOAccounting=no
BlockIOWeight=18446744073709551615
StartupBlockIOWeight=18446744073709551615
MemoryAccounting=no
MemoryLimit=18446744073709551615
DevicePolicy=auto
UMask=0022
LimitCPU=18446744073709551615
LimitFSIZE=18446744073709551615
LimitDATA=18446744073709551615
LimitSTACK=18446744073709551615
LimitCORE=18446744073709551615
LimitRSS=18446744073709551615
LimitNOFILE=4096
LimitAS=18446744073709551615
LimitNPROC=7281
LimitMEMLOCK=65536
LimitLOCKS=18446744073709551615
LimitSIGPENDING=7281
LimitMSGQUEUE=819200
LimitNICE=0
LimitRTPRIO=0
LimitRTTIME=18446744073709551615
OOMScoreAdjust=0
Nice=0
IOScheduling=0
CPUSchedulingPolicy=0
CPUSchedulingPriority=0
TimerSlackNSec=50000
CPUSchedulingResetOnFork=no
NonBlocking=no
StandardInput=null
StandardOutput=journal
StandardError=inherit
TTYReset=no
TTYVHangup=no
TTYVTDisallocate=no
SyslogPriority=30
SyslogLevelPrefix=yes
SecureBits=0
CapabilityBoundingSet=18446744073709551615
MountFlags=0
PrivateTmp=no
PrivateNetwork=no
PrivateDevices=no
ProtectHome=no
ProtectSystem=no
SameProcessGroup=yes
IgnoreSIGPIPE=yes
NoNewPrivileges=no
SystemCallErrorNumber=0
RuntimeDirectoryMode=0755
KillMode=control-group
KillSignal=15
SendSIGKILL=yes
SendSIGHUP=no
Id=mnt.mount
Names=mnt.mount
Requires=-.mount network.target
Wants=system.slice network-online.target
RequiredBy=remote-fs.target
Conflicts=umount.target
Before=umount.target remote-fs.target
After=remote-fs-pre.target network.target system.slice systemd-journald.socket -
RequiresMountsFor=/
Documentation=man:fstab(5) man:systemd-fstab-generator(8)
Description=/mnt
LoadState=loaded
ActiveState=active
SubState=mounted
FragmentPath=/run/systemd/generator/mnt.mount
SourcePath=/etc/fstab
UnitFileState=bad
UnitFilePreset=disabled
InactiveExitTimestamp=Thu 2016-09-22 16:17:20 BRT
InactiveExitTimestampMonotonic=18256616
ActiveEnterTimestamp=Thu 2016-09-22 16:17:20 BRT
ActiveEnterTimestampMonotonic=18345116
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
CanStart=yes
CanStop=yes
CanReload=yes
CanIsolate=no
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
OnFailureJobMode=replace
IgnoreOnIsolate=yes
IgnoreOnSnapshot=no
NeedDaemonReload=no
JobTimeoutUSec=0
JobTimeoutAction=none
ConditionResult=yes
AssertResult=yes
ConditionTimestamp=Thu 2016-09-22 16:17:20 BRT
ConditionTimestampMonotonic=18254893
AssertTimestamp=Thu 2016-09-22 16:17:20 BRT
AssertTimestampMonotonic=18254894
Transient=no


[root@localhost ~]# ls /mnt | wc -l ^M
68^M
[root@localhost ~]# mount | grep mnt^M
192.168.1.9:/home/fleitner/Music on /^[[01;31m^[[Kmnt^[[m^[[K type nfs4 (rw,relatime,vers=4.0,rsize=262144,wsize=262144,namlen=255,hard,proto=tcp,port=0,timeo=600,retrans=2,sec=sys,clientaddr=192.168.122.199,local_lock=none,addr=192.168.1.9)^M
[root@localhost ~]# shutdown -h now ^M
[   72.588515] systemd[1]: Deactivating swap /dev/disk/by-uuid/e372f819-753e-4468-bb2c-edb2ec6b632a...^M
[   72.593168] systemd[1]: Stopping Open vSwitch Forwarding Unit...^M
[   72.594664] systemd[1]: Stopping Hostname Service...^M
[   72.595482] systemd[1]: Stopped target Timers.^M
[   72.596213] systemd[1]: Stopping Timers.^M
[   72.598058] systemd[1]: Stopping Session 1 of user root.^M
[   72.599161] systemd[1]: Unmounting RPC Pipe File System...^M
[   72.600296] systemd[1]: Stopped Dump dmesg to /var/log/dmesg.^M
[   72.601424] systemd[1]: Stopping Dump dmesg to /var/log/dmesg...^M
[   72.602953] systemd[1]: Stopping Open vSwitch...^M
[   72.603844] systemd[1]: Stopped target Multi-User System.^M
[   72.604764] systemd[1]: Stopping Multi-User System.^M
[   72.606270] systemd[1]: Stopping Command Scheduler...^M
[   72.607249] systemd[1]: Stopping Job spooling tools...^M
[   72.608351] systemd[1]: Stopping Enable periodic update of entitlement certificates....^M
[   72.609777] systemd[1]: Stopping ABRT kernel log watcher...^M
[   72.610917] systemd[1]: Stopping irqbalance daemon...^M
[   72.611918] systemd[1]: Stopping NTP client/server...^M
[   72.612798] systemd[1]: Stopping Hardware RNG Entropy Gatherer Daemon...^M
[   72.614399] systemd[1]: Stopping Dynamic System Tuning Daemon...^M
[   72.615546] systemd[1]: Stopping Self Monitoring and Reporting Technology (SMART) Daemon...^M
[   72.617113] systemd[1]: Stopping Postfix Mail Transport Agent...^M
[   72.618224] systemd[1]: Stopping libstoragemgmt plug-in server daemon...^M
[   72.619130] systemd[1]: Stopped target Login Prompts.^M
[   72.619888] systemd[1]: Stopping Login Prompts.^M
[   72.620587] systemd[1]: Stopping Serial Getty on ttyS0...^M
[   72.621660] systemd[1]: Stopped Resets System Activity Logs.^M
[   72.622492] systemd[1]: Stopping Resets System Activity Logs...^M
[   72.624469] systemd[1]: Stopping OpenSSH server daemon...^M
[   72.625200] systemd[1]: Stopped Daily Cleanup of Temporary Directories.^M
[   72.626090] systemd[1]: Stopping Daily Cleanup of Temporary Directories.^M
[   72.627407] systemd[1]: Stopping Getty on tty1...^M
[   72.628395] systemd[1]: Stopping LSB: Starts the Spacewalk Daemon...^M
[   72.630216] systemd[1]: Stopping Install ABRT coredump hook...^M
[   72.630891] systemd[1]: Stopping System Logging Service...^M
[   72.631457] systemd[1]: Stopping Authorization Manager...^M
[   72.637000] systemd[1]: Stopped libstoragemgmt plug-in server daemon.^M
[   72.639054] systemd[1]: Stopped Hardware RNG Entropy Gatherer Daemon.^M
[   72.642324] systemd[1]: Stopped Self Monitoring and Reporting Technology (SMART) Daemon.^M
[   72.645767] systemd[1]: Stopped irqbalance daemon.^M
[   72.647630] systemd[1]: Stopped ABRT kernel log watcher.^M
[   72.649285] systemd[1]: Stopped Authorization Manager.^M
[   72.653564] systemd[1]: Stopped NTP client/server.^M
[   72.660461] systemd[1]: Stopped Hostname Service.^M
[   72.662684] systemd[1]: Stopped Enable periodic update of entitlement certificates..^M
[   72.664733] systemd[1]: Stopped OpenSSH server daemon.^M
[   72.666981] systemd[1]: Stopped Job spooling tools.^M
[   72.668089] systemd[1]: Stopped Command Scheduler.^M
[   72.671536] systemd[1]: Stopped Getty on tty1.^M
[   72.673692] systemd[1]: Stopped Serial Getty on ttyS0.^M
[   72.677449] systemd[1]: Stopped Session 1 of user root.^M
[   72.679465] systemd[1]: Stopped Open vSwitch.^M
[   72.682057] systemd[1]: Stopped Install ABRT coredump hook.^M
[   72.691675] systemd[1]: Stopped Postfix Mail Transport Agent.^M
[   72.693227] systemd[1]: Stopping Login Service...^M
[   72.693999] systemd[1]: Removed slice user-0.slice.^M
[   72.694548] systemd[1]: Stopping user-0.slice.^M
[   72.695083] systemd[1]: Removed slice system-serial\x2dgetty.slice.^M
[   72.695879] systemd[1]: Stopping system-serial\x2dgetty.slice.^M
[   72.697139] systemd[1]: Starting Show Plymouth Power Off Screen...^M
[   72.698098] systemd[1]: Removed slice system-getty.slice.^M
[   72.698872] systemd[1]: Stopping system-getty.slice.^M
[   72.700061] systemd[1]: Stopping Permit User Sessions...^M
[   72.704443] systemd[1]: Stopping ABRT Automated Bug Reporting Tool...^M
[   72.707392] systemd[1]: Stopped Permit User Sessions.^M
[   72.709765] systemd[1]: Stopped ABRT Automated Bug Reporting Tool.^M
[   72.721498] systemd[1]: Stopped Login Service.^M
[   72.726838] systemd[1]: Stopped System Logging Service.^M
[   72.729953] systemd[1]: Deactivated swap /dev/disk/by-uuid/e372f819-753e-4468-bb2c-edb2ec6b632a.^M
[   72.733275] systemd[1]: Deactivated swap /dev/disk/by-path/virtio-pci-0000:00:05.0-part1.^M
[   72.734487] systemd[1]: Deactivated swap /dev/vda1.^M
[   72.735404] systemd[1]: var-lib-nfs-rpc_pipefs.mount mount process exited, code=exited status=32^M
[   72.736762] systemd[1]: Unmounted RPC Pipe File System.^M
[   72.737447] systemd[1]: Unit var-lib-nfs-rpc_pipefs.mount entered failed state.^M
[   72.826770] systemd[1]: Stopped Open vSwitch Forwarding Unit.^M
[   72.828252] systemd[1]: Stopping Open vSwitch Database Unit...^M
[   72.830893] systemd[1]: Stopped LSB: Starts the Spacewalk Daemon.^M
[   72.832313] systemd[1]: Stopped target Remote File Systems.^M
[   72.833400] systemd[1]: Stopping Remote File Systems.^M
[   72.834596] systemd[1]: Unmounting /mnt...^M
[   72.836495] systemd[1]: Received SIGRTMIN+20 from PID 2729 (plymouthd).^M
[   72.839230] systemd[1]: Started Show Plymouth Power Off Screen.^M
[^[[32m  OK  ^[[0m] Started Show Plymouth Power Off Screen.^M^M
[   72.949319] systemd[1]: Stopped Open vSwitch Database Unit.^M
[^[[32m  OK  ^[[0m] Stopped Open vSwitch Database Unit.^M^M
[   73.584953] systemd[1]: Stopped Dynamic System Tuning Daemon.^M
[^[[32m  OK  ^[[0m] Stopped Dynamic System Tuning Daemon.^M^M
[  162.893488] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  253.160090] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  295.509250] nfs: server 192.168.1.9 not responding, timed out^M
[  343.426506] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  433.693043] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  523.959484] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  614.226018] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  680.155592] nfs: server 192.168.1.9 not responding, timed out^M
[  680.156997] nfs: server 192.168.1.9 not responding, timed out^M
[  704.492519] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  794.759038] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  885.025505] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  975.292037] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[  986.387630] nfs: server 192.168.1.9 not responding, timed out^M
[ 1065.558476] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1155.825023] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1246.091496] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1292.619687] nfs: server 192.168.1.9 not responding, timed out^M
[ 1336.358025] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1426.624500] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1516.891001] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1598.851492] nfs: server 192.168.1.9 not responding, timed out^M
[ 1607.157510] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1697.423989] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1787.690520] systemd[1]: mnt.mount unmounting timed out. Stopping.^M
[ 1872.956084] systemd[1]: Job poweroff.target/start timed out.^M
[ 1872.956981] systemd[1]: Timed out starting Power-Off.^M
[ 1872.958611] systemd[1]: Job poweroff.target/start failed with result 'timeout'.^M
[ 1872.960241] systemd[1]: Forcibly powering off as result of failure.^M
[[ 1872.961775] systemd[1]: Shutting down.^M
^[[1;31m !!  ^[[0m] Forcibly powering off as result of failure.^M^M
[ 1872.970511] systemd-shutdown[1]: Sending SIGTERM to remaining processes...^M
[ 1872.983563] systemd-journald[370]: Received SIGTERM from PID 1 (systemd-shutdow).^M
[ 1872.995079] type=1305 audit(1474554895.567:105): audit_pid=0 old=484 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1^M
[ 1882.985340] systemd-shutdown[1]: Sending SIGKILL to remaining processes...^M
[ 1882.989603] systemd-shutdown[1]: Sending SIGKILL to PID 2799 (umount).^M
[ 1882.991770] systemd-shutdown[1]: Unmounting file systems.^M
[ 1882.993948] systemd-shutdown[1]: Unmounting /run/user/0.^M
[ 1882.995472] systemd-shutdown[1]: Unmounting /mnt.^M
[ 1883.085204] EXT4-fs (vda2): re-mounted. Opts: (null)^M
[ 1883.087675] EXT4-fs (vda2): re-mounted. Opts: (null)^M
[ 1883.088306] EXT4-fs (vda2): re-mounted. Opts: (null)^M
[ 1883.088983] systemd-shutdown[1]: All filesystems unmounted.^M
[ 1883.089717] systemd-shutdown[1]: Deactivating swaps.^M
[ 1883.090519] systemd-shutdown[1]: All swaps deactivated.^M
[ 1883.091017] systemd-shutdown[1]: Detaching loop devices.^M
[ 1883.091808] systemd-shutdown[1]: All loop devices detached.^M
[ 1883.092368] systemd-shutdown[1]: Detaching DM devices.^M
[ 1883.092893] systemd-shutdown[1]: All DM devices detached.^M
[ 1883.099327] EXT4-fs (vda2): re-mounted. Opts: (null)^M
[ 1883.101117] type=1400 audit(1474554905.671:106): avc:  denied  { write } for  pid=2806 comm="dmesg" path="/shutdown-log.txt" dev="vda2" ino=850 scontext=system_u:system_r:dmesg_t:s0 tcontext=system_u:object_r:root_t:s0 tclass=file^M
[ 1883.103025] type=1300 audit(1474554905.671:106): arch=c000003e syscall=59 success=yes exit=0 a0=1449240 a1=1449220 a2=14477d0 a3=7ffdedc255a0 items=0 ppid=2802 pid=2806 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dmesg" exe="/usr/bin/dmesg" subj=system_u:system_r:dmesg_t:s0 key=(null)^M
[ 1883.107617] type=1400 audit(1474554905.678:107): avc:  denied  { getattr } for  pid=2806 comm="dmesg" path="/shutdown-log.txt" dev="vda2" ino=850 scontext=system_u:system_r:dmesg_t:s0 tcontext=system_u:object_r:root_t:s0 tclass=file^M
[ 1883.109993] type=1300 audit(1474554905.678:107): arch=c000003e syscall=5 success=yes exit=0 a0=1 a1=7ffe71f6d770 a2=7ffe71f6d770 a3=7f4f9faa5740 items=0 ppid=2802 pid=2806 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="dmesg" exe="/usr/bin/dmesg" subj=system_u:system_r:dmesg_t:s0 key=(null)^M
[ 1883.243781] EXT4-fs (vda2): re-mounted. Opts: (null)^M
[ 1883.245099] systemd-shutdown[1]: Powering off.^M
[ 1883.263466] ACPI: Preparing to enter system sleep state S5^M
[ 1883.264053] Power down.^M
Comment 7 Flavio Leitner 2016-09-22 19:25:13 UTC 
Created attachment 1203902 [details]
shutdown-log.txt
Comment 8 Lukáš Nykrýn 2016-09-23 08:00:54 UTC 
So the general network is now not the problem. From the logs it looks that the umount of the disk fails before network.target is stopped. So NetworkManager or network.service should still live.

Can you please check the order of your services? Some of them seems to be terminated in parallel with the mount.
Comment 9 Flavio Leitner 2016-09-23 13:37:10 UTC 
This is the main one that controls the other two:

# systemctl cat openvswitch.service
# /usr/lib/systemd/system/openvswitch.service
[Unit]
Description=Open vSwitch
PartOf=network.target
BindsTo=ovsdb-server.service
BindsTo=ovs-vswitchd.service

[Service]
Type=oneshot
ExecStart=/bin/true
ExecReload=/bin/true
ExecStop=/bin/true
RemainAfterExit=yes

[Install]
WantedBy=multi-user.target

-------------------------

[root@localhost ~]# systemctl cat ovs-vswitchd.service
# /usr/lib/systemd/system/ovs-vswitchd.service
[Unit]
Description=Open vSwitch Forwarding Unit
After=ovsdb-server.service
Requires=ovsdb-server.service
ReloadPropagatedFrom=ovsdb-server.service
AssertPathIsReadWrite=/var/run/openvswitch/db.sock
PartOf=openvswitch.service

[Service]
Type=forking
EnvironmentFile=-/etc/sysconfig/openvswitch
ExecStart=/usr/share/openvswitch/scripts/ovs-ctl \
          --no-ovsdb-server --no-monitor --system-id=random \
          start $OPTIONS
ExecStop=/usr/share/openvswitch/scripts/ovs-ctl --no-ovsdb-server stop
ExecReload=/usr/share/openvswitch/scripts/ovs-ctl --no-ovsdb-server \
          --no-monitor --system-id=random \
          restart $OPTIONS

-------------------------

# systemctl cat ovsdb-server.service
# /usr/lib/systemd/system/ovsdb-server.service
[Unit]
Description=Open vSwitch Database Unit
After=syslog.target
ReloadPropagatedFrom=openvswitch.service
PartOf=openvswitch.service

[Service]
Type=forking
EnvironmentFile=-/etc/sysconfig/openvswitch
ExecStart=/usr/share/openvswitch/scripts/ovs-ctl \
          --no-ovs-vswitchd --no-monitor --system-id=random \
          start $OPTIONS
ExecStop=/usr/share/openvswitch/scripts/ovs-ctl --no-ovs-vswitchd stop
ExecReload=/usr/share/openvswitch/scripts/ovs-ctl --no-ovs-vswitchd \
           --no-monitor restart $OPTIONS
RuntimeDirectory=openvswitch
RuntimeDirectoryMode=0755
Comment 10 Lukáš Nykrýn 2016-09-23 13:58:54 UTC 
Should they be ordered Before=network.target? So they would go away after the connection to network is no longer needed.
Comment 11 Flavio Leitner 2016-09-26 13:30:39 UTC 
*** Bug 1331590 has been marked as a duplicate of this bug. ***
Comment 12 Aaron Conole 2016-09-26 13:56:38 UTC 
If you set them Before=network.target, then when they start if the network has not come yet, it is possible for the daemons to come up before the network interfaces are being created.

Can we check the before and after dependencies in the example mount?
I think it should be:

========================8<===============================
[Unit]
SourcePath=/etc/fstab
Documentation=man:fstab(5) man:systemd-fstab-generator(8)
After=remote-fs.target
After=network.target
Requires=network.target

[Mount]
What=192.168.1.9:/home/fleitner/Music
Where=/mnt
Type=nfs
Options=x-systemd.requires=network.target
========================8<===============================

 Before=remote-fs.target  to After=remote-fs.target  (because it will wait for remote-fs target to complete before finishing, which is not what is desired, I think)?

I haven't tested this.  I didn't use a systemd mountpoint when I had tested, so I could be wrong on the example.
Comment 13 Flavio Leitner 2016-09-26 23:42:26 UTC 
(In reply to Aaron Conole from comment #12)
> If you set them Before=network.target, then when they start if the network
> has not come yet, it is possible for the daemons to come up before the
> network interfaces are being created.

That is udev for physical devices and there no ordering between udev and network.target AFAIK. The systemd relies on hotplug/NetworkManager to handle that case.

> Can we check the before and after dependencies in the example mount?
> I think it should be:

Deferring to Lukáš to answer.

> I haven't tested this.  I didn't use a systemd mountpoint when I had tested,
> so I could be wrong on the example.

That is a consequence of adding a entry to /etc/fstab as described in comment#3.
Comment 17 Flavio Leitner 2016-10-07 17:11:11 UTC 
The OVS service has 3 services:

ovsdb-server.service which takes care of the OVS database
ovs-vswitchd.service which takes care of the vswitch itself.
openvswitch.service which is a wrapper to manage the other two.

The openvswitch.service has PartOf=network.target and in the logs it comes after remote-fs.target.  However, the other two OVS services were racing with remote-fs.target.


With this patch the order looks correct and I cannot reproduce the issue:
--- a/rhel/usr_lib_systemd_system_openvswitch.service
+++ b/rhel/usr_lib_systemd_system_openvswitch.service
@@ -1,5 +1,7 @@
 [Unit]
 Description=Open vSwitch
+Before=network.target network.service
+After=network-pre.target
 PartOf=network.target
 BindsTo=ovsdb-server.service
 BindsTo=ovs-vswitchd.service
--- a/rhel/usr_lib_systemd_system_ovs-vswitchd.service
+++ b/rhel/usr_lib_systemd_system_ovs-vswitchd.service
@@ -1,6 +1,7 @@
 [Unit]
 Description=Open vSwitch Forwarding Unit
-After=ovsdb-server.service
+After=ovsdb-server.service network-pre.target
+Before=network.target network.service
 Requires=ovsdb-server.service
 ReloadPropagatedFrom=ovsdb-server.service
 AssertPathIsReadWrite=/var/run/openvswitch/db.sock
--- a/rhel/usr_lib_systemd_system_ovsdb-server.service
+++ b/rhel/usr_lib_systemd_system_ovsdb-server.service
@@ -1,6 +1,7 @@
 [Unit]
 Description=Open vSwitch Database Unit
-After=syslog.target
+After=syslog.target network-pre.target
+Before=network.target network.service
 ReloadPropagatedFrom=openvswitch.service
 PartOf=openvswitch.service

Log snippet:
[...]
[  192.883442] systemd[1]: Stopping Remote File Systems.^M
[  192.887971] systemd[1]: Unmounting /mnt...^M
[  192.900130] systemd[1]: Unmounted /mnt.^M
[  192.900913] systemd[1]: Reached target Unmount All Filesystems.^M
[  192.901797] systemd[1]: Starting Unmount All Filesystems.^M
[  192.902601] systemd[1]: Stopped target Network is Online.^M
[  192.903426] systemd[1]: Stopping Network is Online.^M
[  192.904654] systemd[1]: Stopping Remote File Systems (Pre).^M
Reached target Unmount All Filesystems.^M^M
[  192.906666] systemd[1]: Stopped target NFS client services.^M
[  192.906691] systemd[1]: Stopping NFS client services.^M
] Stopped target Network is Online.
[  192.907205] systemd[1]: Stopping GSSAPI Proxy Daemon...
Stopped target Remote File Systems (Pre).
Stopped target NFS client services.
[  192.984438] systemd[1]: Stopping Network.^M
[  193.558957] device eth0 left promiscuous mode^M
[  194.165070] device int0 left promiscuous mode^M
[  194.676187] device ovsbr0 left promiscuous mode^M
[  194.861795] systemd[1]: Stopping Open vSwitch Forwarding Unit...^M
[  194.862678] systemd[1]: Stopping Open vSwitch...^M
[  194.863739] systemd[1]: Stopped Network Manager Wait Online.^M
[  194.864657] systemd[1]: Stopping Network Manager Wait Online...^M
Stopped LSB: Bring up/down networking.^M^M
Stopping Open vSwitch Forwarding Unit...^M^M
Stopping Open vSwitch...^M^M
[  194.980444] systemd[1]: Stopped Open vSwitch Forwarding Unit.^M
[^[[32m  OK  ^[[0m] Stopped Open vSwitch Forwarding Unit.^M^M
[  194.982082] systemd[1]: Stopping Open vSwitch Database Unit...^M
         Stopping Open vSwitch Database Unit...^M^M
[  194.996254] systemd[1]: Stopped Open vSwitch Database Unit.^M
Comment 18 Flavio Leitner 2016-10-07 17:35:56 UTC 
I am moving this back to openvswitch component based on the previous comment.
Comment 20 Xin Long 2016-10-09 11:39:06 UTC 
(In reply to Flavio Leitner from comment #17)
> The OVS service has 3 services:
> 
> ovsdb-server.service which takes care of the OVS database
> ovs-vswitchd.service which takes care of the vswitch itself.
> openvswitch.service which is a wrapper to manage the other two.
> 
> The openvswitch.service has PartOf=network.target and in the logs it comes
> after remote-fs.target.  However, the other two OVS services were racing
> with remote-fs.target.
> 
> 
> With this patch the order looks correct and I cannot reproduce the issue:
> --- a/rhel/usr_lib_systemd_system_openvswitch.service
> +++ b/rhel/usr_lib_systemd_system_openvswitch.service
> @@ -1,5 +1,7 @@
>  [Unit]
>  Description=Open vSwitch
> +Before=network.target network.service
> +After=network-pre.target
>  PartOf=network.target
>  BindsTo=ovsdb-server.service
>  BindsTo=ovs-vswitchd.service

Hi, Flavio.

I don't know much about ovs, but here is very similar with teamd.
https://github.com/jpirko/libteam/commit/0641375d10d692e3dacaeec95e36f2525b95881d

If we want one service is stopped after network.service when system shutdown,
it should be:

    Before=network-pre.target
    Wants=network-pre.target

I got this suggestion from systemd-devel:
http://systemd-devel.freedesktop.narkive.com/JWPXnu8v/does-before-network-target-really-work

Did I miss something here ?
Comment 21 Aaron Conole 2016-10-19 12:49:46 UTC 
This is now added to the RPM.
Comment 22 Aaron Conole 2016-10-19 12:51:54 UTC 
-18
Comment 25 Flavio Leitner 2016-10-25 16:48:59 UTC 
(In reply to Xin Long from comment #20)
> Did I miss something here ?

The difference is that teamd doesn't require the network to work, so the only requirement is to shutdown in the correct order, but OVS may require the network. So, running before network-pre.target doesn't sound correct to me. The intention is to run as if OVS was the actual network-like services, somewhere between network-pre.target and network.target. To be honest I don't consider myself a systemd expert so the proposed solution might not be the best one.