Add load/reloader logs

DEVELOPMENT.md

@@ -4,12 +4,19 @@ This page summarizes a couple of rules to keep in mind when developing features
 
 ## Debugging and Logging
 
+### General Logging
+
 While developing feature or making changes in general, you can log error/warning/debug
 using `_log_error` `_log_warning` and `_log_debug`. This will help you solve problems quicker
 and also propagate important notes to other users of Bash-it.
 You can see the logs by using `bash-it doctor` command to reload and see the logs.
 Alternatively, you can set `BASH_IT_LOG_LEVEL` to `BASH_IT_LOG_LEVEL_ERROR`, `BASH_IT_LOG_LEVEL_WARNING` or `BASH_IT_LOG_LEVEL_ALL`.
 
+### Log Prefix/Context
+
+You can define `BASH_IT_LOG_PREFIX` in your files in order to a have a constant prefix before your logs.
+Note that we prefer to uses "tags" based logging, i.e `plugins: git: DEBUG: Loading git plugin`.
+
 
 ## Load Order
 

bash_it.sh

@@ -1,37 +1,49 @@
 #!/usr/bin/env bash
 # Initialize Bash It
+BASH_IT_LOG_PREFIX="core: main: "
 
 # Only set $BASH_IT if it's not already set
 if [ -z "$BASH_IT" ];
 then
   # Setting $BASH to maintain backwards compatibility
-  # TODO: warn users that they should upgrade their .bash_profile
   export BASH_IT=$BASH
   BASH="$(bash -c 'echo $BASH')"
   export BASH
+  BASH_IT_OLD_BASH_SETUP=true
 fi
 
+# Load composure first, so we support function metadata
+# shellcheck source=./lib/composure.bash
+source "${BASH_IT}/lib/composure.bash"
+# We need to load logging module first as well in order to be able to log
+# shellcheck source=./lib/log.bash
+source "${BASH_IT}/lib/log.bash"
+
+# We can only log it now
+[ -z "$BASH_IT_OLD_BASH_SETUP" ] || _log_warning "BASH_IT variable not initialized, please upgrade your bash-it version and reinstall it!"
+
 # For backwards compatibility, look in old BASH_THEME location
 if [ -z "$BASH_IT_THEME" ];
 then
-  # TODO: warn users that they should upgrade their .bash_profile
+  _log_warning "BASH_IT_THEME variable not initialized, please upgrade your bash-it version and reinstall it!"
   export BASH_IT_THEME="$BASH_THEME";
   unset BASH_THEME;
 fi
 
-# Load composure first, so we support function metadata
-# shellcheck source=./lib/composure.bash
-source "${BASH_IT}/lib/composure.bash"
-
 # support 'plumbing' metadata
 cite _about _param _example _group _author _version
 
 # libraries, but skip appearance (themes) for now
+_log_debug "Loading libraries(except appearance)..."
 LIB="${BASH_IT}/lib/*.bash"
 APPEARANCE_LIB="${BASH_IT}/lib/appearance.bash"
 for _bash_it_config_file in $LIB
 do
   if [ "$_bash_it_config_file" != "$APPEARANCE_LIB" ]; then
+    filename=${_bash_it_config_file##*/}
+    filename=${filename%.bash}
+    BASH_IT_LOG_PREFIX="lib: ${filename}: "
+    _log_debug "Loading library file..."
     # shellcheck disable=SC1090
     source "$_bash_it_config_file"
   fi
@@ -51,36 +63,51 @@ done
 
 # Load theme, if a theme was set
 if [[ ! -z "${BASH_IT_THEME}" ]]; then
+  _log_debug "Loading \"${BASH_IT_THEME}\" theme..."
   # Load colors and helpers first so they can be used in base theme
+  BASH_IT_LOG_PREFIX="themes: colors: "
   # shellcheck source=./themes/colors.theme.bash
   source "${BASH_IT}/themes/colors.theme.bash"
+  BASH_IT_LOG_PREFIX="themes: githelpers: "
   # shellcheck source=./themes/githelpers.theme.bash
   source "${BASH_IT}/themes/githelpers.theme.bash"
+  BASH_IT_LOG_PREFIX="themes: p4helpers: "
   # shellcheck source=./themes/p4helpers.theme.bash
   source "${BASH_IT}/themes/p4helpers.theme.bash"
+  BASH_IT_LOG_PREFIX="themes: base: "
   # shellcheck source=./themes/base.theme.bash
   source "${BASH_IT}/themes/base.theme.bash"
 
+  BASH_IT_LOG_PREFIX="lib: appearance: "
   # appearance (themes) now, after all dependencies
   # shellcheck source=./lib/appearance.bash
   source "$APPEARANCE_LIB"
 fi
 
-# Load custom aliases, completion, plugins
+BASH_IT_LOG_PREFIX="core: main: "
+_log_debug "Loading custom aliases, completion, plugins..."
 for file_type in "aliases" "completion" "plugins"
 do
   if [ -e "${BASH_IT}/${file_type}/custom.${file_type}.bash" ]
   then
+    BASH_IT_LOG_PREFIX="${file_type}: custom: "
+    _log_debug "Loading component..."
     # shellcheck disable=SC1090
     source "${BASH_IT}/${file_type}/custom.${file_type}.bash"
   fi
 done
 
 # Custom
+BASH_IT_LOG_PREFIX="core: main: "
+_log_debug "Loading general custom files..."
 CUSTOM="${BASH_IT_CUSTOM:=${BASH_IT}/custom}/*.bash ${BASH_IT_CUSTOM:=${BASH_IT}/custom}/**/*.bash"
 for _bash_it_config_file in $CUSTOM
 do
   if [ -e "${_bash_it_config_file}" ]; then
+    filename=$(basename "${_bash_it_config_file}")
+    filename=${filename%*.bash}
+    BASH_IT_LOG_PREFIX="custom: $filename"
+    _log_debug "Loading custom file..."
     # shellcheck disable=SC1090
     source "$_bash_it_config_file"
   fi

lib/appearance.bash

@@ -1,15 +1,5 @@
 #!/usr/bin/env bash
 
-function _has_colors()
-{
-    # Check that stdout is a terminal
-    test -t 1 || return 1
-
-    ncolors=$(tput colors)
-    test -n "$ncolors" && test "$ncolors" -ge 8 || return 1
-    return 0
-}
-
 # colored ls
 export LSCOLORS='Gxfxcxdxdxegedabagacad'
 

lib/helpers.bash

@@ -21,7 +21,7 @@ function _command_exists ()
   _param '1: command to check'
   _example '$ _command_exists ls && echo exists'
   _group 'lib'
-  type "$1" &> /dev/null ;
+  type "$1" &> /dev/null || (_log_warning "Command $1 does not exist!" && return 1) ;
 }
 
 function _make_reload_alias() {

lib/log.bash

@@ -4,45 +4,57 @@ export BASH_IT_LOG_LEVEL_ERROR=1
 export BASH_IT_LOG_LEVEL_WARNING=2
 export BASH_IT_LOG_LEVEL_ALL=3
 
-function _log_general()
+function _has_colors()
 {
-  _about 'Internal function used for logging'
-  _param '1: color of the message'
-  _param '2: message to log'
-  _group 'log'
+  # Check that stdout is a terminal
+  test -t 1 || return 1
+
+  ncolors=$(tput colors)
+  test -n "$ncolors" && test "$ncolors" -ge 8 || return 1
+  return 0
+}
 
-  _has_colors && echo -e "$1$2${echo_normal}" || echo -e "$2"
+function _log_general()
+{
+  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'
+
+  message=$2${BASH_IT_LOG_PREFIX}$3
+  _has_colors && echo -e "$1${message}${echo_normal}" || echo -e "${message}"
 }
 
 function _log_debug()
 {
-  _about 'log a debug message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_ALL'
-  _param '1: message to log'
-  _example '$ _log_debug "Loading plugin git..."'
-  _group 'log'
+  about 'log a debug message by echoing to the screen. needs BASH_IT_LOG_LEVEL >= BASH_IT_LOG_LEVEL_ALL'
+  param '1: message to log'
+  example '$ _log_debug "Loading plugin git..."'
+  group 'log'
 
-  [[ "$BASH_IT_LOG_LEVEL" -ge $BASH_IT_LOG_LEVEL_ALL ]] || return
-  _log_general "${echo_green}" "DEBUG: $1"
+  [[ "$BASH_IT_LOG_LEVEL" -ge $BASH_IT_LOG_LEVEL_ALL ]] || return 0
+  _log_general "${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'
+  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" -ge $BASH_IT_LOG_LEVEL_WARNING ]] || return
-  _log_general "${echo_yellow}" " WARN: $1"
+  [[ "$BASH_IT_LOG_LEVEL" -ge $BASH_IT_LOG_LEVEL_WARNING ]] || return 0
+  _log_general "${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'
+  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" -ge $BASH_IT_LOG_LEVEL_ERROR ]] || return
-  _log_general "${echo_red}" "ERROR: $1"
+  [[ "$BASH_IT_LOG_LEVEL" -ge $BASH_IT_LOG_LEVEL_ERROR ]] || return 0
+  _log_general "${echo_red}" "ERROR: " "$1"
 }

lib/utilities.bash

@@ -6,6 +6,24 @@
 # Generic utilies
 ###########################################################################
 
+_bash-it-get-component-name-from-path() {
+  # filename without path
+  filename=${1##*/}
+  # filename without path or priority
+  filename=${filename##*---}
+  # filename without path, priority or extension
+  echo ${filename%.*.bash}
+}
+
+_bash-it-get-component-type-from-path() {
+  # filename without path
+  filename=${1##*/}
+  # filename without path or priority
+  filename=${filename##*---}
+  # extension
+  echo ${filename} | cut -d '.' -f 2
+}
+
 # This function searches an array for an exact match against the term passed
 # as the first argument to the function. This function exits as soon as
 # a match is found.

scripts/reloader.bash

@@ -1,15 +1,26 @@
 #!/bin/bash
+BASH_IT_LOG_PREFIX="core: reloader: "
 pushd "${BASH_IT}" >/dev/null || exit 1
 
-# TODO: Add debugging output
+function _set-prefix-based-on-path()
+{
+  filename=$(_bash-it-get-component-name-from-path "$1")
+  extension=$(_bash-it-get-component-type-from-path "$1")
+  BASH_IT_LOG_PREFIX="$extension: $filename: "
+}
 
 if [ "$1" != "skip" ] && [ -d "./enabled" ]; then
   _bash_it_config_type=""
   if [[ "${1}" =~ ^(alias|completion|plugin)$ ]]; then
     _bash_it_config_type=$1
+    _log_debug "Loading enabled $1 components..."
+  else
+    _log_debug "Loading all enabled components..."
   fi
   for _bash_it_config_file in $(sort <(compgen -G "./enabled/*${_bash_it_config_type}.bash")); do
     if [ -e "${_bash_it_config_file}" ]; then
+      _set-prefix-based-on-path "${_bash_it_config_file}"
+      _log_debug "Loading component..."
       # shellcheck source=/dev/null
       source $_bash_it_config_file
     else
@@ -20,9 +31,11 @@ fi
 
 
 if [ ! -z "${2}" ] && [[ "${2}" =~ ^(aliases|completion|plugins)$ ]] && [ -d "${2}/enabled" ]; then
-  # TODO: We should warn users they're using legacy enabling
+  _log_warning "Using legacy enabling for $2, please update your bash-it version and migrate"
   for _bash_it_config_file in $(sort <(compgen -G "./${2}/enabled/*.bash")); do
     if [ -e "$_bash_it_config_file" ]; then
+      _set-prefix-based-on-path "${_bash_it_config_file}"
+      _log_debug "Loading component..."
       # shellcheck source=/dev/null
       source "$_bash_it_config_file"
     else

test/lib/helpers.bats

@@ -2,6 +2,7 @@
 
 load ../test_helper
 load ../../lib/composure
+load ../../lib/log
 load ../../lib/utilities
 load ../../lib/search
 load ../../plugins/available/base.plugin

test/lib/log.bats

@@ -77,3 +77,10 @@ load ../../lib/log
   run _log_error "test test test"
   refute_output
 }
+
+@test "lib log: logging with prefix" {
+  BASH_IT_LOG_LEVEL=$BASH_IT_LOG_LEVEL_ALL
+  BASH_IT_LOG_PREFIX="nice: prefix: "
+  run _log_debug "test test test"
+  assert_output "DEBUG: nice: prefix: test test test"
+}

test/themes/base.theme.bats

@@ -2,6 +2,7 @@
 
 load ../test_helper
 load ../../lib/composure
+load ../../lib/log
 
 cite _about _param _example _group _author _version
 

test/themes/base.theme.git.bats

@@ -2,6 +2,7 @@
 
 load ../test_helper
 load ../../lib/composure
+load ../../lib/log
 
 cite _about _param _example _group _author _version
 

test/themes/base.theme.svn.bats

@@ -2,6 +2,7 @@
 
 load ../test_helper
 load ../../lib/composure
+load ../../lib/log
 
 cite _about _param _example _group _author _version