Provider testing - long-running afterEach hook does not complete execution

[james-kuihi]

Software versions

• OS: Ubuntu 20 (via WSL2)
• Consumer Pact library: Pact JS 10.4.1
• Provider Pact library: Pact JS 10.4.1
• Node Version: v18.12.1

Issue Checklist

Please confirm the following:

• I have upgraded to the latest
• I have the read the FAQs in the Readme
• 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

In the provider tests, when executing a long-running function in the afterEach hook, such as a database clean-up activity, then the function should complete execution before the test runner terminates.

Actual behaviour

Test runner terminates before the function completes execution.

Steps to reproduce

1. Clone down the reproducing repository - https://github.com/james-kuihi/pact-js-aftreEach-bug-demo
2. Run the tests which reproduce the issue:

cd examples/v3/afterEach-bug
npm install
npm test

You should see log output including:

Starting afterEach
...
Finished afterEach

However, only the first line is present. The pertinent provider test which reproduces this is here.

Relevant log files

test.log

Other

This was raised and discussed on the PactJS Slack channel, and a improvement idea for the core framework raised in Canny.

[TimothyJones]

I think this is the same bug as reported here: https://pact-foundation.slack.com/archives/C9VBGLUM9/p1677060601328999

[TimothyJones]

Oh, you reported it the first time. Carry on!

[mhelmer]

It seems to me that the afterEach hook doesn't work as intended at all.

If I add an afterEach hook to the v3 e2e example it seems to execute just after the request is received, rather than after the request has finished. See output from logs at the bottom. Looking at the implementation it is somewhat expected.

export const registerAfterHook = (
  app: express.Express,
  config: ProxyOptions,
  stateSetupPath: string
): void => {
  app.use(async (req, res, next) => {
    if (config.afterEach !== undefined) {
      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}`));
        }
      }
    } else {
      next();
    }
  });
};

To my understanding it is not guaranteed that the response has completed at the point where next() function returns, since the request to the underlying service happens async through the proxy. I'm thinking also that response needs to be delayed until the afterEach has completed, or otherwise the pact verifier might move on the next interaction earlier than anticipated. That might be the reason for the issue that's reported here.

Also note that if the afterEach function errors out, the next function will be called twice which doesn't seem right.

In order to get the afterEach hook to run at the correct time (ie when the underlying service has responded) it could register res.on('finish', () => {}). This would however not prevent the request from resolving before the hook has completed. Perhaps the res.send method could be overridden to run the afterEach before calling the actual res.send. There might also be some appropriate event on the http proxy that could be used.

2023-03-21T15:39:14.377964Z  INFO ThreadId(11) pact_verifier: Running provider verification for 'a request for an animal as text with an ID'
2023-03-21T15:39:14.378076Z  INFO ThreadId(11) pact_verifier::provider_client: Sending request to provider at http://localhost:55551/
2023-03-21T15:39:14.378080Z  INFO ThreadId(11) pact_verifier::provider_client: Sending request HTTP Request ( method: GET, path: /animals/100, query: None, headers: Some({"Authorization": ["Bearer token"], "Accept": ["text/plain"]}), body: Missing )
Middleware invoked before provider API - injecting Authorization token
HERE: after each
2023-03-21T15:39:14.382110Z  INFO ThreadId(11) pact_verifier::provider_client: Received response: HTTP Response ( status: 200, headers: Some({"content-type": ["text/plain; charset=utf-8"], "content-length": ["49"], "access-control-allow-origin": ["*"], "connection": ["close"], "x-powered-by": ["Express"], "date": ["Tue", "21 Mar 2023 15:39:14 GMT"]}), body: Present(49 bytes, text/plain;charset=utf-8) )
2023-03-21T15:39:14.382136Z  INFO ThreadId(11) pact_matching: comparing to expected response: HTTP Response ( status: 200, headers: Some({"Content-Type": ["text/plain; charset=utf-8"]}), body: Present(49 bytes, text/plain;charset=utf-8) )
2023-03-21T15:39:14.382481Z  INFO ThreadId(11) pact_verifier: Running teardown provider state change handler 'is authenticated' for 'a request for an animal as text with an ID'
HERE: before each

[lhokktyn]

Just picking up on this as we too have come across this behaviour of afterEach being prematurely called in the latest version (13.1.13).

Log snippet:

DEBUG ThreadId(02) verify_interaction{interaction="a sample status description"}: hyper_util::client::legacy::pool: reuse idle connection for ("http", 127.0.0.1:58805)
DEBUG (37023): pact@13.1.3: incoming request: {"body":{},"headers":{"accept":"application/json","accept-encoding":"gzip, deflate","host":"127.0.0.1:58805"},"method":"GET","path":"/find"}
DEBUG (37023): pact@13.1.3: Proxying GET: /find
DEBUG (37023): pact@13.1.3: executing 'afterEach' hook
DEBUG (37023): pact@13.1.3: outgoing response: {"body":"[]","headers":{"content-type":"application/json","content-length":"2","connection":"close"},"status":200}

afterEach appears to be executed in between the Proxying GET: /find activity, and the outgoing response... activity, whereas I'd expect afterEach to be mentioned after the response had completed.

This means we're unable to use afterEach to perform any state clean up because doing do will clear out the state before the response has had a chance to be built.

[YOU54F]

Should be resolved by #1242

Feel free to comment back or raise a new issue if not sorted