kcov emits partial lines of Bash PS4 profiling data to stderr

[jack-rann]

For some bats based testing, extraneous debug lines will appear in kcov output. I noticed that the only tests which appeared to do this were using bats' assert_output --partial to validate output lines. Equivalent tests using bats' assert_line did not have the same issue. The following output is a very much simplified test suite to demonstrate the symptom seen:

$ ../build/src/kcov --dump-summary --include-path=src coverage bats test/sh.bats
1..2
ok 1 using assert_line
in func1
in func2
err: to stderr != *\a\r\g\s\:\ \t\e\s\t* ]]
in func1
in func2
err: to stderr != *\i\n\ \f\u\n\c\1* ]]
in func1
in func2
err: to stderr != *\i\n\ \f\u\n\c\2* ]]
in func1
in func2
err: to stderr != *\e\r\r\:\ \t\o\ \s\t\d\e\r\r* ]]
ok 2 using assert_output --partial
{
  "files": [
    {"file": "/Users/jrann/git/kcov/sample/src/app.sh", "percent_covered": "87.50"}
  ],
  "percent_covered": "87.50",
  "covered_lines": 7,
  "total_lines": 8
}
$ 

Note the using assert_line test does not generate this output, but it is present in the using assert_output --partial test.

This problem can be simplified and implemented without bats using the following Bash script gen.sh:

#!/usr/bin/env bash

multi_line="a
b
c
d"

# Echo single lines to stdout and stderr
echo >&1 "out: line 1"
echo >&1 "out: line 2"
echo >&2 "err: line 3"

# Echo multi-line to stdout and stderr
echo >&1 "out: $multi_line"
echo >&2 "err: $multi_line"

# Evaluate a multi-line string
if [[ $multi_line == *z* ]]; then
    echo >&2 "..."
fi

This script explicitly echoes single lines to both stdout and stderr, echoes a multi-line string to both stdout and stderr, and performs a logical comparison on a multi-line string. This last item mimics what bats' assert_output does.

Executing gen.sh by itself will generate the following output:

$ ./gen.sh
out: line 1
out: line 2
err: line 3
out: a
b
c
d
err: a
b
c
d
$ 

However, executing it via kcov will generate the following:

$ ../build/src/kcov --dump-summary --include-path=gen.sh coverage ./gen.sh
err: line 3
err: a
b
c
d
out: line 1
out: line 2
out: a
b
c
d
b
c
d == *z* ]]
{
  "files": [
    {"file": "/Users/jrann/git/kcov/sample/gen.sh", "percent_covered": "87.50"}
  ],
  "percent_covered": "87.50",
  "covered_lines": 7,
  "total_lines": 8
}
$ 

Two things to note about this output:

• The order of output lines is different. The err: lines appear ahead of out: lines.
• Extra output of b\nc\nd == *z* ]] is present.

The coverage statistics, however, are correct. Only the echo >&2 "..." line is not covered.

bash-engine.cc creates both stdoutPipe and stderrPipe. stdoutPipe is plumbed up to the child process' stdout, while stderrPipe is plumbed up to the child process' XTRACE file descriptor. Older Bash implementations will not support an XTRACE file descriptor and instead emit that information on stderr. Newer Bash implementations will support an XTRACE file descriptor separate from stderr.

We have 3 output streams from the child process:

• fd=1 stdout -> |stdoutPipe| -> kcov and emitted to stdout
• fd=2 stderr -> emitted directly to the terminal
• fd= XTRACE -> |stderrPipe| -> kcov and read/parsed for kcov@ markers, otherwise emitted to stderr

Making a small change to bash-engine.cc to annotate every line read from the child process' stderr stream allows us to see what is happening:

$ git diff
diff --git a/src/engines/bash-engine.cc b/src/engines/bash-engine.cc
index a4e8125..d61afb5 100644
--- a/src/engines/bash-engine.cc
+++ b/src/engines/bash-engine.cc
@@ -288,6 +288,7 @@ public:
                        return false;
 
                std::string cur(curLine);
+               fprintf(stdout, ">>>>>%s", cur.c_str());
                // Line markers always start with kcov@
 
                if (m_inputType == INPUT_SINGLE_QUOTE) {
$ 

Running this and redirecting kcov's stdout and stderr to separate files:

$ ../build/src/kcov --dump-summary --include-path=gen.sh coverage ./gen.sh 1>kcov.1 2>kcov.2

Looking at the kcov.2 stderr output we see the expected output along with the additional PS4 style debug information:

err: line 3
err: a
b
c
d
b
c
d == *z* ]]

Looking at the kcov.1 stdout stream we see the child's stdout and annotated lines read from the stderrPipe:

out: line 1
out: line 2
out: a
b
c
d
>>>>>kcov@./gen.sh@6@multi_line='a
>>>>>b
>>>>>c
>>>>>d'
>>>>>kcov@./gen.sh@9@echo 'out: line 1'
>>>>>kcov@./gen.sh@10@echo 'out: line 2'
>>>>>kcov@./gen.sh@11@echo 'err: line 3'
>>>>>kcov@./gen.sh@14@echo 'out: a
>>>>>b
>>>>>c
>>>>>d'
>>>>>kcov@./gen.sh@15@echo 'err: a
>>>>>b
>>>>>c
>>>>>d'
>>>>>kcov@./gen.sh@18@[[ a
>>>>>b
>>>>>c
>>>>>d == *z* ]]
{
  "files": [
    {"file": "/Users/jrann/git/kcov/sample/gen.sh", "percent_covered": "87.50"}
  ],
  "percent_covered": "87.50",
  "covered_lines": 7,
  "total_lines": 8
}

The annotated lines for ./gen.sh@14 and ./gen.sh@15 are in the middle of single quoted lines that bash-engine.cc essentially skips over. However the logical comparison at ./gen.sh@18 are not seen as a single quoted line. The 3 subsequent lines are not expected, and are emitted to stderr. This is likely done to support older Bash implementations which emit the PS4 profiling information on stderr.

A simple hack to ignore these extraneous lines appears to provide the desired behavior.

I wonder whether bash-engine.cc should even involve itself with the child process' stdout stream. It seems that this should be simply allowed to flow to the terminal, just as the stderr stream does when using a modern Bash implementation that supports a dedicated XTRACE file descriptor. However, the second part of handleStdout() references kcov@ coverage markers on older Bash implementations. I don't know whether that is still needed or not.