afterEach does not support async operation

lhokktyn commented 1 month ago

Software versions

Please provide at least OS and version of pact-js

OS: Mac OS Sonoma 14.7
Consumer Pact library: Pact JS v13.1.13
Provider Pact library: Pact JS v13.1.13
Node Version: 22.9.0

Issue Checklist

Please confirm the following:

[x] I have upgraded to the latest
[x] I have the read the FAQs in the Readme
[x] I have triple checked, that there are no unhandled promises in my code and have read the section on intermittent test failures
[ ] I have set my log level to debug and attached a log file showing the complete request/response cycle
[ ] For bonus points and virtual high fives, I have created a reproduceable git repository (see below) to illustrate the problem

Expected behaviour

When defining an async function for afterEach, it should pause further execution of the verification tests until that Promise has resolved.

We require async behaviour for clearing up state in afterEach as part of our verification tests.

Actual behaviour

Test execution is not paused, and Promise is not handled cleanly.

Steps to reproduce

Install the sample project as a basis for this test
Upgrade project to latest pact-js version (npm i -DE @pact-foundation/pact@latest)

Modify provider.spec.js to configure the provider verifier as so:

const pact = new pact_1.Verifier({
pactUrls: ["./pacts/myconsumer-myprovider.json"],
providerBaseUrl: "http://127.0.0.1:8080",
afterEach: async () => {
return new Promise((resolve) => setTimeout(resolve, 2000))
},
});

Run provider test (./node_modules/.bin/jest provider.spec.js)

Given this afterEach hook, I would expect test execution to pause for ~2 seconds, but it doesn't and jest does not exit cleanly, giving the warning:

Jest did not exit one second after the test run has completed.

'This usually means that there are asynchronous operations that weren't stopped in your tests. Consider running Jest with `--detectOpenHandles` to troubleshoot this issue.

Note the timestamps either side of the executing 'afterEach' hook log indicate execution on this thread is no paused ...

2024-10-04T16:15:22.434564Z DEBUG ThreadId(02) verify_interaction{interaction="a request for dynamic keys"}: hyper_util::client::legacy::pool: reuse idle connection for ("http", 127.0.0.1:60185)
[17:15:22.434] DEBUG (53817): pact@13.1.3: incoming request: {"body":{},"headers":{"accept":"*/*","accept-encoding":"gzip, deflate","host":"127.0.0.1:60185"},"method":"GET","path":"/"}
[17:15:22.434] DEBUG (53817): pact@13.1.3: Proxying GET: /
[17:15:22.436] DEBUG (53817): pact@13.1.3: executing 'afterEach' hook
[17:15:22.438] DEBUG (53817): pact@13.1.3: outgoing response: {"body":"{\"foo\":\"1\"}","headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"11","etag":"W/\"b-Pvi0Q5/yHZyhiaQpID3i4+RNmB4\"","date":"Fri, 04 Oct 2024 16:15:22 GMT","connection":"close"},"status":200}

Note that beforeEach does appear to support async operation. Here are the equivalent logs when replacing afterEach with beforeEach in the above snippet, which show a ~2 second gap between logs:

2024-10-04T16:23:18.834894Z DEBUG ThreadId(02) verify_interaction{interaction="a request for dynamic keys"}: hyper_util::client::legacy::connect::http: connected to 127.0.0.1:60460
[17:23:18.845] DEBUG (58216): pact@13.1.3: executing 'beforeEach' hook
[17:23:20.849] DEBUG (58216): pact@13.1.3: incoming request: {"body":{"action":"setup","params":{},"state":""},"headers":{"content-type":"application/json","accept":"*/*","accept-encoding":"gzip, deflate","host":"127.0.0.1:60460","content-length":"41"},"method":"POST","path":"/_pactSetup"}

lhokktyn commented 1 month ago

Related to https://github.com/pact-foundation/pact-js/issues/1068 which discusses the premature execution of afterEach

mefellows commented 1 month ago

Thanks for the helpful repro @lhokktyn, I'd be open to a PR to fix this. The problem might be in https://github.com/pact-foundation/pact-js/blob/1a3815ef456dc7e608a02e3cc2b267cac8b1f8ca/src/dsl/verifier/proxy/hooks.ts, but would need further investigation.

TimothyJones commented 1 month ago

I'm not a maintainer any more, but I'm pretty sure the problem is:

      logger.trace("registered 'afterEach' hook");
      next();
      if (req.path !== stateSetupPath) {
        logger.debug("executing 'afterEach' hook");
        try {
          await config.afterEach();
        } catch (e) {
          logger.error(`error executing 'afterEach' hook: ${e.message}`);
          logger.debug(`Stack trace was: ${e.stack}`);
          next(new Error(`error executing 'afterEach' hook: ${e.message}`));
        }

should be:


      logger.trace("registered 'afterEach' hook");

      if (req.path !== stateSetupPath) {
        logger.debug("executing 'afterEach' hook");
        try {
          await config.afterEach();
          next();
        } catch (e) {
          logger.error(`error executing 'afterEach' hook: ${e.message}`);
          logger.debug(`Stack trace was: ${e.stack}`);
          next(new Error(`error executing 'afterEach' hook: ${e.message}`));
        }

TimothyJones commented 1 month ago

Also that "registered afterEach hook" trace line is in the wrong place - should be outside the app.use

pact-foundation / pact-js