Merge lp:~jamesodhunt/ubuntu/saucy/sysvinit/log-processes-and-open-files-on-shutdown into lp:ubuntu/saucy/sysvinit

[James Hunt]

= Problem =

Occasionally, people report issues where the root filesystem cannot be unmounted cleanly on shutdown. To debug these issues generally involves either producing custom PPA packages, or requesting users hack around with the existing shutdown sequence (not ideal).

= Overview =

Since these shutdown issues re-occur from time-to-time (*) it makes sense to put in place a facility to aid debugging without having to produce custom PPA package builds, etc.

This MP logs running processes and open files just prior to unmounting the disks such that if problems are observed on shutdown, they can be investigated on the next boot by looking at the files below which are generated on shutdown:

- /var/log/shutdown-ps.log
- /var/log/shutdown-lsof.log

= Notes =

The lsof command can take some time to run on a normal system. However, note that this should not be a problem at shutdown in the usual case since we don't expect many processes to still be running (and hence it will only slow down the shutdown slightly in the cases where something _has_ gone wrong and hence we need to run lsof to diagnose). Note too that by using the '-lnP' options, lsof is run as fast as possible.

If accepted, this should be forwarded to Debian too.

(*) - this does not imply a regression: it may be that some combination of package versions from the full archive interact in unexpected ways in a particular release (it is not possible to test every combination).

[James Hunt (jamesodhunt)]

Note that once this feature is available, apport hooks can make use of these files for reporting shutdown issues.

[Steve Langasek (vorlon)]

Thanks for taking this on, James.

I would like to see a few improvements here:
 - These logs are written unconditionally. I would recommend that we write them *only* in the error case, by doing some analysis of the open files first and logging only if we find an issue with files open for writing.
 - Fixing this to only write the logs in case of error means that the sysvinit package itself can be made to trigger apport in the case of a failure, instead of relying on this being picked up by an apport hook later. I would like to see this done. (This does raise the bar for correctness of our checks... the last time something like this was enabled in sendsigs, the false positive rate was terrible and it had to be disabled again. But we should be able to get this done accurately if we're properly checking only for files open for writing and files open on non-root filesystems.)
 - I think logging the process list is redundant. We are going to need the lsof logs for analysis, and if lsof is unavailable, I don't think the ps output is going to be sufficient for debugging: it may let us point the finger at a particular process, but won't tell us anything about why.
 - This output is being written to /var/log in the umountfs script. It's possible (though unlikely) for a file to be opened for writing *after* umountfs has run, but before umountroot is run. I think we want to capture this data at that later point, which is more definitive? Also, since /var/log may not be on the root filesystem, we can't rely on writing there from umountroot. This suggests to me that for best results, we either need to designate some place guaranteed to be on the root filesystem to write a log from umountroot (either directly in / analagous to the /forcefsck flag, or under /etc), or log this information to the console rather than the filesystem. The latter would be /potentially/ useful in the case of a read-only root filesystem, except in that case umountroot can never fail so we don't need to log anything anyway. Oh, and /usr may *also* not be on the root filesystem, which makes it problematic to call /usr/bin/lsof. Perhaps the best approach is to log any problems to /var/log from umountfs, and then again log any problems to the console from umountroot if possible.

Finally, the exact patch here is not very idiomatic:

+ # Log open files as quickly as possible
+ { `command -v lsof` && lsof -lnP > /var/log/shutdown-lsof.log && sync; } || :

This script is not 'set -e', so the { ;} || : is unnecessary and inconsistent with the style of the rest of the script. `command -v lsof` is actually buggy, because this takes the output of 'command -v' and *runs* it, resulting in a duplicate call to lsof (without the speed optimizations). And chaining with '&&' makes the flow less obvious than it could be.

I recommend writing this as:

        if command -v lsof >/dev/null 2>&1; then
            lsof -lnP > /var/log/shutdown-lsof.log
            sync
        fi

review: Needs Fixing

[James Hunt (jamesodhunt)]

Hi Steve,

Thanks for reviewing. I've made the suggested changes. In the umountroot case, I wonder if we should check the permissions on the root mountpoint and if they are rw also log to '/.shutdown-lsof.log'?

[Colin Watson (cjwatson)]

Just one drive-by nit: in new code we should use the POSIX form "head -n1" rather than the old-style "head -1".

[James Hunt (jamesodhunt)]

Use https://code.launchpad.net/~jamesodhunt/ubuntu/trusty/sysvinit/log-open-files-on-shutdown/+merge/196141 instead.

[Iain Lane (laney)]

Per the last comment, → rejected.

Unmerged revisions

191. By James Hunt on 2013-09-27

* debian/src/initscripts/etc/init.d/umountroot: Fix typo and use POSIX
  form of head(1) (thanks cjwatson).

190. By James Hunt on 2013-05-24

* debian/src/initscripts/etc/init.d/umountfs: Log open files on root
  filesystem just prior to unmounting filesystems to aid diagnosis of
  shutdown issues.
* debian/src/initscripts/etc/init.d/umountroot: Check again for open files
  and log to console.

=== modified file 'debian/changelog'
--- debian/changelog	2013-06-04 08:53:47 +0000
+++ debian/changelog	2013-09-27 07:40:31 +0000
@@ -1,3 +1,4 @@
+<<<<<<< TREE
 sysvinit (2.88dsf-41ubuntu3) saucy; urgency=low
 
   * Exit the ondemand script silently if we are on a system that has
@@ -18,6 +19,16 @@
 
  -- Steve Langasek <[e-mail]>  Tue, 28 May 2013 12:23:43 -0700
 
+=======
+sysvinit (2.88dsf-41ubuntu2) saucy; urgency=low
+
+  * debian/src/initscripts/etc/init.d/umountfs: Log open files on root
+    filesystem just prior to unmounting filesystems to aid diagnosis of
+    shutdown issues.
+  * debian/src/initscripts/etc/init.d/umountroot: Check again for open files
+    and log to console.
+
+>>>>>>> MERGE-SOURCE
 sysvinit (2.88dsf-41ubuntu1) saucy; urgency=low
 
   * Merge from Debian unstable:

=== modified file 'debian/src/initscripts/etc/init.d/umountfs'
--- debian/src/initscripts/etc/init.d/umountfs	2013-05-17 06:03:10 +0000
+++ debian/src/initscripts/etc/init.d/umountfs	2013-09-27 07:40:31 +0000
@@ -16,6 +16,25 @@
 
 umask 022
 
+# Before unmounting filesystems, log all files open for writing on the root
+# filesystem for possible analysis on the next boot since such files
+# will cause an unclean shutdown.
+do_log () {
+	if command -v lsof >/dev/null 2>&1; then
+		# capture list of open files on root mountpoint as quickly as possible
+		output=$(lsof -lnPR /)
+
+		# look for first occurence of file open for writing
+		open_files=$(echo "$output"|awk '$5 ~ /^[0-9][0-9]*[uw]/ {print;exit 0}')
+
+		if [ -n "$open_files" ]; then
+			# log full lsof output
+			echo "$output" > /var/log/shutdown-lsof.log
+			sync
+		fi
+	fi
+}
+
 do_stop () {
 	PROTECTED_MOUNTS="$(sed -n ':a;/^[^ ]* \/ /!{H;n;ba};{H;s/.*//;x;s/\n//;p}' /proc/mounts)"
 	WEAK_MTPTS="" # be gentle, don't use force
@@ -119,6 +138,7 @@
 	exit 3
 	;;
   stop)
+	do_log
 	do_stop
 	;;
   *)

=== modified file 'debian/src/initscripts/etc/init.d/umountroot'
--- debian/src/initscripts/etc/init.d/umountroot	2013-05-17 06:03:10 +0000
+++ debian/src/initscripts/etc/init.d/umountroot	2013-09-27 07:40:31 +0000
@@ -14,6 +14,26 @@
 
 . /lib/lsb/init-functions
 
+# Before unmounting root, log all files open for writing to the console
+# (since no other locations are available for writing and root may be
+# read-only).
+do_log () {
+	if command -v lsof >/dev/null 2>&1; then
+		# capture list of open files on root mountpoint as quickly as possible
+		output=$(lsof -lnPR /)
+		open_files=$(echo "$output"|awk '$5 ~ /^[0-9][0-9]*[uw]/ {print}')
+
+		if [ -n "$open_files" ]; then
+			echo "INFO: files open at shutdown"
+			# show lsof header
+			echo "$output"|head -n1
+			# just show the open files to avoid completely
+			# flooding the console.
+			echo "$open_files" > /dev/console
+		fi
+	fi
+}
+
 do_stop () {
 	[ "$VERBOSE" = no ] || log_action_begin_msg "Mounting root filesystem read-only"
 	# Ask init to re-exec itself before we go down if it has been