Skip to content

Commit

Permalink
armbian-next: cleanup extensions logging, using display_alert new…
Browse files Browse the repository at this point in the history 
… 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
  • Loading branch information
@rpardini
rpardini committed Feb 18, 2023
1 parent 72bc1b0 commit c4eaf49
Show file tree
Hide file tree
Showing 3 changed files with 41 additions and 50 deletions.
11 changes: 2 additions & 9 deletions extensions/detect-unused-extensions.sh
View file
Original file line number Diff line number Diff line change
@@ -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

Expand All @@ -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

Expand All @@ -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
}
64 changes: 23 additions & 41 deletions lib/extensions.sh
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand All @@ -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
Expand Down Expand Up @@ -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="__"
Expand All @@ -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.
Expand All @@ -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
Expand All @@ -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)
Expand All @@ -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=""
Expand All @@ -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))
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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.
Expand All @@ -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}"
Expand All @@ -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.
}
Expand All @@ -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}"
Expand Down Expand Up @@ -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.
Expand Down
16 changes: 16 additions & 0 deletions lib/functions/logging/logging.sh
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down

0 comments on commit c4eaf49

Please sign in to comment.