JDM170/build
1
0
Fork 0
mirror of https://github.com/armbian/build synced 2025-09-24 19:47:06 +07:00
Code Issues Packages Projects Releases Wiki Activity

armbian-next: cleanup extensions logging, using display_alert new levels extensions (SHOW_EXTENSIONS=yes) and extensionstrace (SHOW_EXTENSIONS_TRACE=yes)

Browse Source 
- 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
This commit is contained in:
Ricardo Pardini
2022-10-21 15:39:05 +02:00
parent 72bc1b09d8
commit c4eaf49f3d
3 changed files with 41 additions and 50 deletions
Download Patch File Download Diff File Expand all files Collapse all files

11
extensions/detect-unused-extensions.sh
View File

@@ -1,6 +1,4 @@
#!/usr/bin/env bash #!/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 ## Hooks
@@ -26,11 +24,7 @@ function extension_metadata_ready__999_detect_wishful_hooking() {
line_info="${hook_point_function_trace_lines["${one_defined_function}"]}" line_info="${hook_point_function_trace_lines["${one_defined_function}"]}"
stack="$(get_extension_hook_stracktrace "${source_info}" "${line_info}")" stack="$(get_extension_hook_stracktrace "${source_info}" "${line_info}")"
if [[ "$source_info" != "" ]]; then if [[ "$source_info" != "" ]]; then
# log to debug log. it's reassuring. display_alert "Hook function stacktrace for '${one_defined_function}'" "${stack}" "extensionstrace"
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
continue # found a caller, move on. continue # found a caller, move on.
fi fi
@@ -40,12 +34,11 @@ function extension_metadata_ready__999_detect_wishful_hooking() {
found_honeypot_function=1 found_honeypot_function=1
else else
# unexpected wishful hooking. Log and wrn the user. # 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" display_alert "Wishful hooking detected" "Function '${one_defined_function}' is defined (${defined_info}) but never called by the build." "wrn"
fi fi
done done
if [[ $found_honeypot_function -lt 1 ]]; then 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 fi
} }

64
lib/extensions.sh
View File

@@ -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_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 -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 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. # This is a helper function for calling hooks.
# It follows the pattern long used in the codebase for hook-like behaviour: # 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" 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 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. # 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[*]}")" "extensions"
display_alert "--> Extension Method '${1}' being called from" "$(get_extension_hook_stracktrace "${BASH_SOURCE[*]}" "${BASH_LINENO[*]}")" ""
# Then call the hooks, if they are defined. # Then call the hooks, if they are defined.
for hook_name in "$@"; do 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 if [[ $(type -t ${hook_name} || true) == function ]]; then
${hook_name} ${hook_name}
fi fi
@@ -66,18 +62,14 @@ initialize_extension_manager() {
display_alert "Initializing EXTENSION_MANAGER_TMP_DIR" "${EXTENSION_MANAGER_TMP_DIR}" "debug" display_alert "Initializing EXTENSION_MANAGER_TMP_DIR" "${EXTENSION_MANAGER_TMP_DIR}" "debug"
mkdir -p "${EXTENSION_MANAGER_TMP_DIR}" mkdir -p "${EXTENSION_MANAGER_TMP_DIR}"
# Log destination. # Metadata about hook_point_calls. This is used to generate the documentation / example extensions
export EXTENSION_MANAGER_LOG_FILE="${LOGDIR}/999.extensions.log"
[[ "${WRITE_EXTENSIONS_METADATA:-yes}" == "no" ]] && echo -n "" > "${EXTENSION_MANAGER_TMP_DIR}/hook_point_calls.txt" [[ "${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 trap handler to cleanup and not leave garbage behind when exiting.
add_cleanup_handler cleanup_handler_extensions add_cleanup_handler cleanup_handler_extensions
# globally initialize the extensions log. # log whats happening; extensions has its own log level. enable with SHOW_EXTENSIONS=yes
echo "-- lib/extensions.sh included. logs will be below, followed by the debug generated by the initialize_extension_manager() function." > "${EXTENSION_MANAGER_LOG_FILE}" display_alert "Initializing EXTENSION_MANAGER" "initializing extension manager" "extensions"
# log whats happening.
echo "-- initialize_extension_manager() called." >> "${EXTENSION_MANAGER_LOG_FILE}"
# this is the all-important separator. # this is the all-important separator.
local hook_extension_delimiter="__" local hook_extension_delimiter="__"
@@ -98,7 +90,7 @@ initialize_extension_manager() {
local hook_point="" local hook_point=""
# now loop over the hook_points. # now loop over the hook_points.
for hook_point in ${all_hook_points}; do 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. # 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. # 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 local existing_hook_point_function
existing_hook_point_function="$(compgen -A function | grep "^${hook_point}\$" || true)" existing_hook_point_function="$(compgen -A function | grep "^${hook_point}\$" || true)"
if [[ "${existing_hook_point_function}" == "${hook_point}" ]]; then 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" display_alert "Extension conflict" "function ${hook_point} already defined! ignoring functions: $(compgen -A function | grep "^${hook_point}${hook_extension_delimiter}")" "wrn"
continue continue
fi fi
@@ -130,7 +122,7 @@ initialize_extension_manager() {
# gather the real names of the functions (after the delimiter). # 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)" 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. # 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) # 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... # actually sort the sort_id's...
# shellcheck disable=SC2086 # 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)" 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.. # then map back to the real names, keeping the order..
hook_point_functions="" hook_point_functions=""
@@ -155,7 +147,7 @@ initialize_extension_manager() {
done done
# shellcheck disable=SC2086 # shellcheck disable=SC2086
hook_point_functions="$(echo -n ${hook_point_functions})" 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_point_functions_counter=0
hook_points_counter=$((hook_points_counter + 1)) hook_points_counter=$((hook_points_counter + 1))
@@ -172,7 +164,7 @@ initialize_extension_manager() {
done done
common_function_vars="${common_function_vars} HOOK_POINT_TOTAL_FUNCS=\"${hook_point_functions_counter}\"" 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" local temp_source_file_for_hook_point="${EXTENSION_MANAGER_TMP_DIR}/extension_function_definition.sh"
hook_point_functions_loop_counter=0 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) # - 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}" cat <<- FUNCTION_DEFINITION_HEADER > "${temp_source_file_for_hook_point}"
${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 FUNCTION_DEFINITION_HEADER
for hook_point_function in ${hook_point_functions}; do 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}" 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_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[*]}" 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}" "" display_alert "Extension Method ${hook_point}" "${hook_point_functions_loop_counter}/${hook_point_functions_counter} (ext:${EXTENSION:-built-in}) ${hook_point_function}" "extensionstrace"
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-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} "\$@" ${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 FUNCTION_DEFINITION_CALLSITE
# output the cleanup for the implementation as well. # output the cleanup for the implementation as well.
@@ -228,17 +220,13 @@ initialize_extension_manager() {
done done
cat <<- FUNCTION_DEFINITION_FOOTER >> "${temp_source_file_for_hook_point}" 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 } # end ${hook_point}() function
FUNCTION_DEFINITION_FOOTER FUNCTION_DEFINITION_FOOTER
# unsets, lest the next loop inherits them # unsets, lest the next loop inherits them
unset hook_point_functions hook_point_functions_sortname_to_realname hook_point_functions_realname_to_sortname 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. # source the generated function.
# shellcheck disable=SC1090 # shellcheck disable=SC1090
source "${temp_source_file_for_hook_point}" 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) # Dont show any output until we have more than 1 hook function (we implement one already, below)
[[ ${hook_functions_counter} -gt 0 ]] && [[ ${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. 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" display_alert "yeah the extensions trap handler..." "cleanup_handler_extensions" "cleanup"
cleanup_extension_manager cleanup_extension_manager
# Stop logging.
unset EXTENSION_MANAGER_LOG_FILE
# cleanup our tmpdir. # cleanup our tmpdir.
if [[ -d "${EXTENSION_MANAGER_TMP_DIR}" ]]; then if [[ -d "${EXTENSION_MANAGER_TMP_DIR}" ]]; then
rm -rf "${EXTENSION_MANAGER_TMP_DIR}" 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 extension_dir extension_file extension_file_in_dir extension_floating_file
local stacktrace local stacktrace
# if LOG_ENABLE_EXTENSION, output useful stack, so user can figure out which extensions are being added where if [[ "${SHOW_DEBUG}" == "yes" ]]; then
if [[ "${LOG_ENABLE_EXTENSION}" == "yes" ]]; then stacktrace="${ENABLE_EXTENSION_TRACE_HINT}$(get_extension_hook_stracktrace "${BASH_SOURCE[*]}" "${BASH_LINENO[*]}")"
if [[ "${SHOW_DEBUG}" == "yes" ]]; then display_alert "Enabling extension" "${extension_name} :: added by ${stacktrace}" "debug"
stacktrace="${ENABLE_EXTENSION_TRACE_HINT}$(get_extension_hook_stracktrace "${BASH_SOURCE[*]}" "${BASH_LINENO[*]}")" else
display_alert "Enabling extension" "${extension_name} :: added by ${stacktrace}" "debug" display_alert "Enabling extension" "${extension_name}" ""
else
display_alert "Enabling extension" "${extension_name}" ""
fi
fi fi
# first a check, has the extension manager already initialized? then it is too late to enable_extension(). bail. # first a check, has the extension manager already initialized? then it is too late to enable_extension(). bail.

16
lib/functions/logging/logging.sh
View File

@@ -203,6 +203,22 @@ function display_alert() {
inline_logs_color="${tool_color}" # either gray or normal, a bit subdued. 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) git)
if [[ "${SHOW_GIT}" != "yes" ]]; then # git-related debugging messages, very very verbose if [[ "${SHOW_GIT}" != "yes" ]]; then # git-related debugging messages, very very verbose
skip_screen=1 skip_screen=1