boottrace: annotate init and shutdown utilities

Add boottrace annotations to record events in init(8), shutdown(8), and
reboot(8).

Sponsored by:	NetApp, Inc.
Sponsored by:	Klara, Inc.
X-NetApp-PR:	#23
Differential Revision:	https://reviews.freebsd.org/D31928

4 files changed, 137 insertions, 13 deletions

diff --git a/sbin/init/init.c b/sbin/init/init.c
index 230c141bd351..93a525c46427 100644
--- a/sbin/init/init.c
+++ b/sbin/init/init.c
@@ -47,21 +47,26 @@ static const char rcsid[] =
 #endif /* not lint */
 
 #include <sys/param.h>
+#include <sys/boottrace.h>
 #include <sys/ioctl.h>
 #include <sys/mman.h>
 #include <sys/mount.h>
-#include <sys/sysctl.h>
-#include <sys/wait.h>
+#include <sys/reboot.h>
 #include <sys/stat.h>
+#include <sys/sysctl.h>
 #include <sys/uio.h>
+#include <sys/wait.h>
 
 #include <db.h>
+#include <err.h>
 #include <errno.h>
 #include <fcntl.h>
 #include <kenv.h>
 #include <libutil.h>
 #include <paths.h>
 #include <signal.h>
+#include <stdarg.h>
+#include <stdbool.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
@@ -69,10 +74,6 @@ static const char rcsid[] =
 #include <time.h>
 #include <ttyent.h>
 #include <unistd.h>
-#include <sys/reboot.h>
-#include <err.h>
-
-#include <stdarg.h>
 
 #ifdef SECURE
 #include <pwd.h>
@@ -213,6 +214,8 @@ main(int argc, char *argv[])
 	if (getuid() != 0)
 		errx(1, "%s", strerror(EPERM));
 
+	BOOTTRACE("init(8) starting...");
+
 	/* System V users like to reexec init. */
 	if (getpid() != 1) {
 #ifdef COMPAT_SYSV_INIT
@@ -876,6 +879,7 @@ single_user(void)
 
 	if (Reboot) {
 		/* Instead of going single user, let's reboot the machine */
+		BOOTTRACE("shutting down the system");
 		sync();
 		/* Run scripts after all processes have been terminated. */
 		runfinal();
@@ -887,6 +891,7 @@ single_user(void)
 		_exit(0); /* panic as well */
 	}
 
+	BOOTTRACE("going to single user mode");
 	shell = get_shell();
 
 	if ((pid = fork()) == 0) {
@@ -1028,8 +1033,10 @@ runcom(void)
 {
 	state_func_t next_transition;
 
+	BOOTTRACE("/etc/rc starting...");
 	if ((next_transition = run_script(_PATH_RUNCOM)) != NULL)
 		return next_transition;
+	BOOTTRACE("/etc/rc finished");
 
 	runcom_mode = AUTOBOOT;		/* the default */
 	return (state_func_t) read_ttys;
@@ -1598,6 +1605,59 @@ collect_child(pid_t pid)
 	add_session(sp);
 }
 
+static const char *
+get_current_state(void)
+{
+
+	if (current_state == single_user)
+		return ("single-user");
+	if (current_state == runcom)
+		return ("runcom");
+	if (current_state == read_ttys)
+		return ("read-ttys");
+	if (current_state == multi_user)
+		return ("multi-user");
+	if (current_state == clean_ttys)
+		return ("clean-ttys");
+	if (current_state == catatonia)
+		return ("catatonia");
+	if (current_state == death)
+		return ("death");
+	if (current_state == death_single)
+		return ("death-single");
+	return ("unknown");
+}
+
+static void
+boottrace_transition(int sig)
+{
+	const char *action;
+
+	switch (sig) {
+	case SIGUSR2:
+		action = "halt & poweroff";
+		break;
+	case SIGUSR1:
+		action = "halt";
+		break;
+	case SIGINT:
+		action = "reboot";
+		break;
+	case SIGWINCH:
+		action = "powercycle";
+		break;
+	case SIGTERM:
+		action = Reboot ? "reboot" : "single-user";
+		break;
+	default:
+		BOOTTRACE("signal %d from %s", sig, get_current_state());
+		return;
+	}
+
+	/* Trace the shutdown reason. */
+	SHUTTRACE("%s from %s", action, get_current_state());
+}
+
 /*
  * Catch a signal and request a state transition.
  */
@@ -1605,6 +1665,7 @@ static void
 transition_handler(int sig)
 {
 
+	boottrace_transition(sig);
 	switch (sig) {
 	case SIGHUP:
 		if (current_state == read_ttys || current_state == multi_user ||
@@ -1648,6 +1709,7 @@ transition_handler(int sig)
 static state_func_t
 multi_user(void)
 {
+	static bool inmultiuser = false;
 	pid_t pid;
 	session_t *sp;
 
@@ -1677,6 +1739,11 @@ multi_user(void)
 		add_session(sp);
 	}
 
+	if (requested_transition == 0 && !inmultiuser) {
+		inmultiuser = true;
+		/* This marks the change from boot-time tracing to run-time. */
+		RUNTRACE("multi-user start");
+	}
 	while (!requested_transition)
 		if ((pid = waitpid(-1, (int *) 0, 0)) != -1)
 			collect_child(pid);
@@ -1843,6 +1910,7 @@ death_single(void)
 
 	revoke(_PATH_CONSOLE);
 
+	BOOTTRACE("start killing user processes");
 	for (i = 0; i < 2; ++i) {
 		if (kill(-1, death_sigs[i]) == -1 && errno == ESRCH)
 			return (state_func_t) single_user;
@@ -1894,6 +1962,8 @@ runshutdown(void)
 	char *argv[4];
 	struct stat sb;
 
+	BOOTTRACE("init(8): start rc.shutdown");
+
 	/*
 	 * rc.shutdown is optional, so to prevent any unnecessary
 	 * complaints from the shell we simply don't run it if the
@@ -1944,6 +2014,8 @@ runshutdown(void)
 			kill(wpid, SIGTERM);
 			warning("timeout expired for %s: %m; going to "
 			    "single user mode", _PATH_RUNDOWN);
+			BOOTTRACE("rc.shutdown's %d sec timeout expired",
+				  shutdowntimeout);
 			return -1;
 		}
 		if (wpid == -1) {
diff --git a/sbin/reboot/reboot.c b/sbin/reboot/reboot.c
index 4dcade7611c2..118ac304024c 100644
--- a/sbin/reboot/reboot.c
+++ b/sbin/reboot/reboot.c
@@ -43,10 +43,12 @@ static char sccsid[] = "@(#)reboot.c	8.1 (Berkeley) 6/5/93";
 #include <sys/cdefs.h>
 __FBSDID("$FreeBSD$");
 
-#include <sys/reboot.h>
-#include <sys/time.h>
 #include <sys/types.h>
+#include <sys/boottrace.h>
+#include <sys/reboot.h>
 #include <sys/sysctl.h>
+#include <sys/time.h>
+
 #include <signal.h>
 #include <err.h>
 #include <errno.h>
@@ -210,10 +212,12 @@ main(int argc, char *argv[])
 	}
 
 	/* Just stop init -- if we fail, we'll restart it. */
+	BOOTTRACE("SIGTSTP to init(8)...");
 	if (kill(1, SIGTSTP) == -1)
 		err(1, "SIGTSTP init");
 
 	/* Send a SIGTERM first, a chance to save the buffers. */
+	BOOTTRACE("SIGTERM to all other processes...");
 	if (kill(-1, SIGTERM) == -1 && errno != ESRCH)
 		err(1, "SIGTERM processes");
 
@@ -235,6 +239,7 @@ main(int argc, char *argv[])
 	}
 
 	for (i = 1;; ++i) {
+		BOOTTRACE("SIGKILL to all other processes(%d)...", i);
 		if (kill(-1, SIGKILL) == -1) {
 			if (errno == ESRCH)
 				break;
@@ -252,6 +257,7 @@ main(int argc, char *argv[])
 	/* FALLTHROUGH */
 
 restart:
+	BOOTTRACE("SIGHUP to init(8)...");
 	sverrno = errno;
 	errx(1, "%s%s", kill(1, SIGHUP) == -1 ? "(can't restart init): " : "",
 	    strerror(sverrno));
diff --git a/sbin/shutdown/shutdown.c b/sbin/shutdown/shutdown.c
index 67a433b8edde..76e02d1fd6b1 100644
--- a/sbin/shutdown/shutdown.c
+++ b/sbin/shutdown/shutdown.c
@@ -44,9 +44,10 @@ static char sccsid[] = "@(#)shutdown.c	8.4 (Berkeley) 4/28/95";
 __FBSDID("$FreeBSD$");
 
 #include <sys/param.h>
-#include <sys/time.h>
+#include <sys/boottrace.h>
 #include <sys/resource.h>
 #include <sys/syslog.h>
+#include <sys/time.h>
 
 #include <ctype.h>
 #include <err.h>
@@ -221,10 +222,13 @@ poweroff:
 	}
 	mbuflen = strlen(mbuf);
 
-	if (offset)
+	if (offset) {
+		BOOTTRACE("Shutdown at %s", ctime(&shuttime));
 		(void)printf("Shutdown at %.24s.\n", ctime(&shuttime));
-	else
+	} else {
+		BOOTTRACE("Shutdown NOW!");
 		(void)printf("Shutdown NOW!\n");
+	}
 
 	if (!(whom = getlogin()))
 		whom = (pw = getpwuid(getuid())) ? pw->pw_name : "???";
@@ -360,12 +364,16 @@ die_you_gravy_sucking_pig_dog(void)
 {
 	char *empty_environ[] = { NULL };
 
+	BOOTTRACE("%s by %s",
+	    doreboot ? "reboot" : dohalt ? "halt" : dopower ? "power-down" :
+	    docycle ? "power-cycle" : "shutdown", whom);
 	syslog(LOG_NOTICE, "%s by %s: %s",
 	    doreboot ? "reboot" : dohalt ? "halt" : dopower ? "power-down" :
 	    docycle ? "power-cycle" : "shutdown", whom, mbuf);
 
 	(void)printf("\r\nSystem shutdown time has arrived\007\007\r\n");
 	if (killflg) {
+		BOOTTRACE("fake shutdown...");
 		(void)printf("\rbut you'll have to do it yourself\r\n");
 		exit(0);
 	}
@@ -383,6 +391,7 @@ die_you_gravy_sucking_pig_dog(void)
 	(void)printf("\nkill -HUP 1\n");
 #else
 	if (!oflag) {
+		BOOTTRACE("signal to init(8)...");
 		(void)kill(1, doreboot ? SIGINT :	/* reboot */
 			      dohalt ? SIGUSR1 :	/* halt */
 			      dopower ? SIGUSR2 :	/* power-down */
@@ -390,6 +399,7 @@ die_you_gravy_sucking_pig_dog(void)
 			      SIGTERM);			/* single-user */
 	} else {
 		if (doreboot) {
+			BOOTTRACE("exec reboot(8) -l...");
 			execle(_PATH_REBOOT, "reboot", "-l", nosync, 
 				(char *)NULL, empty_environ);
 			syslog(LOG_ERR, "shutdown: can't exec %s: %m.",
@@ -397,6 +407,7 @@ die_you_gravy_sucking_pig_dog(void)
 			warn(_PATH_REBOOT);
 		}
 		else if (dohalt) {
+			BOOTTRACE("exec halt(8) -l...");
 			execle(_PATH_HALT, "halt", "-l", nosync,
 				(char *)NULL, empty_environ);
 			syslog(LOG_ERR, "shutdown: can't exec %s: %m.",
@@ -404,6 +415,7 @@ die_you_gravy_sucking_pig_dog(void)
 			warn(_PATH_HALT);
 		}
 		else if (dopower) {
+			BOOTTRACE("exec halt(8) -l -p...");
 			execle(_PATH_HALT, "halt", "-l", "-p", nosync,
 				(char *)NULL, empty_environ);
 			syslog(LOG_ERR, "shutdown: can't exec %s: %m.",
@@ -417,6 +429,7 @@ die_you_gravy_sucking_pig_dog(void)
 				_PATH_HALT);
 			warn(_PATH_HALT);
 		}
+		BOOTTRACE("SIGTERM to init(8)...");
 		(void)kill(1, SIGTERM);		/* to single-user */
 	}
 #endif
diff --git a/sys/sys/boottrace.h b/sys/sys/boottrace.h
index b09888bff4ac..2cb17c15ff0f 100644
--- a/sys/sys/boottrace.h
+++ b/sys/sys/boottrace.h
@@ -36,9 +36,42 @@
 #define	BT_EVENT_NAMELEN	40
 #define	BT_MSGLEN		(BT_EVENT_NAMELEN + 1 + BT_EVENT_TDNAMELEN)
 
-#ifdef _KERNEL
+#ifndef _KERNEL
+#include <stdarg.h>
+#include <stdio.h>
+#include <string.h>
+#include <sys/sysctl.h>
+
+/*
+ * Convenience macros. Userland API.
+ */
+#define	BOOTTRACE(...)		_boottrace(_BOOTTRACE_BOOTTRACE, __VA_ARGS__)
+#define	RUNTRACE(...)		_boottrace(_BOOTTRACE_RUNTRACE, __VA_ARGS__)
+#define	SHUTTRACE(...)		_boottrace(_BOOTTRACE_SHUTTRACE, __VA_ARGS__)
+
+/*
+ * Call the requested boottrace sysctl with provided va-formatted message.
+ */
+static __inline void
+_boottrace(const char *sysctlname, const char *fmt, ...)
+{
+	va_list ap;
+	char msg[BT_MSGLEN];
+	int len;
+
+	va_start(ap, fmt);
+	len = vsnprintf(msg, sizeof(msg), fmt, ap);
+	va_end(ap);
+
+	/* Log the event, even if truncated. */
+	if (len >= 0)
+		(void)sysctlbyname(sysctlname, NULL, NULL, msg, strlen(msg));
+}
+
+#else /* _KERNEL */
+
 /*
- * Convenience macros.
+ * Convenience macros. Kernel API.
  */
 #define	_BOOTTRACE(tdname, ...) do {					\
 		if (boottrace_enabled)					\