logging bash scripts with verbose and xtrace (set -vx) and customizing PS4

Question

I am trying to configure PS4 for better xtrace output when I also have verbose set for verbose mode. Several of the things I would like to do spawn subshells but I want to see any -x or -v output for those operations because they would print for every line.

I also wanted to get rid of the nesting/indirection depth level indicator (+) because I want the trace output to be aligned.

My initial idea was:

BACKSPACES=$'\b\b\b\b\b\b\b\b'
PS4='+`printf "%s[\t] %-16.16s:%03d (%-16.16s) $ " ${BACKSPACES:0:$BASH_SUBSHELL} $(basename $BASH_SOURCE) $LINENO ${FUNCNAME[0]:+${FUNCNAME[0]}}`'

The first problem I ran into was that $BASH_SUBSHELL doesn't always seem to be the same as the number of +'s that would print. Looking into $SHLVL didn't help either.

echo $X
+ 0 2 $ echo x <-- toplevel prints one + and $BASH_SUBSHELL is 0, as expected
x

( echo subshell )
+ 1 2 $ echo subshell <-- $BASH_SUBSHELL increments to 1 as expected, but why only one + instead of two ++?

source ./test2.sh
+ 0 2 $ source ./test2.sh
echo $X$X$X$X
++ 0 2 $ echo xxxx <-- ??? is $BASH_SUBSHELL relative to the current file or something but the + indicators are not???
xxxx
subshell

I think I have gotten around this by forgetting about using $BASH_SUBSHELL and instead making the first character in PS4 an unprintable one but I'd still like to know why $BASH_SUBSHELL isn't what I expect.

To work around the issue with subshells being created within PS4, I looked an equivalent of PS1's PROMPT_COMMAND but didn't find anything except some indications on how to implement it myself.

The best way I thought I found was to trap the DEBUG signal.

trap 'debugfun $BASH_SOURCE' DEBUG

Of course, the -vx options also apply to calls to debugfun. My solution to suppress that output was to wrap the function's steps in set +vx and set -vx.

debugfun() {
  set +vx
  VAR=`basename $1 .sh`
  set -vx
}

Now... I had to deal with the matter of every call printing:

debugfun $BASH_SOURCE <-- from -v
++ debugfun ./test.sh <-- from -x
++ set +vx <-- from -x

I'm not sure why -v doesn't cause a print on the "set +vx" line either. I thought -T option might do that but it didn't.

Anyway, I thought the output was always going to consistent so all I had to do was erase those 3 lines from within debugfun. My ugly solution was to add this line after the "set +vx":

printf "\b\r\033[K\b\r\033[K\b\r\033[K" # clear previous 3 lines

It worked!

... Except when I pipe more than once.

I'll remove the printf line to show why:

echo $X$X | sed 's/x/y/' # pipe once... debugfun is called every time before each pipe component
debugfun $BASH_SOURCE
++ debugfun ./test.sh
++ set +vx
debugfun $BASH_SOURCE
++ debugfun ./test.sh
++ set +vx
+ echo xx
+ sed s/x/y/

echo $X$X$X | sed 's/x/y/' | sed 's/y/x/' # pipe twice 
debugfun $BASH_SOURCE
++ debugfun ./test.sh
++ set +vx
debugfun $BASH_SOURCE
++ debugfun ./test.sh
++ set +vx
+ echo xxx 
+ sed s/x/y/ # because this line is here, clearing 3 previous lines from the next "set +vx" would clear it
debugfun $BASH_SOURCE
++ debugfun ./test.sh
++ set +vx
+ sed s/y/x/
xxx

I did, finally, come up with this solution but I think it's really ugly and, while close, isn't exactly what I want:

SPACES="                        "
PS4='^@\[\e[31m\]+ [\t] \
${SPACES:0:$((${#BASH_SOURCE} > 24 ? 0 : 24 - ${#BASH_SOURCE}))}${BASH_SOURCE:$((${#BASH_SOURCE} < 24 ? 0 : -24))}:\
${SPACES:0:$((3-${#LINENO}))}$LINENO \
${FUNCNAME:-${SPACES:0:20}}${FUNCNAME:+${SPACES:0:$((20 - ${#FUNCNAME}))}} \
$ \[\e[0m\]'

The main thing I don't like is that I can't nest the bash string manipulations to not only reverse truncate $BASH_SOURCE, but to get it's basename without a subshell (i.e. combine with echo ${BASH_SOURCE##*/})

I'm out of ideas and would appreciate and clarification or tips on how to accomplish what I'm trying to do.

GNU bash, version 4.1.2(1)-release (x86_64-redhat-linux-gnu)

Answer 1

I'd suggest forgoing PS4 and doing all trace output in a DEBUG trap. Most, if not all the information -x prints is available elsewhere. See BASH_SOURCE, BASH_LINENO, FUNCNAME and BASH_COMMAND.

Like this:

function trace()
{
    echo "TRACE" \
         "${BASH_SOURCE[1]}:${BASH_LINENO[0]}:${FUNCNAME[1]}:" \
         "$BASH_COMMAND"
}

set -o functrace
shopt -s extdebug
trap trace DEBUG