WIP: Add a --trace feature #137

mbland · 2018-08-09T14:56:23Z

Closes #136. The final implementation will set the BATS_TRACE variable via a command-line flag, but setting BATS_TRACE=1 bin/bats ... will work.

This did require explicitly filtering out the line from bats_perform_test that executes the test case; somehow the "$BATS_SOURCE" != "$1" condition doesn't filter it. If I (or anyone else) can think of a cleaner way to filter out this line than quoting it directly, I'm all for it.

Two minor caveats:

If a command fails, it will be printed twice. Then, of course, it'll appear in the failure output, for a total of three times.
When using the pretty formatter, the first line of the trace from a test case will overlap with the line printing the name of the test case before execution begins.

Also, I still need to add tests, of course.

cc: @gtkramer

I have reviewed the Contributor Guidelines.
I have reviewed the Code of Conduct and agree to abide by it

Part of #136. The final implementation will set the BATS_TRACE variable via a command-line flag, but setting `BATS_TRACE=1 bin/bats ...` will work. This did require explicitly filtering out the line from `bats_perform_test` that executes the test case; somehow the `"$BATS_SOURCE" != "$1"` condition doesn't filter it. If I (or anyone else) can think of a cleaner way to filter out this line than quoting it directly, I'm all for it. Two minor caveats: - If a command fails, it will be printed twice. Then, of course, it'll appear in the failure output, for a total of three times. - When using the pretty formatter, the first line of the trace from a test case will overlap with the line printing the name of the test case before execution begins.

This prevents `bats_capture_stack_trace` from executing on lines that realistically will never fail. (Or, more precisely, if they do, then Bats itself is seriously broken.) This consistently shaves off O(0.1s) from the test suite under both Bash 3.2.57(1)-release and 4.4.23(1)-release on my Macbook Pro (2.5GHz Core i7, 16GB RAM).

This replaces setting `BATS_TRACE` as an environment variable. And in the next commit...tests!

This final version will filter out any stack trace values and trace output where: - the `DEBUG` trap fires for the function definition itself, resulting in redundant --trace output lines (comparing `BASH_COMMAND` against `${FUNCNAME[1]}`) - the `DEBUG` trap fires before the `ERR` trap on error; apparently when both functions fire, `$?` refers to the value returned by the last command before either trap is fired (checking `$status` before emitting the trace output) The use of `case` patterns instead of multiple tests in an `if` condition is a bit more compact, and very slightly faster on average. Hence, I took the opportunity to apply a `case` statement in `bats_capture_stack_trace` as well.

mbland · 2018-08-10T01:57:16Z

OK, tests are added; this PR is ready for review. From the last commit message:

This final version will filter out any stack trace values and trace output where:

the DEBUG trap fires for the function definition itself, resulting in redundant --trace output lines (comparing BASH_COMMAND against ${FUNCNAME[1]})
the DEBUG trap fires before the ERR trap on error; apparently when both functions fire, $? refers to the value returned by the last command before either trap is fired (checking $status before emitting the trace output)

The use of case patterns instead of multiple tests in an if condition is a bit more compact, and very slightly faster on average. Hence, I took the opportunity to apply a case statement in bats_capture_stack_trace as well.

The previous implementation had two bugs: - Recursive function calls wouldn't appear in the trace output as they should've. - The `$?` check by itself meant that the first line of an `else` clause wouldn't get printed. For more discussion of this phenemonon: #110 (comment) The new test case reproduced both of these bugs, and the new implementation fixes them. However, there is a slight but measurable performance degradation with this update. I'm going to see if I can't tweak it some more before merging this PR.

mbland · 2018-08-11T16:13:27Z

I pushed a new commit to cover recursive function calls and else clause commands; see the message from commit 73952a6 for details.

However, test case 57, "trace a failing test case", now fails consistently on Bash 4.0.44(1)-release, 4.1.17(2)-release, and 4.2.53(2)-release. I'll have to investigate and fix a little later.

Regarding the slight performance regression mentioned in the last commit message, I'm thinking of leaving it for now, as performance overall doesn't seem to suffer from the new feature. However, I do have ideas for making a more radical performance improvement—I think I see a way to get away with only capturing the stack trace on error—but I'll try it in another PR.

mbland · 2018-08-13T00:49:37Z

FYI, I just filed #138 with some stack trace optimizations. It doesn't eliminate the need to capture the stack trace on every call, but eliminates some unnecessary calls and makes the code a little cleaner.

I'll likely try to merge that PR first and update this one, and then attempt to fix the breakages. Still, @gtkramer, the semantics won't change, and I'd be interested in hearing some feedback once you try out this branch in the meanwhile.

Note that this commit also extracts the `bats_emit_trace` function and makes use of variables introduced by #138.

Turns out with the `BASH_COMMAND` and `BATS_LINENO` comparisons, the value of `$?` is completely irrelevant. This feature still introduces a very slight decrease in performance for the existing test suite (before the three new test cases). This is somewhat unavoidable since we're introducing an extra conditional into `bats_debug_trap`, the most frequently executed function in the system. Bash 3.2.57(1)-release before: real 0m6.217s user 0m3.067s sys 0m1.927s real 0m6.051s user 0m3.070s sys 0m1.946s real 0m6.135s user 0m3.091s sys 0m1.997s Bash 3.2.57(1)-release after: real 0m6.131s user 0m3.124s sys 0m1.982s real 0m6.096s user 0m3.113s sys 0m1.975s Bash 4.4.23(1)-release before: real 0m6.490s user 0m3.106s sys 0m2.091s real 0m6.480s user 0m3.097s sys 0m2.087s real 0m6.513s user 0m3.099s sys 0m2.106s Bash 4.4.23(1)-release after: real 0m6.529s user 0m3.146s sys 0m2.096s real 0m6.522s user 0m3.136s sys 0m2.087s

mbland · 2018-08-19T23:16:48Z

The strangest thing is happening with these failures under Bash 4.0.44, 4.1.17, and 4.2.53. When I run the tests under those versions locally, adding emit_debug_output to the failing test case, I get:

$ time PATH="/usr/local/bash/4.2.53/bin:$PATH" bin/bats test -f 'trace a failing'                                     
 ✗ trace a failing test case
   (in test file test/bats.bats, line 488)
     `[ "${#lines[@]}" -eq 8 ]' failed
   output:
   1..1
   # test/fixtures/bats/trace.bats:6: run printf 'The TEST_RESULT is: %s\n' "$TEST_RESULT"                                                                      
   # test/fixtures/bats/trace.bats:7: evaluate_result "$output"
   # test/fixtures/bats/trace.bats:2: [ "$1" = 'The TEST_RESULT is: PASS' ]
   # test/fixtures/bats/trace.bats:257: [ "$1" = 'The TEST_RESULT is: PASS' ]
   not ok 1 traced test case
   # (from function `evaluate_result' in file test/fixtures/bats/trace.bats, line 2,                                                                            
   #  in test file test/fixtures/bats/trace.bats, line 7)
   #   `evaluate_result "$output"' failed

1 test, 1 failure


real    0m0.412s
user    0m0.283s
sys     0m0.085s

That last line number, 257, corresponds to the last command executed by bats_debug_trap, which is the last line executed by bats_emit_trace. I know this because trying different commands in those functions changes that line number.

This appears to be attributable to the fact that starting with Bash 4.3, the line_number_for_err_trap variable in execute_cmd.c went from being declared a static int to a global int, so that parse_prologue in builtins/evalstring.c could wrap it in an unwind_protect_int call. (In Bash 3.2.57, the problem was different, in that the BASH_LINENO value would get clobbered with the number of the first line of the function.)

This is tricky to work around. I'll let it sit and think about it some more, or whether it's worth adjusting/skipping the test under Bash 4.0, 4.1, and 4.2. Ideas welcome.

mbland · 2018-08-20T13:07:14Z

Some notes to myself about how to handle this:

Perhaps arrange it so the trace is printed for the previous command, rather than the current one. Would need to take care to see how that would play with teardown, however.
Let go of trying to filter out the beginning-of-function-definition traces.

andrewmiller1 · 2018-09-24T03:53:29Z

~~It works on 5 beta as well~~

andrew@pop-os:~/opt/bats-core (trace * u= origin/trace) $ bash -c 'echo $BASH_VERSION' 5.0.0(1)-beta andrew@pop-os:~/opt/bats-core (trace * u= origin/trace) $ time bin/bats --tap test 1..76 ok 1 no arguments prints message and usage instructions ok 2 invalid option prints message and usage instructions ok 3 -v and --version print version number ok 4 -h and --help print help ok 5 invalid filename prints an error ok 6 empty test file runs zero tests ok 7 one passing test ok 8 summary passing tests ok 9 summary passing and skipping tests ok 10 tap passing and skipping tests ok 11 summary passing and failing tests ok 12 summary passing, failing and skipping tests ok 13 tap passing, failing and skipping tests ok 14 BATS_CWD is correctly set to PWD as validated by bats_trim_filename ok 15 one failing test ok 16 one failing and one passing test ok 17 failing test with significant status ok 18 failing helper function logs the test case's line number ok 19 test environments are isolated ok 20 setup is run once before each test ok 21 teardown is run once after each test, even if it fails ok 22 setup failure ok 23 passing test with teardown failure ok 24 failing test with teardown failure ok 25 teardown failure with significant status ok 26 failing test file outside of BATS_CWD ok 27 load sources scripts relative to the current test file ok 28 load aborts if the specified script does not exist ok 29 load sources scripts by absolute path ok 30 load aborts if the script, specified by an absolute path, does not exist ok 31 output is discarded for passing tests and printed for failing tests ok 32 -c prints the number of tests ok 33 dash-e is not mangled on beginning of line ok 34 dos line endings are stripped before testing ok 35 test file without trailing newline ok 36 skipped tests ok 37 skipped test with parens (pretty formatter) ok 38 extended syntax ok 39 pretty and tap formats ok 40 pretty formatter bails on invalid tap ok 41 single-line tests ok 42 testing IFS not modified by run ok 43 expand variables in test name ok 44 handle quoted and unquoted test names ok 45 ensure compatibility with unofficial Bash strict mode ok 46 parse @test lines with various whitespace combinations ok 47 duplicate tests cause a warning on stderr ok 48 sourcing a nonexistent file in setup produces error output ok 49 referencing unset parameter in setup produces error output ok 50 sourcing a nonexistent file in test produces error output ok 51 referencing unset parameter in test produces error output ok 52 sourcing a nonexistent file in teardown produces error output ok 53 referencing unset parameter in teardown produces error output ok 54 execute exported function without breaking failing test output ok 55 output printed even when no final newline ok 56 trace a passing test case ok 57 trace a failing test case ok 58 trace a test case calling a recursive function ok 59 install.sh creates a valid installation ok 60 install.sh only updates permissions for Bats files ok 61 bin/bats is resilient to symbolic links ok 62 #113: set BATS_ROOT when /bin is a symlink to /usr/bin ok 63 set BATS_ROOT with extreme symlink resolution ok 64 running a suite with no test files ok 65 running a suite with one test file ok 66 counting tests in a suite ok 67 aggregated output of multiple tests in a suite ok 68 a failing test in a suite results in an error exit code ok 69 running an ad-hoc suite by specifying multiple test files ok 70 extended syntax in suite ok 71 recursive support (short option) ok 72 recursive support (long option) ok 73 run entire suite when --filter isn't set ok 74 use --filter to run subset of test cases from across the suite ok 75 --filter can handle regular expressions that contain [_- ] ok 76 --filter can handle regular expressions that start with ^ real 0m6.437s user 0m4.325s sys 0m2.257s andrew@pop-os:~/opt/bats-core (trace * u= origin/trace) $

Edit: The first test run was actually run on bash 4.4.19(1)-release. bash had gone to /usr/local/bin/bash (5.0.0(1)-beta). However, my shell was started via a keyboard shortcut, which used /bin/bash (4.4.19(1)-release).

The actual test run on bash 5.0.0(1)-beta

andrew@pop-os:~$ help | grep version
GNU bash, version 5.0.0(1)-beta (x86_64-pc-linux-gnu)
andrew@pop-os:~$ echo $BASH_VERSION 
5.0.0(1)-beta
andrew@pop-os:~$ bash -c 'echo $BASH_VERSION'
5.0.0(1)-beta
andrew@pop-os:~$ cd opt/bats-core/
andrew@pop-os:~/opt/bats-core$ time bin/bats --tap test
1..76
ok 1 no arguments prints message and usage instructions
ok 2 invalid option prints message and usage instructions
ok 3 -v and --version print version number
ok 4 -h and --help print help
ok 5 invalid filename prints an error
ok 6 empty test file runs zero tests
ok 7 one passing test
ok 8 summary passing tests
ok 9 summary passing and skipping tests
ok 10 tap passing and skipping tests
ok 11 summary passing and failing tests
ok 12 summary passing, failing and skipping tests
ok 13 tap passing, failing and skipping tests
ok 14 BATS_CWD is correctly set to PWD as validated by bats_trim_filename
ok 15 one failing test
ok 16 one failing and one passing test
ok 17 failing test with significant status
ok 18 failing helper function logs the test case's line number
ok 19 test environments are isolated
ok 20 setup is run once before each test
ok 21 teardown is run once after each test, even if it fails
ok 22 setup failure
ok 23 passing test with teardown failure
ok 24 failing test with teardown failure
ok 25 teardown failure with significant status
ok 26 failing test file outside of BATS_CWD
ok 27 load sources scripts relative to the current test file
ok 28 load aborts if the specified script does not exist
ok 29 load sources scripts by absolute path
ok 30 load aborts if the script, specified by an absolute path, does not exist
ok 31 output is discarded for passing tests and printed for failing tests
ok 32 -c prints the number of tests
ok 33 dash-e is not mangled on beginning of line
ok 34 dos line endings are stripped before testing
ok 35 test file without trailing newline
ok 36 skipped tests
ok 37 skipped test with parens (pretty formatter)
ok 38 extended syntax
ok 39 pretty and tap formats
ok 40 pretty formatter bails on invalid tap
ok 41 single-line tests
ok 42 testing IFS not modified by run
ok 43 expand variables in test name
ok 44 handle quoted and unquoted test names
ok 45 ensure compatibility with unofficial Bash strict mode
ok 46 parse @test lines with various whitespace combinations
ok 47 duplicate tests cause a warning on stderr
ok 48 sourcing a nonexistent file in setup produces error output
ok 49 referencing unset parameter in setup produces error output
ok 50 sourcing a nonexistent file in test produces error output
ok 51 referencing unset parameter in test produces error output
ok 52 sourcing a nonexistent file in teardown produces error output
ok 53 referencing unset parameter in teardown produces error output
ok 54 execute exported function without breaking failing test output
ok 55 output printed even when no final newline
ok 56 trace a passing test case
ok 57 trace a failing test case
ok 58 trace a test case calling a recursive function
ok 59 install.sh creates a valid installation
ok 60 install.sh only updates permissions for Bats files
ok 61 bin/bats is resilient to symbolic links
ok 62 #113: set BATS_ROOT when /bin is a symlink to /usr/bin
ok 63 set BATS_ROOT with extreme symlink resolution
ok 64 running a suite with no test files
ok 65 running a suite with one test file
ok 66 counting tests in a suite
ok 67 aggregated output of multiple tests in a suite
ok 68 a failing test in a suite results in an error exit code
ok 69 running an ad-hoc suite by specifying multiple test files
ok 70 extended syntax in suite
ok 71 recursive support (short option)
ok 72 recursive support (long option)
ok 73 run entire suite when --filter isn't set
ok 74 use --filter to run subset of test cases from across the suite
ok 75 --filter can handle regular expressions that contain [_- ]
ok 76 --filter can handle regular expressions that start with ^

real	0m6.760s
user	0m4.437s
sys	0m2.378s
andrew@pop-os:~/opt/bats-core$

grahamwhaley · 2019-06-11T18:39:52Z

Just wondering, if this PR stuck? I had 'fun' following the history of requests for a trace/verbosity/debug feature for bats. It is so needed. So much that without it ultimately I'd start pushing folks off bats, as trying to debug broken or flaky tests without some built in debug feature is just too much pain :-)
Would love to see this land :-)

NorseGaud · 2021-07-18T14:58:22Z

Bump

martin-schulze-vireso · 2021-07-23T23:27:15Z

I am closing this in favor of #467

mbland added the Type: Enhancement label Aug 9, 2018

mbland self-assigned this Aug 9, 2018

mbland requested a review from a team August 9, 2018 14:56

ghost added the review label Aug 9, 2018

Bland, Mike added 3 commits August 9, 2018 08:07

trace: Pass through --trace flag from command line

4b263e9

This replaces setting `BATS_TRACE` as an environment variable. And in the next commit...tests!

mbland mentioned this pull request Aug 10, 2018

Add a test trace option #136

Closed

mbland requested review from jasonkarns and sublimino August 14, 2018 13:48

Bland, Mike added 2 commits August 19, 2018 15:57

Merge branch 'master' into trace

8340e27

Note that this commit also extracts the `bats_emit_trace` function and makes use of variables introduced by #138.

mbland force-pushed the trace branch from 55efb32 to 7f20e38 Compare August 19, 2018 21:09

This was referenced Nov 2, 2020

How to make 'set -x' work? #325

Closed

Want basic logging support for logging output and other side-effects #60

Closed

martin-schulze-vireso removed the review label Jun 19, 2021

martin-schulze-vireso added Component: Bash Code Everything regarding the bash code Priority: High Broken behavior in specific environments like in parallel mode or only on some operating systems labels Jul 18, 2021

NorseGaud mentioned this pull request Jul 20, 2021

[ignore] Verbose output for faster troubleshooting of test problems #467

Closed

martin-schulze-vireso closed this Jul 23, 2021

martin-schulze-vireso deleted the trace branch May 13, 2022 23:07

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

WIP: Add a --trace feature #137

WIP: Add a --trace feature #137

Uh oh!

mbland commented Aug 9, 2018

Uh oh!

mbland commented Aug 10, 2018

Uh oh!

mbland commented Aug 11, 2018

Uh oh!

mbland commented Aug 13, 2018

Uh oh!

mbland commented Aug 19, 2018

Uh oh!

mbland commented Aug 20, 2018

Uh oh!

andrewmiller1 commented Sep 24, 2018 •

edited

Loading

Uh oh!

grahamwhaley commented Jun 11, 2019

Uh oh!

NorseGaud commented Jul 18, 2021

Uh oh!

martin-schulze-vireso commented Jul 23, 2021

Uh oh!

Uh oh!

WIP: Add a --trace feature #137

WIP: Add a --trace feature #137

Uh oh!

Conversation

mbland commented Aug 9, 2018

Uh oh!

mbland commented Aug 10, 2018

Uh oh!

mbland commented Aug 11, 2018

Uh oh!

mbland commented Aug 13, 2018

Uh oh!

mbland commented Aug 19, 2018

Uh oh!

mbland commented Aug 20, 2018

Uh oh!

andrewmiller1 commented Sep 24, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

grahamwhaley commented Jun 11, 2019

Uh oh!

NorseGaud commented Jul 18, 2021

Uh oh!

martin-schulze-vireso commented Jul 23, 2021

Uh oh!

Uh oh!

andrewmiller1 commented Sep 24, 2018 •

edited

Loading