Async test cases report second failure if `expect` fails after timeout

[timschumi]

Consider the following test setup:

{
    name = "Some test",
    async = true,
    timeout = 1,
    func = function()
        call_callback_after_five_seconds(function()
            expect(nil).to.exist()  -- (Having a `fail(message)` would be pretty nice, manually throwing
            done()                  -- errors doesn't work here because async callbacks run unprotected.)
        end)
    end
},

This will result in the following test output:

[GLuaTest] FAIL [Some test]
    File:
       garrysmod/lua/tests/path/to/test.lua

    Context:
      ____________________________________________________
     | 
  14 |     [...]
  15 |     func = function() <- Timeout
     |____________________________________________________

[GLuaTest] Test run complete! 🎉
[GLuaTest] FAIL [Some test]
    File:
       garrysmod/lua/tests/path/to/test.lua

    Context:
      ________________________________________________________________________________
     | 
  22 | call_callback_after_five_seconds(function()
  23 |     expect(nil).to.exist() <- Unhandled: Expected nil to exist, got nil
     |________________________________________________________________________________

The fact that the test being done doesn't stop pending callbacks from running is quite logical, but one would assume that any late-arriving failures would simply be discarded if the test itself is already considered dead due to a timeout (or that it at least won't print the whole header twice).

[brandonsturgeon]

Good catch! Thanks for the report.

I believe I have code that's meant to prevent this. I'll take a look to see why it isn't working.

[brandonsturgeon]

I'm having trouble reproducing this.

Here's the test file I used:

return {
    cases = {
        {
            name = "It should not fail after test ends",
            async = true,
            timeout = 1,
            func = function()
                timer.Simple( 5, function()
                    expect( nil ).to.exist()
                    done()
                end )
            end
        },
        {
            name = "It should not fail after this test ends either",
            async = true,
            timeout = 3,
            func = function()
                timer.Simple( 8, function()
                    expect( nil ).to.exist()
                    done()
                end )
            end
        }
    }
}

Here's the output I got:

[GLuaTest] === Running express/async_test.lua... ===
[GLuaTest] FAIL [It should not fail after test ends]
    File:
       addons/gm_express/lua/tests/express/async_test.lua

    Context:
      ___________________________________________________________
     |
   2 | cases = {
   3 |     {
   4 |         name = "It should not fail after test ends",
   5 |         async = true,
   6 |         timeout = 1,
   7 |         func = function() <- Timeout
     |___________________________________________________________

[GLuaTest] FAIL [It should not fail after this test ends either]
    File:
       addons/gm_express/lua/tests/express/async_test.lua

    Context:
      ___________________________________________________________________
     |
  13 | },
  14 | {
  15 |     name = "It should not fail after this test ends either",
  16 |     async = true,
  17 |     timeout = 3,
  18 |     func = function() <- Timeout
     |___________________________________________________________________

[GLuaTest] Test run complete! 🎉

I tried with a single test case, and multiple files with different async cases.

Am I missing something?

[timschumi]

The following test successfully reproduces it for me (CHTTP required, obviously):

return {
    groupName = "CHTTP",
    cases = {
        {
            name = "CHTTP loads successfully",
            func = function()
                expect(require, "chttp").to.succeed()
                expect(CHTTP).to.exist()
            end
        },
        {
            name = "HTTPS requests run successfully",
            async = true,
            timeout = 1,
            func = function()
                CHTTP({
                    url = "https://timschumi.net/delay.php",
                    timeout = 10,
                    success = function(code, body, headers)
                        expect(code).to.equal(200)
                        done()
                    end,
                    failed = function(err)
                        expect(nil).to.exist()
                        done()
                    end
                })
            end
        },
    }
}

Note that, at least when running in the game client, the "Timeout" failure is quite far up in the console scrollback.

However, I can't spot anything in your reproducer that would be missing, at least assuming that CHTTP isn't accidentally doing something weird while running callbacks.

[brandonsturgeon]

Ahhh, that makes a lot more sense.

I cheat a bit in GLuaTest by wrapping hooks, timers, and http functions and manipulate the environment of any callbacks passed to them. While I didn't love the solution when I made it, it's becoming clear how shortsighted it really was.

In any case, you're right. Simply making sure any late expect or done calls are simply discarded is a doable short-term solution.

I'll whip up a fix here shortly 👍

[brandonsturgeon]

Running the PR I just opened (#26), here's what my output looks like with your test:

lua_run print(CurTime()); gluatest_run_tests
81.575759887695

[GLuaTest] === Running express/CHTTP... ===
[GLuaTest] PASS [CHTTP loads successfully]
[GLuaTest] FAIL [HTTPS requests run successfully]
    File:
       addons/gm_express/lua/tests/express/express.lua

    Context:
      ____________________________________________________
     |
  10 | },
  11 | {
  12 |     name = "HTTPS requests run successfully",
  13 |     async = true,
  14 |     timeout = 1,
  15 |     func = function() <- Timeout
     |____________________________________________________

[GLuaTest] Test run complete! 🎉

lua_run print(CurTime())
100.06060791016

As you can see, the second CurTime call is ~ 20 seconds after the first.

If this looks correct to you (or if you'd like to give that branch a try), let me know and I'll merge it 👍

[brandonsturgeon]

Resolved in #26 - thanks again for your help!