Compatibility Suite: Random fail on 'Supports a random hexadecimal generator' scenario

[tienvx]

   Scenario: Supports a random hexadecimal generator                                     # compatibility-suite/pact-compatibility-suite/features/V3/generators.feature:17
    Given a request configured with the following generators:                           # PhpPactTest\CompatibilitySuite\Context\V3\RequestGeneratorsContext::aRequestConfiguredWithTheFollowingGenerators()
      | body             | generators               |
      | file: basic.json | randomhex-generator.json |

Verifying a pact between c and p

  Interaction 1 (0s loading, 7ms verification)
    returns a response which
      has status code 200 (FAILED)
      has a matching body (OK)


Failures:

1) Verifying a pact between c and p - Interaction 1
    1.1) has status code 200
           expected 200 but was 500

There were 1 pact failures

     When the request is prepared for use                                                # PhpPactTest\CompatibilitySuite\Context\V3\RequestGeneratorsContext::theRequestIsPreparedForUse()
    Then the body value for "$.one" will have been replaced with a "hexadecimal number" # PhpPactTest\CompatibilitySuite\Context\V3\BodyGeneratorsContext::theBodyValueForWillHaveBeenReplacedWithA()
      string does not contain a valid JSON object. (JsonPath\InvalidJsonException)

[tienvx]

Full log:

2024-10-20T09:01:29.631469Z DEBUG ThreadId(02) pact_models::content_types: Detecting content type from contents: '{"one":{"pact:generator:type":"RandomHexadecimal","digits":6,"pact:matcher:type":"integer","value":null},"two":"b"}'
2024-10-20T09:01:29.631540Z DEBUG ThreadId(02) pact_ffi::mock_server::bodies: Path = $
2024-10-20T09:01:29.631547Z DEBUG ThreadId(02) pact_ffi::mock_server::bodies: Configuring a normal object
2024-10-20T09:01:29.631564Z DEBUG ThreadId(02) pact_ffi::mock_server::bodies: Path = $.one
2024-10-20T09:01:29.631568Z DEBUG ThreadId(02) pact_ffi::mock_server::bodies: detected pact:matcher:type, will configure a matcher
2024-10-20T09:01:29.631597Z DEBUG ThreadId(02) pact_ffi::mock_server::bodies: detected pact:generator:type, will configure a generators
2024-10-20T09:01:29.631646Z DEBUG ThreadId(02) pact_ffi::mock_server::handles: Failed to parse the value, treating it as a plain string: expected value at line 1 column 1
2024-10-20T09:01:29.631677Z DEBUG ThreadId(02) pact_ffi::mock_server: pact_ffi::mock_server::pactffi_create_mock_server_for_transport FFI function invoked
2024-10-20T09:01:29.631955Z DEBUG ThreadId(02) pact_mock_server::mock_server: Started mock server on ::1:41989
2024-10-20T09:01:29.632033Z  INFO ThreadId(02) pact_mock_server::mock_server: Writing pact out to '/home/runner/work/pact-php/pact-php/compatibility-suite/tests/Constant/../../pacts/c-p.json'
2024-10-20T09:01:29.632054Z DEBUG ThreadId(02) pact_models::pact: Writing new pact file to "/home/runner/work/pact-php/pact-php/compatibility-suite/tests/Constant/../../pacts/c-p.json"
2024-10-20T09:01:29.632270Z DEBUG ThreadId(02) 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
2024-10-20T09:01:29.632287Z DEBUG ThreadId(02) pact_mock_server::server_manager: Shutting down mock server with ID 574f268b-dc0a-42f9-af62-9ee22a0cad4a - MockServerMetrics { requests: 0, requests_by_path: {} }
2024-10-20T09:01:29.632300Z DEBUG ThreadId(02) pact_mock_server::mock_server: Mock server 574f268b-dc0a-42f9-af62-9ee22a0cad4a shutdown - MockServerMetrics { requests: 0, requests_by_path: {} }
2024-10-20T09:01:29.632308Z DEBUG tokio-runtime-worker hyper::server::shutdown: signal received, starting graceful shutdown
2024-10-20T09:01:29.633317Z DEBUG ThreadId(02) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_new_for_application FFI function invoked
2024-10-20T09:01:29.633343Z DEBUG ThreadId(02) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_set_provider_info FFI function invoked
2024-10-20T09:01:29.633360Z DEBUG ThreadId(02) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_set_filter_info FFI function invoked
2024-10-20T09:01:29.633371Z DEBUG ThreadId(02) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_set_provider_state FFI function invoked
2024-10-20T09:01:29.633382Z DEBUG ThreadId(02) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_set_verification_options FFI function invoked
2024-10-20T09:01:29.633394Z DEBUG ThreadId(02) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_set_consumer_filters FFI function invoked
2024-10-20T09:01:29.633406Z DEBUG ThreadId(02) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_add_file_source FFI function invoked
2024-10-20T09:01:29.633416Z DEBUG ThreadId(02) pact_ffi::verifier: pact_ffi::verifier::pactffi_verifier_execute FFI function invoked
2024-10-20T09:01:29.633420Z DEBUG ThreadId(02) pact_ffi::verifier::handle: Pact source to verify = File(/home/runner/work/pact-php/pact-php/compatibility-suite/tests/Constant/../../pacts/c-p.json)
2024-10-20T09:01:29.639095Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier: Executing provider states
2024-10-20T09:01:29.639113Z  INFO ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier: Running setup provider state change handler with empty state for 'Interaction 1'
2024-10-20T09:01:29.639120Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier: State Change: "ProviderState { name: "", params: {} }" -> Ok({})
2024-10-20T09:01:29.639130Z  INFO ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier: Running provider verification for 'Interaction 1'
2024-10-20T09:01:29.639142Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier: Verifying a HTTP interaction
2024-10-20T09:01:29.639167Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_matching: Applying body generators...
2024-10-20T09:01:29.639198Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_matching::generators::bodies: apply_body_generators: JSON content type
2024-10-20T09:01:29.639214Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_models::generators: Applying generator RandomHexadecimal(6) to key $.one
2024-10-20T09:01:29.639231Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_models::generators: Generating value from RandomHexadecimal(6) context={}
2024-10-20T09:01:29.639248Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_models::generators: Generated value = Ok(String("01B39D"))
2024-10-20T09:01:29.639272Z  INFO ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier::provider_client: Sending request to provider at http://localhost:45243/
2024-10-20T09:01:29.639281Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier::provider_client: Provider details = ProviderInfo { name: "p", protocol: "http", host: "localhost", port: Some(45243), path: "/", transports: [ProviderTransport { transport: "http", port: Some(45243), path: Some("/"), scheme: Some("http") }] }
2024-10-20T09:01:29.639289Z  INFO ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier::provider_client: Sending request HTTP Request ( method: PUT, path: /request-generators, query: None, headers: Some({"Content-Type": ["application/json"]}), body: Present(26 bytes, application/json) )
2024-10-20T09:01:29.639300Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier::provider_client: body:
{"one":"01B39D","two":"b"}
2024-10-20T09:01:29.639411Z DEBUG tokio-runtime-worker hyper_util::client::legacy::connect::dns: resolving host="localhost"
2024-10-20T09:01:29.639578Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: hyper_util::client::legacy::connect::http: connecting to [::1]:45243
2024-10-20T09:01:29.639763Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: hyper_util::client::legacy::connect::http: connected to [::1]:45243
2024-10-20T09:01:29.639960Z DEBUG tokio-runtime-worker hyper::proto::h1::io: parsed 5 headers
2024-10-20T09:01:29.639972Z DEBUG tokio-runtime-worker hyper::proto::h1::conn: incoming body is content-length (26 bytes)
2024-10-20T09:01:29.639984Z DEBUG tokio-runtime-worker hyper::proto::h1::conn: incoming body completed
2024-10-20T09:01:29.639998Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Creating pact request from hyper request
2024-10-20T09:01:29.640009Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Extracting query from uri /request-generators
2024-10-20T09:01:29.640047Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Received request PUT /request-generators
2024-10-20T09:01:29.640056Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: 
      ----------------------------------------------------------------------------------------
       method: PUT
       path: /request-generators
       query: None
       headers: Some({"host": ["localhost:45243"], "accept-encoding": ["gzip", "deflate"], "accept": ["*/*"], "content-length": ["26"], "content-type": ["application/json"]})
       body: Present(26 bytes, application/json) '{"one":"01B39D","two":"b"}'
      ----------------------------------------------------------------------------------------
      
2024-10-20T09:01:29.640096Z DEBUG tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: POST, path: /messages, query: None, headers: Some({"Content-Type": ["application/json"]}), body: Present(23 bytes, application/json) )
2024-10-20T09:01:29.640106Z DEBUG tokio-runtime-worker pact_matching:      body: '{"description":"basic"}'
2024-10-20T09:01:29.640109Z DEBUG tokio-runtime-worker pact_matching:      matching_rules: MatchingRules { rules: {BODY: MatchingRuleCategory { name: BODY, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {} }} }
2024-10-20T09:01:29.640114Z DEBUG tokio-runtime-worker pact_matching:      generators: Generators { categories: {} }
2024-10-20T09:01:29.640136Z DEBUG tokio-runtime-worker pact_matching::matchers: String -> String: comparing '/messages' to '/request-generators' ==> false cascaded=false matcher=Equality
2024-10-20T09:01:29.640151Z DEBUG tokio-runtime-worker pact_matching: expected content type = 'application/json', actual content type = 'application/json'
2024-10-20T09:01:29.640171Z DEBUG tokio-runtime-worker pact_matching: content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
2024-10-20T09:01:29.640182Z DEBUG tokio-runtime-worker pact_plugin_driver::catalogue_manager: Looking for a content matcher for application/json
2024-10-20T09:01:29.640772Z DEBUG tokio-runtime-worker pact_matching: No content matcher defined for content type 'application/json', using core matcher implementation
2024-10-20T09:01:29.640784Z DEBUG tokio-runtime-worker pact_matching: Using body matcher for content type 'application/json'
2024-10-20T09:01:29.640794Z DEBUG tokio-runtime-worker pact_matching::json: compare: Comparing path $
2024-10-20T09:01:29.640798Z DEBUG tokio-runtime-worker pact_matching::json: compare_maps: Comparing maps at $: {"description": String("basic")} -> {"one": String("01B39D"), "two": String("b")}
2024-10-20T09:01:29.640861Z DEBUG tokio-runtime-worker pact_matching: --> Mismatches: [MethodMismatch { expected: "POST", actual: "PUT" }, PathMismatch { expected: "/messages", actual: "/request-generators", mismatch: "Expected '/request-generators' to be equal to '/messages'" }, BodyMismatch { path: "$", expected: Some(b"[\"description\"]"), actual: Some(b"[\"one\",\"two\"]"), mismatch: "Expected a Map with keys [description] but received one with keys [one, two]" }]
2024-10-20T09:01:29.640907Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Request did not match: Request was not expected - HTTP Request ( method: PUT, path: /request-generators, query: None, headers: Some({"host": ["localhost:45243"], "accept-encoding": ["gzip", "deflate"], "accept": ["*/*"], "content-length": ["26"], "content-type": ["application/json"]}), body: Present(26 bytes, application/json) )
2024-10-20T09:01:29.640979Z DEBUG tokio-runtime-worker hyper::proto::h1::io: flushed 768 bytes
2024-10-20T09:01:29.641121Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: hyper_util::client::legacy::pool: pooling idle connection for ("http", localhost:45243)
2024-10-20T09:01:29.641143Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier::provider_client: Received native response: Response { url: "http://localhost:45243/request-generators", status: 500, headers: {"access-control-allow-origin": "*", "content-type": "application/json; charset=utf-8", "x-pact": "Unexpected-Request", "content-length": "565", "date": "Sun, 20 Oct 2024 09:01:28 GMT"} }
2024-10-20T09:01:29.641194Z  INFO ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier::provider_client: Received response: HTTP Response ( status: 500, headers: Some({"x-pact": ["Unexpected-Request"], "date": ["Sun, 20 Oct 2024 09:01:28 GMT"], "access-control-allow-origin": ["*"], "content-length": ["565"], "content-type": ["application/json; charset=utf-8"]}), body: Present(565 bytes, application/json;charset=utf-8) )
2024-10-20T09:01:29.641209Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_verifier::provider_client: body:
{"error":"Unexpected-Request : HttpRequest { method: \"PUT\", path: \"/request-generators\", query: None, headers: Some({\"host\": [\"localhost:45243\"], \"accept-encoding\": [\"gzip\", \"deflate\"], \"accept\": [\"*/*\"], \"content-length\": [\"26\"], \"content-type\": [\"application/json\"]}), body: Present(b\"{\\\"one\\\":\\\"01B39D\\\",\\\"two\\\":\\\"b\\\"}\", Some(ContentType { main_type: \"application\", sub_type: \"json\", attributes: {}, suffix: None }), None), matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }"}
2024-10-20T09:01:29.641222Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_matching: comparing to expected response: HTTP Response ( status: 200, headers: None, body: Missing )
2024-10-20T09:01:29.641236Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_matching: expected content type = '*/*', actual content type = 'application/json;charset=utf-8'
2024-10-20T09:01:29.641251Z DEBUG ThreadId(02) verify_interaction{interaction="Interaction 1"}: pact_matching: content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
2024-10-20T09:01:29.641364Z DEBUG tokio-runtime-worker hyper::proto::h1::conn: read eof
2024-10-20T09:01:29.641380Z DEBUG ThreadId(02) pact_matching::metrics: 'PACT_DO_NOT_TRACK' environment variable is set, will not send metrics

[tienvx]

Real issue:

2024-10-20T09:01:29.640861Z DEBUG tokio-runtime-worker pact_matching: --> Mismatches: [MethodMismatch { expected: "POST", actual: "PUT" }, PathMismatch { expected: "/messages", actual: "/request-generators", mismatch: "Expected '/request-generators' to be equal to '/messages'" }, BodyMismatch { path: "$", expected: Some(b"[\"description\"]"), actual: Some(b"[\"one\",\"two\"]"), mismatch: "Expected a Map with keys [description] but received one with keys [one, two]" }]

[tienvx]

The root cause is: the registered interaction for POST '/messages' is not clean up from mock server after being used.