Merge branch 'bulk_log'

4 files changed, 72 insertions, 47 deletions

diff --git a/src/share/poudriere/bulk.sh b/src/share/poudriere/bulk.sh
index ddf34b1b..39823da5 100755
--- a/src/share/poudriere/bulk.sh
+++ b/src/share/poudriere/bulk.sh
@@ -237,16 +237,17 @@ read_packages_from_params "$@"
 
 CLEANUP_HOOK=bulk_cleanup
 
-run_hook bulk start
-
-jail_start "${JAILNAME}" "${PTNAME}" "${SETNAME}"
-
 _log_path LOGD
 if [ -d ${LOGD} -a ${CLEAN} -eq 1 ]; then
 	msg "Cleaning up old logs in ${LOGD}"
 	[ ${DRY_RUN} -eq 0 ] && rm -Rf ${LOGD} 2>/dev/null
 fi
 
+log_start bulk 1
+run_hook bulk start
+
+jail_start "${JAILNAME}" "${PTNAME}" "${SETNAME}"
+
 prepare_ports
 show_build_summary
 show_dry_run_summary
diff --git a/src/share/poudriere/common.sh b/src/share/poudriere/common.sh
index 305555fa..1b8d90c2 100755
--- a/src/share/poudriere/common.sh
+++ b/src/share/poudriere/common.sh
@@ -377,7 +377,8 @@ _logfile() {
 		# the issue by looking for files older than 1 minute.
 
 		# Make sure directory exists
-		mkdir -p "${_log}/logs" "${_latest_log}"
+		mkdir -p "${_log}/logs" "${_latest_log}" \
+		    "${_log}/../latest-per-pkg"
 
 		:> "${_logfile}"
 
@@ -831,11 +832,15 @@ run_hook_file() {
 	return 0
 }
 
+stripcolors() {
+	sed -u 's,\x1B\[[0-9;]*m,,g'
+}
+
 log_start() {
 	[ $# -eq 2 ] || eargs log_start pkgname need_tee
 	local pkgname="$1"
 	local need_tee="$2"
-	local logfile
+	local logfile tee_pipe_in strip_pipe_in TIME_START
 
 	_logfile logfile "${pkgname}"
 
@@ -844,37 +849,42 @@ log_start() {
 	export OUTPUT_REDIRECTED=1
 	export OUTPUT_REDIRECTED_STDOUT=3
 	export OUTPUT_REDIRECTED_STDERR=4
+	strip_pipe_in="$(mktemp -ut strip_pipe_in)"
+	mkfifo "${strip_pipe_in}"
+	stripcolors > "${logfile}" < "${strip_pipe_in}" &
+	SPID="$!"
 	# Pipe output to tee(1) or timestamp if needed.
 	if [ ${need_tee} -eq 1 ] || [ "${TIMESTAMP_LOGS}" = "yes" ]; then
-		if [ ! -e ${logfile}.pipe ]; then
-			mkfifo ${logfile}.pipe
-		fi
-		if [ ${need_tee} -eq 1 ]; then
-			if [ "${TIMESTAMP_LOGS}" = "yes" ]; then
-				# Unbuffered for 'echo -n' support.
-				# Otherwise need setbuf -o L here due to
-				# stdout not writing to terminal but to tee.
-				TIME_START="${TIME_START_JOB:-${TIME_START:-0}}" \
-				    timestamp -u < ${logfile}.pipe | \
-				    tee ${logfile} &
-			else
-				tee ${logfile} < ${logfile}.pipe &
+		tee_pipe_in="$(mktemp -ut tee_pipe_in)"
+		mkfifo "${tee_pipe_in}"
+		(
+			trap '' INFO
+			TIME_START="${TIME_START_JOB:-${TIME_START:-0}}"
+			export TIME_START
+			unlink "${strip_pipe_in}"
+			if [ "${need_tee}" -eq 1 ]; then
+				if [ "${TIMESTAMP_LOGS}" = "yes" ]; then
+					# Unbuffered for 'echo -n' support.
+					# Otherwise need setbuf -o L here due
+					# to stdout not writing to terminal
+					# but to tee.
+					timestamp -u |
+					    tee "/dev/fd/${OUTPUT_REDIRECTED_STDOUT}"
+				else
+					tee "/dev/fd/${OUTPUT_REDIRECTED_STDOUT}"
+				fi
+			elif [ "${TIMESTAMP_LOGS}" = "yes" ]; then
+				timestamp
 			fi
-		elif [ "${TIMESTAMP_LOGS}" = "yes" ]; then
-			TIME_START="${TIME_START_JOB:-${TIME_START:-0}}" \
-			    timestamp > ${logfile} < ${logfile}.pipe &
-		fi
-		tpid=$!
-		exec > ${logfile}.pipe 2>&1
-
-		# Remove fifo pipe file right away to avoid orphaning it.
-		# The pipe will continue to work as long as we keep
-		# the FD open to it.
-		unlink ${logfile}.pipe
+		) < "${tee_pipe_in}" > "${strip_pipe_in}" &
+		TPID="$!"
+		exec > "${tee_pipe_in}" 2>&1
+		unlink "${tee_pipe_in}"
 	else
-		# Send output directly to file.
-		tpid=
-		exec > ${logfile} 2>&1
+		# Send output directly to the log writer
+		TPID=
+		exec > "${strip_pipe_in}" 2>&1
+		unlink "${strip_pipe_in}"
 	fi
 }
 
@@ -1042,10 +1052,13 @@ log_stop() {
 		unset OUTPUT_REDIRECTED_STDOUT
 		unset OUTPUT_REDIRECTED_STDERR
 	fi
-	if [ -n "${tpid-}" ]; then
-		# Give tee a moment to flush buffers
-		timed_wait_and_kill 5 $tpid 2>/dev/null || :
-		unset tpid
+	if [ -n "${TPID-}" ]; then
+		timed_wait_and_kill 5 "${TPID}" 2>/dev/null || :
+		unset TPID
+	fi
+	if [ -n "${SPID-}" ]; then
+		timed_wait_and_kill 5 "${SPID}" 2>/dev/null || :
+		unset SPID
 	fi
 }
 
@@ -1326,8 +1339,8 @@ exit_handler() {
 	# file in the jail like builders.pipe on socket 6.
 	exec </dev/null
 
+	log_stop
 	if was_a_bulk_run; then
-		log_stop
 		# build_queue may have done cd MASTER_DATADIR/pool,
 		# but some of the cleanup here assumes we are
 		# PWD=MASTER_DATADIR.  Switch back if possible.
@@ -1491,12 +1504,8 @@ ${COLOR_RESET}Tobuild: %-${queue_width}d  Time: %s\n" \
 	    "${nbtobuild}" "${buildtime}"
 }
 
-siginfo_handler() {
+_siginfo_handler() {
 	local IFS; unset IFS;
-	in_siginfo_handler=1
-	if [ "${POUDRIERE_BUILD_TYPE}" != "bulk" ]; then
-		return 0
-	fi
 	local status
 	local now
 	local j elapsed elapsed_phase job_id_color
@@ -1511,13 +1520,11 @@ siginfo_handler() {
 
 	_bget status status || status=unknown
 	if [ "${status}" = "index:" -o "${status#stopped:}" = "crashed:" ]; then
-		enable_siginfo_handler
 		return 0
 	fi
 
 	_bget nbq stats_queued || nbq=0
 	if [ -z "${nbq}" ]; then
-		enable_siginfo_handler
 		return 0
 	fi
 
@@ -1646,6 +1653,19 @@ siginfo_handler() {
 	display_output >&2
 
 	show_log_info >&2
+}
+
+siginfo_handler() {
+	local -; set +x
+
+	in_siginfo_handler=1
+	if [ "${POUDRIERE_BUILD_TYPE}" != "bulk" ]; then
+		return 0
+	fi
+	trap '' INFO
+	_siginfo_handler \
+	    >&${OUTPUT_REDIRECTED_STDOUT:-1} \
+	    2>&${OUTPUT_REDIRECTED_STDERR:-2}
 	enable_siginfo_handler
 }
 
diff --git a/src/share/poudriere/html/build.html b/src/share/poudriere/html/build.html
index f7d5766e..7a20bd52 100644
--- a/src/share/poudriere/html/build.html
+++ b/src/share/poudriere/html/build.html
@@ -75,6 +75,8 @@
 									<ul class="dropdown-menu">
 										<li><a href="logs/" class="data_url" target="logs"><span class="glyphicon glyphicon-share-alt"></span>All Logs</a></li>
 										<li><a href="logs/errors/" class="data_url" target="logs"><span class="glyphicon glyphicon-share-alt"></span>Error Logs</a></li>
+										<li><a href="logs/bulk.log" class="data_url" target="logs"><span class="glyphicon glyphicon-share-alt"></span>Bulk Log</a></li>
+										<li><a href="logs/testport.log" class="data_url" target="logs"><span class="glyphicon glyphicon-share-alt"></span>Testport Log</a></li>
 										<li><a href=".poudriere.pkg_deps%25" class="data_url" target="dependecny_graph"><span class="glyphicon glyphicon-share-alt"></span>Dependency graph</a></li>
 									</ul>
 								</li>
diff --git a/src/share/poudriere/testport.sh b/src/share/poudriere/testport.sh
index 07b78831..ea483c90 100755
--- a/src/share/poudriere/testport.sh
+++ b/src/share/poudriere/testport.sh
@@ -191,6 +191,9 @@ export MASTERNAME
 export MASTERMNT
 export POUDRIERE_BUILD_TYPE=bulk
 
+_log_path log
+log_start testport 1
+
 jail_start "${JAILNAME}" "${PTNAME}" "${SETNAME}"
 
 _pget portsdir ${PTNAME} mnt
@@ -250,8 +253,6 @@ prepare_ports
 show_dry_run_summary
 markfs prepkg ${MASTERMNT}
 
-_log_path log
-
 PARALLEL_JOBS=${BUILD_PARALLEL_JOBS}
 
 POUDRIERE_BUILD_TYPE=bulk parallel_build ${JAILNAME} ${PTNAME} ${SETNAME}
@@ -320,6 +321,7 @@ if [ -n "${MAX_MEMORY}" -o -n "${MAX_FILES}" ]; then
 	JEXEC_LIMITS=1
 fi
 unset PKGNAME_VARNAME
+log_stop
 log_start "${PKGNAME}" 1
 buildlog_start "${PKGNAME}" "${ORIGINSPEC}"
 ret=0