Bug 1281821

Summary: XFS recovery after enabling SELinux and relabeling - root not unmounted
Product: Red Hat Enterprise Linux 7 Reporter: Robert Palco <rpalco>
Component: initscriptsAssignee: initscripts Maintenance Team <initscripts-maint-list>
Status: CLOSED ERRATA QA Contact: Leos Pol <lpol>
Severity: high Docs Contact: Aneta Šteflová Petrová <apetrova>
Priority: urgent    
Version: 7.2CC: esandeen, fkrska, harald, jkurik, jruemker, jscotka, kari.hautio, lnykryn, lpol, mkarg, msekleta, pbokoc, plambri, qe-baseos-daemons, sknauss, systemd-maint-list
Target Milestone: rcKeywords: ZStream
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: initscripts-9.49.31-1.el7 Doc Type: Bug Fix
Doc Text:
Disks are now cleanly unmounted after SELinux automatic re-label Previously, after SELinux relabel, the *rhel-autorelabel* script started system reboot by running the "systemctl --force reboot" command. Consequently, certain steps required to cleanly unmount the *rootfs* image and deactivate the underlying Device Mapper (DM) device were skipped. To fix this bug, the *rhel-autorelabel* script has been modified to invoke the *dracut-initframs-restore* script before the reboot. As a result, disks are now cleanly unmounted in the described scenario.
 Story Points: ---
Clone Of:
: 1303700 (view as bug list) Environment:
Last Closed: 2016-11-04 06:42:47 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: 1203710, 1289485, 1303700    

Description Robert Palco 2015-11-13 13:59:47 UTC 
Description of problem:
After SELinux is enabled and system is rebooted, xfs recovery is always performed after the system relabeling.

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

How reproducible:
Anytime if there is Selinux relabeling performed 

Steps to Reproduce:
1. disable SELinux (/etc/selinux/config ==> SELINUX=disabled)
2. reboot (no xfs recovery performed during sysroot mount 
3. enable SELinux (/etc/selinux/config ==> SELINUX=enforced)
4. reboot (XFS (dm-1): Starting recovery (logdev: internal))

Actual results:
XFS recovery procedure performed

Expected results:
XFS procedure not to be performed

Additional info:
Comment 2 Eric Sandeen 2015-11-13 16:08:10 UTC 
Odd; recovery should only be performed if a clean unmount wasn't done; XFS is likely just the messenger here.

I'll instrument XFS and see if an actual unmount is done during the enable/reboot cycle.
Comment 3 Eric Sandeen 2015-11-13 16:50:30 UTC 
Actually the latest rhel7 kernels already tell us when xfs unmounts.

After changing to Enforcing, during reboot:

[  112.827079] XFS (dm-0): Unmounting Filesystem

Next reboot:

...
*** Warning -- SELinux targeted policy relabel is required.
*** Relabeling could take a very long time, depending on file
*** system size and speed of hard drives.
...

After relabeling is complete, we get:

[   82.074819] watchdog watchdog0: watchdog did not stop!
[   82.125376] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[   82.149516] systemd-journald[542]: Received SIGTERM from PID 1 (systemd-shutdow).
[   82.162824] type=1305 audit(1447433260.125:12): audit_pid=0 old=698 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1
[   82.226931] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[   82.246651] systemd-shutdown[1]: Hardware watchdog 'iTCO_wdt', version 0
[   82.260215] systemd-shutdown[1]: Unmounting file systems.
[   82.302631] systemd-shutdown[1]: Unmounting /boot.
[   82.312424] XFS (sda1): Unmounting Filesystem
[   82.350037] systemd-shutdown[1]: Unmounting /home.
[   82.359611] XFS (dm-2): Unmounting Filesystem
[   82.368744] systemd-shutdown[1]: Unmounting /var/lib/nfs/rpc_pipefs.
[   82.591427] systemd-shutdown[1]: All filesystems unmounted.

>>> note, the root filesystem dm-0 was never unmounted.

[   82.602556] systemd-shutdown[1]: Deactivating swaps.
[   82.612675] systemd-shutdown[1]: Deactivating swap /dev/dm-1.
[   82.626666] systemd-shutdown[1]: All swaps deactivated.
[   82.637096] systemd-shutdown[1]: Detaching loop devices.
[   82.647967] systemd-shutdown[1]: All loop devices detached.
[   82.659084] systemd-shutdown[1]: Detaching DM devices.
[   82.669661] systemd-shutdown[1]: Detaching DM 253:2.
[   82.696100] systemd-shutdown[1]: Detaching DM 253:1.
[   82.720053] systemd-shutdown[1]: Not all DM devices detached, 1 left.
[   82.733030] systemd-shutdown[1]: Detaching DM devices.
[   82.743490] systemd-shutdown[1]: Not all DM devices detached, 1 left.
[   82.756344] systemd-shutdown[1]: Cannot finalize remaining DM devices, continuing.
[   82.771969] systemd-shutdown[1]: Failed to finalize  DM devices, ignoring
[   82.814927] systemd-shutdown[1]: Rebooting.
[   82.823298] kvm: exiting hardware virtualization
[   82.832728] sd 0:2:0:0: [sda] Synchronizing SCSI cache
[   82.866487] Restarting system.
[   82.872577] reboot: machine restart

Seems that xfs was never cleanly unmounted, hence the log replay on the next reboot.

Moving over to systemd for more triage...
Comment 4 Eric Sandeen 2015-11-13 17:22:00 UTC 
For the customer, though, I'll note that xfs recovery isn't necessarily a problem; the filesystem will be fully consistent after recovery.
Comment 5 Robert Palco 2015-11-24 12:56:24 UTC 
Hello,
any update on this please?
Thank you in advance.
Comment 6 Kari Hautio 2015-11-24 16:47:58 UTC 
(In reply to Eric Sandeen from comment #4)
> For the customer, though, I'll note that xfs recovery isn't necessarily a
> problem; the filesystem will be fully consistent after recovery.

The consistency is not really the problem, the biggest problem is that in some cases the recovery can take awfully long making dracut to timeout /sysroot mount.

In most cases recuvery is short; just few seconds and it will make the dracut ~5 minute timeout without problem, however I have seen it taking as long as 20 minutes to complete leading to dracut shell.
Comment 7 Harald Hoyer 2015-11-30 13:00:05 UTC 
Does the file "/run/initramfs/.need_shutdown" exist?
Comment 8 Harald Hoyer 2015-11-30 13:03:58 UTC 
Also, what is the output of:

# sudo dracut --print-cmdline
# cat /proc/cmdline
Comment 9 Kari Hautio 2015-12-01 09:01:01 UTC 
Following is RHEL7.2 minimal install running in virt-manager.

Steps done before this
- disable selinux
- reboot
- enable selinus
- reboot
...
         Starting LVM2 PV scan on device 8:2...
[  OK  ] Started LVM2 PV scan on device 8:2.
[  OK  ] Reached target Sound Card.
[  OK  ] Mounted /boot.
[  OK  ] Reached target Local File Systems.
         Starting Relabel all filesystems, if necessary...
         Starting Import network configuration from initramfs...
         Starting Tell Plymouth To Write Out Runtime Data...
[  OK  ] Started Import network configuration from initramfs.
[  OK  ] Started Tell Plymouth To Write Out Runtime Data.
         Starting Create Volatile Files and Directories...

*** Warning -- SELinux targeted policy relabel is required.
*** Relabeling could take a very long time, depending on file
*** system size and speed of hard drives.
[  OK  ] Started Create Volatile Files and Directories.
         Starting Security Auditing Service...
[    5.771651] type=1305 audit(1448960056.817:5): audit_pid=641 old=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1
[  OK  ] Started Security Auditing Service.
         Starting Update UTMP about System Boot/Shutdown...
[  OK  ] Started Update UTMP about System Boot/Shutdown.
Warning: Skipping the following R/O filesystems:
/sys/fs/cgroup
100.0%
total 4
drwxr-xr-x.  4 root root 120 Dec  1 10:54 .
drwxr-xr-x. 20 root root 520 Dec  1 10:54 ..
drwxr-xr-x.  2 root root  40 Dec  1 10:54 log
-rw-r--r--.  1 root root   0 Dec  1 10:54 .need_shutdown
-rw-r--r--.  1 root root  61 Dec  1 10:54 rwtab
drwxr-xr-x.  4 root root  80 Dec  1 10:54 state
 rd.lvm.lv=rhel/swap 
 rd.lvm.lv=rhel/root 
 root=/dev/mapper/rhel-root rootflags=rw,relatime,seclabel,attr2,inode64,noquota rootfstype=xfs
BOOT_IMAGE=/vmlinuz-3.10.0-327.el7.x86_64 root=/dev/mapper/rhel-root ro crashkernel=auto rd.lvm.lv=rhel/root rd.lvm.lv=rhel/swap console=ttyS0,115200 LANG=en_US.UTF-8
Error getting authority: Error initializing authority: Could not connect: No such file or directory (g-io-error-quark, 1)
[   30.331771] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[   30.347646] systemd-journald[491]: Received SIGTERM from PID 1 (systemd-shutdow).
[   30.362273] type=1305 audit(1448960081.407:12): audit_pid=0 old=641 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1
[   30.375766] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[   30.380904] systemd-shutdown[1]: Unmounting file systems.
[   30.389801] systemd-shutdown[1]: Unmounting /boot.
[   30.390987] XFS (sda1): Unmounting Filesystem
[   30.518722] systemd-shutdown[1]: All filesystems unmounted.
[   30.520306] systemd-shutdown[1]: Deactivating swaps.
[   30.521857] systemd-shutdown[1]: Deactivating swap /dev/dm-1.
[   30.524591] systemd-shutdown[1]: All swaps deactivated.
[   30.525316] systemd-shutdown[1]: Detaching loop devices.
[   30.526291] systemd-shutdown[1]: All loop devices detached.
[   30.527074] systemd-shutdown[1]: Detaching DM devices.
[   30.528100] systemd-shutdown[1]: Detaching DM 253:1.
[   30.539851] systemd-shutdown[1]: Not all DM devices detached, 1 left.
[   30.541284] systemd-shutdown[1]: Detaching DM devices.
[   30.542263] systemd-shutdown[1]: Not all DM devices detached, 1 left.
[   30.543781] systemd-shutdown[1]: Cannot finalize remaining DM devices, continuing.
[   30.545772] systemd-shutdown[1]: Failed to finalize  DM devices, ignoring
[   30.549067] systemd-shutdown[1]: Rebooting.
[   30.549770] Unregister pv shared memory for cpu 1
[   30.549784] Unregister pv shared memory for cpu 2
[   30.549821] Unregister pv shared memory for cpu 0
[   30.552048] Unregister pv shared memory for cpu 3
[   30.553292] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[   30.589395] Restarting system.
[   30.589873] reboot: machine restart
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 3.10.0-327.el7.x86_64 (mockbuild.eng.bos.redhat.com) (gcc version 4.8.3 20140911 (Red Hat 4.8.3-9) (GCC) ) #1 SMP Thu Oct 29 17:29:29 EDT 2015
[    0.000000] Command line: BOOT_IMAGE=/vmlinuz-3.10.0-327.el7.x86_64 root=/dev/mapper/rhel-root ro crashkernel=auto rd.lvm.lv=rhel/root rd.lvm.lv=rhel/swap console=ttyS0,115200 LANG=en_US.UTF-8
...
[  OK  ] Reached target Remote File Systems (Pre).
[  OK  ] Reached target Remote File Systems.
[    2.446280] SGI XFS with ACLs, security attributes, no debug enabled
[    2.450292] XFS (dm-0): Mounting V4 Filesystem
[    3.293645] XFS (dm-0): Starting recovery (logdev: internal)
[    3.375219] XFS (dm-0): Ending recovery (logdev: internal)
[  OK  ] Mounted /sysroot.
[  OK  ] Reached target Initrd Root File System.
Comment 10 Kari Hautio 2015-12-01 09:04:53 UTC 
Following change was done to /lib/systemd/rhel-autorelabel to show the required information just prior to reboot

      fi
      rm -f  /.autorelabel
+     ls -la /run/initramfs
+     dracut --print-cmdline
+     cat /proc/cmdline
      systemctl --force reboot
  }
Comment 11 Michal Sekletar 2015-12-08 13:45:27 UTC 
I think that problem is that after SELinux autorelabel we short-circuit system reboot by calling "systemctl --force reboot" from rhel-autorelabel script.

Because of that dracut-shutdown.service is not executed and initramfs content is not restored, hence /run/initramfs/shutdown doesn't exist and systemd will not pivot_root into initramfs so it can cleanly unmount rootfs and deactivate underlying DM device. 

Following workaround/fix should do the trick but it is a hack, but hey, rhel-autorelabel is part of initscripts package so who cares right :)

diff --git a/systemd/rhel-autorelabel b/systemd/rhel-autorelabel
index 7cb9b40..924df8e 100755
--- a/systemd/rhel-autorelabel
+++ b/systemd/rhel-autorelabel
@@ -31,6 +31,7 @@ relabel_selinux() {
        /sbin/fixfiles $FORCE restore > /dev/null 2>&1
     fi
     rm -f  /.autorelabel
+    /usr/lib/dracut/dracut-initramfs-restore
     systemctl --force reboot
 }
Comment 12 Michal Sekletar 2015-12-08 13:49:44 UTC 
Also moving to initscripts as I believe this is the place where bug should be fixed. At any rate, this is clearly not a systemd bug.
Comment 13 Lukáš Nykrýn 2015-12-25 10:07:46 UTC 
The fix from commment 11 looks sane enough.
Comment 14 Robert Palco 2016-01-20 08:55:27 UTC 
The fix works for the customer and should be processed further. He would need a hotfix initscript package as well.
Comment 19 Lukáš Nykrýn 2016-02-01 16:05:16 UTC 
https://git.fedorahosted.org/cgit/initscripts.git/commit/?h=rhel7-branch&id=46f5c65d242efafcc27c5da23d0f0d8387ba7250
Comment 21 Kari Hautio 2016-03-21 12:41:27 UTC 
Apparently the fix is not perfect, it solves the issue on some cases but not always.

I can quite easily reproduce this on a real system using multipathed ISCSI LUN for root, it also is reproducible with a virtual VM with 2 virtual disks being used for volumegroup used for root LV.
Comment 22 Michal Sekletar 2016-03-22 18:09:48 UTC 
(In reply to Kari Hautio from comment #21)
> Apparently the fix is not perfect, it solves the issue on some cases but not
> always.
> 
> I can quite easily reproduce this on a real system using multipathed ISCSI
> LUN for root, it also is reproducible with a virtual VM with 2 virtual disks
> being used for volumegroup used for root LV.

This bug is basically about not pivoting back to initramfs on reboot after relabeling the filesystems. With the fix applied and editing kernel command line (added "autorelabel rd.break=shutdown") I was always dropped to shell just before we call reboot from initramfs at reboot. I installed VM with / on LVM thin LV on top of VG consisting of two PVs. In initramfs we actually unmount the root filesystem, thus you shouldn't see any recovery on next boot.

Can you try adding rd.break=shutdown and autorelabel on kernel command line and report back whether you are dropped to shell just before reboot after the relabel is done?
Comment 23 Mike McCune 2016-03-28 22:42:18 UTC 
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune with any questions
Comment 27 Kari Hautio 2016-05-30 13:07:36 UTC 
I do not see it drop to shell after relabel. I get into shell at earlier phase 

------

[ESC[32m  OK  ESC[0m] Started dracut initqueue hook.
[ESC[32m  OK  ESC[0m] Reached target Remote File Systems (Pre).
[ESC[32m  OK  ESC[0m] Reached target Remote File Systems.
[ESC[32m  OK  ESC[0m] Started File Syste
Generating "/run/initramfs/rdsosreport.txt"


Entering emergency mode. Exit the shell to continue.
Type "journalctl" to view system logs.
You might want to save "/run/initramfs/rdsosreport.txt" to a USB stick or /boot
after mounting them and attach it to a bug report.


switch_root:/# logout
[ESC[32m  OK  ESC[0m] Closed udev Kernel Socket.
[ESC[32m  OK  ESC[0m] Closed udev Control Socket.
         Starting Cleanup udevd DB...

-----

Log from console:

^M100.0%^M100.0%^M100.0%^M100.0%^M100.0%^M100.0%^M100.0%^M100.0%^M100.0%
Error getting authority: Error initializing authority: Could not connect: No such file or directory (g-io-error-quark, 1)
[  207.348661] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[  207.372705] systemd-journald[2643]: Received SIGTERM from PID 1 (systemd-shutdow).
[  207.385715] type=1305 audit(1464609872.937:12): audit_pid=0 old=3058 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1
[  207.388858] systemd-readahead[2640]: open(/etc/selinux/targeted/modules/active/policy.kern) failed: Too many levels of symbolic links
[  207.419361] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[  207.437390] systemd-shutdown[1]: Hardware watchdog 'HP iLO2+ HW Watchdog Timer', version 0
[  207.440426] systemd-shutdown[1]: Unmounting file systems.
[  207.444840] systemd-shutdown[1]: Unmounting /var/lib/ceph/osd/ceph-1.
[  207.447103] XFS (dm-14): Unmounting Filesystem
[  207.449903] systemd-shutdown[1]: Unmounting /var/lib/nfs/rpc_pipefs.
[  207.562788] systemd-shutdown[1]: All filesystems unmounted.
[  207.565525] systemd-shutdown[1]: Deactivating swaps.
[  207.567740] systemd-shutdown[1]: Deactivating swap /dev/dm-3.
[  207.570410] systemd-shutdown[1]: All swaps deactivated.
[  207.572578] systemd-shutdown[1]: Detaching loop devices.
[  207.575550] systemd-shutdown[1]: All loop devices detached.
[  207.577459] systemd-shutdown[1]: Detaching DM devices.
[  207.579766] systemd-shutdown[1]: Detaching DM 253:9.
[  207.601785] systemd-shutdown[1]: Detaching DM 253:8.
[  207.619752] systemd-shutdown[1]: Detaching DM 253:7.
[  207.643824] systemd-shutdown[1]: Detaching DM 253:5.
[  207.645586] systemd-shutdown[1]: Could not detach DM /dev/dm-5: Device or resource busy
[  207.648267] systemd-shutdown[1]: Detaching DM 253:4.
[  207.667459] systemd-shutdown[1]: Detaching DM 253:3.
[  207.685769] systemd-shutdown[1]: Detaching DM 253:2.
[  207.703853] systemd-shutdown[1]: Detaching DM 253:14.
[  207.721488] systemd-shutdown[1]: Detaching DM 253:13.
[  207.739806] systemd-shutdown[1]: Detaching DM 253:12.
[  207.757855] systemd-shutdown[1]: Detaching DM 253:11.
[  207.781549] systemd-shutdown[1]: Detaching DM 253:10.
[  207.799515] systemd-shutdown[1]: Detaching DM 253:1.
[  207.817494] systemd-shutdown[1]: Detaching DM 253:0.
[  207.819515] systemd-shutdown[1]: Could not detach DM /dev/dm-0: Device or resource busy
[  207.819519] systemd-shutdown[1]: Not all DM devices detached, 3 left.
[  207.819603] systemd-shutdown[1]: Detaching DM devices.
[  207.819748] systemd-shutdown[1]: Detaching DM 253:5.
[  207.819755] systemd-shutdown[1]: Could not detach DM /dev/dm-5: Device or resource busy
[  207.819757] systemd-shutdown[1]: Detaching DM 253:0.
[  207.819761] systemd-shutdown[1]: Could not detach DM /dev/dm-0: Device or resource busy
[  207.819763] systemd-shutdown[1]: Not all DM devices detached, 3 left.
[  207.819765] systemd-shutdown[1]: Cannot finalize remaining DM devices, continuing.
[  208.488316] systemd-shutdown[1]: Failed to finalize  DM devices, ignoring
[  208.491282] systemd-shutdown[1]: Rebooting.
[  208.493026] kvm: exiting hardware virtualization
[  208.498083]  pci0000:20: System wakeup enabled by ACPI
[  208.500262]  pci0000:20: System wakeup enabled by ACPI
[  208.587106] Restarting system.
[  208.588130] reboot: machine restart
Comment 35 Leos Pol 2016-08-11 11:58:20 UTC 
I can't reproduce the issue with initscripts-9.49.35-1.el7, all I can see are clean xfs mounts.
Comment 48 errata-xmlrpc 2016-11-04 06:42:47 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2016-2456.html