Efficient Logging Mechanism in Shell ( log4sh )

Shell script is powerful, quick, easy to write and gets your work done. But the real problem is when you want to figure out the failure point in your script. With any compiled language, its easy to identify code flaws / exceptions / errors using good amount of logging statements. However, shell script is an interpreted (not compiled) language and the only way to debug it, is by adding echo statements to your scripts and then either display it on console or re-direct it to some log file.

Lets look at richness of logging statements in a compiled language like JAVA or C++. To begin with, System.out.println outputs to standard output, which typically is a console window. The output from Log4j can go to the console, but it can also go to an email server, a database table, a log file, or various other destinations.

Another benefit of Log4j is that we can set different levels of logging based on the depth of analysis needed. The levels are hierarchical and are as follows: TRACE, DEBUG, INFO, WARN, ERROR, and FATAL. Shown below are sample logs using a log4j library:

2016-02-25 20:52:39 [DEBUG]    This is debug
2016-02-25 20:52:39 [INFO]        This is info
2016-02-25 20:52:39 [WARN]      This is warn
2016-02-25 20:52:39 [ERROR]    This is error
2016-02-25 20:52:39 [FATAL]      This is fatal

Similar level of logging mechanism for shell scripts is difficult to achieve since we can only write echo "some string" type of statements. Well, I mentioned it previously also "shell scripts are powerful and gets your work done". Let's try to simulate a similar behaviour for logging in shell scripts.

Expected format:
TimeStamp    LogLevel   Message

We need to create three common functions with names INFO, DEBUG, ERROR as part of the logger.sh helper script. We also need a way to track which function of which script is being invoked, just like the finest level of debugging in JAVA. Below is the helper script:

#!/bin/sh

SCRIPT_LOG=/home/cubicrace/SystemOut.log
touch $SCRIPT_LOG

function SCRIPTENTRY(){
 timeAndDate=`date`
 script_name=`basename "$0"`
 script_name="${script_name%.*}"
 echo "[$timeAndDate] [DEBUG]  > $script_name $FUNCNAME" >> $SCRIPT_LOG
}

function SCRIPTEXIT(){
 script_name=`basename "$0"`
 script_name="${script_name%.*}"
 echo "[$timeAndDate] [DEBUG]  < $script_name $FUNCNAME" >> $SCRIPT_LOG
}

function ENTRY(){
 local cfn="${FUNCNAME[1]}"
 timeAndDate=`date`
 echo "[$timeAndDate] [DEBUG]  > $cfn $FUNCNAME" >> $SCRIPT_LOG
}

function EXIT(){
 local cfn="${FUNCNAME[1]}"
 timeAndDate=`date`
 echo "[$timeAndDate] [DEBUG]  < $cfn $FUNCNAME" >> $SCRIPT_LOG
}


function INFO(){
 local function_name="${FUNCNAME[1]}"
    local msg="$1"
    timeAndDate=`date`
    echo "[$timeAndDate] [INFO]  $msg" >> $SCRIPT_LOG
}


function DEBUG(){
 local function_name="${FUNCNAME[1]}"
    local msg="$1"
    timeAndDate=`date`
 echo "[$timeAndDate] [DEBUG]  $msg" >> $SCRIPT_LOG
}

function ERROR(){
 local function_name="${FUNCNAME[1]}"
    local msg="$1"
    timeAndDate=`date`
    echo "[$timeAndDate] [ERROR]  $msg" >> $SCRIPT_LOG
}

FUNCNAME: 

1. Its a global internal variable maintained by any linux shell. 
2. Its of type array and consists the name of the current function from where we are trying to read its value. 
3. FUNCNAME[0] is the current function name and FUNCNAME[1] is the previous function name and so on ... Its a stack-trace of functions executed by a shell script. 
4. Value of FUNCNAME gets cleared every-time we execute a new shell script.

How to use this log helper using a simple demo.sh:

#!/bin/sh

source ./logger.sh
SCRIPTENTRY
updateUserDetails(){
    ENTRY
    DEBUG "Username: $1, Key: $2"
    INFO "User details updated for $1"
    EXIT
}

INFO "Updating user details..."
updateUserDetails "cubicrace" "3445"

rc=2

if [ ! "$rc" = "0" ]
then
    ERROR "Failed to update user details. RC=$rc"
fi
SCRIPTEXIT

Execution output for demo.sh:
cat /home/cubicrace/SystemOut.log

[Tue Sep 27 20:13:50 IST 2016]    [DEBUG]        > demo SCRIPTENTRY
[Tue Sep 27 20:13:50 IST 2016]    [INFO]            Updating user details...
[Tue Sep 27 20:13:50 IST 2016]    [DEBUG]        > updateUserDetails ENTRY
[Tue Sep 27 20:13:50 IST 2016]    [DEBUG]        Username: cubicrace, Key: 3445
[Tue Sep 27 20:13:50 IST 2016]    [INFO]            User details updated for cubicrace
[Tue Sep 27 20:13:50 IST 2016]    [DEBUG]        < updateUserDetails EXIT
[Tue Sep 27 20:13:50 IST 2016]    [ERROR]         Failed to update user details. RC=2
[Tue Sep 27 20:13:50 IST 2016]    [DEBUG]        < demo SCRIPTEXIT