How to modify call stack in Bash?

Question

Suppose I want to write a smart logging function log, that would read the line that is immediately after the log invocation and store it and its output in the log file. The function can find, read and execute the line of code that is in question. The problem is, that when the function returns, bash executes the line again.

Everything works fine except that assignment to BASH_LINENO[0] is silently discarded. Reading the http://wiki.bash-hackers.org/syntax/shellvars#bash_lineno I've learned that the variable is not read only.

function log()
{
        BASH_LINENO[0]=$((${BASH_LINENO[0]}+1))

        file=${BASH_SOURCE[1]##*/}
        linenr=$((${BASH_LINENO[0]} + 1 ))
        line=`sed "1,$((${linenr}-1)) d;${linenr} s/^ *//; q" $file`
        if [ -f /tmp/tmp.txt ]; then
            rm /tmp/tmp.txt
        fi
        exec 3>&1 4>&2 >>/tmp/tmp.txt 2>&1 
        set -x
        eval $line 
        exitstatus=$?
        set +x
        exec 1>&3 2>&4 4>&- 3>&-
        #Here goes the code that parses the /tmp/tmp.txt and stores it in the log
        if [ "$exitstatus" -ne "0" ]; then
            exit $exitstatus
        fi
}

#Test case:
log
echo "Unfortunately this line gets appended twice" | tee -a bla.txt;

Answer 1

After consulting the wisdom of users on bug-bash@gnu.org mailing list it appears that modifying the call stack is not possible, after all. Here is an answer I got from Chet Ramey:

BASH_LINENO is a call stack; assignments to it should be (and are) ignored. That's been the case since at least bash-3.2 (that's where I quit looking).

There is an indirect way to force bash to not execute the next command: set the extdebug option and have the DEBUG trap return a non-zero status.

The above technique works very well for my purposes. I am finally able to do a production version of the log function.

#!/bin/bash
shopt -s extdebug
repetition_count=0

_ERR_HDR_FMT="%.8s %s@%s:%s:%s"
_ERR_MSG_FMT="[${_ERR_HDR_FMT}]%s \$ "

msg() {
    printf "$_ERR_MSG_FMT" $(date +%T) $USER $HOSTNAME $PWD/${BASH_SOURCE[2]##*/} ${BASH_LINENO[1]}
    echo ${@}
}

function rlog()
{
    case $- in *x*) USE_X="-x";; *) USE_X=;; esac
    set +x
    if [ "${BASH_LINENO[0]}" -ne "$myline" ]; then
        repetition_count=0
        return 0; 
    fi
    if [ "$repetition_count" -gt "0" ]; then
        return -1; 
    fi
    if [ -z "$log" ]; then
        return 0
    fi
    file=${BASH_SOURCE[1]##*/}
    line=`sed "1,$((${myline}-1)) d;${myline} s/^ *//; q" $file`
    if [ -f /tmp/tmp.txt ]; then
        rm /tmp/tmp.txt
    fi
    echo "$line" > /tmp/tmp2.txt
    mymsg=`msg`
    exec 3>&1 4>&2 >>/tmp/tmp.txt 2>&1 
    set -x
    source /tmp/tmp2.txt
    exitstatus=$?
    set +x
    exec 1>&3 2>&4 4>&- 3>&-
    repetition_count=1 #This flag is to prevent multiple execution of the current line of code. This condition gets checked at the beginning of the function
    frstline=`sed '1q' /tmp/tmp.txt`
    [[ "$frstline" =~ ^(\++)[^+].*$ ]]
#   echo "BASH_REMATCH[1]=${BASH_REMATCH[1]}"
    eval 'tmp="${BASH_REMATCH[1]}"'
    pluscnt=$(( (${#tmp} + 1) *2 ))
    pluses="\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+\+"
    pluses=${pluses:0:$pluscnt}
    commandlines="`awk \" gsub(/^${pluses}\\s/,\\\"\\\")\" /tmp/tmp.txt`"
    n=0
    #There might me more then 1 command in the debugged line. The next loop appends each command to the log.
    while read -r line; do
        if [ "$n" -ne "0" ]; then
            echo "+ $line" >>$log
        else
            echo "${mymsg}$line" >>$log
            n=1
        fi
    done <<< "$commandlines"
    #Next line extracts all lines that are prefixed by sufficent number of "+" (usually 3), that are immidiately after the last line prefixed with $pluses, i.e. after the last command line.
    awk "BEGIN {flag=0} /${pluses}/ { flag=1 } /^[^+]/ { if (flag==1) print \$0; }" /tmp/tmp.txt | tee -a $log
    if [ "$exitstatus" -ne "0" ]; then
        echo "## Exit status: $exitstatus" >>$log
    fi
    echo >>$log
    if [ "$exitstatus" -ne "0" ]; then
        exit $exitstatus
    fi
    if [ -n "$USE_X" ]; then
        set -x
    fi
    return -1
}

log_next_line='eval if [ -n "$log" ]; then myline=$(($LINENO+1)); trap "rlog" DEBUG; fi;'
logoff='trap - DEBUG'

The usage of the file is intended as follows:

#!/bin/bash

log=mylog.log

if [ -f mylog.log ]; then
    rm mylog.log
fi

. ./log.sh
a=example
x=a

$log_next_line
echo "KUKU!"
$log_next_line
echo $x
$log_next_line
echo ${!x}
$log_next_line
echo ${!x} > /dev/null
$log_next_line
echo "Proba">/tmp/mtmp.txt
$log_next_line
touch ${!x}.txt
$log_next_line
if [ $(( ${#a} + 6 )) -gt 10 ]; then echo "Too long string"; fi
$log_next_line
echo "\$a and \$x">/dev/null
$log_next_line
echo $x
$log_next_line
ls -l
$log_next_line
mkdir /ddad/adad/dad #Generates an error

The output (`mylog.log):

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:14] $ echo 'KUKU!'
KUKU!

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:16] $ echo a
a

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:18] $ echo example
example

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:20] $ echo example

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:22] $ echo 1,2,3

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:24] $ touch example.txt

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:26] $ '[' 13 -gt 10 ']'
+ echo 'Too long string'
Too long string

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:28] $ echo '$a and $x'

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:30] $ echo a
a

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:32] $ ls -l
total 12
-rw-rw-r-- 1 adam adam   0 gru  4 13:39 example.txt
lrwxrwxrwx 1 adam adam  66 gru  4 13:29 log.sh -> /home/Adama-docs/Adam/Adam/MyDocs/praca/Puppet/bootstrap/common.sh
-rwxrwxr-x 1 adam adam 520 gru  4 13:29 log-test-case.sh
-rw-rw-r-- 1 adam adam 995 gru  4 13:39 mylog.log

[13:39:51 adam@adam-N56VZ:/home/Adama-docs/Adam/Adam/linux/tmp/log/log-test-case.sh:34] $ mkdir /ddad/adad/dad
mkdir: cannot create directory ‘/ddad/adad/dad’: No such file or directory
## Exit status: 1

The standard output is unchanged.

Limitations

Limitations are serious, unfortunately.

Exit code of logged command gets discarded

First of all, the exit code of the logged command is discarded, so user cannot test for it in the next statement. The current code exits the script if there was an error (which I believe is the best behavior). It is possible to modify the script to test

Limited support for bash tracing

The function honors bash tracing with -x. If it finds that the user traces output, it temporarily disables the output (as it would interfere with the trace anyway), and restores it back at the end. Unfortunately, it also appends a few extra lines to the trace.

Unless user turns off logging (with $logoff) there is a considerable speed penalty for all commands after the first $log_next_line, even if no logging takes place.

In ideal world the function should disable debug trapping (trap - DEBUG) after each invocation. Unfortunately I don't know how to do it, so beginning with the first $log_next_line macro, interpretation of each line invokes a custom function.

I use this function before every key command in my complex bootstrapping scripts. With it I can see what exactly and when was executed and what was the output, without the need to really understand the logic of the lengthy and sometimes messy scripts.