init: allow for logging of early userspace

This introduces support for the rd.log and rd.debug kernel command line
options, which log early userspace activity to /run/initramfs/init.log.

Code is largely inspired by Dracut's implementation of early userspace
logging, but without needless complexity and redundancies.

Signed-off-by: Dave Reisner <dreisner@archlinux.org>

3 files changed, 176 insertions, 2 deletions

diff --git a/init b/init
index dfebd53..2578cf8 100644
--- a/init
+++ b/init
@@ -3,6 +3,7 @@
 udevd_running=0
 mount_handler=default_mount_handler
 init=/sbin/init
+rd_logmask=0
 
 if [ -x /usr/bin/systemd-timestamp ]; then
     RD_TIMESTAMP=$(systemd-timestamp)
@@ -19,6 +20,9 @@ mkdir -m755 /run/initramfs
 # parse the kernel command line
 parse_cmdline </proc/cmdline
 
+# setup logging as early as possible
+rdlogger_start
+
 for d in ${disablehooks//,/ }; do
     [ -e "/hooks/$d" ] && chmod 644 "/hooks/$d"
 done
@@ -72,6 +76,8 @@ if [ "${break}" = "postmount" ]; then
     launch_interactive_shell
 fi
 
+rdlogger_stop
+
 exec env -i \
     "TERM=$TERM" \
     "RD_TIMESTAMP=$RD_TIMESTAMP" \
diff --git a/init_functions b/init_functions
index 98bf354..7e591fc 100644
--- a/init_functions
+++ b/init_functions
@@ -1,5 +1,11 @@
 # This file contains common functions used in init and in hooks
 
+# logging targets
+_rdlog_file=$(( 1 << 0 ))
+_rdlog_kmsg=$(( 1 << 1 ))
+_rdlog_cons=$(( 1 << 2 ))
+_rdlog_all=$(( (1 << 3) - 1 ))
+
 msg () {
     [ "${quiet}" != "y" ] && echo $@
 }
@@ -7,6 +13,11 @@ err () {
     echo "ERROR: $@"
 }
 
+log_kmsg() {
+    local fmt=$1; shift
+    printf "<31>initramfs: $fmt\n" "$@"
+}
+
 poll_device() {
     local device=$1 seconds=${2//[!0-9]}
 
@@ -37,8 +48,17 @@ poll_device() {
 
 launch_interactive_shell() {
     export PS1='[rootfs \W]\$ '
-    [ "$1" = "--exec" ] && exec sh -i
-    sh -i
+
+    # explicitly redirect to /dev/console in case we're logging. note that
+    # anything done in the rescue shell will NOT be logged.
+    {
+        [ "$1" = "--exec" ] && exec sh -i
+        sh -i
+    } 0</dev/console 1>/dev/console 2>/dev/console
+}
+
+bitfield_has_bit() {
+    [ $(( $1 & $2 )) -eq $2 ]
 }
 
 major_minor_to_device() {
@@ -70,6 +90,30 @@ run_hookfunctions() {
     done
 }
 
+set_log_option() {
+    local opt
+
+    for opt in ${1//|/ }; do
+        case $opt in
+            all)
+                rd_logmask=$_rdlog_all
+                ;;
+            kmsg)
+                rd_logmask=$(( rd_logmask | _rdlog_kmsg ))
+                ;;
+            file)
+                rd_logmask=$(( rd_logmask | _rdlog_file ))
+                ;;
+            console)
+                rd_logmask=$(( rd_logmask | _rdlog_cons ))
+                ;;
+            *)
+                err "unknown rd.log parameter: '$opt'"
+                ;;
+        esac
+    done
+}
+
 parse_cmdline() {
     local _w _quoted _lhs _rhs _cmdline
     read -r _cmdline
@@ -93,6 +137,19 @@ parse_cmdline() {
                             ;;
                     esac
                     ;;
+                rd.*)
+                    case ${_w#rd.} in
+                        debug)
+                            rd_debug=y
+                            ;;
+                        log)
+                            rd_logmask=$(( _rdlog_kmsg | _rdlog_cons ))
+                            ;;
+                        log=*)
+                            set_log_option "${_w#rd.log=}"
+                            ;;
+                    esac
+                    ;;
                 # abide by shell variable naming rules
                 [[:alpha:]_]*=*)
                     _rhs=${_w#*=}
@@ -261,4 +318,90 @@ default_mount_handler() {
     fi
 }
 
+rdlogger_start() {
+    # rd.debug implies rd.log=console if rd.log(=.*)? isn't present
+    if [ "$rd_logmask" -eq 0 ] && [ -n "$rd_debug" ]; then
+        rd_logmask=$_rdlog_cons
+    fi
+
+    [ "$rd_logmask" -gt 0 ] || return
+
+    mkfifo /run/initramfs/rdlogger.pipe
+
+    rdlogger </run/initramfs/rdlogger.pipe >/dev/console 2>&1 &
+    printf %s $! >/run/initramfs/rdlogger.pid
+
+    exec >/run/initramfs/rdlogger.pipe 2>&1
+    [ -n "$rd_debug" ] && set -x
+}
+
+rdlogger_stop() {
+    local i=0 pid
+
+    [ -e /run/initramfs/rdlogger.pipe ] || return
+
+    [ -n "$rd_debug" ] && { set +x; } 2>/dev/null
+
+    # this nudges rdlogger to exit
+    exec 0<>/dev/console 1<>/dev/console 2<>/dev/console
+
+    # wait up to 1 second for a graceful shutdown
+    until [ ! -e /run/initramfs/rdlogger.pipe ] || [ $i -eq 10 ]; do
+        sleep 0.1
+        i=$(( i + 1 ))
+    done
+
+    if [ $i -eq 10 ]; then
+        # racy! the logger might still go away on its own
+        read -r pid </run/initramfs/rdlogger.pid 2>/dev/null
+        if [ -n "$pid" ]; then
+            kill "$pid" 2>/dev/null
+        fi
+    fi
+}
+
+rdlogger() {
+    local line
+
+    # establish logging FDs. Either redirect to an appropriate target or to
+    # /dev/null. This way, log methods can simply write and the associated FD
+    # will Do The Right Thing™.
+
+    # rd.log=console
+    if [ -z "$quiet" ] && bitfield_has_bit "$rd_logmask" "$_rdlog_cons"; then
+        exec 4>/dev/console
+    else
+        exec 4>/dev/null
+    fi
+
+    # rd.log=kmsg
+    if [ -c /dev/kmsg ] && bitfield_has_bit "$rd_logmask" "$_rdlog_kmsg"; then
+        exec 5>/dev/kmsg
+    else
+        exec 5>/dev/null
+    fi
+
+    # rd.log=file
+    if bitfield_has_bit "$rd_logmask" "$_rdlog_file"; then
+        exec 6>/run/initramfs/init.log
+    else
+        exec 6>/dev/null
+    fi
+
+    while read -r line; do
+        # rd.log=console
+        printf '%s\n' "$line" >&4
+
+        # rd.log=kmsg
+        log_kmsg '%s' "$line" >&5
+
+        # rd.log=file
+        printf '%s\n' "$line" >&6
+    done
+
+    # EOF, shutting down...
+    exec 4>&- 5>&- 6>&-
+    rm -f /run/initramfs/rdlogger.pipe /run/initramfs/rdlogger.pid
+}
+
 # vim: set ft=sh ts=4 sw=4 et:
diff --git a/man/mkinitcpio.8.txt b/man/mkinitcpio.8.txt
index 56ac571..4175609 100644
--- a/man/mkinitcpio.8.txt
+++ b/man/mkinitcpio.8.txt
@@ -248,6 +248,31 @@ the kernel command line:
 	device to show up, if it is not available immediately. This defaults to 5
 	seconds. If an invalid integer is passed, this variable will have no effect.
 
+*rd.debug*::
+	Enables shell debug (xtrace). If 'rd.log' is not also a parameter on the kernel
+	command line, this parameter implies 'rd.log=console'.
+
+*rd.log*['=<console|file|kmsg|all>']::
+	Enables logging of early userspace messages. If specified, the optional
+	parameter describes where this information is logged. Multiple options can be
+	OR'd together using the pipe (|) character. Messages are always logged to
+	the console unless the 'quiet' parameter is passed. If the optional parameter
+	is not specified, 'kmsg|console' is assumed. If 'rd.log' is not present on the
+	kernel command line, no logging will take place.
+
+	*console*;;
+		Writes output to '/dev/console'.
+
+	*file*;;
+		Writes output to '/run/initramfs/init.log'.
+
+	*kmsg*;;
+		Writes output to the '/dev/kmsg' device (introduced in Linux 3.5). This
+		option is a no-op if your kernel lacks support for '/dev/kmsg'.
+
+	*all*;;
+		Writes output to all known log targets.
+
 These are only the variables that the core of mkinitcpio honor. Additional
 hooks may look for other environment variables and should be documented by the
 help output for the hook.