How do I manage log verbosity inside a shell script?

Question

I have a pretty long bash script that invokes quite a few external commands (git clone, wget, apt-get and others) that print a lot of stuff to the standard output.

I want the script to have a few verbosity options so it prints everything from the external commands, a summarized version of it (e.g. "Installing dependencies...", "Compiling...", etc.) or nothing at all. But how can I do it without cluttering up all my code?

I've thought about to possible solutions to this: One is to create a wrapper function that runs the external commands and prints what's needed to the standard output, depending on the options set at the start. This ones seems easier to implement, but it means adding a lot of extra clutter to the code.

The other solution is to send all the output to a couple of external files and, when parsing the arguments at the start of the script, running tail -f on that file if verbosity is specified. This would be very easy to implement, but seems pretty hacky to me and I'm concerned about the performance impact of it.

Which one is better? I'm also open to other solutions.

Answer 1

Improving on @Fred's idea a little bit more, we could build a small logging library this way:

declare -A _log_levels=([FATAL]=0 [ERROR]=1 [WARN]=2 [INFO]=3 [DEBUG]=4 [VERBOSE]=5)
declare -i _log_level=3
set_log_level() {
  level="${1:-INFO}"
  _log_level="${_log_levels[$level]}"
}

log_execute() {
  level=${1:-INFO}
  if (( $1 >= ${_log_levels[$level]} )); then
    "${@:2}" >/dev/null
  else
    "${@:2}"
  fi
}

log_fatal()   { (( _log_level >= ${_log_levels[FATAL]} ))   && echo "$(date) FATAL  $*";  }
log_error()   { (( _log_level >= ${_log_levels[ERROR]} ))   && echo "$(date) ERROR  $*";  }
log_warning() { (( _log_level >= ${_log_levels[WARNING]} )) && echo "$(date) WARNING  $*";  }
log_info()    { (( _log_level >= ${_log_levels[INFO]} ))    && echo "$(date) INFO   $*";  }
log_debug()   { (( _log_level >= ${_log_levels[DEBUG]} ))   && echo "$(date) DEBUG  $*";  }
log_verbose() { (( _log_level >= ${_log_levels[VERBOSE]} )) && echo "$(date) VERBOSE $*"; }

# functions for logging command output
log_debug_file()   { (( _log_level >= ${_log_levels[DEBUG]} ))   && [[ -f $1 ]] && echo "=== command output start ===" && cat "$1" && echo "=== command output end ==="; }
log_verbose_file() { (( _log_level >= ${_log_levels[VERBOSE]} )) && [[ -f $1 ]] && echo "=== command output start ===" && cat "$1" && echo "=== command output end ==="; }

Let's say the above source is in a library file called logging_lib.sh, we could use it in a regular shell script this way:

#!/bin/bash

source /path/to/lib/logging_lib.sh

set_log_level DEBUG

log_info  "Starting the script..."

# method 1 of controlling a command's output based on log level
log_execute INFO date

# method 2 of controlling the output based on log level
date &> date.out
log_debug_file date.out

log_debug "This is a debug statement"
...
log_error "This is an error"
...
log_warning "This is a warning"
...
log_fatal "This is a fatal error"
...
log_verbose "This is a verbose log!"

Will result in this output:

Fri Feb 24 06:48:18 UTC 2017 INFO    Starting the script...
Fri Feb 24 06:48:18 UTC 2017
=== command output start ===
Fri Feb 24 06:48:18 UTC 2017
=== command output end ===
Fri Feb 24 06:48:18 UTC 2017 DEBUG   This is a debug statement
Fri Feb 24 06:48:18 UTC 2017 ERROR   This is an error
Fri Feb 24 06:48:18 UTC 2017 WARNING   This is a warning
Fri Feb 24 06:48:18 UTC 2017 FATAL   This is a fatal error

As we can see, log_verbose didn't produce any output since the log level is at DEBUG, one level below VERBOSE. However, log_debug_file date.out did produce the output and so did log_execute INFO, since log level is set to DEBUG, which is >= INFO.

Using this as the base, we could also write command wrappers if we need even more fine tuning:

git_wrapper() {
  # run git command and print the output based on log level
}

With these in place, the script could be enhanced to take an argument --log-level level that can determine the log verbosity it should run with.

---

Here is a complete implementation of logging for Bash, rich with multiple loggers:

https://github.com/codeforester/base/blob/master/lib/stdlib.sh

---

If anyone is curious about why some variables are named with a leading underscore in the code above, see this post:

• Correct Bash and shell script variable capitalization