Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

systemd: Do not unmount /storage and /flash at shutdown as this always fails #546

Merged
merged 1 commit into from
Jul 20, 2016
Merged

systemd: Do not unmount /storage and /flash at shutdown as this always fails #546

merged 1 commit into from
Jul 20, 2016

Conversation

MilhouseVH
Copy link
Contributor

@MilhouseVH MilhouseVH commented Jul 18, 2016

The default systemd-halt.service will unmount all mounted file systems prior to shutting down the system.

Unfortunately, this means that systemd attempts to unmount /storage early in the shutdown process when /storage is still in use (for various purposes, most notably the system journal, plus /storage/.config as we haven't executed any shutdown scripts yet...), and consequently the unmount of /storage always fails.

Here is the shutdown log based on current master when booting Generic on i5 NUC - note that I have two additional mount points /storage/freenas and /storage/data that are being correctly unmounted:

Jul 17 21:03:43 NUC systemd[1]: Stopping Udevil mount service...
Jul 17 21:03:43 NUC systemd[1]: Starting Save random entropy at shutdown...
Jul 17 21:03:43 NUC systemd[1]: Stopped configure Xorg Server for i915.
Jul 17 21:03:43 NUC systemd[1]: Unmounting /storage/freenas...
Jul 17 21:03:43 NUC systemd[1]: Stopped target Sound Card.
Jul 17 21:03:43 NUC systemd[1]: Stopped target Kodi Mediacenter Interface.
Jul 17 21:03:43 NUC systemd[1]: Stopping Udevil mount service...
Jul 17 21:03:43 NUC systemd[1]: Removed slice system-xorg\x2dconfigure.slice.
Jul 17 21:03:43 NUC systemd[1]: Stopping Kodi Media Center...
Jul 17 21:03:43 NUC systemd[1]: Stopped target Bluetooth.
Jul 17 21:03:43 NUC systemd[1]: Unmounting /storage/data...
Jul 17 21:03:43 NUC systemd[1]: Stopped target Timers.
Jul 17 21:03:43 NUC systemd[1]: Stopped Daily Cleanup of Temporary Directories.
Jul 17 21:03:43 NUC add-random-at-shutdown[833]: 4+0 records in
Jul 17 21:03:43 NUC add-random-at-shutdown[833]: 4+0 records out
Jul 17 21:03:43 NUC add-random-at-shutdown[833]: 2048 bytes (2.0KB) copied, 0.000529 seconds, 3.7MB/s
Jul 17 21:03:43 NUC udevil[832]: udevil: denied 71: '/' is not an allowed media directory
Jul 17 21:03:43 NUC systemd[1]: Started Save random entropy at shutdown.
Jul 17 21:03:43 NUC systemd[1]: Unmounted /flash.
Jul 17 21:03:43 NUC systemd[1]: Requested transaction contradicts existing jobs: Transaction is destructive.
Jul 17 21:03:43 NUC samba-autoshare[844]: Failed to restart smbd.service: Transaction is destructive.
Jul 17 21:03:43 NUC samba-autoshare[844]: See system logs and 'systemctl status smbd.service' for details.
Jul 17 21:03:43 NUC avahi-daemon[321]: dbus-entry-group.c: interface=org.freedesktop.Avahi.EntryGroup, path=/Client2/EntryGroup6, member=Free
Jul 17 21:03:43 NUC systemd[1]: Stopped Udevil mount service.
Jul 17 21:03:43 NUC systemd[1]: Unmounted /storage/freenas.
Jul 17 21:03:43 NUC udevil[835]: udevil: success running umount as current user
Jul 17 21:03:43 NUC systemd[1]: Unmounted /storage/data.
Jul 17 21:03:43 NUC systemd[1]: Unmounting /storage...
Jul 17 21:03:43 NUC umount[856]: umount: can't unmount /storage: Device or resource busy
Jul 17 21:03:43 NUC systemd[1]: storage.mount: Mount process exited, code=exited status=1
Jul 17 21:03:43 NUC systemd[1]: Failed unmounting /storage.
Jul 17 21:03:43 NUC systemd[1]: Stopped Udevil mount service.
Jul 17 21:03:43 NUC systemd[1]: Removed slice system-udevil\x2dmount.slice.

(Full log: http://sprunge.us/CWLD)

This failure to unmount /storage results in the following user experience on shutdown:

s1

With this PR, we prevent the umount.target from unmounting /storage in umount.c - we don't want it unmounted when we still need it, and it's still in use anyway so unmounting will always fail.

Following this PR, the umount.target is a success on shutdown:

Jul 17 22:28:42 NUC systemd[1]: Stopping Udevil mount service...
Jul 17 22:28:42 NUC systemd[1]: Stopping Udevil mount service...
Jul 17 22:28:42 NUC systemd[1]: Stopped target Timers.
Jul 17 22:28:42 NUC systemd[1]: Stopped Daily Cleanup of Temporary Directories.
Jul 17 22:28:42 NUC systemd[1]: Unmounting /storage/data...
Jul 17 22:28:42 NUC systemd[1]: Stopped target Sound Card.
Jul 17 22:28:42 NUC systemd[1]: Stopped target Kodi Mediacenter Interface.
Jul 17 22:28:42 NUC systemd[1]: Stopping Kodi Media Center...
Jul 17 22:28:42 NUC systemd[1]: Starting Save random entropy at shutdown...
Jul 17 22:28:42 NUC systemd[1]: Unmounting /storage/freenas...
Jul 17 22:28:42 NUC systemd[1]: Stopped configure Xorg Server for i915.
Jul 17 22:28:42 NUC systemd[1]: Removed slice system-xorg\x2dconfigure.slice.
Jul 17 22:28:42 NUC systemd[1]: Stopped target Bluetooth.
Jul 17 22:28:42 NUC udevil[841]: udevil: denied 71: '/' is not an allowed media directory
Jul 17 22:28:42 NUC systemd[1]: Unmounted /flash.
Jul 17 22:28:42 NUC add-random-at-shutdown[844]: 4+0 records in
Jul 17 22:28:42 NUC add-random-at-shutdown[844]: 4+0 records out
Jul 17 22:28:42 NUC add-random-at-shutdown[844]: 2048 bytes (2.0KB) copied, 0.000573 seconds, 3.4MB/s
Jul 17 22:28:42 NUC systemd[1]: Started Save random entropy at shutdown.
Jul 17 22:28:42 NUC avahi-daemon[331]: dbus-entry-group.c: interface=org.freedesktop.Avahi.EntryGroup, path=/Client2/EntryGroup6, member=Free
Jul 17 22:28:42 NUC systemd[1]: Requested transaction contradicts existing jobs: Transaction is destructive.
Jul 17 22:28:42 NUC samba-autoshare[853]: Failed to restart smbd.service: Transaction is destructive.
Jul 17 22:28:42 NUC samba-autoshare[853]: See system logs and 'systemctl status smbd.service' for details.
Jul 17 22:28:42 NUC systemd[1]: Stopped Udevil mount service.
Jul 17 22:28:42 NUC systemd[1]: Unmounted /storage/data.
Jul 17 22:28:42 NUC systemd[1]: Unmounted /storage/freenas.
Jul 17 22:28:42 NUC udevil[840]: udevil: success running umount as current user
Jul 17 22:28:42 NUC systemd[1]: Stopped Udevil mount service.
Jul 17 22:28:42 NUC systemd[1]: Removed slice system-udevil\x2dmount.slice.

(Full log: http://sprunge.us/OEAA)

And the shutdown user experience is now much improved - there's not much to see (just the console text from startup, which is how it should be):

s1

This has been tested on RPi, RPi2 and Generic.

I only became aware of this shutdown issue when rebooting an i5 NUC (Generic).

Prior to using this system I hadn't seen any errors when restarting a Revo3700/ION2 (nvidia legacy) system - apparently the Revo3700 reboots before the error messages are rendered by the console. Adding a shutdown delay in /storage/.config/shutdown.sh:

sleep 10

revealed the shutdown errors which are identical to the NUC (see first picture, above).

With the RPi/RPi2, there are no errors visible when shutting down as the console framebuffer has already been hidden. However after analysing the journal it is evident that the same unmount /storage failure is occurring on RPi/RPi2.

It is also apparent that attempting to unmount /flash (through flash.mount) on the RPi/RPi2 will also fail, since the system is still running from /flash.

RPi2 shutdown log (without this PR) - edited to remove noise, showing failures to unmount /storage and /flash:

Jul 18 01:14:49 rpi22 systemd[1]: Stopping Udevil mount service...
Jul 18 01:14:49 rpi22 systemd[1]: Unmounting /storage/freenas...
Jul 18 01:14:49 rpi22 systemd[1]: Starting Save random entropy at shutdown...
Jul 18 01:14:49 rpi22 systemd[1]: Stopped target Bluetooth.
Jul 18 01:14:49 rpi22 systemd[1]: Stopping Udevil mount service...
Jul 18 01:14:49 rpi22 systemd[1]: Stopping Broadcom sdio firmware update for BCM43430A1...
Jul 18 01:14:49 rpi22 systemd[1]: Stopped target Timers.
Jul 18 01:14:49 rpi22 systemd[1]: Stopped Daily Cleanup of Temporary Directories.
Jul 18 01:14:49 rpi22 systemd[1]: Stopping Bluetooth service...
Jul 18 01:14:49 rpi22 systemd[1]: Unmounting /storage/data...
Jul 18 01:14:49 rpi22 systemd[1]: Stopped target Kodi Mediacenter Interface.
Jul 18 01:14:49 rpi22 systemd[1]: Stopping Kodi Media Center...
Jul 18 01:14:49 rpi22 systemd[1]: Stopping Udevil mount service...
Jul 18 01:14:49 rpi22 systemd[1]: Stopped Bluetooth service.
Jul 18 01:14:49 rpi22 udevil[795]: udevil: denied 71: '/' is not an allowed media directory
Jul 18 01:14:49 rpi22 add-random-at-shutdown[794]: 4+0 records in
Jul 18 01:14:49 rpi22 add-random-at-shutdown[794]: 4+0 records out
Jul 18 01:14:49 rpi22 add-random-at-shutdown[794]: 2048 bytes (2.0KB) copied, 0.000875 seconds, 2.2MB/s
Jul 18 01:14:49 rpi22 systemd[1]: Started Save random entropy at shutdown.
Jul 18 01:14:49 rpi22 systemd[1]: Unmounted /storage/freenas.
Jul 18 01:14:49 rpi22 systemd[1]: Unmounted /var/media/Images.
Jul 18 01:14:49 rpi22 systemd[1]: Unmounted /storage/data.
Jul 18 01:14:49 rpi22 systemd[1]: Unmounting /storage...
Jul 18 01:14:49 rpi22 umount[814]: umount: can't unmount /storage: Device or resource busy
Jul 18 01:14:49 rpi22 udevil[799]: udevil: success running umount as current user
Jul 18 01:14:49 rpi22 systemd[1]: storage.mount: Mount process exited, code=exited status=1
Jul 18 01:14:49 rpi22 systemd[1]: Failed unmounting /storage.
Jul 18 01:14:49 rpi22 udevil[792]: udevil: denied 71: '/' is not an allowed media directory
Jul 18 01:14:49 rpi22 systemd[1]: Stopped Udevil mount service.
Jul 18 01:14:49 rpi22 systemd[1]: Stopped Udevil mount service.
Jul 18 01:14:49 rpi22 systemd[1]: Stopped Udevil mount service.
Jul 18 01:14:49 rpi22 systemd[1]: Removed slice system-udevil\x2dmount.slice.
...
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Eventlirc server daemon.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped target Basic System.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped target Sockets.
Jul 18 01:14:57 rpi22 systemd[1]: Closed RPCbind Server Activation Socket.
Jul 18 01:14:57 rpi22 systemd[1]: Closed D-Bus System Message Bus Socket.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped target Slices.
Jul 18 01:14:57 rpi22 systemd[1]: Removed slice User and Session Slice.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped target Paths.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Forward Password Requests to Wall Directory Watch.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped target System Initialization.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Apply Kernel Variables.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Create Volatile Files and Directories.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Flush Journal to Persistent Storage.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped target Local File Systems.
Jul 18 01:14:57 rpi22 systemd[1]: Unmounting /flash...
Jul 18 01:14:57 rpi22 systemd[1]: Unmounting Temporary Directory...
Jul 18 01:14:57 rpi22 systemd[1]: Unmounting Variable Directory...
Jul 18 01:14:57 rpi22 umount[852]: umount: can't unmount /flash: Device or resource busy
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Load Kernel Modules.
Jul 18 01:14:57 rpi22 systemd[1]: flash.mount: Mount process exited, code=exited status=1
Jul 18 01:14:57 rpi22 systemd[1]: Failed unmounting /flash.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped target Local File Systems (Pre).
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Create Static Device Nodes in /dev.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Remount Root and Kernel File Systems.
Jul 18 01:14:57 rpi22 systemd[1]: Unmounted Temporary Directory.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped target Swap.
Jul 18 01:14:57 rpi22 systemd[1]: Stopped Mounting swapfile.
Jul 18 01:14:57 rpi22 systemd[1]: Reached target Shutdown.
Jul 18 01:14:57 rpi22 systemd[1]: Unmounted Variable Directory.
Jul 18 01:14:57 rpi22 systemd[1]: Reached target Unmount All Filesystems.
Jul 18 01:14:57 rpi22 systemd[1]: Reached target Final Step.
Jul 18 01:15:19 rpi22 systemd[1]: Started Kodi reboot script.
Jul 18 01:15:19 rpi22 systemd[1]: Starting Reboot...
Jul 18 01:15:19 rpi22 systemd[1]: Shutting down.
Jul 18 01:15:19 rpi22 systemd[1]: Hardware watchdog 'Broadcom BCM2835 Watchdog timer', version 0
Jul 18 01:15:19 rpi22 systemd[1]: Failed to set timeout to 600s: Invalid argument
Jul 18 01:15:19 rpi22 systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Jul 18 01:15:19 rpi22 systemd-journald[221]: Journal stopped
-- Reboot --

(Full log: http://sprunge.us/SfUd)

Thus /flash is also added to the ignore list when unmounting mount points.

Unmounting of /storage also fails in OpenELEC 6.0.3 so this isn't an entirely new phenomenon, however the shutdown sequence in OE 6.0.3 (based on systemd-219) is very different to that in LibreELEC, with the filesystem unmounts occurring later in the shutdown sequence. Although /storage cannot be unmounted in OpenELEC, it isn't being logged as a failure (for a reason I haven't been able to determine).

So, as OE and LE have never actually unmounted /storage (and also - at least on RPi/RPi2 - /flash) successfully, ignoring /storage and /flash when unmounting filesystems should have no noticeable effect other than to avoid failures being logged and potentially shown to the user.

Ping @seo as you may have a better idea how to solve this issue...

As far as I can see, the only way to successfully unmount /storage would be to do so after the journal service has stopped, ie. right at the very end of the shutdown sequence. The problem with delaying umount.target will be that any network mounts will have difficulty unmounting as the network will already be down - this is a problem solved in OE with OpenELEC/OpenELEC.tv#4659.

I also don't see how it would be possible to unmount /flash when the system is still running from that mount point.

Consequently reorganising the shutdown sequence to resolve these largely cosmetic issues might be more trouble than it's worth - hence this quick hack - but anything you can suggest would be welcome.

@gdachs you reported issue OpenELEC/OpenELEC.tv#4475 against OpenELEC, can you confirm if this is still an issue in LibreELEC with and without this new PR?

@lrusak
Copy link
Member

lrusak commented Jul 18, 2016

Could this be something we backport to LE 7.0 as a bugfix?

@MilhouseVH
Copy link
Contributor Author

If there are plans for any further LE 7.0 releases then I can backport this based on whatever we end up merging to master.

@MilhouseVH
Copy link
Contributor Author

Meant to ping @stefansaraev not @seo. :)

@stefansaraev
Copy link
Contributor

stefansaraev commented Jul 18, 2016

I have never seen this issue, but it seems to be a race condition due to wrong service ordering

OE/LE has too much services with DefaultDependencies=no declared. this is a bad thing, and behaviour may suddenly change every time you update systemd, or you add yet another service.

my 2 cents. all services that use DefaultDependencies=no should be looked at, and whenever possible, cleaned up better sooner than later. those that run on shutdown should be Before=shutdown.target and WantedBy=shutdown.target (or poweroff/reboot targets).

those should also always have Type=oneshot and RemainAfterExit=yes

less services that break default dependency chain - less trouble in future.

I lost track on what's going on with OE/LE development, my very stripped down fork has exactly 5 non-systemd shipped services, so perhaps I should not comment too much. of course, if it is really not possible to safely umount /flash and /storage, this PR is ok. dirty but ok.

EDIT:

I also don't see how it would be possible to unmount /flash when the system is still running from that mount point.

true, but systems with > 1G of ram will run from ram (/dev/SYSTEM), there you can even umount /flash while LE is runing, and/or do "in place upgrade" replacing contents of /flash and just rebooting, I have done that for years on my old ION :)

EDIT: oh well, and long time ago, I voted against adding shutdown.sh support. but that's another story ;)

@MilhouseVH
Copy link
Contributor Author

@stefansaraev thanks, your comments sound reasonable and perhaps it's something we can look at in the future to try and improve the way we use systemd (though likely not something for the feint of heart!)

@stefansaraev
Copy link
Contributor

offtopic. umounting storage if it's on nfs should be fine if you use KillSignal=SIGKILL in connman.servce /me runs

@piotrasd
Copy link
Contributor

i got this same issue from some time ...

@escalade
Copy link
Contributor

Same here, haswell NUC. With this PR there's no failed unmounting during shutdown, but the console is still spammed with OK messages.

@MilhouseVH
Copy link
Contributor Author

MilhouseVH commented Jul 18, 2016

but the console is still spammed with OK messages.

Presumably the spam is caused by a different service in your case?

Diagnosing in this PR wouldn't be the right place but try adding a sleep 30 in /storage/.config/shutdown.sh so you can observe the console messages and perhaps try to work out which service is the problem. Analysing the log may also provide some clues - kodi.bin is often marked as failed. To be honest I'm not entirely sure what triggers systemd to spam the console.

@jester-xbmc
Copy link
Contributor

my 2 cents, I'm getting the console spam on shutdown/reboot running LE on NUC, error is Failed unmouting /storage
unmounting /flash gets an ok.

@MilhouseVH
Copy link
Contributor Author

@jester-xbmc if you want to test this it's in my last Generic test build: http://forum.kodi.tv/showthread.php?tid=269815&pid=2376765#pid2376765

@jester-xbmc
Copy link
Contributor

@MilhouseVH I know ;-) thx

@lrusak
Copy link
Member

lrusak commented Jul 20, 2016

Good to go?

@MilhouseVH
Copy link
Contributor Author

I think so. Easy enough to revert if we do find a problem (or better solution).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

6 participants