From c4eaf49f3d16c6e740348880acbaece6d8e93b01 Mon Sep 17 00:00:00 2001 From: Ricardo Pardini Date: Fri, 21 Oct 2022 15:39:05 +0200 Subject: [PATCH] armbian-next: cleanup `extensions` logging, using `display_alert` new levels `extensions` (`SHOW_EXTENSIONS=yes`) and `extensionstrace` (`SHOW_EXTENSIONS_TRACE=yes`) - DEBUG_EXTENSION_CALLS is gone. use SHOW_EXTENSIONS instead. - LOG_ALL_HOOK_TRACES is gone. use SHOW_EXTENSIONS_TRACE instead - LOG_ENABLE_EXTENSION is gone. use SHOW_DEBUG=yes instead --- extensions/detect-unused-extensions.sh | 11 +---- lib/extensions.sh | 64 +++++++++----------------- lib/functions/logging/logging.sh | 16 +++++++ 3 files changed, 41 insertions(+), 50 deletions(-) diff --git a/extensions/detect-unused-extensions.sh b/extensions/detect-unused-extensions.sh index 73989925e493..28422387af26 100644 --- a/extensions/detect-unused-extensions.sh +++ b/extensions/detect-unused-extensions.sh @@ -1,6 +1,4 @@ #!/usr/bin/env bash -## Configuration -export LOG_ALL_HOOK_TRACES=no # Should we log all hook function traces to stdout? (no, or level: wrn info) ## Hooks @@ -26,11 +24,7 @@ function extension_metadata_ready__999_detect_wishful_hooking() { line_info="${hook_point_function_trace_lines["${one_defined_function}"]}" stack="$(get_extension_hook_stracktrace "${source_info}" "${line_info}")" if [[ "$source_info" != "" ]]; then - # log to debug log. it's reassuring. - echo "\$\$\$ Hook function stacktrace for '${one_defined_function}': '${stack}' (${defined_info})" >> "${EXTENSION_MANAGER_LOG_FILE}" - if [[ "${LOG_ALL_HOOK_TRACES}" != "no" ]]; then - display_alert "Hook function stacktrace for '${one_defined_function}'" "${stack}" "${LOG_ALL_HOOK_TRACES}" - fi + display_alert "Hook function stacktrace for '${one_defined_function}'" "${stack}" "extensionstrace" continue # found a caller, move on. fi @@ -40,12 +34,11 @@ function extension_metadata_ready__999_detect_wishful_hooking() { found_honeypot_function=1 else # unexpected wishful hooking. Log and wrn the user. - echo "\$\$\$ Wishful hooking detected" "Function '${one_defined_function}' is defined (${defined_info}) but never called by the build." >> "${EXTENSION_MANAGER_LOG_FILE}" display_alert "Wishful hooking detected" "Function '${one_defined_function}' is defined (${defined_info}) but never called by the build." "wrn" fi done if [[ $found_honeypot_function -lt 1 ]]; then - display_alert "Wishful hook DETECTION FAILED" "detect-wishful-hooking is not working. Good chance the environment vars are corrupted. Avoid child shells. Sorry." "wrn" | tee -a "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Wishful hook DETECTION FAILED" "detect-wishful-hooking is not working. Good chance the environment vars are corrupted. Avoid child shells. Sorry." "wrn" fi } diff --git a/lib/extensions.sh b/lib/extensions.sh index f3eea82f0dfc..fbf50942c3bb 100644 --- a/lib/extensions.sh +++ b/lib/extensions.sh @@ -6,9 +6,6 @@ declare -A defined_hook_point_functions # keeps a map of hook point fu declare -A hook_point_function_trace_sources # keeps a map of hook point functions that were actually called and their source declare -A hook_point_function_trace_lines # keeps a map of hook point functions that were actually called and their source declare fragment_manager_cleanup_file # this is a file used to cleanup the manager's produced functions, for build_all_ng -# configuration. Command line might override this. -export DEBUG_EXTENSION_CALLS=no # set to yes to log every hook function called to the main build log -export LOG_ENABLE_EXTENSION=yes # colorful logs with stacktrace when enable_extension is called. # This is a helper function for calling hooks. # It follows the pattern long used in the codebase for hook-like behaviour: @@ -30,13 +27,12 @@ call_extension_method() { display_alert "Extension problem" "Call to call_extension_method() ($*: in ${BASH_SOURCE[1]- $(get_extension_hook_stracktrace "${BASH_SOURCE[*]}" "${BASH_LINENO[*]}")}) before extension manager is initialized." "err" fi - # With DEBUG_EXTENSION_CALLS, log the hook call. Users might be wondering what/when is a good hook point to use, and this is visual aid. - [[ "${DEBUG_EXTENSION_CALLS}" == "yes" ]] && - display_alert "--> Extension Method '${1}' being called from" "$(get_extension_hook_stracktrace "${BASH_SOURCE[*]}" "${BASH_LINENO[*]}")" "" + # Log the hook call. Users might be wondering what/when is a good hook point to use, and this is visual aid. + display_alert "Extension Method '${1}' being called from" "$(get_extension_hook_stracktrace "${BASH_SOURCE[*]}" "${BASH_LINENO[*]}")" "extensions" # Then call the hooks, if they are defined. for hook_name in "$@"; do - echo "-- Extension Method being called: ${hook_name}" >> "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extension Method being called: ${hook_name}" "hook: ${hook_name}" "extensions" if [[ $(type -t ${hook_name} || true) == function ]]; then ${hook_name} fi @@ -66,18 +62,14 @@ initialize_extension_manager() { display_alert "Initializing EXTENSION_MANAGER_TMP_DIR" "${EXTENSION_MANAGER_TMP_DIR}" "debug" mkdir -p "${EXTENSION_MANAGER_TMP_DIR}" - # Log destination. - export EXTENSION_MANAGER_LOG_FILE="${LOGDIR}/999.extensions.log" + # Metadata about hook_point_calls. This is used to generate the documentation / example extensions [[ "${WRITE_EXTENSIONS_METADATA:-yes}" == "no" ]] && echo -n "" > "${EXTENSION_MANAGER_TMP_DIR}/hook_point_calls.txt" # Add trap handler to cleanup and not leave garbage behind when exiting. add_cleanup_handler cleanup_handler_extensions - # globally initialize the extensions log. - echo "-- lib/extensions.sh included. logs will be below, followed by the debug generated by the initialize_extension_manager() function." > "${EXTENSION_MANAGER_LOG_FILE}" - - # log whats happening. - echo "-- initialize_extension_manager() called." >> "${EXTENSION_MANAGER_LOG_FILE}" + # log whats happening; extensions has its own log level. enable with SHOW_EXTENSIONS=yes + display_alert "Initializing EXTENSION_MANAGER" "initializing extension manager" "extensions" # this is the all-important separator. local hook_extension_delimiter="__" @@ -98,7 +90,7 @@ initialize_extension_manager() { local hook_point="" # now loop over the hook_points. for hook_point in ${all_hook_points}; do - echo "-- hook_point ${hook_point}" >> "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extensions hook point" "${hook_point}" "extensions" # check if the hook point is already defined as a function. # that can happen for example with user_config(), that can be implemented itself directly by a userpatches config. @@ -107,7 +99,7 @@ initialize_extension_manager() { local existing_hook_point_function existing_hook_point_function="$(compgen -A function | grep "^${hook_point}\$" || true)" if [[ "${existing_hook_point_function}" == "${hook_point}" ]]; then - echo "--- hook_point_functions (final sorted realnames): ${hook_point_functions}" >> "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extensions final sorted realnames" "${hook_point_functions}" "extensionstrace" display_alert "Extension conflict" "function ${hook_point} already defined! ignoring functions: $(compgen -A function | grep "^${hook_point}${hook_extension_delimiter}")" "wrn" continue fi @@ -130,7 +122,7 @@ initialize_extension_manager() { # gather the real names of the functions (after the delimiter). hook_point_functions_pre_sort="$(compgen -A function | grep "^${hook_point}${hook_extension_delimiter}" | awk -F "${hook_extension_delimiter}" '{print $2}' | xargs echo -n)" - echo "--- hook_point_functions_pre_sort: ${hook_point_functions_pre_sort}" >> "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extensions hook_point_functions_pre_sort" "${hook_point_functions_pre_sort}" "extensionstrace" # add "500_" to the names of function that do NOT start with a number. # keep a reference from the new names to the old names (we'll sort on the new, but invoke the old) @@ -146,7 +138,7 @@ initialize_extension_manager() { # actually sort the sort_id's... # shellcheck disable=SC2086 hook_point_functions_sorted_by_sort_id="$(echo "${hook_point_functions_realname_to_sortname[*]}" | tr " " "\n" | LC_ALL=C sort ${FUNCTION_SORT_OPTIONS} | xargs echo -n)" - echo "--- hook_point_functions_sorted_by_sort_id: ${hook_point_functions_sorted_by_sort_id}" >> "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extensions hook_point_functions_sorted_by_sort_id" "${hook_point_functions_sorted_by_sort_id}" "extensionstrace" # then map back to the real names, keeping the order.. hook_point_functions="" @@ -155,7 +147,7 @@ initialize_extension_manager() { done # shellcheck disable=SC2086 hook_point_functions="$(echo -n ${hook_point_functions})" - echo "--- hook_point_functions (final sorted realnames): ${hook_point_functions}" >> "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extensions hook_point_functions (final sorted realnames)" "${hook_point_functions}" "extensionstrace" hook_point_functions_counter=0 hook_points_counter=$((hook_points_counter + 1)) @@ -172,7 +164,7 @@ initialize_extension_manager() { done common_function_vars="${common_function_vars} HOOK_POINT_TOTAL_FUNCS=\"${hook_point_functions_counter}\"" - echo "-- hook_point: ${hook_point} will run ${hook_point_functions_counter} functions: ${hook_point_functions}" >> "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extensions hook_point: ${hook_point} will run ${hook_point_functions_counter} functions" "${hook_point_functions_counter}" "extensions" local temp_source_file_for_hook_point="${EXTENSION_MANAGER_TMP_DIR}/extension_function_definition.sh" hook_point_functions_loop_counter=0 @@ -188,7 +180,7 @@ initialize_extension_manager() { # - define call-specific environment variables, to help extension authors to write portable extensions (eg: EXTENSION_DIR) cat <<- FUNCTION_DEFINITION_HEADER > "${temp_source_file_for_hook_point}" ${hook_point}() { - echo "*** Extension-managed hook starting '${hook_point}': will run ${hook_point_functions_counter} functions: '${hook_point_functions}'" >>"\${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extension-managed hook starting '${hook_point}': will run ${hook_point_functions_counter} functions" "${hook_point_functions}" "extensionstrace" FUNCTION_DEFINITION_HEADER for hook_point_function in ${hook_point_functions}; do @@ -212,10 +204,10 @@ initialize_extension_manager() { cat <<- FUNCTION_DEFINITION_CALLSITE >> "${temp_source_file_for_hook_point}" hook_point_function_trace_sources["${hook_point}${hook_extension_delimiter}${hook_point_function}"]="\${BASH_SOURCE[*]}" hook_point_function_trace_lines["${hook_point}${hook_extension_delimiter}${hook_point_function}"]="\${BASH_LINENO[*]}" - [[ "\${DEBUG_EXTENSION_CALLS}" == "yes" ]] && display_alert "---> Extension Method ${hook_point}" "${hook_point_functions_loop_counter}/${hook_point_functions_counter} (ext:${EXTENSION:-built-in}) ${hook_point_function}" "" - echo "*** *** Extension-managed hook starting ${hook_point_functions_loop_counter}/${hook_point_functions_counter} '${hook_point}${hook_extension_delimiter}${hook_point_function}':" >>"\${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extension Method ${hook_point}" "${hook_point_functions_loop_counter}/${hook_point_functions_counter} (ext:${EXTENSION:-built-in}) ${hook_point_function}" "extensionstrace" + display_alert "Extension-managed hook starting ${hook_point_functions_loop_counter}/${hook_point_functions_counter}" "${hook_point}${hook_extension_delimiter}${hook_point_function}" "extensionstrace" ${hook_point_function_variables} ${hook_point}${hook_extension_delimiter}${hook_point_function} "\$@" - echo "*** *** Extension-managed hook finished ${hook_point_functions_loop_counter}/${hook_point_functions_counter} '${hook_point}${hook_extension_delimiter}${hook_point_function}':" >>"\${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extension-managed hook finished ${hook_point_functions_loop_counter}/${hook_point_functions_counter}" "${hook_point}${hook_extension_delimiter}${hook_point_function}" "extensionstrace" FUNCTION_DEFINITION_CALLSITE # output the cleanup for the implementation as well. @@ -228,17 +220,13 @@ initialize_extension_manager() { done cat <<- FUNCTION_DEFINITION_FOOTER >> "${temp_source_file_for_hook_point}" - echo "*** Extension-managed hook ending '${hook_point}': completed." >>"\${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extension-managed hook ending '${hook_point}': completed" "${hook_point}" "extensionstrace" } # end ${hook_point}() function FUNCTION_DEFINITION_FOOTER # unsets, lest the next loop inherits them unset hook_point_functions hook_point_functions_sortname_to_realname hook_point_functions_realname_to_sortname - # log what was produced in our own debug logfile - cat "${temp_source_file_for_hook_point}" >> "${EXTENSION_MANAGER_LOG_FILE}" - cat "${fragment_manager_cleanup_file}" >> "${EXTENSION_MANAGER_LOG_FILE}" - # source the generated function. # shellcheck disable=SC1090 source "${temp_source_file_for_hook_point}" @@ -248,7 +236,7 @@ initialize_extension_manager() { # Dont show any output until we have more than 1 hook function (we implement one already, below) [[ ${hook_functions_counter} -gt 0 ]] && - display_alert "Extension manager" "processed ${hook_points_counter} Extension Methods calls and ${hook_functions_counter} Extension Method implementations" "info" | tee -a "${EXTENSION_MANAGER_LOG_FILE}" + display_alert "Extension manager" "processed ${hook_points_counter} Extension Methods calls and ${hook_functions_counter} Extension Method implementations" "info" return 0 # exit with success, short-circuit above. } @@ -271,9 +259,6 @@ function cleanup_handler_extensions() { display_alert "yeah the extensions trap handler..." "cleanup_handler_extensions" "cleanup" cleanup_extension_manager - # Stop logging. - unset EXTENSION_MANAGER_LOG_FILE - # cleanup our tmpdir. if [[ -d "${EXTENSION_MANAGER_TMP_DIR}" ]]; then rm -rf "${EXTENSION_MANAGER_TMP_DIR}" @@ -337,14 +322,11 @@ enable_extension() { local extension_dir extension_file extension_file_in_dir extension_floating_file local stacktrace - # if LOG_ENABLE_EXTENSION, output useful stack, so user can figure out which extensions are being added where - if [[ "${LOG_ENABLE_EXTENSION}" == "yes" ]]; then - if [[ "${SHOW_DEBUG}" == "yes" ]]; then - stacktrace="${ENABLE_EXTENSION_TRACE_HINT}$(get_extension_hook_stracktrace "${BASH_SOURCE[*]}" "${BASH_LINENO[*]}")" - display_alert "Enabling extension" "${extension_name} :: added by ${stacktrace}" "debug" - else - display_alert "Enabling extension" "${extension_name}" "" - fi + if [[ "${SHOW_DEBUG}" == "yes" ]]; then + stacktrace="${ENABLE_EXTENSION_TRACE_HINT}$(get_extension_hook_stracktrace "${BASH_SOURCE[*]}" "${BASH_LINENO[*]}")" + display_alert "Enabling extension" "${extension_name} :: added by ${stacktrace}" "debug" + else + display_alert "Enabling extension" "${extension_name}" "" fi # first a check, has the extension manager already initialized? then it is too late to enable_extension(). bail. diff --git a/lib/functions/logging/logging.sh b/lib/functions/logging/logging.sh index 73cc89d006ca..28389c7be595 100644 --- a/lib/functions/logging/logging.sh +++ b/lib/functions/logging/logging.sh @@ -203,6 +203,22 @@ function display_alert() { inline_logs_color="${tool_color}" # either gray or normal, a bit subdued. ;; + extensions) + if [[ "${SHOW_EXTENSIONS}" != "yes" ]]; then # enable to log a lot about extensions, hook methos, etc. + skip_screen=1 + fi + level_indicator="🎣" # fishing pole and "hook" + inline_logs_color="\e[0;36m" # a dim cyan + ;; + + extensionstrace) + if [[ "${SHOW_EXTENSIONS_TRACE}" != "yes" ]]; then # waaaay too verbose, logs traces in extensions + skip_screen=1 + fi + level_indicator="🐾" + inline_logs_color="\e[0;36m" # a dim cyan + ;; + git) if [[ "${SHOW_GIT}" != "yes" ]]; then # git-related debugging messages, very very verbose skip_screen=1