Why does "bash -x" break this script?

Question

I have a script which measures how long some command executes.

It needs the "real" time command, meaning, a binary for example in /usr/bin/time (as the bash-built-in doesn't have the -fflag).

Below, a simplified script which can be debugged:

#!/bin/bash

TIMESEC=$(echo blah | ( /usr/bin/time -f %e grep blah >/dev/null ) 2>&1 | awk -F. '{print $1}')

echo ABC--$TIMESEC--DEF

if [ "$TIMESEC" -eq 0 ] ; then
   echo "we are here!"
fi

Save as "test.sh" and execute:

$ bash test.sh
ABC--0--DEF
we are here!

So it worked.

Now, let's try to debug this by adding "-x" to bash command line:

$ bash -x test.sh
++ echo blah
++ awk -F. '{print $1}'
+ TIMESEC='++ /usr/bin/time -f %e grep blah
0'
+ echo ABC--++ /usr/bin/time -f %e grep blah 0--DEF
ABC--++ /usr/bin/time -f %e grep blah 0--DEF
+ '[' '++ /usr/bin/time -f %e grep blah
0' -eq 0 ']'
test.sh: line 10: [: ++ /usr/bin/time -f %e grep blah
0: integer expression expected

Why does this script break when we're using "-x", and works fine without it?

Answer 1

The problem is this line:

TIMESEC=$(echo blah | ( /usr/bin/time -f %e grep blah >/dev/null ) 2>&1 | awk -F. '{print $1}')

where you are redirecting the standard error to match the standard output. bash is writing its trace-messages to the standard error, and is (for instance) using its built-in echo along with other shell constructs all in the bash process.

If you change it to something like

TIMESEC=$(echo blah | sh -c "( /usr/bin/time -f %e grep blah >/dev/null )" 2>&1 | awk -F. '{print $1}')

it will work around that problem, and perhaps be an acceptable compromise between tracing and working:

++ awk -F. '{print $1}'
++ sh -c '( /usr/bin/time -f %e grep blah >/dev/null )'
++ echo blah
+ TIMESEC=0                 
+ echo ABC--0--DEF
ABC--0--DEF
+ '[' 0 -eq 0 ']'
+ echo 'we are here!'
we are here!

Answer 2

you can also just drop the subshell. apparently it is the nested shells which wind up upsetting one another:

TIMESEC=$(
    echo blah |
    /usr/bin/time -f %e grep blah 2>&1 >/dev/null |
    awk -F. '{print $1}'
)

---

If you do:

---

...| ( subshell ) 2>pipe | ...

---

... you wind up with the subshell launched to handle that section of the pipeline hosting the subshell within. Because the shell without redirects even the debug output of the subshell within (as it would also do for any other kind of { compound command; } >redirect you might choose to use) to its section of the pipeline you wind up mixing streams. It has to do with the order of redirection.

Instead, if you simply first redirect only the error output of the commands you're attempting gauge, and let the host shell's output make it to stderr, you don't wind up with the same problem.

and so...

---

... | command 2>pipe 1>/dev/null | ...

---

...the host shell is free to continue writing its stderr where it pleases while only redirecting the output of the commands which it calls into the pipe.

---

bash -x time.sh
+++ echo blah
+++ /usr/bin/time -f %e grep blah
+++ awk -F. '{print $1}'
++ TIMESEC=0
++ echo ABC--0--DEF
ABC--0--DEF
++ '[' 0 -eq 0 ']'
++ echo 'we are here!'
we are here!

---

For that matter...

---

TIMESEC=$(
    echo blah |
    /usr/bin/time -f %e grep blah 2>&1 >/dev/null
)
printf %s\\n "ABC--${TIMESEC%%.*}--DEF"
if [ "${TIMESEC%%.*}" -eq 0 ] ; then
   echo "we are here!"
fi