failed assert_file_exist reports as not executed when teardown() with load

[NorthboundTrain]

OS: MacOS 11.6.1 Bash: 5.1.12(1) (from MacPorts) Bats: da56a30 (2022-01-05) Bats-File: 17fa557 (2020-04-29)

This one took me hours to come up with a reproducible example; I didn't also have the fortitude to dig into the code and figure out the cause or a fix, too -- sorry!

If my program calls assert_file_exist and fails, instead of reporting a failure it will report the test as not being executed, but only when there's a teardown function with a load call in it. Here's a test case; commentary follows:

setup() {
    load 'test_helper/bats-support/load'
    load 'test_helper/bats-assert/load'
    load 'test_helper/bats-file/load'
}

teardown() {
    load 'foofoo'
}


@test "[1] this one executes successfully" {

    foo=/tmp/foo
    touch $foo

    assert_file_exist "$foo"
}

@test "[2] this one will execute and fail" {
    foo=/tmp/foo
    touch $foo

    [[ -e "x$foo" ]]
}

@test "[3] this one will report as not executed" {
    foo=/tmp/foo
    touch $foo

    assert_file_exist "x$foo"
}

@test "[4] this one works fine no matter what" {
    foo=/tmp/foo
    touch $foo

    assert_file_not_exist "x$foo"
}

@test "[5] this one will also execute and fail" {
    foo=/tmp/foo
    touch $foo

    run /bin/false
    assert_success
}

The foofoo.bash file is zero bytes; it just needs to exist.

When run, this produces the following output:

$ test/bats/bin/bats test/99*
 ✓ [1] this one executes successfully
 ✗ [2] this one will execute and fail
   (in test file test/99-bats-issue.bats, line 24)
     `[[ -e "x$foo" ]]' failed
 ✓ [4] this one works fine no matter what
 ✗ [5] this one will also execute and fail
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    in test file test/99-bats-issue.bats, line 46)
     `assert_success' failed

   -- command failed --
   status : 1
   output :
   --

   bats warning: Executed 4 instead of expected 5 tests

5 tests, 2 failures, 1 not run

Notice that one of the tests is shown as not being run, and test #​3 does in fact not show up in the output. If you watch the output closely, though, you'll see it is reported, it's just overwritten -- if you move test #​3 to be the last test, its line won't get overwritten and you'll see it in the output:

$ test/bats/bin/bats test/99*
 ✓ [1] this one executes successfully
 ✗ [2] this one will execute and fail
   (in test file test/99-bats-issue.bats, line 24)
     `[[ -e "x$foo" ]]' failed
 ✓ [4] this one works fine no matter what
 ✗ [5] this one will also execute and fail
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    in test file test/99-bats-issue.bats, line 39)
     `assert_success' failed

   -- command failed --
   status : 1
   output :
   --

   [3] this one will report as not executed                                                                                                       5/5
   bats warning: Executed 4 instead of expected 5 tests

5 tests, 2 failures, 1 not run

If you remove the teardown function (by either deleting it or renaming it), test #​3 will properly show as executing and failing:

$ test/bats/bin/bats test/99*
 ✓ [1] this one executes successfully
 ✗ [2] this one will execute and fail
   (in test file test/99-bats-issue.bats, line 24)
     `[[ -e "x$foo" ]]' failed
 ✗ [3] this one will report as not executed
   (from function `assert_file_exist' in file test/test_helper/bats-file/src/file.bash, line 72,
    in test file test/99-bats-issue.bats, line 31)
     `assert_file_exist "x$foo"' failed

   -- file does not exist --
   path : x/tmp/foo
   --

 ✓ [4] this one works fine no matter what
 ✗ [5] this one will also execute and fail
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    in test file test/99-bats-issue.bats, line 46)
     `assert_success' failed

   -- command failed --
   status : 1
   output :
   --


5 tests, 3 failures

The same results can be achieved by removing the load line, e.g.

teardown() {
    : load 'foofoo'
}

I replicated this aberrant behavior with one or two other assert_* commands from bats-file, but I did not test each one.

[martin-schulze-vireso]

Can you post the output with --formatter cat? I think this is an issue with a failure in teardown combined with the pretty formatter.

[NorthboundTrain]

Here is the output:

$ test/bats/bin/bats test/99* --formatter cat
1..5
suite /tmp/bats-assert-issue/test/99-bats-issue.bats
begin 1 [1] this one executes successfully
ok 1 [1] this one executes successfully
begin 2 [2] this one will execute and fail
not ok 2 [2] this one will execute and fail
# (in test file test/99-bats-issue.bats, line 24)
#   `[[ -e "x$foo" ]]' failed
begin 3 [3] this one will report as not executed
not ok 3 [3] this one will report as not executed
# (from function `assert_file_exist' in file test/test_helper/bats-file/src/file.bash, line 72,
#  in test file test/99-bats-issue.bats, line 31)
#   `assert_file_exist "x$foo"' failed
#
# -- file does not exist --
# path : x/tmp/foo
# --
#
begin 4 [4] this one works fine no matter what
ok 4 [4] this one works fine no matter what
begin 5 [5] this one will also execute and fail
not ok 5 [5] this one will also execute and fail
# (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
#  in test file test/99-bats-issue.bats, line 46)
#   `assert_success' failed
#
# -- command failed --
# status : 1
# output :
# --
#

[martin-schulze-vireso]

This was with load enabled?

[NorthboundTrain]

It was not -- my apologies!

$ test/bats/bin/bats test/99* --formatter cat
1..5
suite /tmp/bats-assert-issue/test/99-bats-issue.bats
begin 1 [1] this one executes successfully
ok 1 [1] this one executes successfully
begin 2 [2] this one will execute and fail
not ok 2 [2] this one will execute and fail
# (in test file test/99-bats-issue.bats, line 24)
#   `[[ -e "x$foo" ]]' failed
begin 3 [3] this one will report as not executed
begin 4 [4] this one works fine no matter what
ok 4 [4] this one works fine no matter what
begin 5 [5] this one will also execute and fail
not ok 5 [5] this one will also execute and fail
# (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
#  in test file test/99-bats-issue.bats, line 46)
#   `assert_success' failed
#
# -- command failed --
# status : 1
# output :
# --
#
# bats warning: Executed 4 instead of expected 5 tests

[martin-schulze-vireso]

Okay, that is not a formatter issue. It is very likely not even bats-file related. Does the same behavior occur when you replace the assertion with false?

[NorthboundTrain]

Sadly it does. Replacing the third test with the following:

@test "[3a] this one will report as not executed" {
    foo=/tmp/foo
    touch $foo

    assert_file_exist "x$foo"
}

@test "[3b] this one will report as not executed" {
    foo=/tmp/foo
    touch $foo

    false
}

results in this output:

$ test/bats/bin/bats test/99*
 ✓ [1] this one executes successfully
 ✗ [2] this one will execute and fail
   (in test file test/99-bats-issue.bats, line 24)
     `[[ -e "x$foo" ]]' failed
 ✗ [3b] this one will report as not executed
   (in test file test/99-bats-issue.bats, line 38)
     `false' failed
 ✓ [4] this one works fine no matter what
 ✗ [5] this one will also execute and fail
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    in test file test/99-bats-issue.bats, line 53)
     `assert_success' failed

   -- command failed --
   status : 1
   output :
   --

   bats warning: Executed 5 instead of expected 6 tests

6 tests, 3 failures, 1 not run

Test 3a (the original) is not executed, test 3b (replacing assert_file_exist with false) executes just fine.

Thanks!

[martin-schulze-vireso]

Well thats really interesting. assert_file_exists creates a local readonly variable that is named file. load also creates a local variable named file. It seems that teardown gets called within the scope of assert_file_exists' file which prevents the name from being used again. This smells a bit like a bash bug. I am afraid there is little we can do. In theory we can have abritrary failing functions that lock variable names which we use inside teardown and associated functions, socan only pick less common variable names or try to work around this peculiar call order. However, I am not sure if this breaks existing code and is even possible.

Additional Details:

I used this test script:

#!/usr/bin/env bash
set_var() {
        echo set_var ${BASH_LINENO[@]} $*
        local var=foo
        echo after
}

set_readonly_var() {
        echo set_readonly_var ${BASH_LINENO[@]}
        local -r var=bar
        false # trigger err trap
}

trap 'set_var EXIT' EXIT
trap 'set_var ERR'  ERR
set -eE

set_readonly_var

Which generates the following output with bash 5.1:

set_readonly_var 17 0
set_var 10 17 0 ERR
after
set_var 1 17 0 EXIT
test.bash: line 3: local: var: readonly variable
set_var 3 1 17 0 ERR
after

As you can see set_var's assignment of var triggers an error when called via the exit trap but not when called via the ERR trap. The BASH_LINENO array indicates the ERR being called from false whereas EXIT is called from the last line. This looks counterintuitive to the scope explanation for var.

[NorthboundTrain]

That's very esoteric -- thanks for digging into it! I agree, that's a Bash bug that can be worked around rather than a Bats issue to be fixed. Will you log the Bash bug or should I do it (using your test case)?

[martin-schulze-vireso]

Feel free to submit the report. I am not done investigating a workaround. Even if this is fixed, we need to support older bash versions.

[NorthboundTrain]

I think this behavior is intended (or at least expected). From the Bash manual:

local

local [option] name[=value] …

For each argument, a local variable named name is created, and assigned value. The option can be any of the options accepted by declare. local can only be used within a function; it makes the variable name have a visible scope restricted to that function and its children. If name is ‘-’, the set of shell options is made local to the function in which local is invoked: shell options changed using the set builtin inside the function are restored to their original values when the function returns. The restore is effected as if a series of set commands were executed to restore the values that were in place before the function. The return status is zero unless local is used outside a function, an invalid name is supplied, or name is a readonly variable.

(emphasis mine)

It's surprising that children of the function can see local variables, but given that, the behavior makes sense (for some definition of the word sense).

[martin-schulze-vireso]

Yes, for true recursion that behavior is expected. However, in the script above, set_var is called multiple times but fails only in the exit trap. This is at least inconsistent. IMHO, the actual failure/trap call location is outside the function that defines the readonly local variable, so it should not be in scope anymore.

[martin-schulze-vireso]

Hm, I dug a bit deeper and it gets more confusing:

1. Redefining a local -r variable is not an error:

set_var() {
    local var=foo
}
set_readonly_var() {
    local -r var=bar
    set_var
}

set_readonly_var

Does not trigger any error. I think this is not a contradiction to your quote, since or name is a readonly variable might refer to global readonly variables.

2. Redefining in the exit trap does trigger an error, if errexit (set -e) is active:

set_var() {
    local var=foo
}
set_readonly_var() {
    local -r var=bar
    exit 0
}

trap set_var EXIT

# set -e # uncomment to trigger error
set_readonly_var

3. once errexit (set -e) is enabled, the above code gives line 2: local: var: readonly variable.
4. this does not happen in the ERR trap:

set_var() {
    local var=foo
    echo set_var
}
set_readonly_var() {
    set -e
    trap set_var ERR
    local -r var=bar
    echo set_readonly_var
    false
}

set_readonly_var

So to summarize: EXIT trap + set -e does trigger the local -r problem. I'd have to check the different bash versions to see if this behavior changed. My tests were with 5.1.