From d24f3631877133114232bbf54e00151d3bfa3211 Mon Sep 17 00:00:00 2001 From: Ricardo Pardini Date: Thu, 12 Jan 2023 19:00:06 +0100 Subject: [PATCH] armbian-oleg: logging: new logfile format; `SHOW_LOG=yes` default; introduce `DEBUG=yes` - default `SHOW_LOG=yes` if user on terminal - shortcut: `DEBUG=yes` defaults both `SHOW_LOG=yes` & `SHOW_DEBUG=yes` - much simpler logging format for log file - skip all display_alert()'s more verbose than DEBUG from logfile - set `DEBUG=yes` to log everything again - skip Markdown assets from being included in ANSI log - use of `ccze` - introduce internal var for controlling COMMAND-level log - remove unused `run_on_sdcard()` that somehow was left there - drop `export_html_logs()` and `EXPORT_HTML_LOG` -- are no more --- lib/functions/logging/display-alert.sh | 40 +++++++++----- lib/functions/logging/export-logs.sh | 74 +++----------------------- lib/functions/logging/logging.sh | 38 +++++++------ lib/functions/logging/runners.sh | 32 +++++------ lib/functions/logging/trap-logging.sh | 6 --- 5 files changed, 71 insertions(+), 119 deletions(-) diff --git a/lib/functions/logging/display-alert.sh b/lib/functions/logging/display-alert.sh index cf9b772872..b67552e610 100644 --- a/lib/functions/logging/display-alert.sh +++ b/lib/functions/logging/display-alert.sh @@ -6,9 +6,10 @@ function display_alert() { return 0 fi - local message="${1}" level="${3}" # params - local level_indicator="" inline_logs_color="" extra="" ci_log="" # this log - local skip_screen=0 # setting to 1 will write to logfile only + declare message="${1}" level="${3}" # params + declare level_indicator="" inline_logs_color="" extra="" ci_log="" # this log + declare -i 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="💥" @@ -43,14 +44,16 @@ function display_alert() { fi level_indicator="🧽" inline_logs_color="\e[1;33m" + skip_logfile=1 ;; - debug | deprecation) + 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) @@ -59,6 +62,7 @@ function display_alert() { fi level_indicator="🦋" inline_logs_color="\e[1;34m" # blue; 36 would be cyan + skip_logfile=1 ;; command) @@ -75,6 +79,7 @@ function display_alert() { fi level_indicator="🐜" inline_logs_color="${tool_color}" # either gray or normal, a bit subdued. + skip_logfile=1 ;; extensions) @@ -83,6 +88,7 @@ function display_alert() { fi level_indicator="🎣" # fishing pole and "hook" inline_logs_color="\e[0;36m" # a dim cyan + skip_logfile=1 ;; extensionstrace) @@ -91,6 +97,7 @@ function display_alert() { fi level_indicator="🐾" inline_logs_color="\e[0;36m" # a dim cyan + skip_logfile=1 ;; git) @@ -99,6 +106,7 @@ function display_alert() { fi level_indicator="🔖" inline_logs_color="${tool_color}" # either gray or normal, a bit subdued. + skip_logfile=1 ;; ccache) @@ -107,14 +115,17 @@ function display_alert() { fi level_indicator="🙈" inline_logs_color="\e[1;34m" # blue; 36 would be cyan + skip_logfile=1 ;; + # @TODO this is dead I think aggregation) if [[ "${SHOW_AGGREGATION}" != "yes" ]]; then # aggregation (PACKAGE LISTS), very very verbose skip_screen=1 fi level_indicator="📦" inline_logs_color="\e[0;32m" + skip_logfile=1 ;; *) @@ -129,15 +140,18 @@ function display_alert() { echo -e "${level}: ${1} [ ${2} ]" | sed 's/\x1b\[[0-9;]*m//g' | systemd-cat --identifier="${ARMBIAN_LOGS_JOURNAL_IDENTIFIER:-armbian}" fi - # Now, log to file. This will be colorized later by ccze and such, so remove any colors it might already have. - # See also the stuff done in runners.sh for logging exact command lines and runtimes. - # the "echo" runs in a subshell due to the "sed" pipe (! important !), so we store BASHPID (current subshell) outside the scope - # BASHPID is the current subshell; $$ is parent's?; $_ is the current bashopts local CALLER_PID="${BASHPID}" + + # Attention: do not pipe the output before writing to the logfile. + # For example, to remove ansi colors. + # If you do that, "echo" runs in a subshell due to the "sed" pipe (! important !) + # for the future: BASHPID is the current subshell; $$ is parent's?; $_ is the current bashopts + if [[ -f "${CURRENT_LOGFILE}" ]]; then - # ANSI-less version - #echo -e "--> ${level_indicator} $(printf "%4s" "${SECONDS}"): $$ - ${CALLER_PID} - ${BASHPID}: $-: ${level}: ${1} [ ${2} ]" >> "${CURRENT_LOGFILE}" # | sed 's/\x1b\[[0-9;]*m//g' - echo -e "--> ${level_indicator} $(printf "%4s" "${SECONDS}"): $$ - ${CALLER_PID} - ${BASHPID}: $-: ${level}: ${1} [ ${2} ]" >> "${CURRENT_LOGFILE}" # | sed 's/\x1b\[[0-9;]*m//g' + # If not asked to skip, or debugging is enabled, log to file. + if [[ ${skip_logfile} -lt 1 || "${DEBUG}" == "yes" ]]; then + echo -e "--> (${SECONDS}) ${level^^}: ${1} [ ${2} ]" >> "${CURRENT_LOGFILE}" # bash ^^ is "to upper case" + fi fi if [[ ${skip_screen} -eq 1 ]]; then @@ -159,12 +173,12 @@ function display_alert() { bashopts_info="${tool_color}(${normal_color}$-${tool_color})" # $- is the currently active bashopts fi - [[ -n $2 ]] && extra=" [${inline_logs_color} ${2} ${normal_color}]" + [[ -n ${2} ]] && extra=" [${inline_logs_color} ${2} ${normal_color}]" echo -e "${normal_color}${left_marker}${padding}${level_indicator}${padding}${normal_color}${right_marker}${timing_info}${pids_info}${bashopts_info} ${normal_color}${message}${extra}${normal_color}" >&2 # Now write to CI, if we're running on it. Remove ANSI escapes which confuse GitHub Actions. if [[ "${CI}" == "true" ]] && [[ "${ci_log}" != "" ]]; then - echo -e "::${ci_log} ::" "$@" | sed 's/\x1b\[[0-9;]*m//g' >&2 + echo -e "::${ci_log} ::" "${1} ${2}" | sed 's/\x1b\[[0-9;]*m//g' >&2 fi return 0 # make sure to exit with success, always diff --git a/lib/functions/logging/export-logs.sh b/lib/functions/logging/export-logs.sh index 7ccdc329fb..6cf5baea6b 100644 --- a/lib/functions/logging/export-logs.sh +++ b/lib/functions/logging/export-logs.sh @@ -59,15 +59,14 @@ function export_ansi_logs() { if [[ -n "$(command -v git)" && -d "${SRC}/.git" ]]; then display_alert "Gathering git info for logs" "Processing git information, please wait..." "debug" cat <<- GIT_ANSI_HEADER >> "${target_file}" - ---------------------------------------------------------------------------------------------------------------- # Last revision: - $(LC_ALL=C LANG=C git --git-dir="${SRC}/.git" log -1 --color --format=short --decorate) + $(LC_ALL=C LANG=C git --git-dir="${SRC}/.git" log -1 --color --format=short --decorate || true) ---------------------------------------------------------------------------------------------------------------- # Git status: - $(LC_ALL=C LANG=C git -c color.status=always --work-tree="${SRC}" --git-dir="${SRC}/.git" status) + $(LC_ALL=C LANG=C git -c color.status=always --work-tree="${SRC}" --git-dir="${SRC}/.git" status || true) ---------------------------------------------------------------------------------------------------------------- # Git changes: - $(LC_ALL=C LANG=C git --work-tree="${SRC}" --git-dir="${SRC}/.git" diff -u --color) + $(LC_ALL=C LANG=C git --work-tree="${SRC}" --git-dir="${SRC}/.git" diff -u --color || true) ---------------------------------------------------------------------------------------------------------------- GIT_ANSI_HEADER fi @@ -80,71 +79,14 @@ function export_ansi_logs() { for logfile_full in "${logfiles_array[@]}"; do local logfile_base="$(basename "${logfile_full}")" - cat <<- ANSI_ONE_LOGFILE_NO_CCZE >> "${target_file}" - ------------------------------------------------------------------------------------------------------------ + # skip if logfile_base ends in ".md"; those are handled in the markdown version of logs + [[ "${logfile_base}" =~ \.md$ ]] && continue + cat <<- ANSI_ONE_LOGFILE >> "${target_file}" ## ${logfile_base} $(cat "${logfile_full}") ------------------------------------------------------------------------------------------------------------ - ANSI_ONE_LOGFILE_NO_CCZE + ANSI_ONE_LOGFILE done - display_alert "Built ANSI log file" "${target_file}" -} - -# Export logs in HTML format. (EXPORT_HTML_LOG=yes) -- very slow. -function export_html_logs() { - display_alert "Preparing HTML log from" "${LOGDIR}" "debug" - - cat <<- ANSI_HEADER > "${target_file}" - - - Armbian logs for ${ARMBIAN_BUILD_UUID} - - - -

Armbian build at $(LC_ALL=C LANG=C date) on $(hostname || true)

-

${ARMBIAN_ORIGINAL_ARGV[@]@Q}

-
- - $(LC_ALL=C LANG=C git --git-dir="${SRC}/.git" log -1 --color --format=short --decorate | ansi2html --no-wrap --no-header) -
- - $(LC_ALL=C LANG=C git -c color.status=always --work-tree="${SRC}" --git-dir="${SRC}/.git" status | ansi2html --no-wrap --no-header) -
- - $(LC_ALL=C LANG=C git --work-tree="${SRC}" --git-dir="${SRC}/.git" diff -u --color | ansi2html --no-wrap --no-header) -
- - ANSI_HEADER - - # Find and sort the files there, store in array one per logfile - declare -a logfiles_array - mapfile -t logfiles_array < <(find "${LOGDIR}" -type f | LC_ALL=C sort -h) - - for logfile_full in "${logfiles_array[@]}"; do - local logfile_base="$(basename "${logfile_full}")" - if [[ -f /usr/bin/ccze ]] && [[ -f /usr/bin/ansi2html ]]; then - cat <<- HTML_ONE_LOGFILE_WITH_CCZE >> "${target_file}" -

${logfile_base}

-
- $(ccze -o nolookups --raw-ansi < "${logfile_full}" | ansi2html --no-wrap --no-header) -
-
- HTML_ONE_LOGFILE_WITH_CCZE - else - cat <<- ANSI_ONE_LOGFILE_NO_CCZE >> "${target_file}" -

${logfile_base}

- 
$(cat "${logfile_full}")
- ANSI_ONE_LOGFILE_NO_CCZE - fi - done - - cat <<- HTML_FOOTER >> "${target_file}" - - HTML_FOOTER - - display_alert "Built HTML log file" "${target_file}" + display_alert "ANSI log file built; inspect it by running:" "less -R ${target_file}" } diff --git a/lib/functions/logging/logging.sh b/lib/functions/logging/logging.sh index 09671aaa3c..a104f24fce 100644 --- a/lib/functions/logging/logging.sh +++ b/lib/functions/logging/logging.sh @@ -1,21 +1,32 @@ #!/usr/bin/env bash function logging_init() { + # defaults. + # if stdout is a terminal, then default SHOW_LOG to yes + [[ -t 1 ]] && declare -g SHOW_LOG="${SHOW_LOG:-"yes"}" + + # if DEBUG=yes (via env only, at this point) is set then default both log & debug to yes + if [[ "${DEBUG}" == "yes" ]]; then + declare -g SHOW_LOG="${SHOW_LOG:-"yes"}" + declare -g SHOW_DEBUG="${SHOW_DEBUG:-"yes"}" + fi + # globals - export padding="" left_marker="[" right_marker="]" - export normal_color="\x1B[0m" gray_color="\e[1;30m" # "bright black", which is grey - declare -i logging_section_counter=0 # -i: integer - export logging_section_counter - export tool_color="${gray_color}" # default to gray... (should be ok on terminals) - if [[ "${CI}" == "true" ]]; then # ... but that is too dark for Github Actions - export tool_color="${normal_color}" + declare -g padding="" left_marker="[" right_marker="]" + declare -g normal_color="\x1B[0m" gray_color="\e[1;30m" # "bright black", which is grey + declare -i logging_section_counter=0 # -i: integer + declare -g logging_section_counter + declare -g tool_color="${gray_color}" # default to gray... (should be ok on terminals) + if [[ "${CI}" == "true" ]]; then # ... but that is too dark for Github Actions + declare -g tool_color="${normal_color}" + declare -g SHOW_LOG="${SHOW_LOG:-"yes"}" # if in CI/GHA, default to showing log fi if [[ "${ARMBIAN_RUNNING_IN_CONTAINER}" == "yes" ]]; then # if in container, add a cyan "whale emoji" to the left marker wrapped in dark gray brackets local container_emoji="🐳" # 🐳 or 🐋 - export left_marker="${gray_color}[${container_emoji}|${normal_color}" + declare -g left_marker="${gray_color}[${container_emoji}|${normal_color}" elif [[ "$(uname -s)" == "Darwin" ]]; then # if on Mac, add a an apple emoji to the left marker wrapped in dark gray brackets local mac_emoji="🍏" # 🍏 or 🍎 - export left_marker="${gray_color}[${mac_emoji}|${normal_color}" + declare -g left_marker="${gray_color}[${mac_emoji}|${normal_color}" fi } @@ -32,13 +43,8 @@ function logging_error_show_log() { local prefix_sed_cmd="s/^/${prefix_sed_contents}/;" display_alert " 👇👇👇 Showing logfile below 👇👇👇" "${logfile_to_show}" "err" - if [[ -f /usr/bin/ccze ]]; then # use 'ccze' to colorize the log, making errors a lot more obvious. - # shellcheck disable=SC2002 # my cat is great. thank you, shellcheck. - cat "${logfile_to_show}" | grep -v -e "^$" | /usr/bin/ccze -o nolookups -A | sed -e "${prefix_sed_cmd}" 1>&2 # write it to stderr!! - else - # shellcheck disable=SC2002 # my cat is great. thank you, shellcheck. - cat "${logfile_to_show}" | grep -v -e "^$" | sed -e "${prefix_sed_cmd}" 1>&2 # write it to stderr!! - fi + # shellcheck disable=SC2002 # my cat is great. thank you, shellcheck. + cat "${logfile_to_show}" | grep -v -e "^$" | sed -e "${prefix_sed_cmd}" 1>&2 # write it to stderr!! display_alert " 👆👆👆 Showing logfile above 👆👆👆" "${logfile_to_show}" "err" else diff --git a/lib/functions/logging/runners.sh b/lib/functions/logging/runners.sh index 2f80bad33f..969ca654f0 100644 --- a/lib/functions/logging/runners.sh +++ b/lib/functions/logging/runners.sh @@ -1,5 +1,8 @@ #!/usr/bin/env bash +# All those runner helper functions have a particular non-quoting style. +# callers might need to force quote with bash's @Q modifier. + # shortcut function chroot_sdcard_apt_get_install() { chroot_sdcard_apt_get --no-install-recommends install "$@" @@ -76,12 +79,14 @@ function chroot_sdcard_apt_get() { # please, please, unify around this function. function chroot_sdcard() { - TMPDIR="" run_host_command_logged_raw chroot "${SDCARD}" /bin/bash -e -o pipefail -c "$*" + raw_command="$*" raw_extra="chroot_sdcard" TMPDIR="" \ + run_host_command_logged_raw chroot "${SDCARD}" /bin/bash -e -o pipefail -c "$*" } # please, please, unify around this function. function chroot_mount() { - TMPDIR="" run_host_command_logged_raw chroot "${MOUNT}" /bin/bash -e -o pipefail -c "$*" + raw_command="$*" raw_extra="chroot_mount" TMPDIR="" \ + run_host_command_logged_raw chroot "${MOUNT}" /bin/bash -e -o pipefail -c "$*" } # This should be used if you need to capture the stdout produced by the command. It is NOT logged, and NOT run thru bash, and NOT quoted. @@ -104,13 +109,13 @@ function chroot_custom_long_running() { # fi # return $_exit_code - TMPDIR="" run_host_command_logged_raw chroot "${target}" /bin/bash -e -o pipefail -c "$*" + raw_command="$*" raw_extra="chroot_custom_long_running" TMPDIR="" run_host_command_logged_raw chroot "${target}" /bin/bash -e -o pipefail -c "$*" } function chroot_custom() { local target=$1 shift - TMPDIR="" run_host_command_logged_raw chroot "${target}" /bin/bash -e -o pipefail -c "$*" + raw_command="$*" raw_extra="chroot_custom" TMPDIR="" run_host_command_logged_raw chroot "${target}" /bin/bash -e -o pipefail -c "$*" } # for deb building. @@ -136,7 +141,7 @@ function run_host_command_logged_long_running() { #return $_exit_code # Run simple and exit with it's code. Sorry. - run_host_command_logged_raw /bin/bash -e -o pipefail -c "$*" + raw_command="$*" run_host_command_logged_raw /bin/bash -e -o pipefail -c "$*" } # For installing packages host-side. Not chroot! @@ -178,7 +183,7 @@ function run_host_x86_binary_logged() { # run_host_command_logged is the very basic, should be used for everything, but, please use helpers above, this is very low-level. function run_host_command_logged() { - run_host_command_logged_raw /bin/bash -e -o pipefail -c "$*" + raw_command="$*" run_host_command_logged_raw /bin/bash -e -o pipefail -c "$*" } # for interactive, dialog-like host-side invocations. no redirections performed, but same bash usage and expansion, for consistency. @@ -189,7 +194,8 @@ function run_host_command_dialog() { # do NOT use directly, it does NOT expand the way it should (through bash) function run_host_command_logged_raw() { # Log the command to the current logfile, so it has context of what was run. - display_alert "Command debug" "$*" "command" # A special 'command' level. + # The real command might be very long, so, if raw_command is defined, log that instead. + display_alert "${raw_command:-"$*"}" "" "command" # A special 'command' level. # In this case I wanna KNOW exactly what failed, thus disable errexit, then re-enable immediately after running. set +e @@ -209,9 +215,6 @@ function run_host_command_logged_raw() { # Obtain extra info about error, eg, log files produced, extra messages set by caller, etc. logging_enrich_run_command_error_info - - elif [[ -f "${CURRENT_LOGFILE}" ]]; then - echo "-->--> command run successfully after $((SECONDS - seconds_start)) seconds" >> "${CURRENT_LOGFILE}" fi logging_clear_run_command_error_info # clear the error info vars, always, otherwise they'll leak into the next invocation. @@ -241,9 +244,7 @@ function logging_enrich_run_command_error_info() { LOG_ASSET="chroot_error_context__$(basename "${found_file}")" do_with_log_asset cat "${found_file}" display_alert "File contents for error context" "${found_file}" "err" - # shellcheck disable=SC2002 # cat is not useless, ccze _only_ takes stdin - cat "${found_file}" | ccze -A 1>&2 # to stderr - # @TODO: 3x repeated ccze invocation, lets refactor it later + cat "${found_file}" 1>&2 # to stderr done ### if_error_detail_message, array: messages to display if the command failed. @@ -251,8 +252,3 @@ function logging_enrich_run_command_error_info() { display_alert "Error context msg" "${if_error_detail_message}" "err" fi } - -# @TODO: logging: used by desktop.sh exclusively. let's unify? -run_on_sdcard() { - chroot_sdcard "${@}" -} diff --git a/lib/functions/logging/trap-logging.sh b/lib/functions/logging/trap-logging.sh index 78ba7fa465..f2ada0969e 100644 --- a/lib/functions/logging/trap-logging.sh +++ b/lib/functions/logging/trap-logging.sh @@ -55,12 +55,6 @@ function trap_handler_cleanup_logging() { export_markdown_logs reset_uid_owner "${target_file}" - if [[ "${EXPORT_HTML_LOG}" == "yes" ]]; then - local target_file="${target_path}/armbian-${ARMBIAN_LOG_CLI_ID}-${ARMBIAN_BUILD_UUID}.html" - export_html_logs - reset_uid_owner "${target_file}" - fi - local target_file="${target_path}/armbian-${ARMBIAN_LOG_CLI_ID}-${ARMBIAN_BUILD_UUID}.ansitxt.log" export_ansi_logs reset_uid_owner "${target_file}"