>Number:         27393
>Category:       bin
>Synopsis:       Logging capability for rc and rc.shutdown
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    bin-bug-people
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          change-request
>Submitter-Id:   net
>Arrival-Date:   Sat Oct 23 15:38:00 UTC 2004
>Closed-Date:
>Last-Modified:
>Originator:     Mike M. Volokhov
>Release:        NetBSD 2.99.x, others too
>Organization:
Insakharprom-K, Ltd.
>Environment:
	Boot and shutdown framework on NetBSD
>Description:

	Greetings!

	It sometimes very covenient to see how your NetBSD boots
	and how it halts. Unfortunately, if hardware have no monitor
	installed or by any other reason you are missing something
	in boot/shutdown messages, it is not possible to revert
	logs back and detaily analyse all contained info.

	Of course, your output may be directed to serial console
	with logging capabilities but often it not done in such
	way (or at least too hard to implement).

>How-To-Repeat:

	Reboot the system and watch all output. If messages directed
	to device without logging capabilities (such as plain CRT
	monitor) information will be quickly pushed by new data.
	Login to system and see you have not any boot/shutdown
	output stored anywhere.

>Fix:

	Having discussed at tech-userlevel@ this issue (see topic
	"Re: rc.d boot log [was: Re: Cosmetic changes to rc.d
	scripts]") I had reworked my latest patch with fault
	tolerance in mind and suppose the following way:

	1) Logging available if rc_log_output is set to YES;
	otherwise rc works just like before a patch.

	2) By default we use tee(1). But if log inavailable (for
	example, on read-only mounted filesystem) as well as tee
	itself, we falling back to buffering (in shell variables)
	all output until log may be written back to disk.

	3) We will write new log to disk in case only if previous
	one has been backed up (rotated).

	4) Logs are rotated once per /etc/rc or /etc/rc.shutdown
	execution, and stored to /var/log/{boot,shutdown}.{log,prev}
	files.

	5) Buffers are flushed every time after logs was wrote
	(irrelevant on what way was - echo or tee).  If buffers
	still contain any data after very last rclog() call, this
	really means that logfile is no more available.  In this
	case we try to save log in /etc/rclog.tmp file.

	6) Output from the verbose commands will be delayed for a
	one line only, but no more.

	Please see a patch below to fix this issue. It diffed
	against rc, rc.shutdown, and rc.subr files. Thus, to patch
	your system use the following command:

		cd /etc && patch < /path/to/saved/rclog.patch

	Don't forget to set rc_log_output variable in your /etc/rc.conf
	file.

	--
	Best regards,
	Mishka.


--- /build/netbsd/src-current/etc/rc	2003-01-08 19:46:19.000000000 +0200
+++ rc	2004-10-21 09:47:26.000000000 +0300
@@ -17,6 +17,8 @@
 . /etc/rc.conf
 _rc_conf_loaded=true
 
+_rc_state=boot
+
 if ! checkyesno rc_configured; then
 	echo "/etc/rc.conf is not configured.  Multiuser boot aborted."
 	exit 1
@@ -35,13 +37,19 @@
 trap : INT
 trap "echo 'Boot interrupted.'; exit 1" QUIT
 
-date
+rclog "echo Starting up at `date`"
 
 files=$(rcorder -s nostart ${rc_rcorder_flags} /etc/rc.d/*)
 
 for _rc_elem in $files; do
-	run_rc_script $_rc_elem start
+	rclog "run_rc_script $_rc_elem start"
 done
 
-date
+rclog "echo System was started at `date`"
+
+if checkyesno rc_log_output && [ -n "$_rclogbuf" ]; then
+	warn "stale log found in buffer; saving to /etc/rclog.tmp"
+	echo "$_rclogbuf" >> /etc/rclog.tmp
+fi
+
 exit 0
--- /build/netbsd/src-current/etc/rc.shutdown	2002-06-10 02:38:05.000000000 +0300
+++ rc.shutdown	2004-10-19 17:06:04.000000000 +0300
@@ -14,6 +14,8 @@
 . /etc/rc.subr
 . /etc/rc.conf
 
+_rc_state=shutdown
+
 if ! checkyesno do_rcshutdown; then
 	echo "Skipping shutdown hooks."
 	exit 0
@@ -43,6 +45,7 @@
 	_rcshutdown_watchdog=$!
 fi
 
+rclog "echo System going down at `date`"
 
 #	Determine the shutdown order of the /etc/rc.d scripts,
 #	and perform the operation
@@ -50,7 +53,7 @@
 files=$(rcorder -k shutdown ${rcshutdown_rcorder_flags} /etc/rc.d/*)
 
 for _rc_elem in $(reverse_list $files); do
-	run_rc_script $_rc_elem stop
+	rclog "run_rc_script $_rc_elem stop"
 done
 
 
@@ -60,5 +63,11 @@
 	kill -TERM $_rcshutdown_watchdog >/dev/null 2>&1
 fi
 
-date
+rclog "echo Running shutdown scripts finished at `date`"
+
+if checkyesno rc_log_output && [ -n "$_rclogbuf" ]; then
+	warn "stale log found in buffer; saving to /etc/rclog.tmp"
+	echo "$_rclogbuf" >> /etc/rclog.tmp
+fi
+
 exit 0
--- /build/netbsd/src-current/etc/rc.subr	2004-10-13 12:50:44.000000000 +0300
+++ rc.subr	2004-10-21 12:24:04.000000000 +0300
@@ -819,6 +819,70 @@
 }
 
 #
+# rclog command
+#	Run "command" and append log all output to $_rclogfile. If it cannot
+#	be saved by any reason, accumulate log in _rclogbuf variable.
+#
+rclog()
+{
+	_rclogcmd=$1
+	if checkyesno rc_log_output && [ -n "${_rc_state}" ]; then
+		: ${_rclogfile:=/var/log/${_rc_state}.log}
+		: ${_rclogfile_prev:=/var/log/${_rc_state}.prev}
+
+		if [ -z "$_rclog_rotated" -a -d /var/log ]; then
+			if [ -f ${_rclogfile} ]; then
+				mv -f $_rclogfile $_rclogfile_prev 2>/dev/null
+			fi
+			if [ ! -f ${_rclogfile} ] && \
+				echo "Log file turned over at `date`" \
+					> $_rclogfile 2>/dev/null; then
+				echo "The rc $_rc_state log was rotated."
+				_rclog_rotated=$_rc_state
+			fi
+		fi
+
+		if [ -f ${_rclogfile} -a -n "$_rclog_rotated" -a \
+				-x /usr/bin/tee -a -x /usr/bin/touch ] && \
+				/usr/bin/touch $_rclogfile 2>/dev/null; then
+			if [ -n "$_rclogbuf" ]; then
+				echo -n "$_rclogbuf" >> ${_rclogfile}
+				_rclogbuf=
+			fi
+			${_rclogcmd} 2>&1 | /usr/bin/tee -a ${_rclogfile}
+		else
+			_rclogcmdbuf=$( ${_rclogcmd} 2>&1 | _rctee_output )
+			if [ -n "$_rclogcmdbuf" ]; then
+				_rclogcmdbuf="$_rclogcmdbuf
+"
+				_rclogbuf="${_rclogbuf}${_rclogcmdbuf}"
+				_rclogcmdbuf=
+			fi
+			if [ -n "$_rclogbuf" -a -f ${_rclogfile} -a \
+					-n "$_rclog_rotated" ] && \
+					echo -n "$_rclogbuf" >> $_rclogfile \
+						2>/dev/null; then
+				_rclogbuf=
+			fi
+		fi
+	else
+		$_rclogcmd
+	fi
+}
+
+#
+# _rctee_output
+#	Take stdin line by line and send it to stdout and stderr
+#
+_rctee_output()
+{
+	while read _rctee_buffer; do
+		echo "$_rctee_buffer"
+		echo "$_rctee_buffer" 1>&2
+	done
+}
+
+#
 # backup_file action file cur backup
 #	Make a backup copy of `file' into `cur', and save the previous
 #	version of `cur' as `backup' or use rcs for archiving.

>Release-Note:
>Audit-Trail:
>Unformatted: