Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Pact consumer core crash prevents interactions being completed when using V4 spec #470

Open
5 tasks done
lhokktyn opened this issue Oct 26, 2023 · 1 comment
Open
5 tasks done
Labels
bug Indicates an unexpected problem or unintended behavior

Comments

@lhokktyn
Copy link

Software versions

Please provide at least OS and version of pact-js

  • OS: Mac OSX 13.6
  • Pact Node version: @pact-foundation/[email protected]
  • Node Version: 18.13.0
  • Other Versions: Any other versions you think might be relevant (optional)

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
  • 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 code snippet (see below) to illustrate the problem

Expected behaviour

When more than one interaction is tested with pact.addInteraction()...executeTest(), both tests pass without error.

Actual behaviour

The first test passes, but the next one fails with the error:

Test failed for the following reasons:

  Mock server failed with the following mismatches:

        0) The following request was expected but not received: 
            Method: GET
            Path: /pet/one
            Headers:
              Accept: application/json

Pact appears to be re-driving the first interaction, so in subsequent executeTest() calls the mock server is receiving the wrong request.

This feels like user error, but for the life of me I'm not seeing where I've gone wrong! The docs all appear to be geared around V3 at the moment whilst V4 support is in beta, so I've been using examples such as this one to pull things together.

Steps to reproduce

Minimal-ish script to replicate (replicate.js):

import { PactV4, SpecificationVersion, MatchersV3 } from "@pact-foundation/pact";

const { string, number, regex } = MatchersV3;

const provider = new PactV4({
  consumer: "consumer",
  provider: "provider",
  spec: SpecificationVersion.SPECIFICATION_VERSION_V4,
  logLevel: "fatal",
});

const test1 = async () => {
  const petId = "one";
  await provider
    .addInteraction()
    .uponReceiving("a request for a pet with an invalid ID")
    .withRequest('get', regex("/pet/[a-z]+", `/pet/${petId}`), (builder) => builder
      .headers({ Accept: "application/json" })
    )
    .willRespondWith(400, (builder) => builder
      .headers({ "content-type": "application/json" })
      .jsonBody({
        code: number(1),
        type: string("error"),
        message: string("Invalid ID supplied"),
      })
    )
    .executeTest(async (mockserver) => {
      await fetch(`${mockserver.url}/pet/${petId}`, {
        headers: {
          Accept: "application/json",
        },
      });
    });
};

const test2 = async () => {
  const petId = 100;
  await provider
    .addInteraction()
    .given("no pets exist")
    .uponReceiving("a request for a pet with an ID")
    .withRequest('get', regex("/pet/[0-9]+", `/pet/${petId}`), (builder) => builder
      .headers({ Accept: "application/json" })
    )
    .willRespondWith(404, (builder) => builder
      .headers({ "content-type": "text/plain" })
    )
    .executeTest(async (mockserver) => {
      await fetch(`${mockserver.url}/pet/${petId}`, {
        headers: {
          Accept: "application/json",
        },
      });
    });
  };

const delay = (t) => new Promise((r) => setTimeout(r, t));

try {
  await test1();
  await delay(1000); // not needed
  await test2();
} catch(e) {
  console.log(e.message);
}

Run with:

ENABLE_FEATURE_V4=1 PACT_DO_NOT_TRACK=1 node replicate.js

To confirm behaviour with a single test running, comment out await test1() and re-run - it should pass with no error.

Relevant log files

Minimal logs:

2023-10-26T11:43:45.687066Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Received request GET /pet/one
2023-10-26T11:43:45.688576Z  INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: get, path: /pet/one, query: None, headers: Some({"Accept": ["application/json"]}), body: Missing )
2023-10-26T11:43:45.694120Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Request matched, sending response
2023-10-26T11:43:46.710220Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Received request GET /pet/100
2023-10-26T11:43:46.710271Z  INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: get, path: /pet/one, query: None, headers: Some({"Accept": ["application/json"]}), body: Missing )
2023-10-26T11:43:46.710371Z  INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: get, path: /pet/100, query: None, headers: Some({"Accept": ["application/json"]}), body: Missing )
2023-10-26T11:43:46.710428Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Request matched, sending response

Full debug logs:

[12:45:18.045] INFO (73031): 0.4.6: pact native library successfully found, and the correct version
2023-10-26T11:45:18.052784Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: detected pact:matcher:type, will configure a matcher
2023-10-26T11:45:18.053474Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: parsed header value: Left("application/json")
2023-10-26T11:45:18.053881Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: parsed header value: Left("application/json")
2023-10-26T11:45:18.055043Z DEBUG ThreadId(01) pact_plugin_driver::catalogue_manager: Updated catalogue entries:
core/transport/http
core/transport/https
2023-10-26T11:45:18.055137Z DEBUG ThreadId(01) pact_plugin_driver::catalogue_manager: Updated catalogue entries:
core/content-generator/binary
core/content-generator/json
core/content-matcher/json
core/content-matcher/multipart-form-data
core/content-matcher/text
core/content-matcher/xml
2023-10-26T11:45:18.055191Z DEBUG ThreadId(01) pact_plugin_driver::catalogue_manager: Updated catalogue entries:
core/matcher/v1-equality
core/matcher/v2-max-type
core/matcher/v2-min-type
core/matcher/v2-minmax-type
core/matcher/v2-regex
core/matcher/v2-type
core/matcher/v3-content-type
core/matcher/v3-date
core/matcher/v3-datetime
core/matcher/v3-decimal-type
core/matcher/v3-includes
core/matcher/v3-integer-type
core/matcher/v3-null
core/matcher/v3-number-type
core/matcher/v3-time
core/matcher/v4-array-contains
core/matcher/v4-equals-ignore-order
core/matcher/v4-max-equals-ignore-order
core/matcher/v4-min-equals-ignore-order
core/matcher/v4-minmax-equals-ignore-order
core/matcher/v4-not-empty
core/matcher/v4-semver
2023-10-26T11:45:18.055681Z DEBUG ThreadId(01) pact_mock_server::mock_server: Started mock server on 127.0.0.1:52832
2023-10-26T11:45:18.082974Z DEBUG tokio-runtime-worker hyper::proto::h1::io: parsed 7 headers
2023-10-26T11:45:18.083030Z DEBUG tokio-runtime-worker hyper::proto::h1::conn: incoming body is empty
2023-10-26T11:45:18.083086Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Creating pact request from hyper request
2023-10-26T11:45:18.083118Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Extracting query from uri /pet/one
2023-10-26T11:45:18.083188Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Received request GET /pet/one
2023-10-26T11:45:18.083204Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: 
      ----------------------------------------------------------------------------------------
       method: GET
       path: /pet/one
       query: None
       headers: Some({"sec-fetch-mode": ["cors"], "accept-encoding": ["gzip", "deflate"], "accept": ["application/json"], "host": ["127.0.0.1:52832"], "accept-language": ["*"], "user-agent": ["undici"], "connection": ["keep-alive"]})
       body: Empty
      ----------------------------------------------------------------------------------------
      
2023-10-26T11:45:18.083301Z  INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: get, path: /pet/one, query: None, headers: Some({"Accept": ["application/json"]}), body: Missing )
2023-10-26T11:45:18.083329Z DEBUG tokio-runtime-worker pact_matching:      body: ''
2023-10-26T11:45:18.083340Z DEBUG tokio-runtime-worker pact_matching:      matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {DocPath { path_tokens: [Root], expr: "$" }: RuleList { rules: [Regex("/pet/[a-z]+")], rule_logic: And, cascaded: false }} }} }
2023-10-26T11:45:18.083361Z DEBUG tokio-runtime-worker pact_matching:      generators: Generators { categories: {} }
2023-10-26T11:45:18.083507Z DEBUG tokio-runtime-worker pact_matching::matchers: String -> String: comparing '/pet/one' to '/pet/one' ==> true cascaded=false matcher=Regex("/pet/[a-z]+")
2023-10-26T11:45:18.083541Z DEBUG tokio-runtime-worker pact_matching: expected content type = '*/*', actual content type = '*/*'
2023-10-26T11:45:18.083598Z DEBUG tokio-runtime-worker pact_matching: content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
2023-10-26T11:45:18.083707Z DEBUG tokio-runtime-worker pact_matching: --> Mismatches: []
2023-10-26T11:45:18.083792Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Test context = {"mockServer": Object {"port": Number(52832), "url": String("http://127.0.0.1:52832")}}
2023-10-26T11:45:18.083829Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Request matched, sending response
2023-10-26T11:45:18.083840Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: 
          ----------------------------------------------------------------------------------------
           status: 400
           headers: Some({"content-type": ["application/json"]})
           body: Present(57 bytes, application/json) '{"code":1,"message":"Invalid ID supplied","type":"error"}'
          ----------------------------------------------------------------------------------------
          
2023-10-26T11:45:18.083954Z DEBUG tokio-runtime-worker hyper::proto::h1::io: flushed 418 bytes
2023-10-26T11:45:18.092830Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: pact_ffi::mock_server::handles::pactffi_pact_handle_write_file FFI function invoked
2023-10-26T11:45:18.093014Z DEBUG ThreadId(01) pact_models::pact: Merging pact with file "./pacts/consumer-provider.json"
2023-10-26T11:45:18.094448Z DEBUG ThreadId(01) pact_matching::metrics: Could not get the tokio runtime, will not send metrics - there is no reactor running, must be called from the context of a Tokio 1.x runtime
2023-10-26T11:45:18.094488Z DEBUG ThreadId(01) pact_mock_server::server_manager: Shutting down mock server with ID 530ec6d6-7f87-495c-b47c-f20a32846ee8 - MockServerMetrics { requests: 1, requests_by_path: {"/pet/one": 1} }
2023-10-26T11:45:18.094517Z DEBUG ThreadId(01) pact_mock_server::mock_server: Mock server 530ec6d6-7f87-495c-b47c-f20a32846ee8 shutdown - MockServerMetrics { requests: 1, requests_by_path: {"/pet/one": 1} }
2023-10-26T11:45:18.094542Z DEBUG tokio-runtime-worker hyper::server::shutdown: signal received, starting graceful shutdown
2023-10-26T11:45:18.094826Z DEBUG ThreadId(01) pact_ffi::plugins: pact_ffi::plugins::pactffi_cleanup_plugins FFI function invoked
[12:45:19.096] ERROR (73031): [email protected]: !!!!!!!!! PACT CRASHED !!!!!!!!!

The pact consumer core returned false at 'given'. This
should only happen if the core methods were invoked out of order

...[snip]...

[12:45:19.097] ERROR (73031): [email protected]: !!!!!!!!! PACT CRASHED !!!!!!!!!

The pact consumer core returned false at 'uponReceiving'. This
should only happen if the core methods were invoked out of order

...[snip]...

2023-10-26T11:45:19.097852Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: detected pact:matcher:type, will configure a matcher
[12:45:19.097] ERROR (73031): [email protected]: !!!!!!!!! PACT CRASHED !!!!!!!!!

The pact consumer core returned false at 'withRequest'. This
should only happen if the core methods were invoked out of order

...[snip]...

2023-10-26T11:45:19.098453Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: parsed header value: Left("application/json")
[12:45:19.098] ERROR (73031): [email protected]: !!!!!!!!! PACT CRASHED !!!!!!!!!

The pact consumer core returned false at 'withRequestHeader'. This
should only happen if the core methods were invoked out of order

...[snip]...

[12:45:19.098] ERROR (73031): [email protected]: !!!!!!!!! PACT CRASHED !!!!!!!!!

The pact consumer core returned false at 'withStatus'. This
should only happen if the core methods were invoked out of order

...[snip]...

2023-10-26T11:45:19.099126Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: parsed header value: Left("text/plain")
[12:45:19.099] ERROR (73031): [email protected]: !!!!!!!!! PACT CRASHED !!!!!!!!!

The pact consumer core returned false at 'withResponseHeader'. This
should only happen if the core methods were invoked out of order

...[snip]...

2023-10-26T11:45:19.099795Z DEBUG ThreadId(01) pact_mock_server::mock_server: Started mock server on 127.0.0.1:52835
2023-10-26T11:45:19.101570Z DEBUG tokio-runtime-worker hyper::proto::h1::io: parsed 7 headers
2023-10-26T11:45:19.101593Z DEBUG tokio-runtime-worker hyper::proto::h1::conn: incoming body is empty
2023-10-26T11:45:19.101607Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Creating pact request from hyper request
2023-10-26T11:45:19.101617Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Extracting query from uri /pet/100
2023-10-26T11:45:19.101656Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Received request GET /pet/100
2023-10-26T11:45:19.101667Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: 
      ----------------------------------------------------------------------------------------
       method: GET
       path: /pet/100
       query: None
       headers: Some({"connection": ["keep-alive"], "sec-fetch-mode": ["cors"], "host": ["127.0.0.1:52835"], "user-agent": ["undici"], "accept-language": ["*"], "accept-encoding": ["gzip", "deflate"], "accept": ["application/json"]})
       body: Empty
      ----------------------------------------------------------------------------------------
      
2023-10-26T11:45:19.101738Z  INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: get, path: /pet/one, query: None, headers: Some({"Accept": ["application/json"]}), body: Missing )
2023-10-26T11:45:19.101750Z DEBUG tokio-runtime-worker pact_matching:      body: ''
2023-10-26T11:45:19.101757Z DEBUG tokio-runtime-worker pact_matching:      matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {DocPath { path_tokens: [Root], expr: "$" }: RuleList { rules: [Regex("/pet/[a-z]+")], rule_logic: And, cascaded: false }} }} }
2023-10-26T11:45:19.101767Z DEBUG tokio-runtime-worker pact_matching:      generators: Generators { categories: {} }
2023-10-26T11:45:19.101805Z DEBUG tokio-runtime-worker pact_matching::matchers: String -> String: comparing '/pet/one' to '/pet/100' ==> false cascaded=false matcher=Regex("/pet/[a-z]+")
2023-10-26T11:45:19.101838Z DEBUG tokio-runtime-worker pact_matching: expected content type = '*/*', actual content type = '*/*'
2023-10-26T11:45:19.101853Z DEBUG tokio-runtime-worker pact_matching: content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
2023-10-26T11:45:19.101882Z DEBUG tokio-runtime-worker pact_matching: --> Mismatches: [PathMismatch { expected: "/pet/one", actual: "/pet/100", mismatch: "Expected '/pet/100' to match '/pet/[a-z]+'" }]
2023-10-26T11:45:19.101922Z  INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: get, path: /pet/100, query: None, headers: Some({"Accept": ["application/json"]}), body: Missing )
2023-10-26T11:45:19.101932Z DEBUG tokio-runtime-worker pact_matching:      body: ''
2023-10-26T11:45:19.101938Z DEBUG tokio-runtime-worker pact_matching:      matching_rules: MatchingRules { rules: {PATH: MatchingRuleCategory { name: PATH, rules: {DocPath { path_tokens: [Root], expr: "$" }: RuleList { rules: [Regex("/pet/[0-9]+")], rule_logic: And, cascaded: false }} }, HEADER: MatchingRuleCategory { name: HEADER, rules: {} }} }
2023-10-26T11:45:19.101946Z DEBUG tokio-runtime-worker pact_matching:      generators: Generators { categories: {} }
2023-10-26T11:45:19.101966Z DEBUG tokio-runtime-worker pact_matching::matchers: String -> String: comparing '/pet/100' to '/pet/100' ==> true cascaded=false matcher=Regex("/pet/[0-9]+")
2023-10-26T11:45:19.101979Z DEBUG tokio-runtime-worker pact_matching: expected content type = '*/*', actual content type = '*/*'
2023-10-26T11:45:19.101990Z DEBUG tokio-runtime-worker pact_matching: content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
2023-10-26T11:45:19.102008Z DEBUG tokio-runtime-worker pact_matching: --> Mismatches: []
2023-10-26T11:45:19.102047Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Test context = {"mockServer": Object {"port": Number(52835), "url": String("http://127.0.0.1:52835")}}
2023-10-26T11:45:19.102062Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Request matched, sending response
2023-10-26T11:45:19.102070Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: 
          ----------------------------------------------------------------------------------------
           status: 404
           headers: Some({"content-type": ["text/plain"]})
           body: Missing
          ----------------------------------------------------------------------------------------
          
2023-10-26T11:45:19.102122Z DEBUG tokio-runtime-worker hyper::proto::h1::io: flushed 352 bytes
2023-10-26T11:45:19.103908Z DEBUG ThreadId(01) pact_matching::metrics: Could not get the tokio runtime, will not send metrics - there is no reactor running, must be called from the context of a Tokio 1.x runtime
2023-10-26T11:45:19.103948Z DEBUG ThreadId(01) pact_mock_server::server_manager: Shutting down mock server with ID 9ef4391d-30e7-4844-84c8-c4b20a64aacb - MockServerMetrics { requests: 1, requests_by_path: {"/pet/100": 1} }
2023-10-26T11:45:19.103965Z DEBUG ThreadId(01) pact_mock_server::mock_server: Mock server 9ef4391d-30e7-4844-84c8-c4b20a64aacb shutdown - MockServerMetrics { requests: 1, requests_by_path: {"/pet/100": 1} }
2023-10-26T11:45:19.103985Z DEBUG tokio-runtime-worker hyper::server::shutdown: signal received, starting graceful shutdown
2023-10-26T11:45:19.104104Z DEBUG ThreadId(01) pact_ffi::plugins: pact_ffi::plugins::pactffi_cleanup_plugins FFI function invoked
Test failed for the following reasons:

  Mock server failed with the following mismatches:

	0) The following request was expected but not received: 
	    Method: GET
	    Path: /pet/one
	    Headers:
	      Accept: application/json

@lhokktyn lhokktyn added the bug Indicates an unexpected problem or unintended behavior label Oct 26, 2023
@lhokktyn
Copy link
Author

Tweaking this a little to turn provider into a factory function, so generating a new PactV4 instance for every interaction, seems to resolve the issue:

import { PactV4, SpecificationVersion, MatchersV3 } from "@pact-foundation/pact";

const { string, number, regex } = MatchersV3;

const provider = () => new PactV4({
  consumer: "consumer",
  provider: "provider",
  spec: SpecificationVersion.SPECIFICATION_VERSION_V4,
  logLevel: "fatal",
});

const test1 = async () => {
  const petId = "one";
  await provider()
    .addInteraction()
    .uponReceiving("a request for a pet with an invalid ID")
    .withRequest('get', regex("/pet/[a-z]+", `/pet/${petId}`), (builder) => builder
      .headers({ Accept: "application/json" })
    )
    .willRespondWith(400, (builder) => builder
      .headers({ "content-type": "application/json" })
      .jsonBody({
        code: number(1),
        type: string("error"),
        message: string("Invalid ID supplied"),
      })
    )
    .executeTest(async (mockserver) => {
      await fetch(`${mockserver.url}/pet/${petId}`, {
        headers: {
          Accept: "application/json",
        },
      });
    });
};

const test2 = async () => {
  const petId = 100;
  await provider()
    .addInteraction()
    .given("no pets exist")
    .uponReceiving("a request for a pet with an ID")
    .withRequest('get', regex("/pet/[0-9]+", `/pet/${petId}`), (builder) => builder
      .headers({ Accept: "application/json" })
    )
    .willRespondWith(404, (builder) => builder
      .headers({ "content-type": "text/plain" })
    )
    .executeTest(async (mockserver) => {
      await fetch(`${mockserver.url}/pet/${petId}`, {
        headers: {
          Accept: "application/json",
        },
      });
    });
  };

const delay = (t) => new Promise((r) => setTimeout(r, t));

try {
  await test1();
  // await delay(1000); // not needed
  await test2();
} catch(e) {
  console.log(e.message);
}

And both interactions are written to the same pact json without conflict. So problem solved ... but is the correct approach? The example I was following is 3 months old at the time of writing, so perhaps things have moved on?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Indicates an unexpected problem or unintended behavior
Projects
None yet
Development

No branches or pull requests

1 participant