bbbash_logging.sh

#!/usr/bin/env bash
# Copyright 2016 Postmates Inc.
#
# Author: Benjamin Staffin
#
# Logging library for bash scripts
#
# Features:
#   * Nicely formatted messages with timestamp, source file and line number
#   * Stack traces on abnormal exits, similar to Python
#   * Numeric comparison asserts, useful for validating function args
#
# Requires Bash >= 4.2

((${__lib_log_loaded:-})) && return  # Include guard

# Log messages above this threshold will be suppressed
# (Higher severity --> higher number, like in Python)
declare -i BBBASH_LOG_THRESHOLD=${BBBASH_LOG_THRESHOLD:-10}

declare -A __bbbash_log_levels=(
  ['DEBUG']=0
  ['INFO']=10
  ['WARN']=20
  ['ERROR']=30
  ['FATAL']=40
)

# Numeric assert helpers:
function CHECK_EQ { log::check_compare "$1" EQ "$2"; }
function CHECK_LE { log::check_compare "$1" LE "$2"; }
function CHECK_LT { log::check_compare "$1" LT "$2"; }
function CHECK_GE { log::check_compare "$1" GE "$2"; }
function CHECK_GT { log::check_compare "$1" GT "$2"; }
function CHECK_NE { log::check_compare "$1" NE "$2"; }

function log::check_compare {
  if [[ $# -ne 3 ]]; then
    log::error "Invalid arguments to $0"
    return 1
  fi
  val1=$1 op=$2 val2=$3
  case $op in
    LE|'<=') op='<=' ;;
    LT|'<' ) op='<'  ;;
    GE|'>=') op='>=' ;;
    GT|'>' ) op='>'  ;;
    EQ|'==') op='==' ;;
    NE|'!=') op='!=' ;;
    *) log::error "Invalid comparison operator '$op'"; return 1 ;;
  esac
  if ! eval "(( $val1 $op $val2 ))"; then
    log::error "Assertion failed: $val1 ! $op $val2"
    return 1
  fi
}

# Trivial LOG wrappers.
function log::debug   { __log::t DEBUG "$@"; }
function log::info    { __log::t INFO  "$@"; }
function log::warn    { __log::t WARN  "$@"; }
function log::warning { __log::t WARN  "$@"; }
function log::error   { __log::t ERROR "$@"; }
# NOTE: log::fatal actually terminates the script!
function log::fatal   { __log::t FATAL "$@"; exit 1; }

# Format and log a message to stderr.
#
# It is recommended that you use the log::<level> wrapper functions
# rather than calling this directly.
#
# Examples:
#   LOG INFO "this is an info log"
#   LOG WARN "you can use printf stuff: %s %s" "$thing1" "$thing2"
#
# Usage:
#   LOG <level> <message> [formatarg...]
function LOG {
  CHECK_GE $# 2
  local level=$1 msg=$2
  shift 2
  level_n=${__bbbash_log_levels[$level]:-$level}
  if ! [[ $level_n =~ [0-9]+ ]]; then
    LOG ERROR "Invalid log level '$level'"
    return 1
  elif ((level_n < BBBASH_LOG_THRESHOLD)); then
    return
  fi
  declare -i tb_skip=$((${tb_skip:-0}+1))

  # Apply format string args, if any
  (($#)) && printf -v msg "$msg" "$@"

  printf '%(%Y-%m-%d %H:%M:%S)T %s %s:%s] %s\n' \
      -1 \
      "$level" \
      "${BASH_SOURCE[$tb_skip]##*/}" \
      "${BASH_LINENO[$((tb_skip-1))]}" \
      "$msg" \
      >&2
  # -1 is equivalent to `date +%s`
}

# Run a command after INFO logging it
function log::run {
  declare -i tb_skip=${tb_skip:-0}
  tb_skip+=1
  printf -v escaped_cmd ' %q' "$@"
  log::info "Running:$escaped_cmd"
  "$@"
}

# Print a formatted stack trace to stdout.
# You generally don't need to call this directly, but it's available.
function log::print_traceback {
  local fmt_tb
  tb_skip=$((${tb_skip:-0}+1)) __log::get_stack
  printf -v fmt_tb '%s\n' "${STACK[@]}"
  # Mention bash in the header avoid confusing people
  printf 'Bash traceback (most recent call last):\n%s' "$fmt_tb"
}

###
### Private functions below here
###

# The log::<level> wrappers can't be aliases unless we add
# `shopt -s expand_aliases` which may result in weird things happening if users
# have aliases in their environment
function __log::t { tb_skip=$((${tb_skip:-0}+2)) LOG "$@"; }

# Populate the variable STACK with a formatted stack trace.
# If tb_skip is non-zero, skip that many lines of the trace.
function __log::get_stack {
  declare -g STACK=()

  # Omit innermost frame (this function itself)
  declare -i tb_skip=$((${tb_skip:-0}+1))

  local i
  local stack_size=${#FUNCNAME[@]}
  for (( i=stack_size; i>=tb_skip; i-- )); do
    local func=${FUNCNAME[$i]:+${FUNCNAME[$i]}()}
    local lineno=${BASH_LINENO[$((i - 1))]}
    local src=${BASH_SOURCE[$i]:-<stdin>}

    # Outermost stack frame is only meaningful if the entrypoint came from
    # bash -c "script...", so skip it otherwise
    if ((i != stack_size)) || [[ -n ${BASH_EXECUTION_STRING:-} ]]; then
      STACK+=("  File \"$src\", line $lineno, in ${func:-<none>}")
    fi
  done
}

# Print a python-like traceback on abnormal exit
# (when errexit is set and this is registered as an ERR handler)
function __log::trap_err {
  local ret=$? cmd=$BASH_COMMAND
  tb_skip=1 log::print_traceback
  printf "    %s\n" "$cmd"
  return $ret
}
trap __log::trap_err ERR

# Keep the ERR trap registred after sourcing this file
set -o errtrace

readonly __lib_log_loaded=1  # Include guard