Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Simple logging levels in Bash

THE ISSUE

I am struggling to adapt a logging function I've written and reused for years across many scripts to honor logging levels.

In short, I would like to use a single global variable to print only those logs which match the desired logging level verbosity.

CURRENTLY

My current code looks like so:

#################################################################################
# SCRIPT LOGGING CONFIGURATION
#
# The following is used by the script to output log data. Depending upon the log
# level indicated, more or less data may be output, with a "lower" level
# providing more detail, and the "higher" level providing less verbose output.
#################################################################################
DATETIME="`date +%Y-%m-%d` `date +%T%z`" # Date format at beginning of log entries to match RFC
DATE_FOR_FILENAME=`date +%Y%m%d`
#
SCRIPT_LOG_DIR="/var/log/company/${APP_NAME}/"
SCRIPT_LOGFILE="${SCRIPT_LOG_DIR}-APPNAME-${DATE_FOR_FILENAME}.log"
#
# Logging Level configuration works as follows:
# DEBUG - Provides all logging output
# INFO  - Provides all but debug messages
# WARN  - Provides all but debug and info
# ERROR - Provides all but debug, info and warn
#
# SEVERE and CRITICAL are also supported levels as extremes of ERROR
#
SCRIPT_LOGGING_LEVEL="DEBUG"
#################################################################################
#          ##      END OF GLOBAL VARIABLE CONFIGURATION      ##
#################################################################################
# LOGGING
#
# Calls to the logThis() function will determine if an appropriate log file
# exists. If it does, then it will use it, if not, a call to openLog() is made,
# if the log file is created successfully, then it is used.
#
# All log output is comprised of
# [+] An RFC 3339 standard date/time stamp
# [+] The declared level of the log output
# [+] The runtime process ID (PID) of the script
# [+] The log message
#################################################################################
function openLog {
    echo -e "${DATETIME} : PID $$ : INFO : New log file (${logFile}) created." >> "${SCRIPT_LOGFILE}"

    if ! [[ "$?" -eq 0 ]]
    then
        echo "${DATETIME} - ERROR : UNABLE TO OPEN LOG FILE - EXITING SCRIPT."
        exit 1
    fi
}

function logThis() {
    DATETIME=$(date --rfc-3339=seconds)
    if [[ -z "${1}" || -z "${2}" ]]
    then
        echo "${DATETIME} - ERROR : LOGGING REQUIRES A DESTINATION FILE, A MESSAGE AND A PRIORITY, IN THAT ORDER."
        echo "${DATETIME} - ERROR : INPUTS WERE: ${1} and ${2}."
        exit 1
    fi

    LOG_MESSAGE="${1}"
    LOG_PRIORITY="${2}"

    # Determine if logging level is supported and desired
    #
    # This seems more complex than may be necessary
    if [[ ${LOG_PRIORITY} -eq "DEBUG" ]] && [[ ${SCRIPT_LOGGING_LEVEL} -eq "DEBUG" ]]
    then
        LOG_PRIORITY_SUPPORTED=true
    elif [[ ${LOG_PRIORITY} -eq "INFO" ]] && [[ ${SCRIPT_LOGGING_LEVEL} -eq "DEBUG"||"INFO" ]]
    then
        LOG_PRIORITY_SUPPORTED=true
    elif [[ ${LOG_PRIORITY} -eq "WARN" ]] && [[ ${SCRIPT_LOGGING_LEVEL} -eq "DEBUG"||"INFO"||"WARN" ]]
    then
        LOG_PRIORITY_SUPPORTED=true
    elif [[ ${LOG_PRIORITY} -eq "ERROR"||"SEVERE"||"CRITICAL" ]] && [[ ${SCRIPT_LOGGING_LEVEL} -eq "DEBUG"||"INFO"||"WARN"||"ERROR"||"SEVERE"||"CRITICAL" ]]
    then
        LOG_PRIORITY_SUPPORTED=true
    else
        echo -e "CRITICAL: Declared log priority is not supported."
        exit 1
    fi

    # If logging level NOT supported, dump it
    if ! [ ${LOG_PRIORITY_SUPPORTED} ]
    then
        echo "priority unsupported"
        break
    fi

    # No log file, create it.
    if ! [[ -f ${SCRIPT_LOGFILE} ]]
    then
        echo -e "INFO : No log file located, creating new log file (${SCRIPT_LOGFILE})."
        echo "${DATETIME} : PID $$ :INFO : No log file located, creating new log file (${SCRIPT_LOGFILE})." >> "${SCRIPT_LOGFILE}"
        openLog
    fi

    # Write log details to file
    echo -e "${LOG_PRIORITY} : ${LOG_MESSAGE}"
    echo -e "${DATETIME} : PID $$ : ${LOG_PRIORITY} : ${LOG_MESSAGE}" >> "${SCRIPT_LOGFILE}"

    # Reset log level support flag
    LOG_PRIORITY_SUPPORTED=false
}

When using the function is becomes used as so:

logThis "This is my log message" "DEBUG"

or

logThis "This is my log message" "ERROR"

or

logThis "This is my log message" "INFO"

THE ATTEMPT

You can see in the code above that I have made an attempt (however complicated) at filtering messages using a case select on the message being passed in.

This does not work. All messages are getting through regardless of the value provided for LOG_PRIORITY.

Even if it's not a supported value. For example, the following still allows log messages to process:

SCRIPT_LOGGING_LEVEL="FARCE"

Or even if I set the value for a given message like so:

logThis "This is my log message" "FARCE"

YOUR HELP

I'm not looking to completely refactor the functions I have. I have too many scripts in the wild using the functions involved and it would require rework of those as well if I alter the standardization.

I don't necessarily need someone to "do the work for me" as they say, but a nudge in an effective direction given my constrains would be sufficient. I will be excited to post the final implementation in a future edit.

UNDERSTOOD

I recognize there are newer and better ways to handle logging functionality in BASH scripts now, but the prevalence of these functions across so many scripts means a simple update to the functions in play will have very broad impact.

===

FINAL SOLUTION

To close the loop on this question, the final solution includes a few changes which weren't originally in-scope, but to meet some better practices I did the following:

  1. Converted all variable names to being mixed case vs ALL CAPS which is reserved for the system and environment variables. This was noted by a couple commenters (@PesaThe and @CharlesDuffy).
  2. My original post noted I used a case select initially, but showed a collection of if and elif statements. I did attempt a case select previously, but had moved on to the upkeep-heavy and illegible if + elif option out of frustration.
  3. The change in code allowed for the removal (as suggested by @PesaThe) of an unclean variable reset at the end of the function.

SOLUTION DETAILS

This solution meets my requirements because it requires the least changes to existing script code and permits the existing method of calling the function to work.

At the time of the acceptance of a solution, there were three recommended options in response to my post. All three options were helpful and on point, but the one I ultimately chose required only three lines of code to implement.

As noted above, I did make some changes which were not in-scope but which did not impact functionality outside the code provided in this post.

One additional note: I did validate these functions in my target environment and they work as desired on Ubuntu 16.04 at the time of this edit.

FINAL CODE

#################################################################################
# SCRIPT LOGGING CONFIGURATION
#
# The following is used by the script to output log data. Depending upon the log
# level indicated, more or less data may be output, with a "lower" level
# providing more detail, and the "higher" level providing less verbose output.
#################################################################################
dateTime="`date +%Y-%m-%d` `date +%T%z`" # Date format at beginning of log entries to match RFC
dateForFileName=`date +%Y%m%d`
#
scriptLogDir="/var/log/company/${appName}/"
scriptLogPath="${scriptLogDir}${appName}-${dateForFileName}.log"
#
# Logging Level configuration works as follows:
# DEBUG - Provides all logging output
# INFO  - Provides all but debug messages
# WARN  - Provides all but debug and info
# ERROR - Provides all but debug, info and warn
#
# SEVERE and CRITICAL are also supported levels as extremes of ERROR
#
scriptLoggingLevel="DEBUG"
#################################################################################
#          ##      END OF GLOBAL VARIABLE CONFIGURATION      ##
#################################################################################
# LOGGING
#
# Calls to the logThis() function will determine if an appropriate log file
# exists. If it does, then it will use it, if not, a call to openLog() is made,
# if the log file is created successfully, then it is used.
#
# All log output is comprised of
# [+] An RFC 3339 standard date/time stamp
# [+] The declared level of the log output
# [+] The runtime process ID (PID) of the script
# [+] The log message
#################################################################################
function openLog {
    echo -e "${dateTime} : PID $$ : INFO : New log file (${scriptLogPath}) created." >> "${scriptLogPath}"

    if ! [[ "$?" -eq 0 ]]
    then
        echo "${dateTime} - ERROR : UNABLE TO OPEN LOG FILE - EXITING SCRIPT."
        exit 1
    fi
}

function logThis() {
    dateTime=$(date --rfc-3339=seconds)

    if [[ -z "${1}" || -z "${2}" ]]
    then
        echo "${dateTime} - ERROR : LOGGING REQUIRES A DESTINATION FILE, A MESSAGE AND A PRIORITY, IN THAT ORDER."
        echo "${dateTime} - ERROR : INPUTS WERE: ${1} and ${2}."
        exit 1
    fi

    logMessage="${1}"
    logMessagePriority="${2}"

    declare -A logPriorities=([DEBUG]=0 [INFO]=1 [WARN]=2 [ERROR]=3 [SEVERE]=4 [CRITICAL]=5)
    [[ ${logPriorities[$logMessagePriority]} ]] || return 1
    (( ${logPriorities[$logMessagePriority]} < ${logPriorities[$scriptLoggingLevel]} )) && return 2


    # No log file, create it.
    if ! [[ -f ${scriptLogPath} ]]
    then
        echo -e "INFO : No log file located, creating new log file (${scriptLogPath})."
        echo "${dateTime} : PID $$ :INFO : No log file located, creating new log file (${scriptLogPath})." >> "${scriptLogPath}"
        openLog
    fi

    # Write log details to file
    echo -e "${logMessagePriority} : ${logMessage}"
    echo -e "${dateTime} : PID $$ : ${logMessagePriority} : ${logMessage}" >> "${scriptLogPath}"
}
like image 485
Chris Giddings Avatar asked Jan 03 '18 23:01

Chris Giddings


People also ask

What are the five logging levels?

Logging levels explained. The most common logging levels include FATAL, ERROR, WARN, INFO, DEBUG, TRACE, ALL, and OFF.

Which logging level is best?

Higher values indicate higher priorities. As such, a rule might look for Error and Fatal messages by looking for values greater than or equal to 40,000 (Level>=40000). Inherit the level from the parent logger.

What does #$ mean in bash?

#$ does "nothing", as # is starting comment and everything behind it on the same line is ignored (with the notable exception of the "shebang"). $# prints the number of arguments passed to a shell script (like $* prints all arguments). Follow this answer to receive notifications.


1 Answers

One way to approach this is to create an associative array of all the levels. Each level is assigned a number and those numbers are then compared to decide whether you should log or not. Imagine you wanted to add another logging level. Those if statements of yours would get out of control:

#!/usr/bin/env bash

declare -A levels=([DEBUG]=0 [INFO]=1 [WARN]=2 [ERROR]=3)
script_logging_level="INFO"

logThis() {
    local log_message=$1
    local log_priority=$2

    #check if level exists
    [[ ${levels[$log_priority]} ]] || return 1

    #check if level is enough
    (( ${levels[$log_priority]} < ${levels[$script_logging_level]} )) && return 2

    #log here
    echo "${log_priority} : ${log_message}"
}

logThis "This will log" "WARN"
logThis "This will not log" "DEBUG"
logThis "This will not log" "OUCH"

LOG_PRIORITY_SUPPORTED=false is an example why you should use local variables in functions. Also, you shouldn't use uppercase variables as they could clash with environmental or internal shell variables.

like image 108
PesaThe Avatar answered Sep 16 '22 15:09

PesaThe