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 ERROR   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

Answer 2

You already have what seems to be the cleanest idea in your question (a wrapper function), but you seem to think it would be messy. I would suggest you reconsider. It could look like the following (not necessarily a full-fledged solution, just to give you the basic idea) :

#!/bin/bash

# Argument 1 : Logging level for that command
# Arguments 2... : Command to execute
# Output suppressed if command level >= current logging level 
log()
{
if
  (($1 >= logging_level))
then
  "${@:2}" >/dev/null 2>&1
else
  "${@:2}"
fi
}

logging_level=2

log 1 command1 and its args
log 2 command2 and its args
log 3 command4 and its args

You can arrange for any required redirection (with file descriptors if you want) to be handled in the wrapper function, so that the rest of the script remains readable and free from redirections and conditions depending on the selected logging level.

Answer 3

Solution 1. Consider using additional file descriptors. Redirect required file descriptors to STDOUT or /dev/null depending on selected verbosity. Redirect output of every statement in your script to a file descriptor corresponding to its importance. Have a look at https://unix.stackexchange.com/a/218355 .

Answer 4

Solution 2.

Set $required_verbosity and pipe STDOUT of every statement in your script to a helper script with two parameters, something like this:

statement | logger actual_verbosity $required_verbosity

In a logger script echo STDIN to STDOUT (or log file, whatever) if $actual_verbosity >= $required_verbosity.