From 8cedc82ec2433b2be7081457eb48e7757393df11 Mon Sep 17 00:00:00 2001
From: Ricardo Pardini <ricardo@pardini.net>
Date: Wed, 18 Jan 2023 22:43:25 +0100
Subject: [PATCH] armbian-next: hopefully improved error logging; avoid logging
 errors up to 3x; subdued red stacktraces

- reorg `display_alert()` so more frequent levels are handled first
- improve some ANSI color usage, still a mess
- don't write failed commands stackstrace as warnings to screen -- just to file (yes it's redundant, except if in test)
- more useful / subdued stacktraces, to make actual error more obvious...
---
 lib/functions/logging/display-alert.sh | 76 +++++++++++++-------------
 lib/functions/logging/export-logs.sh   | 10 ++--
 lib/functions/logging/logging.sh       |  3 +
 lib/functions/logging/runners.sh       |  7 ++-
 lib/functions/logging/stacktraces.sh   |  7 ++-
 lib/functions/logging/traps.sh         | 29 ++++++----
 6 files changed, 74 insertions(+), 58 deletions(-)

diff --git a/lib/functions/logging/display-alert.sh b/lib/functions/logging/display-alert.sh
index ccf2494905..e8ec855b5d 100644
--- a/lib/functions/logging/display-alert.sh
+++ b/lib/functions/logging/display-alert.sh
@@ -12,24 +12,24 @@ function display_alert() {
 
 	declare message="${1}" level="${3}"                                              # params
 	declare level_indicator="" inline_logs_color="" extra="" extra_file="" ci_log="" # this log
-	declare -i skip_screen=0                                                         # setting to 1 will not write to screen
+	declare -i skip_screen=${display_alert_skip_screen:-0}                           # setting to 1 will not write to screen
 	declare -i skip_logfile=0                                                        # setting to 1 will not write to logfile
 	case "${level}" in
-		err | error)
-			level_indicator="💥"
-			inline_logs_color="\e[1;31m"
-			ci_log="error"
+		debug)
+			if [[ "${SHOW_DEBUG}" != "yes" ]]; then # enable debug for many, many debugging msgs
+				skip_screen=1
+			fi
+			level_indicator="🐛"
+			inline_logs_color="\e[1;33m"
+			skip_logfile=1
 			;;
 
-		wrn | warn)
-			level_indicator="🚸"
-			inline_logs_color="\e[1;35m"
-			ci_log="warning"
-			;;
-
-		ext)
-			level_indicator="✨" # or ✅ ?
-			inline_logs_color="\e[1;32m"
+		command)
+			if [[ "${SHOW_COMMAND}" != "yes" ]]; then # enable to log all calls to external cmds
+				skip_screen=1
+			fi
+			level_indicator="🐸"
+			inline_logs_color="\e[0;36m" # a dim cyan
 			;;
 
 		info)
@@ -37,11 +37,6 @@ function display_alert() {
 			inline_logs_color="\e[0;32m"
 			;;
 
-		cachehit)
-			level_indicator="💖"
-			inline_logs_color="\e[0;32m"
-			;;
-
 		cleanup | trap)
 			if [[ "${SHOW_TRAPS}" != "yes" ]]; then # enable debug for many, many debugging msgs
 				skip_screen=1
@@ -51,15 +46,6 @@ function display_alert() {
 			skip_logfile=1
 			;;
 
-		debug)
-			if [[ "${SHOW_DEBUG}" != "yes" ]]; then # enable debug for many, many debugging msgs
-				skip_screen=1
-			fi
-			level_indicator="🐛"
-			inline_logs_color="\e[1;33m"
-			skip_logfile=1
-			;;
-
 		group)
 			if [[ "${SHOW_DEBUG}" != "yes" && "${SHOW_GROUPS}" != "yes" ]]; then # show when debugging, or when specifically requested
 				skip_screen=1
@@ -69,14 +55,6 @@ function display_alert() {
 			skip_logfile=1
 			;;
 
-		command)
-			if [[ "${SHOW_COMMAND}" != "yes" ]]; then # enable to log all calls to external cmds
-				skip_screen=1
-			fi
-			level_indicator="🐸"
-			inline_logs_color="\e[0;36m" # a dim cyan
-			;;
-
 		timestamp | fasthash)
 			if [[ "${SHOW_FASTHASH}" != "yes" ]]; then # timestamp-related debugging messages, very very verbose
 				skip_screen=1
@@ -122,6 +100,11 @@ function display_alert() {
 			skip_logfile=1
 			;;
 
+		cachehit)
+			level_indicator="💖"
+			inline_logs_color="\e[0;32m"
+			;;
+
 		# @TODO this is dead I think
 		aggregation)
 			if [[ "${SHOW_AGGREGATION}" != "yes" ]]; then # aggregation (PACKAGE LISTS), very very verbose
@@ -132,6 +115,25 @@ function display_alert() {
 			skip_logfile=1
 			;;
 
+		err | error | critical)
+			level="error"
+			level_indicator="💥"
+			inline_logs_color="\e[1;31m"
+			ci_log="error"
+			;;
+
+		wrn | warn | warning)
+			level="warning"
+			level_indicator="🚸"
+			inline_logs_color="\e[1;35m"
+			ci_log="warning"
+			;;
+
+		ext)
+			level_indicator="✨" # or ✅ ?
+			inline_logs_color="\e[1;32m"
+			;;
+
 		*)
 			level="${level:-info}" # for file logging.
 			level_indicator="🌿"
@@ -142,7 +144,7 @@ function display_alert() {
 	if [[ -n ${2} ]]; then
 		extra=" [${inline_logs_color} ${2} ${normal_color:-}]"
 		# extra_file=" [${inline_logs_color} ${2} ${normal_color}]" # too much color in logfile
-		extra_file=" [ ${2} ]"
+		extra_file=" [ ${inline_logs_color}${2}${normal_color} ]"
 	fi
 
 	# Log to journald, if asked to.
diff --git a/lib/functions/logging/export-logs.sh b/lib/functions/logging/export-logs.sh
index 8e32926d12..f878ace89c 100644
--- a/lib/functions/logging/export-logs.sh
+++ b/lib/functions/logging/export-logs.sh
@@ -52,10 +52,10 @@ function export_ansi_logs() {
 	dim_line_separator=$(echo -e -n "${gray_color:-}")------------------------------------------------------------------------------------------------------------$(echo -e -n "${normal_color:-}")
 
 	cat <<- ANSI_HEADER > "${target_file}"
-		# Armbian logs for ${ARMBIAN_BUILD_UUID}
-		# Armbian build at $(LC_ALL=C LANG=C date) on $(hostname || true)
+		# Armbian ANSI build logs for ${ARMBIAN_BUILD_UUID} - use "less -SR" to view
+		$(echo -e -n "${bright_blue_color}")# Armbian build at $(LC_ALL=C LANG=C date) on $(hostname || true)
 		${dim_line_separator}
-		# ARGs: ${ARMBIAN_ORIGINAL_ARGV[@]@Q}
+		$(echo -e -n "${bright_blue_color}")# ARGs: ${ARMBIAN_ORIGINAL_ARGV[@]@Q}
 		${dim_line_separator}
 	ANSI_HEADER
 
@@ -95,7 +95,7 @@ function export_ansi_logs() {
 		logfile_title="$(echo "${logfile_base}" | sed -e 's/^[^.]*\.[^.]*\.//')"
 
 		cat <<- ANSI_ONE_LOGFILE >> "${target_file}"
-			$(echo -e -n "\033[94m")### ${logfile_title} $(echo -e -n "${normal_color}")
+			$(echo -e -n "${bright_blue_color}")### ${logfile_title} $(echo -e -n "${normal_color}")
 			$(cat "${logfile_full}" | sed -e "${prefix_sed_cmd}")
 			${dim_line_separator}
 		ANSI_ONE_LOGFILE
@@ -107,6 +107,6 @@ function export_ansi_logs() {
 	if [[ "${show_message_after_export:-"yes"}" != "skip" ]]; then
 		display_alert "ANSI log file built; inspect it by running:" "less -RS ${target_relative_to_src}"
 	fi
-	
+
 	return 0
 }
diff --git a/lib/functions/logging/logging.sh b/lib/functions/logging/logging.sh
index 480be55889..5808401875 100644
--- a/lib/functions/logging/logging.sh
+++ b/lib/functions/logging/logging.sh
@@ -15,6 +15,9 @@ function logging_init() {
 	# globals
 	declare -g padding="" left_marker="[" right_marker="]"
 	declare -g normal_color="\x1B[0m" gray_color="\e[1;30m" # "bright black", which is grey
+	declare -g bright_red_color="\e[1;31m" red_color="\e[0;31m"
+	declare -g bright_blue_color="\e[1;34m" blue_color="\e[0;34m"
+	declare -g bright_magenta_color="\e[1;35m" magenta_color="\e[0;35m"
 	declare -g -i logging_section_counter=0                 # -i: integer
 	declare -g tool_color="${gray_color}"                   # default to gray... (should be ok on terminals, @TODO: I've seen it too dark on a few random screenshots though
 	if [[ "${CI}" == "true" ]]; then                        # ... but that is too dark for Github Actions
diff --git a/lib/functions/logging/runners.sh b/lib/functions/logging/runners.sh
index e03f3b1d3c..66947eeaa4 100644
--- a/lib/functions/logging/runners.sh
+++ b/lib/functions/logging/runners.sh
@@ -209,10 +209,11 @@ function run_host_command_logged_raw() {
 
 	if [[ ${exit_code} != 0 ]]; then
 		if [[ -f "${CURRENT_LOGFILE}" ]]; then # echo -e "\033[91mBright Red\033[0m"
-			echo -e "\033[91m-->--> command failed with error code ${exit_code} after $((SECONDS - seconds_start)) seconds${normal_color:-}" >> "${CURRENT_LOGFILE}"
+			echo -e "${bright_red_color:-}-->--> command failed with error code ${exit_code} after $((SECONDS - seconds_start)) seconds${normal_color:-}" >> "${CURRENT_LOGFILE}"
 		fi
-		display_alert "cmd exited with code ${exit_code}" "$*" "wrn"
-		display_alert "stacktrace for failed command" "$(show_caller_full)" "wrn"
+
+		# @TODO: send these _ONLY_ to logfile. there's enough on screen already...
+		display_alert_skip_screen=1 display_alert "stacktrace for failed command" "exit code ${exit_code}:$*\n$(stack_color="${magenta_color:-}" show_caller_full)" "wrn"
 
 		# Obtain extra info about error, eg, log files produced, extra messages set by caller, etc.
 		logging_enrich_run_command_error_info
diff --git a/lib/functions/logging/stacktraces.sh b/lib/functions/logging/stacktraces.sh
index de1d3e4c4e..cfe54dcab8 100644
--- a/lib/functions/logging/stacktraces.sh
+++ b/lib/functions/logging/stacktraces.sh
@@ -42,8 +42,11 @@ function show_caller_full() {
 			((i++))
 		done | while read -r line_no function_name file_name; do
 			padded_function_name="$(printf "%30s" "$function_name()")"
-			short_file_name="${file_name/"${SRC}/"/"./"}"
-			echo -e "$padded_function_name --> $short_file_name:$line_no"
+			short_file_name="${file_name/"${SRC}/"/""}"
+			if [[ "${short_file_name}" == *"extension_function_definition.sh" ]]; then
+				short_file_name="<extension_magic>"
+			fi
+			echo -e "${stack_color:-"${red_color}"}   $padded_function_name --> $short_file_name:$line_no"
 		done
 	} || true # always success
 }
diff --git a/lib/functions/logging/traps.sh b/lib/functions/logging/traps.sh
index a9d09d6d67..d9b27af873 100644
--- a/lib/functions/logging/traps.sh
+++ b/lib/functions/logging/traps.sh
@@ -5,9 +5,9 @@
 # This also implements the custom "cleanup" handlers, which always run at the end of build, or when exiting prematurely for any reason.
 function traps_init() {
 	# shellcheck disable=SC2034 # Array of cleanup handlers.
-	declare -a trap_manager_cleanup_handlers=()
+	declare -g -a trap_manager_cleanup_handlers=()
 	# shellcheck disable=SC2034 # Global to avoid doubly reporting ERR/EXIT pairs.
-	declare -i trap_manager_error_handled=0
+	declare -g -i trap_manager_error_handled=0
 	trap 'main_trap_handler "ERR" "$?"' ERR
 	trap 'main_trap_handler "EXIT" "$?"' EXIT
 	trap 'main_trap_handler "INT" "$?"' INT
@@ -49,12 +49,14 @@ function main_trap_handler() {
 			# BASHPID is the current subshell; $$ is parent shell pid
 			if [[ "${BASHPID}" == "${$}" ]]; then
 				# Not in subshell, dump the error, complete with log, and show the stack.
-				logging_error_show_log
-				display_alert "Error occurred in main shell" "code ${trap_exit_code} at ${short_stack}\n${stack_caller}\n" "err"
+				if [[ ! ${trap_manager_error_handled} -gt 0 ]]; then
+					logging_error_show_log
+					display_alert "Error ${trap_exit_code} occurred in main shell" "at ${short_stack}\n${stack_caller}\n" "err"
+				fi
 			else
 				# In a subshell. This trap will run again in the parent shell, so just output a message about it;
 				# When the parent shell trap runs, it will show the stack and log.
-				display_alert "Error occurred in SUBSHELL" "SUBSHELL: code ${trap_exit_code} at ${short_stack}" "err"
+				display_alert "Error  ${trap_exit_code} occurred in SUBSHELL" "SUBSHELL at ${short_stack}" "err"
 			fi
 			trap_manager_error_handled=1
 			return # Nothing else to do here, let the EXIT trap do the cleanups.
@@ -63,7 +65,7 @@ function main_trap_handler() {
 		EXIT)
 			if [[ ${trap_manager_error_handled} -lt 1 ]] && [[ ${trap_exit_code} -gt 0 ]]; then
 				logging_error_show_log
-				display_alert "Exit with error detected" "${trap_exit_code} at ${short_stack} -\n${stack_caller}\n" "err"
+				display_alert "Exiting with error ${trap_exit_code}" "at ${short_stack}\n${stack_caller}\n" "err"
 				trap_manager_error_handled=1
 			fi
 
@@ -75,8 +77,8 @@ function main_trap_handler() {
 				bash < /dev/tty >&2 || true
 			fi
 
-			# Run the cleanup handlers, always.
-			run_cleanup_handlers || true
+			# Run the cleanup handlers, always. pass it the exit code so it keep the red theme of errors in its messages.
+			cleanup_exit_code="${trap_exit_code}" run_cleanup_handlers || true
 
 			# If global_final_exit_code is set, use it as the exit code. (used by docker CLI handler)
 			if [[ -n "${global_final_exit_code}" ]]; then
@@ -98,7 +100,11 @@ function run_cleanup_handlers() {
 	if [[ ${#trap_manager_cleanup_handlers[@]} -lt 1 ]]; then
 		return 0 # No handlers set, just return.
 	else
-		display_alert "Cleaning up" "please wait for cleanups to finish" "debug"
+		if [[ ${cleanup_exit_code:-0} -gt 0 ]]; then
+			display_alert "Cleaning up" "please wait for cleanups to finish" "error"
+		else
+			display_alert "Cleaning up" "please wait for cleanups to finish" "info"
+		fi
 	fi
 	# Loop over the handlers, execute one by one. Ignore errors.
 	# IMPORTANT: cleanups are added first to the list, so cleanups run in the reverse order they were added.
@@ -162,11 +168,12 @@ function exit_with_error() {
 	local _function=${FUNCNAME[1]}
 	local _line="${BASH_LINENO[0]}"
 
-	display_alert "error: ${1}" "${2} in ${_function}() at ${_file}:${_line}" "err"
+	display_alert "error!" "${1} ${2}" "err"
+
+	#display_alert "Build terminating..." "please wait for cleanups to finish" "err"
 
 	# @TODO: move this into trap handler
 	# @TODO: integrate both overlayfs and the FD locking with cleanup logic
-	display_alert "Build terminating... wait for cleanups..." "" "err"
 	overlayfs_wrapper "cleanup"
 
 	## This does not really make sense. wtf?