lib/log: automate log prefix

Automatically set log prefix when sourcing a file, and relinquish it when returning from that file.

.editorconfig

@@ -25,6 +25,7 @@ binary_next_line   = true  # like -bn
 switch_case_indent = true  # like -ci
 space_redirects    = true  # like -sr
 keep_padding       = false # like -kp
+#function_next_line = true  # like -fn
 end_of_line        = lf
 charset            = utf-8
 trim_trailing_whitespace = true

aliases/available/bash-it.aliases.bash

@@ -21,3 +21,9 @@ alias bshsch="bash-it search"
 alias bshenp="bash-it enable plugin"
 alias bshena="bash-it enable alias"
 alias bshenc="bash-it enable completion"
+
+# BASH_IT_RELOAD_LEGACY is set.
+if [[ -n "${BASH_IT_RELOAD_LEGACY:-}" ]] && ! _command_exists reload; then
+	# shellcheck disable=SC2139
+	alias reload="builtin source '${BASH_IT_BASHRC?}'"
+fi

bash_it.sh

@@ -3,7 +3,6 @@
 # shellcheck disable=SC2034
 #
 # Initialize Bash It
-BASH_IT_LOG_PREFIX="core: main: "
 : "${BASH_IT:=${BASH_SOURCE%/*}}"
 : "${BASH_IT_CUSTOM:=${BASH_IT}/custom}"
 : "${CUSTOM_THEME_DIR:="${BASH_IT_CUSTOM}/themes"}"
@@ -21,39 +20,36 @@ _bash_it_library_finalize_hook=()
 
 # We need to load logging module early in order to be able to log
 source "${BASH_IT}/lib/log.bash"
+_bash_it_log_prefix_push "main"
 
 # Load libraries
 _log_debug "Loading libraries..."
 for _bash_it_main_file_lib in "${BASH_IT}/lib"/*.bash; do
-	_bash-it-log-prefix-by-path "${_bash_it_main_file_lib}"
+	_bash_it_log_section="${_bash_it_lib_file}"
 	_log_debug "Loading library file..."
 	# shellcheck disable=SC1090
 	source "$_bash_it_main_file_lib"
-	BASH_IT_LOG_PREFIX="core: main: "
 done
 
 # Load the global "enabled" directory, then enabled aliases, completion, plugins
 # "_bash_it_main_file_type" param is empty so that files get sourced in glob order
 for _bash_it_main_file_type in "" "aliases" "plugins" "completion"; do
-	BASH_IT_LOG_PREFIX="core: reloader: "
-	_log_debug "Loading \"${_bash_it_main_file_type}\"..."
+	_bash_it_log_section=reloader
+	_log_debug "Loading '${_bash_it_main_file_type}'..."
 	source "${BASH_IT}/scripts/reloader.bash" "${_bash_it_main_file_type:+skip}" "$_bash_it_main_file_type"
-	_log_debug "Loaded."
-	BASH_IT_LOG_PREFIX="core: main: "
 done
 
 # Load theme, if a theme was set
 # shellcheck source-path=SCRIPTDIR/themes
 if [[ -n "${BASH_IT_THEME:-}" ]]; then
 	_log_debug "Loading theme '${BASH_IT_THEME}'."
-	BASH_IT_LOG_PREFIX="themes: githelpers: "
+	_bash_it_log_section="githelpers"
 	source "${BASH_IT}/themes/githelpers.theme.bash"
-	BASH_IT_LOG_PREFIX="themes: p4helpers: "
+	_bash_it_log_section="p4helpers"
 	source "${BASH_IT}/themes/p4helpers.theme.bash"
-	BASH_IT_LOG_PREFIX="themes: base: "
+	_bash_it_log_section="base"
 	source "${BASH_IT}/themes/base.theme.bash"
 
-	BASH_IT_LOG_PREFIX="lib: appearance: "
 	# shellcheck disable=SC1090
 	if [[ -f "${BASH_IT_THEME}" ]]; then
 		source "${BASH_IT_THEME}"
@@ -62,33 +58,35 @@ if [[ -n "${BASH_IT_THEME:-}" ]]; then
 	elif [[ -f "$BASH_IT/themes/$BASH_IT_THEME/$BASH_IT_THEME.theme.bash" ]]; then
 		source "$BASH_IT/themes/$BASH_IT_THEME/$BASH_IT_THEME.theme.bash"
 	fi
+	_bash_it_log_prefix_pop "theme"
 fi
 
+_bash_it_log_prefix_push "custom"
 _log_debug "Loading custom aliases, completion, plugins..."
 for _bash_it_main_file_type in "aliases" "completion" "plugins"; do
 	_bash_it_main_file_custom="${BASH_IT}/${_bash_it_main_file_type}/custom.${_bash_it_main_file_type}.bash"
 	if [[ -s "${_bash_it_main_file_custom}" ]]; then
-		_bash-it-log-prefix-by-path "${_bash_it_main_file_custom}"
+		_bash_it_log_section="${file_type}"
 		_log_debug "Loading component..."
 		# shellcheck disable=SC1090
 		source "${_bash_it_main_file_custom}"
 	fi
-	BASH_IT_LOG_PREFIX="core: main: "
 done
 
 # Custom
 _log_debug "Loading general custom files..."
 for _bash_it_main_file_custom in "${BASH_IT_CUSTOM}"/*.bash "${BASH_IT_CUSTOM}"/*/*.bash; do
 	if [[ -s "${_bash_it_main_file_custom}" ]]; then
-		_bash-it-log-prefix-by-path "${_bash_it_main_file_custom}"
+		_bash_it_log_section="${_bash_it_custom_file}"
 		_log_debug "Loading custom file..."
 		# shellcheck disable=SC1090
 		source "$_bash_it_main_file_custom"
 	fi
-	BASH_IT_LOG_PREFIX="core: main: "
 done
+_bash_it_log_prefix_pop "custom"
 
 if [[ -n "${PROMPT:-}" ]]; then
+_log_trace "Setting prompt..."
 	PS1="${PROMPT}"
 fi
 
@@ -101,12 +99,6 @@ else
 	PREVIEW="less"
 fi
 
-# BASH_IT_RELOAD_LEGACY is set.
-if [[ -n "${BASH_IT_RELOAD_LEGACY:-}" ]] && ! _command_exists reload; then
-	# shellcheck disable=SC2139
-	alias reload="builtin source '${BASH_IT_BASHRC?}'"
-fi
-
 for _bash_it_library_finalize_f in "${_bash_it_library_finalize_hook[@]:-}"; do
 	eval "${_bash_it_library_finalize_f?}" # Use `eval` to achieve the same behavior as `$PROMPT_COMMAND`.
 done

lib/log.bash

@@ -2,6 +2,12 @@
 #
 # A collection of logging functions.
 
+# Avoid duplicate inclusion
+if [[ "${__bi_log_imported:-}" == "loaded" ]]; then
+	return 0
+fi
+__bi_log_imported="loaded"
+
 # Declare log severity levels, matching syslog numbering
 : "${BASH_IT_LOG_LEVEL_FATAL:=1}"
 : "${BASH_IT_LOG_LEVEL_ERROR:=3}"
@@ -11,8 +17,17 @@
 : "${BASH_IT_LOG_LEVEL_TRACE:=7}"
 readonly "${!BASH_IT_LOG_LEVEL_@}"
 
-function _bash-it-log-prefix-by-path() {
-	local component_path="${1?${FUNCNAME[0]}: path specification required}"
+declare -a __bash_it_log_prefix=("log" "${__bash_it_log_prefix[@]:-core}")
+
+function _bash_it_log_prefix_pop() {
+	_log_trace "End${1:+ (}${1:-}${1:+)}"
+	unset -v '__bash_it_log_prefix[0]'
+	__bash_it_log_prefix=("${__bash_it_log_prefix[@]:-default}")
+}
+
+function _bash_it_log_prefix_push() {
+	local component_path="${_bash_it_log_section:-${1:-default}}"
+	unset _bash_it_log_section
 	local without_extension component_directory
 	local component_filename component_type component_name
 
@@ -39,62 +54,78 @@ function _bash-it-log-prefix-by-path() {
 		fi
 	fi
 
-	# shellcheck disable=SC2034
-	BASH_IT_LOG_PREFIX="${component_type:-lib}: $component_name"
+	if [[ -r "$component_path" ]]; then
+		__bash_it_log_prefix=("${component_type:-default}: $component_name" "${__bash_it_log_prefix[@]}")
+	elif [[ -n "$component_path" ]]; then
+		__bash_it_log_prefix=("${component_name}" "${__bash_it_log_prefix[@]}")
+	fi
+	_log_trace "Begin" "${component_name}"
 }
 
 function _has_colors() {
 	# Check that stdout is a terminal, and that it has at least 8 colors.
 	[[ -t 1 && "${CLICOLOR:=$(tput colors 2> /dev/null)}" -ge 8 ]]
 }
 
-function _bash-it-log-message() {
-	: _about 'Internal function used for logging, uses BASH_IT_LOG_PREFIX as a prefix'
-	: _param '1: color of the message'
-	: _param '2: log level to print before the prefix'
-	: _param '3: message to log'
-	: _group 'log'
-
-	local prefix="${BASH_IT_LOG_PREFIX:-default}"
-	local color="${1-${echo_cyan:-}}"
-	local level="${2:-TRACE}"
-	local message="${level%: }: ${prefix%: }: ${3?}"
-	if _has_colors; then
-		printf '%b%s%b\n' "${color}" "${message}" "${echo_normal:-}"
-	else
-		printf '%s\n' "${message}"
-	fi
+function _bash_it_log_message() {
+	about 'Internal function used for logging, uses __bash_it_log_prefix as a prefix'
+	param '1: color of the message'
+	param '2: severity of the message'
+	param '3: message to log'
+	group 'log'
+
+	message="($SECONDS) $2: ${__bash_it_log_prefix[1]:-}${__bash_it_log_prefix[1]:+: }${__bash_it_log_prefix[0]:-default}: $3"
+	_has_colors && echo -e "$1${message}${echo_normal:-}" || echo -e "${message}"
+}
+
+function _log_trace() {
+	[[ "${BASH_IT_LOG_LEVEL:-0}" -ge ${BASH_IT_LOG_LEVEL_TRACE?} ]] || return 0
+
+	about 'log a message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_TRACE'
+	param '1: message to log'
+	param '2: message origin'
+	example '$ _log_trace "Entering theme plugin"'
+	group 'log'
+
+	_bash_it_log_message "${echo_blue:-}" "TRACE" "$1${2:+ (}${2:-}${2:+)}"
 }
 
 function _log_debug() {
-	: _about 'log a debug message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_INFO'
-	: _param '1: message to log'
-	: _example '$ _log_debug "Loading plugin git..."'
-	: _group 'log'
+	[[ "${BASH_IT_LOG_LEVEL:-0}" -ge ${BASH_IT_LOG_LEVEL_INFO?} ]] || return 0
 
-	if [[ "${BASH_IT_LOG_LEVEL:-0}" -ge "${BASH_IT_LOG_LEVEL_INFO?}" ]]; then
-		_bash-it-log-message "${echo_green:-}" "DEBUG: " "$1"
-	fi
+	about 'log a debug message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_INFO'
+	param '1: message to log'
+	example '$ _log_debug "Loading plugin git..."'
+	group 'log'
+
+	_bash_it_log_message "${echo_green:-}" "DEBUG" "$1"
 }
 
 function _log_warning() {
-	: _about 'log a message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_WARNING'
-	: _param '1: message to log'
-	: _example '$ _log_warning "git binary not found, disabling git plugin..."'
-	: _group 'log'
+	[[ "${BASH_IT_LOG_LEVEL:-0}" -ge ${BASH_IT_LOG_LEVEL_WARNING?} ]] || return 0
 
-	if [[ "${BASH_IT_LOG_LEVEL:-0}" -ge "${BASH_IT_LOG_LEVEL_WARNING?}" ]]; then
-		_bash-it-log-message "${echo_yellow:-}" " WARN: " "$1"
-	fi
+	about 'log a message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_WARNING'
+	param '1: message to log'
+	example '$ _log_warning "git binary not found, disabling git plugin..."'
+	group 'log'
+
+	_bash_it_log_message "${echo_yellow:-}" " WARN" "$1"
 }
 
 function _log_error() {
-	: _about 'log a message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_ERROR'
-	: _param '1: message to log'
-	: _example '$ _log_error "Failed to load git plugin..."'
-	: _group 'log'
+	[[ "${BASH_IT_LOG_LEVEL:-0}" -ge ${BASH_IT_LOG_LEVEL_ERROR?} ]] || return 0
 
-	if [[ "${BASH_IT_LOG_LEVEL:-0}" -ge "${BASH_IT_LOG_LEVEL_ERROR?}" ]]; then
-		_bash-it-log-message "${echo_red:-}" "ERROR: " "$1"
-	fi
+	about 'log a message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_ERROR'
+	param '1: message to log'
+	example '$ _log_error "Failed to load git plugin..."'
+	group 'log'
+
+	_bash_it_log_message "${echo_red:-}" "ERROR" "$1"
 }
+
+# Aliases have no scope, so we can manipulate the global environment.
+alias _log_clean_aliases_and_trap="trap - RETURN; unalias source . _log_clean_aliases_and_trap; _log_trace 'Log trace unregistered.'"
+_bash_it_library_finalize_hook+=('trap - RETURN' 'unalias source . _log_clean_aliases_and_trap' '_log_trace "Log trace unregistered."')
+alias source='_bash_it_log_prefix_push "${BASH_SOURCE##*/}" && builtin source'
+alias .=source
+trap _bash_it_log_prefix_pop RETURN

plugins/available/go.plugin.bash

@@ -29,4 +29,4 @@ _bash-it-gopath-pathmunge() {
 		pathmunge "${apath}/bin" || true
 	done
 }
-_bash-it-gopath-pathmunge
+_bash-it-gopath-pathmunge || true

plugins/available/ruby.plugin.bash

@@ -1,5 +1,4 @@
 # shellcheck shell=bash
-cite about-plugin
 about-plugin 'ruby and rubygems specific functions and settings'
 
 # Make commands installed with 'gem install --user-install' available

scripts/reloader.bash

@@ -2,11 +2,12 @@
 #
 # The core component loader.
 
+_log_debug "Loading..."
 # shellcheck disable=SC2034
-BASH_IT_LOG_PREFIX="core: reloader: "
 _bash_it_reloader_type=""
 
-if [[ "${1:-}" != "skip" ]] && [[ -d "${BASH_IT?}/enabled" ]]; then
+if [[ "${1:-}" != "skip" && -d "${BASH_IT?}/enabled" ]]; then
+	_log_trace "Loading enabled components..."
 	case $1 in
 		alias | completion | plugin)
 			_bash_it_reloader_type=$1
@@ -19,24 +20,25 @@ if [[ "${1:-}" != "skip" ]] && [[ -d "${BASH_IT?}/enabled" ]]; then
 
 	for _bash_it_reloader_file in "$BASH_IT/enabled"/*"${_bash_it_reloader_type}.bash"; do
 		if [[ -e "${_bash_it_reloader_file}" ]]; then
-			_bash-it-log-prefix-by-path "${_bash_it_reloader_file}"
+			_bash_it_log_section="${_bash_it_config_file}"
 			_log_debug "Loading component..."
-			# shellcheck source=/dev/null
 			source "$_bash_it_reloader_file"
 			_log_debug "Loaded."
 		else
 			_log_error "Unable to read ${_bash_it_reloader_file}"
 		fi
+	_log_trace "end: ${_bash_it_config_file##*/}"
 	done
 fi
 
 if [[ -n "${2:-}" ]] && [[ -d "$BASH_IT/${2}/enabled" ]]; then
+	_log_trace "Loading enabled $2 components..."
 	case $2 in
 		aliases | completion | plugins)
 			_log_warning "Using legacy enabling for $2, please update your bash-it version and migrate"
 			for _bash_it_reloader_file in "$BASH_IT/${2}/enabled"/*.bash; do
 				if [[ -e "$_bash_it_reloader_file" ]]; then
-					_bash-it-log-prefix-by-path "${_bash_it_reloader_file}"
+					_bash_it_log_section="${_bash_it_config_file}"
 					_log_debug "Loading component..."
 					# shellcheck source=/dev/null
 					source "$_bash_it_reloader_file"