kcov bash-4.3 generates PS4 output with script that calls a script

[Mark-E-Hamilton]

Hi,
I've tracked down another oddness when using bash-4.3. I've got another set of test scripts:

% cat test1.sh
#!/bin/bash
./test2.sh
./test.py

% cat test.py
#!/usr/bin/env python
import subprocess
proc = subprocess.Popen('test2.sh', shell=True, stdin=None)
proc.wait()

% cat test2.sh
#!/bin/bash
echo Hi

When I run this with kcov and bash-4.1.2 I get only 'Hi' printed.

% kcov /tmp/kcov_out ./test1.sh
Hi
Hi

However, when I run it with bash-4.3 as the parser I get PS4 lines output.

% kcov --bash-parser=/projects/sierra/linux_rh6/install/utilities/bash/4.3/bin/bash /tmp/kcov_out ./test1.sh
kcov@./test2.sh@2@echo Hi
Hi
kcov@./test2.sh@2@echo Hi

If I add more statements to test2, I get more lines echoed. I also noticed that the output seems to be lost in the case where it goes through the python script. Although that might be an issue with the test, it seems to me they should both do the same thing.

[SimonKagstrom]

My guess is that this is a combination of the BASH_XTRACEFD fix and the --bash-parser= option: The test2.sh script gets executed with /bin/bash because it's called from the Python script (and I guess the same thing could happen from pure bash itself). In your case, this will be bash 4.1, so the PS4 stuff will end up on the console.

Probably it's possible to workaround this problem by running with

kcov --bash-parser=bash-4.3 --debug-forced-bash-stderr [other-args]

i.e., falling back to PS4 on stderr, which should work in both bash 4.3 and bash 4.1. I thought of the force-stderr stuff as a pure debugging option (I use it in the automatic tests for kcov itself), but because of this issue, I guess it would be better to make it a proper option. I'll commit that later, but --bash-force-ps4-to-stderr could perhaps be a better name.

I don't think there's any easy way around the problem you see, except perhaps selecting PS4-stderr automatically if --bash-parser= is selected. However, I think that would be confusing in other ways.

[Mark-E-Hamilton]

Could it have something to do with PS4 being an environment variable
instead of a shell variable? I added this line to test1.sh and test2.sh

typeset -p PS4
typeset -p BASH_XTRACEFD

If I just run it PS4 is a shell variable, and BASH_XTRACEFD is not set:

% ./test1.sh
declare -- PS4="+ "
./test1.sh: line 3: typeset: BASH_XTRACEFD: not found
declare -- PS4="+ "
./test2.sh: line 3: typeset: BASH_XTRACEFD: not found
Hi

If I run it with kcov it looks like both are environment variables:

% kcov /tmp/kcov_out ./test1.sh
declare -x PS4="kcov@\${BASH_SOURCE}@\${LINENO}@"
declare -x BASH_XTRACEFD="2"
declare -x PS4="kcov@\${BASH_SOURCE}@\${LINENO}@"
declare -x BASH_XTRACEFD="2"

(I'm not sure where my Hi went in the second case.)

So, the PS4 and BASH_XTRACEFD are set in the sub-shell (test2.sh) but
the xtrace flag isn't.

Interestingly, I get this when I pass --bash-parser

% kcov 
--bash-parser=/projects/sierra/linux_rh6/install/utilities/bash/4.3/bin/bash 
/tmp/kcov_out ./test1.sh
declare -x PS4="kcov@\${BASH_SOURCE}@\${LINENO}@"
kcov@./test2.sh@2@typeset -p PS4
kcov@./test2.sh@3@typeset -p BASH_XTRACEFD
kcov@./test2.sh@4@echo Hi
declare -x BASH_XTRACEFD="782"
declare -x PS4="kcov@\${BASH_SOURCE}@\${LINENO}@"
declare -x BASH_XTRACEFD="782"
Hi

[SimonKagstrom]

I didn't even know there was a difference :-)

Anyway, if the --debug-bash-force-stderr workaround didn't work, I've implemented a fix for Issue #51, which might correct this problem as well (as it should always use the bash you supply with --bash-parser, even for scripts executed directly).

If you have time, it would be nice if you could test the git head to see if it works. The Issue #51 fix is also a bit intrusive, so I'd be interested to know how it works out in larger environments.

[Mark-E-Hamilton]

On 03/01/15 05:41, Simon Kagstrom wrote:

I didn't even know there was a difference :-)

Anyway, if the --debug-bash-force-stderr workaround didn't work, I've
implemented a fix for Issue #51
#51, which might correct
this problem as well (as it should always use the bash you supply with
--bash-parser, even for scripts executed directly).

If you have time, it would be nice if you could test the git head to see
if it works. The Issue #51
#51 fix is also a bit
intrusive, so I'd be interested to know how it works out in larger
environments.

Something has caused kcov to run significantly more slowly. I have a
test that without kcov runs in about 3 seconds. With kcov from afe5793
it runs in about 9 seconds. With kcov from 5f56dc0 it runs in over 80
seconds (though once it took 140.) (These are all single tests, not
averages. YMMV.)

---

Mark E. Hamilton
Engineering Sciences Center
Senior Member of Technical Staff
Sandia National Laboratories
505-844-7666

[SimonKagstrom]

OK, I didn't think about that myself (but I also run with very small bash scripts). Kcov collection has a cost, so the 3->9 second change is probably not abnormal. 80-140 sounds like it would be an issue though. Did you test with 8a97825 as well? I suspect there won't be any difference, but 5f56dc0 had some issues that have been resolved in the later commit.

Anyway, the solution to Issue #51 works by replacing the execve libc call and for each executed file reads a bit at the start of the file to see if it's executed with a #!/bin/sh hash bang. If it is, it will replace the command line with "bash -x /path/to/script". If there are frequent program executions (as is often the case in bash scripts), I can imagine that this can give quite some overhead.

I suppose that feature should be made optional.

[Mark-E-Hamilton]

I saw the issue on 8a97825 first. I reset back to afe5793 to ensure it
was gone, then stepped forward until it occurred. I was going to bisect,
but I hit it on the next commit. I've also checked the current HEAD
commit v25-54-gf5070e8, with the same slowdown.

---

Mark E. Hamilton
Engineering Sciences Center
Senior Member of Technical Staff
Sandia National Laboratories
505-844-7666

[SimonKagstrom]

Thanks for testing this. I'll make this feature optional. The question is just if it should be default-on or default-off. How does your 80 second scripts look? I.e., are they thousands of lines long or short-but-with-loops?

[SimonKagstrom]

This feature is now optional (it also breaks in strange ways on some systems, so it's unsafe as well), and default's to off. Hopefully performance should be better again.

[Mark-E-Hamilton]

On 03/03/15 01:17, Simon Kagstrom wrote:

Thanks for testing this. I'll make this feature optional. The question
is just if it should be default-on or default-off. How does your 80
second scripts look? I.e., are they thousands of lines long or
short-but-with-loops?

Sorry, I've been off on other things for a few days, and will continue
to be so. I'll get back to working with kcov when I can. IAE, our
scripts are thousands of lines. There are some loops, of course, but
probably not an excessive amount.

---

Mark E. Hamilton
Engineering Sciences Center
Senior Member of Technical Staff
Sandia National Laboratories
505-844-7666

[Mark-E-Hamilton]

On 03/04/15 12:07, Simon Kagstrom wrote:

This feature is now optional (it also breaks in strange ways on some
systems, so it's unsafe as well), and default's to off. Hopefully
performance should be better again.

Yep, it is. Thanks.

I've encountered and issue with FUNCNAME which is not a kcov issue, but
shows up when I use bash-4.3 as the parser, that I thought you might
want to know about. Should I just open a new issue to describe it?

---

Mark E. Hamilton
Engineering Sciences Center
Senior Member of Technical Staff
Sandia National Laboratories
505-844-7666

[SimonKagstrom]

No problem!

Feel free to open issues as you please, it's easy to close them if it turns out to be an unrelated problem.