search

pact-foundation / pact-js

JS version of Pact. Pact is a contract testing framework for HTTP APIs and non-HTTP asynchronous messaging systems.
https://pact.io
Other
1.62k stars 344 forks source link

Header is parsed incorrectly #1058

Open GeorgeTailor opened 1 year ago

GeorgeTailor commented 1 year ago

Software versions

Please provide at least OS and version of pact-js

Issue Checklist

Please confirm the following:

Expected behaviour

Header should be parsed as a string, without default behaviour of splitting it by comma for every possible HTTP header.

Actual behaviour

No matter what value is passed in a HTTP Header and what is its name it is always split if it has a comma in it.

Steps to reproduce

Given the following code:

provider
            .given('assignments exist')
            .uponReceiving('a request for all assignments')
            .withRequest({
                method: 'GET',
                path: '/api/assignments',
                headers: {
                    Accept: 'application/json',
                    'X-Custom-Header': '{"id":"asd-asdasd-sd","additionalInfo":"some additional string"}'
                }
            })
            .willRespondWith({
                status: 200,
                headers: { 'Content-Type': 'application/json' },
                body:[]
            });

return provider.executeTest(async mockserver => {
            const response = await axios.get(`${mockserver.url}/api/assignments`, {
                headers: {
                     'X-Custom-Header': '{"id":"asd-asdasd-sd","additionalInfo":"some additional string"}'
                }
            });

            expect(response.data).toEqual([]);
        });

This test fails as pact splits the header by comma and tries to compare a part of invalid JSON between what was sent and what was received. When the header is a string that does not contain any commas it works.

Relevant log files

pact@10.4.1: Test failed for the following reasons:

  Mock server failed with the following mismatches:

        0) The following request was incorrect: 

                GET /api/assignments

                         1.0 Mismatch with header 'X-Custom-Header': Expected '' to be equal to '{"id":"asd-asdasd-sd"' for value at index 0
TimothyJones commented 1 year ago

I agree, this isn't the right behaviour.

TimothyJones commented 1 year ago

Possibly downgrading to 10.4.0 will allow you to work around this - as it looks like this commit is the culprit: https://github.com/pact-foundation/pact-js/commit/9c7939edc944d6736940215deacbe670ed33a29a (cc @mefellows)

mefellows commented 1 year ago

Yes, it's a bug thanks for raising it. Will need a bit of thinking, because that change was introduced to fix an upstream issue. I

mefellows commented 1 year ago

See also https://github.com/pact-foundation/pact-js/issues/1031

TimothyJones commented 1 year ago

Each header has different semantics, so maybe the solution is in specific matchers for different headers.

mefellows commented 1 year ago

Yes, that might be the way about it.

GeorgeTailor commented 1 year ago

I've tested it with 10.4.0 and it behaves the same for this particular case.

mefellows commented 1 year ago

It might be that the core is doing the split also. Out of interest, have you tried the 10.3.x branch?

@rholshausen FYI

rholshausen commented 1 year ago

Currently, the matching assumes all headers follow the RFC multi-value format, unless they specifically don't (like Date has a comma in that should not be split).

Maybe we need to change it to assume headers are single values only, unless they are known multi-value headers. But then if someone creates a new custom header and expects it to be parsed as a multiple value one, it won't work. Maybe configuration to say a header is multi-value or not.

We can also wait for everyone to move over to HTTP2, where this problem goes away because the number of values are explicit in the protocol, and not in the encoded value.

TimothyJones commented 1 year ago

I’m on mobile so it’s not easy to check, but I thought the current RFC just says header values are a string?

I think a specific type of matcher is probably the way to go here

mefellows commented 1 year ago

If my reading is correct, all of these registrations potentially require special treatment. At the very least, Accept and all of the Accept-* accept a comma delimited list that need not be quoted. Anything with the # ABNF notation extension is a comma-separated list, and unfortunately it seems hard to find a definitive list for these. via is another header that allows lists, but is not in that registry, so I'm sure that list is not definitive.

As a general rule, others (including unspecified headers) I believe are essentially a quoted string, which shouldn't be split.

This paragraph I think is the key:

Because commas (",") are used as a generic delimiter between field-values, they need to be treated with care if they are allowed in the field-value. Typically, components that might contain a comma are protected with double-quotes using the quoted-string ABNF production.

mefellows commented 1 year ago

(AH! I forgot to hit send on it, just an FYI)

We can also wait for everyone to move over to HTTP2, where this problem goes away because the number of values are explicit in the protocol, and not in the encoded value.

I'm sure we'll be there very soon. Remember how quickly we all moved to IPv6?

Maybe we need to change it to assume headers are single values only, unless they are known multi-value headers. But then if someone creates a new custom header and expects it to be parsed as a multiple value one, it won't work. Maybe configuration to say a header is multi-value or not.

I've actually updated the Pact JS types to allow a header to be specified as a key with one or more values:

export declare type TemplateHeaders = {
  [header: string]:
    | string
    | MatchersV3.Matcher<string>
    | (MatchersV3.Matcher<string> | string)[];
};

This would make it explicit in the test itself (and means the various components of the headers may also be matched). When we call pactffi_with_header_v2 it could then be assumed by the length of the resulting array type if it should be split or not?

mslowiak commented 1 year ago

It might be that the core is doing the split also. Out of interest, have you tried the 10.3.x branch?

@mefellows Unfortunately, it is not working as well for 10.0.x, 10.1.x, 10.2.x, 10.3.x. Is it possible to get the rough ETA to fix this bug?

mefellows commented 1 year ago

Hi Marcin, thanks for clarifying. I suspect that's related to the previous bug that was addressed in the related change above.

I'll have to work with the team to come back to you on an ETA.

mslowiak commented 1 year ago

We are really keen on work more with Pact, but this is a blocker for us to utilize the tool.

Thanks for response, waiting then for more information 🙇‍♂️

github-actions[bot] commented 1 year ago

👋 Thanks, this ticket has been added to the PactFlow team's backlog as PACT-714

mefellows commented 1 year ago

I've just added a label "smartbear supported" to the ticket, which will create an internal tracking issue in PactFlow's Jira (see that comment above). We will use this to prioritise and assign a team member to this task.

All activity will be public on this ticket. For now, sit tight and we'll update this ticket once we have more information on the next steps.

mefellows commented 1 year ago

@rholshausen does https://github.com/pact-foundation/pact-reference/issues/259 fix the underlying issue here? I think I just need to remove any comma splitting present in Pact JS and defer to the core for logic around multi valued headers, is that right?

rholshausen commented 1 year ago

No, it still follows the header grammar as documented in the RFC, but if you pass an array as the value, it should just use it as is. But I haven't tested this.

webcodesailor commented 1 year ago

We we have any update on this one?

mefellows commented 1 year ago

See upstream issue here: https://github.com/pact-foundation/pact-reference/issues/300

mefellows commented 1 year ago

Failing example: https://github.com/pact-foundation/pact-js/compare/repro/pact-js-issue-1058?expand=1

kroupacz commented 1 year ago

Hello @mefellows did you really test the @GeorgeTailor's case when some custom "x-header" has stringified json as value? Today I updated @pact-foundation/pact to version 12.1.0 and I believe it is still not working.

OS: e.g. Mac OSX 10.15.7 Consumer Pact library: "@pact-foundation/pact": "12.1.0", Node Version: v18.14.0 Pact specification: V3

Pact V3 interaction request:

  withRequest: {
    method: 'GET',
    path: '/api/accounts/oem_user:12345',
    headers: {
      'x-info': JSON.stringify({
        active: true,
        scope: 'read',
        sub: 'oem_user:12345',
      }),
    },
  },

logs:

2023-08-02T09:40:36.432582Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Received request GET /api/accounts/oem_user:12345
2023-08-02T09:40:36.432590Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: 
      ----------------------------------------------------------------------------------------
       method: GET
       path: /api/accounts/oem_user:12345
       query: None
       headers: Some({"accept": ["application/json", "text/plain", "*/*"], "x-info": ["{\"active\":true", "\"scope\":\"read\"", "\"sub\":\"oem_user:12345\"}"], "x-request-id": ["b24d7f83-db85-4f69-8727-5e0d206be26f"], "accept-encoding": ["gzip", "compress", "deflate", "br"], "user-agent": ["axios/1.3.2"], "host": ["127.0.0.1:55668"], "connection": ["close"]})
       body: Empty
      ----------------------------------------------------------------------------------------

2023-08-02T09:40:36.433335Z  INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: GET, path: /api/accounts/oem_user:12345, query: None, headers: Some({"x-info": [""]}), body: Missing )

.......
.....

pact@12.1.0: Test failed for the following reasons:

  Mock server failed with the following mismatches:

        0) The following request was incorrect: 

                GET /api/accounts/oem_user:12345

                         1.0 Mismatch with header 'x-info': Expected '{"active":true' to be equal to '' for value at index 0
                         1.1 Mismatch with header 'x-info': Expected '"scope":"read"' to be equal to '' for value at index 1
                         1.2 Mismatch with header 'x-info': Expected '"sub":"oem_user:12345"' to be equal to '' for value at index 2
mefellows commented 1 year ago

It looks like the JSON object is being iterated on, and each key in the JSON structure is being converted into an index

The repro is here: https://github.com/pact-foundation/pact-js/blob/repro/pact-js-issue-1058/examples/mocha/test/get-dogs.spec.js#L51

✗ npm t

> mochajs-pact-example@1.0.0 test
> rimraf pacts && mocha

[21:40:41.119] TRACE (63992): pact-core@14.0.1: Initiliasing ffi for the first time
[21:40:41.125] DEBUG (63992): pact-core@14.0.1: Initalising native core at log level 'TRACE'
[21:40:41.126] DEBUG (63992): pact-core@14.0.1: binding path #0: : attempting to load native module from:

 - /Users/matthew.fellows/development/public/pact-js/node_modules/@pact-foundation/pact-core/prebuilds/darwin-x64
   source: pact-js-core binding lookup

 - You can override via PACT_PREBUILD_LOCATION

[21:40:41.138] DEBUG (63992): pact-core@14.0.1: binding path #1: : attempting to load native module from:

 - /Users/matthew.fellows/development/public/pact-js/examples/mocha/prebuilds/darwin-x64
   source: pact-js-core binding lookup

 - You can override via PACT_PREBUILD_LOCATION

2023-08-02T11:40:41.165063Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact - ref = 1, keys = [1]
2023-08-02T11:40:41.169383Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact before - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V3 } }
2023-08-02T11:40:41.173168Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact after - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
2023-08-02T11:40:41.173512Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact - ref = 1, keys = [1]
2023-08-02T11:40:41.173650Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact before - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
2023-08-02T11:40:41.178157Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact after - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "", provider_states: [], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
2023-08-02T11:40:41.179726Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact - ref = 1, keys = [1]
2023-08-02T11:40:41.179746Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact before - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "", provider_states: [], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
2023-08-02T11:40:41.180684Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact after - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "", provider_states: [], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }

  The Dog API
    get /dogs
2023-08-02T11:40:41.199854Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - index = 1, interaction = 1
2023-08-02T11:40:41.199896Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - keys = [1]
2023-08-02T11:40:41.200499Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - inner = PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "", provider_states: [], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 }
2023-08-02T11:40:41.200971Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - index = 1, interaction = 1
2023-08-02T11:40:41.200981Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - keys = [1]
2023-08-02T11:40:41.200988Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - inner = PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 }
2023-08-02T11:40:41.201824Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - index = 1, interaction = 1
2023-08-02T11:40:41.201835Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - keys = [1]
2023-08-02T11:40:41.201841Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - inner = PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [ProviderState { name: "i have a list of dogs", params: {} }], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 }
[21:40:41.204] DEBUG (63992): pact@12.1.0: setting header request value for X-Custom-Header at index 0 to "\"{\\\"id\\\":\\\"asd-asdasd-sd\\\",\\\"additionalInfo\\\":\\\"some additional string\\\"}\""
2023-08-02T11:40:41.205655Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - index = 1, interaction = 1
2023-08-02T11:40:41.205666Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - keys = [1]
2023-08-02T11:40:41.205673Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - inner = PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [ProviderState { name: "i have a list of dogs", params: {} }], request: HttpRequest { method: "GET", path: "/dogs", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {PATH: MatchingRuleCategory { name: PATH, rules: {} }} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 }
2023-08-02T11:40:41.224309Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: parsed header value: Left("\"{\\\"id\\\":\\\"asd-asdasd-sd\\\",\\\"additionalInfo\\\":\\\"some additional string\\\"}\"")
[21:40:41.226] DEBUG (63992): pact@12.1.0: setting header request value for Accept at index 0 to "application/problem+json, application/json, text/plain, */*"
2023-08-02T11:40:41.227088Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - index = 1, interaction = 1
2023-08-02T11:40:41.227107Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - keys = [1]
2023-08-02T11:40:41.227121Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - inner = PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [ProviderState { name: "i have a list of dogs", params: {} }], request: HttpRequest { method: "GET", path: "/dogs", query: None, headers: Some({"X-Custom-Header": ["\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", "\\\"additionalInfo\\\":\\\"some additional string\\\"}\""]}), body: Missing, matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {} }} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 }
2023-08-02T11:40:41.228060Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: parsed header value: Left("application/problem+json, application/json, text/plain, */*")
2023-08-02T11:40:41.228889Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - index = 1, interaction = 1
2023-08-02T11:40:41.228902Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - keys = [1]
2023-08-02T11:40:41.228911Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - inner = PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [ProviderState { name: "i have a list of dogs", params: {} }], request: HttpRequest { method: "GET", path: "/dogs", query: None, headers: Some({"Accept": ["application/problem+json", "application/json", "text/plain", "*/*"], "X-Custom-Header": ["\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", "\\\"additionalInfo\\\":\\\"some additional string\\\"}\""]}), body: Missing, matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {} }} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 }
2023-08-02T11:40:41.229258Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - index = 1, interaction = 1
2023-08-02T11:40:41.229268Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - keys = [1]
2023-08-02T11:40:41.229274Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - inner = PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [ProviderState { name: "i have a list of dogs", params: {} }], request: HttpRequest { method: "GET", path: "/dogs", query: None, headers: Some({"Accept": ["application/problem+json", "application/json", "text/plain", "*/*"], "X-Custom-Header": ["\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", "\\\"additionalInfo\\\":\\\"some additional string\\\"}\""]}), body: Missing, matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {} }} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 }
[21:40:41.237] DEBUG (63992): pact@12.1.0: setting header response value for application/json at index 0 to "application/json"
2023-08-02T11:40:41.237857Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - index = 1, interaction = 1
2023-08-02T11:40:41.237875Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - keys = [1]
2023-08-02T11:40:41.237885Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_interaction - inner = PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [ProviderState { name: "i have a list of dogs", params: {} }], request: HttpRequest { method: "GET", path: "/dogs", query: None, headers: Some({"Accept": ["application/problem+json", "application/json", "text/plain", "*/*"], "X-Custom-Header": ["\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", "\\\"additionalInfo\\\":\\\"some additional string\\\"}\""]}), body: Missing, matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {} }} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: Some({"Content-Type": ["application/json"]}), body: Present(b"[{\"dog\":1},{\"dog\":2}]", Some(ContentType { main_type: "application", sub_type: "json", attributes: {}, suffix: None }), None), matching_rules: MatchingRules { rules: {BODY: MatchingRuleCategory { name: BODY, rules: {} }} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 }
2023-08-02T11:40:41.238468Z DEBUG ThreadId(01) pact_ffi::mock_server::handles: parsed header value: Left("application/json")
[21:40:41.238] DEBUG (63992): pact@12.1.0: Setting up Pact mock server with Consumer "MyConsumer" and Provider "MyProvider"
        using mock service on Port: "8992"
2023-08-02T11:40:41.241471Z TRACE ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: pact_ffi::mock_server::handles: with_pact - ref = 1, keys = [1]
2023-08-02T11:40:41.241672Z TRACE ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: pact_ffi::mock_server::handles: with_pact before - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [ProviderState { name: "i have a list of dogs", params: {} }], request: HttpRequest { method: "GET", path: "/dogs", query: None, headers: Some({"Accept": ["application/problem+json", "application/json", "text/plain", "*/*"], "X-Custom-Header": ["\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", "\\\"additionalInfo\\\":\\\"some additional string\\\"}\""]}), body: Missing, matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {} }} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: Some({"Content-Type": ["application/json", "application/json"]}), body: Present(b"[{\"dog\":1},{\"dog\":2}]", Some(ContentType { main_type: "application", sub_type: "json", attributes: {}, suffix: None }), None), matching_rules: MatchingRules { rules: {BODY: MatchingRuleCategory { name: BODY, rules: {} }, HEADER: MatchingRuleCategory { name: HEADER, rules: {} }} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
2023-08-02T11:40:41.247722Z TRACE ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: pact_plugin_driver::catalogue_manager: register_core_entries([CatalogueEntry { entry_type: TRANSPORT, provider_type: CORE, plugin: None, key: "http", values: {} }, CatalogueEntry { entry_type: TRANSPORT, provider_type: CORE, plugin: None, key: "https", values: {} }])
2023-08-02T11:40:41.251826Z DEBUG ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: pact_plugin_driver::catalogue_manager: Updated catalogue entries:
core/transport/http
core/transport/https
2023-08-02T11:40:41.252573Z TRACE ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: pact_plugin_driver::catalogue_manager: register_core_entries([CatalogueEntry { entry_type: CONTENT_MATCHER, provider_type: CORE, plugin: None, key: "xml", values: {"content-types": "application/.*xml,text/xml"} }, CatalogueEntry { entry_type: CONTENT_MATCHER, provider_type: CORE, plugin: None, key: "json", values: {"content-types": "application/.*json,application/json-rpc,application/jsonrequest"} }, CatalogueEntry { entry_type: CONTENT_MATCHER, provider_type: CORE, plugin: None, key: "text", values: {"content-types": "text/plain"} }, CatalogueEntry { entry_type: CONTENT_MATCHER, provider_type: CORE, plugin: None, key: "multipart-form-data", values: {"content-types": "multipart/form-data,multipart/mixed"} }, CatalogueEntry { entry_type: CONTENT_GENERATOR, provider_type: CORE, plugin: None, key: "json", values: {"content-types": "application/.*json,application/json-rpc,application/jsonrequest"} }, CatalogueEntry { entry_type: CONTENT_GENERATOR, provider_type: CORE, plugin: None, key: "binary", values: {"content-types": "application/octet-stream"} }])
2023-08-02T11:40:41.252751Z DEBUG ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: 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-08-02T11:40:41.253264Z TRACE ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: pact_plugin_driver::catalogue_manager: register_core_entries([CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v2-regex", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v2-type", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-number-type", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-integer-type", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-decimal-type", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-date", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-time", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-datetime", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v2-min-type", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v2-max-type", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v2-minmax-type", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-includes", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-null", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v4-equals-ignore-order", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v4-min-equals-ignore-order", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v4-max-equals-ignore-order", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v4-minmax-equals-ignore-order", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v3-content-type", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v4-array-contains", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v1-equality", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v4-not-empty", values: {} }, CatalogueEntry { entry_type: MATCHER, provider_type: CORE, plugin: None, key: "v4-semver", values: {} }])
2023-08-02T11:40:41.253749Z DEBUG ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: 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-08-02T11:40:41.263290Z DEBUG ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: pact_mock_server::mock_server: Started mock server on 127.0.0.1:8992
2023-08-02T11:40:41.266276Z TRACE ThreadId(01) pactffi_create_mock_server_for_pact{pact=PactHandle { pact_ref: 1 } addr_str=0x30eb0ee69 tls=false}: pact_ffi::mock_server::handles: with_pact after - ref = 1, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "a request for all dogs", provider_states: [ProviderState { name: "i have a list of dogs", params: {} }], request: HttpRequest { method: "GET", path: "/dogs", query: None, headers: Some({"Accept": ["application/problem+json", "application/json", "text/plain", "*/*"], "X-Custom-Header": ["\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", "\\\"additionalInfo\\\":\\\"some additional string\\\"}\""]}), body: Missing, matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {} }} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: Some({"Content-Type": ["application/json", "application/json"]}), body: Present(b"[{\"dog\":1},{\"dog\":2}]", Some(ContentType { main_type: "application", sub_type: "json", attributes: {}, suffix: None }), None), matching_rules: MatchingRules { rules: {BODY: MatchingRuleCategory { name: BODY, rules: {} }, HEADER: MatchingRuleCategory { name: HEADER, rules: {} }} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: true, specification_version: V2 } }
[21:40:41.267] DEBUG (63992): pact@12.1.0: mock service started on port: 8992
2023-08-02T11:40:41.288113Z TRACE tokio-runtime-worker hyper::proto::h1::conn: Conn::read_head
2023-08-02T11:40:41.288747Z TRACE tokio-runtime-worker hyper::proto::h1::conn: flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }
2023-08-02T11:40:41.289251Z TRACE tokio-runtime-worker hyper::proto::h1::conn: Conn::read_head
2023-08-02T11:40:41.289416Z TRACE tokio-runtime-worker hyper::proto::h1::io: received 241 bytes
2023-08-02T11:40:41.290010Z TRACE tokio-runtime-worker parse_headers: hyper::proto::h1::role: Request.parse bytes=241
2023-08-02T11:40:41.290498Z TRACE tokio-runtime-worker parse_headers: hyper::proto::h1::role: Request.parse Complete(241)
2023-08-02T11:40:41.292106Z DEBUG tokio-runtime-worker hyper::proto::h1::io: parsed 5 headers
2023-08-02T11:40:41.292120Z DEBUG tokio-runtime-worker hyper::proto::h1::conn: incoming body is empty
2023-08-02T11:40:41.292132Z TRACE tokio-runtime-worker hyper::proto::h1::conn: remote disabling keep-alive
2023-08-02T11:40:41.292780Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Creating pact request from hyper request
2023-08-02T11:40:41.293746Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Extracting query from uri /dogs
2023-08-02T11:40:41.293760Z TRACE tokio-runtime-worker pact_mock_server::hyper_server: path_and_query -> /dogs
2023-08-02T11:40:41.295731Z  INFO tokio-runtime-worker pact_mock_server::hyper_server: Received request GET /dogs
2023-08-02T11:40:41.296038Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server:
      ----------------------------------------------------------------------------------------
       method: GET
       path: /dogs
       query: None
       headers: Some({"x-custom-header": ["{\"id\":\"asd-asdasd-sd\"", "\"additionalInfo\":\"some additional string\"}"], "connection": ["close"], "host": ["127.0.0.1:8992"], "user-agent": ["axios/0.27.2"], "accept": ["application/problem+json", "application/json", "text/plain", "*/*"]})
       body: Empty
      ----------------------------------------------------------------------------------------

2023-08-02T11:40:41.297402Z  INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: GET, path: /dogs, query: None, headers: Some({"Accept": ["application/problem+json", "application/json", "text/plain", "*/*"], "X-Custom-Header": ["\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", "\\\"additionalInfo\\\":\\\"some additional string\\\"}\""]}), body: Missing )
2023-08-02T11:40:41.297425Z DEBUG tokio-runtime-worker pact_matching:      body: ''
2023-08-02T11:40:41.297432Z DEBUG tokio-runtime-worker pact_matching:      matching_rules: MatchingRules { rules: {HEADER: MatchingRuleCategory { name: HEADER, rules: {} }, PATH: MatchingRuleCategory { name: PATH, rules: {} }} }
2023-08-02T11:40:41.297449Z DEBUG tokio-runtime-worker pact_matching:      generators: Generators { categories: {} }
2023-08-02T11:40:41.298098Z TRACE tokio-runtime-worker pact_matching: plugin_data = {}
2023-08-02T11:40:41.299879Z TRACE tokio-runtime-worker matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: PATH, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [], expr: "" }}: pact_models::matchingrules: matcher_is_defined: for category path and path [] -> false
2023-08-02T11:40:41.300563Z DEBUG tokio-runtime-worker matches_with{self="/dogs" actual="/dogs" matcher=Equality cascaded=false}: pact_matching::matchers: String -> String: comparing '/dogs' to '/dogs' ==> true cascaded=false matcher=Equality
2023-08-02T11:40:41.300879Z DEBUG tokio-runtime-worker pact_matching: expected content type = '*/*', actual content type = '*/*'
2023-08-02T11:40:41.301773Z DEBUG tokio-runtime-worker pact_matching: content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
2023-08-02T11:40:41.302567Z TRACE tokio-runtime-worker match_header_value{key="Accept" index=0 expected="application/problem+json" actual="application/problem+json" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("accept")], expr: "$.accept" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "accept"] -> false
2023-08-02T11:40:41.302630Z TRACE tokio-runtime-worker match_header_value{key="Accept" index=0 expected="application/problem+json" actual="application/problem+json" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("accept"), Index(0)], expr: "$.accept[0]" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "accept", "0"] -> false
2023-08-02T11:40:41.303479Z TRACE tokio-runtime-worker match_header_value{key="Accept" index=1 expected="application/json" actual="application/json" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("accept")], expr: "$.accept" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "accept"] -> false
2023-08-02T11:40:41.303520Z TRACE tokio-runtime-worker match_header_value{key="Accept" index=1 expected="application/json" actual="application/json" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("accept"), Index(1)], expr: "$.accept[1]" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "accept", "1"] -> false
2023-08-02T11:40:41.303590Z TRACE tokio-runtime-worker match_header_value{key="Accept" index=2 expected="text/plain" actual="text/plain" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("accept")], expr: "$.accept" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "accept"] -> false
2023-08-02T11:40:41.303627Z TRACE tokio-runtime-worker match_header_value{key="Accept" index=2 expected="text/plain" actual="text/plain" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("accept"), Index(2)], expr: "$.accept[2]" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "accept", "2"] -> false
2023-08-02T11:40:41.303725Z TRACE tokio-runtime-worker match_header_value{key="Accept" index=3 expected="*/*" actual="*/*" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("accept")], expr: "$.accept" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "accept"] -> false
2023-08-02T11:40:41.303765Z TRACE tokio-runtime-worker match_header_value{key="Accept" index=3 expected="*/*" actual="*/*" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("accept"), Index(3)], expr: "$.accept[3]" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "accept", "3"] -> false
2023-08-02T11:40:41.304069Z TRACE tokio-runtime-worker match_header_value{key="X-Custom-Header" index=0 expected="\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"" actual="{\"id\":\"asd-asdasd-sd\"" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("x-custom-header")], expr: "$['x-custom-header']" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "x-custom-header"] -> false
2023-08-02T11:40:41.304107Z TRACE tokio-runtime-worker match_header_value{key="X-Custom-Header" index=0 expected="\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"" actual="{\"id\":\"asd-asdasd-sd\"" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("x-custom-header"), Index(0)], expr: "$['x-custom-header'][0]" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "x-custom-header", "0"] -> false
2023-08-02T11:40:41.304483Z DEBUG tokio-runtime-worker match_header_value{key="X-Custom-Header" index=0 expected="\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"" actual="{\"id\":\"asd-asdasd-sd\"" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matches_with{self="\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"" actual="{\"id\":\"asd-asdasd-sd\"" matcher=Equality cascaded=false}:matches_with{self="\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"" actual="{\"id\":\"asd-asdasd-sd\"" matcher=Equality cascaded=false}: pact_matching::matchers: String -> String: comparing '"{\"id\":\"asd-asdasd-sd\"' to '{"id":"asd-asdasd-sd"' ==> false cascaded=false matcher=Equality
2023-08-02T11:40:41.304739Z TRACE tokio-runtime-worker match_header_value{key="X-Custom-Header" index=1 expected="\\\"additionalInfo\\\":\\\"some additional string\\\"}\"" actual="\"additionalInfo\":\"some additional string\"}" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("x-custom-header")], expr: "$['x-custom-header']" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "x-custom-header"] -> false
2023-08-02T11:40:41.304775Z TRACE tokio-runtime-worker match_header_value{key="X-Custom-Header" index=1 expected="\\\"additionalInfo\\\":\\\"some additional string\\\"}\"" actual="\"additionalInfo\":\"some additional string\"}" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matcher_is_defined{self=CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } path=DocPath { path_tokens: [Root, Field("x-custom-header"), Index(1)], expr: "$['x-custom-header'][1]" }}: pact_models::matchingrules: matcher_is_defined: for category header and path ["$", "x-custom-header", "1"] -> false
2023-08-02T11:40:41.304822Z DEBUG tokio-runtime-worker match_header_value{key="X-Custom-Header" index=1 expected="\\\"additionalInfo\\\":\\\"some additional string\\\"}\"" actual="\"additionalInfo\":\"some additional string\"}" context=HeaderMatchingContext { inner_context: CoreMatchingContext { matchers: MatchingRuleCategory { name: HEADER, rules: {} }, config: NoUnexpectedKeys, matching_spec: V3, plugin_configuration: {} } } single_value=false}:matches_with{self="\\\"additionalInfo\\\":\\\"some additional string\\\"}\"" actual="\"additionalInfo\":\"some additional string\"}" matcher=Equality cascaded=false}:matches_with{self="\\\"additionalInfo\\\":\\\"some additional string\\\"}\"" actual="\"additionalInfo\":\"some additional string\"}" matcher=Equality cascaded=false}: pact_matching::matchers: String -> String: comparing '\"additionalInfo\":\"some additional string\"}"' to '"additionalInfo":"some additional string"}' ==> false cascaded=false matcher=Equality
2023-08-02T11:40:41.304918Z DEBUG tokio-runtime-worker pact_matching: --> Mismatches: [HeaderMismatch { key: "X-Custom-Header", expected: "\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", actual: "{\"id\":\"asd-asdasd-sd\"", mismatch: "Mismatch with header 'X-Custom-Header': Expected '\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"' to be equal to '{\"id\":\"asd-asdasd-sd\"' for value at index 0" }, HeaderMismatch { key: "X-Custom-Header", expected: "\\\"additionalInfo\\\":\\\"some additional string\\\"}\"", actual: "\"additionalInfo\":\"some additional string\"}", mismatch: "Mismatch with header 'X-Custom-Header': Expected '\\\"additionalInfo\\\":\\\"some additional string\\\"}\"' to be equal to '\"additionalInfo\":\"some additional string\"}' for value at index 1" }]
2023-08-02T11:40:41.305754Z DEBUG tokio-runtime-worker pact_mock_server::hyper_server: Request did not match: Request did not match - HTTP Request ( method: GET, path: /dogs, query: None, headers: Some({"Accept": ["application/problem+json", "application/json", "text/plain", "*/*"], "X-Custom-Header": ["\"{\\\"id\\\":\\\"asd-asdasd-sd\\\"", "\\\"additionalInfo\\\":\\\"some additional string\\\"}\""]}), body: Missing )    0) Mismatch with header 'X-Custom-Header': Expected '"{\"id\":\"asd-asdasd-sd\"' to be equal to '{"id":"asd-asdasd-sd"' for value at index 0    1) Mismatch with header 'X-Custom-Header': Expected '\"additionalInfo\":\"some additional string\"}"' to be equal to '"additionalInfo":"some additional string"}' for value at index 1
2023-08-02T11:40:41.306816Z TRACE tokio-runtime-worker encode_headers: hyper::proto::h1::role: Server::encode status=500, body=Some(Known(520)), req_method=Some(GET)
2023-08-02T11:40:41.309139Z TRACE tokio-runtime-worker hyper::proto::h1::io: buffer.queue self.len=201 buf.len=520
2023-08-02T11:40:41.309931Z DEBUG tokio-runtime-worker hyper::proto::h1::io: flushed 721 bytes
2023-08-02T11:40:41.309945Z TRACE tokio-runtime-worker hyper::proto::h1::conn: State::close()
2023-08-02T11:40:41.309951Z TRACE tokio-runtime-worker hyper::proto::h1::conn: flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
2023-08-02T11:40:41.310091Z TRACE tokio-runtime-worker hyper::proto::h1::conn: shut down IO complete
      1) returns the correct response

Pact verification failed!
Test failed for the following reasons:

  Mock server failed with the following mismatches:

    0) The following request was incorrect:

                GET /dogs

             1.0 Mismatch with header 'X-Custom-Header': Expected '"{\"id\":\"asd-asdasd-sd\"' to be equal to '{"id":"asd-asdasd-sd"' for value at index 0
             1.1 Mismatch with header 'X-Custom-Header': Expected '\"additionalInfo\":\"some additional string\"}"' to be equal to '"additionalInfo":"some additional string"}' for value at index 1
[21:40:41.318] TRACE (63992): pact-core@14.0.1: Ffi has already been initialised, no need to repeat it
2023-08-02T11:40:41.321282Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact - ref = 2, keys = [1, 2]
2023-08-02T11:40:41.321316Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact before - ref = 2, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V3 } }
2023-08-02T11:40:41.321339Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact after - ref = 2, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
2023-08-02T11:40:41.321360Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact - ref = 2, keys = [1, 2]
2023-08-02T11:40:41.321369Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact before - ref = 2, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
2023-08-02T11:40:41.321415Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact after - ref = 2, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "", provider_states: [], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
[21:40:41.321] DEBUG (63992): pact@12.1.0: cleaning up old mock server on port 8992
2023-08-02T11:40:41.323151Z 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-08-02T11:40:41.323321Z DEBUG ThreadId(01) pact_mock_server::server_manager: Shutting down mock server with ID 24fe08bf-b1ef-47f3-93df-44157608f5ed - MockServerMetrics { requests: 1, requests_by_path: {"/dogs": 1} }
2023-08-02T11:40:41.324023Z DEBUG ThreadId(01) pact_mock_server::mock_server: Mock server 24fe08bf-b1ef-47f3-93df-44157608f5ed shutdown - MockServerMetrics { requests: 1, requests_by_path: {"/dogs": 1} }
2023-08-02T11:40:41.324086Z DEBUG tokio-runtime-worker hyper::server::shutdown: signal received, starting graceful shutdown
2023-08-02T11:40:41.324970Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact - ref = 2, keys = [1, 2]
2023-08-02T11:40:41.324983Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact before - ref = 2, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "", provider_states: [], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
2023-08-02T11:40:41.325018Z TRACE ThreadId(01) pact_ffi::mock_server::handles: with_pact after - ref = 2, inner = RefCell { value: PactHandleInner { pact: V4Pact { consumer: Consumer { name: "MyConsumer" }, provider: Provider { name: "MyProvider" }, interactions: [SynchronousHttp { id: None, key: None, description: "", provider_states: [], request: HttpRequest { method: "GET", path: "/", query: None, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, response: HttpResponse { status: 200, headers: None, body: Missing, matching_rules: MatchingRules { rules: {} }, generators: Generators { categories: {} } }, comments: {}, pending: false, plugin_config: {}, interaction_markup: InteractionMarkup { markup: "", markup_type: "" }, transport: None }], metadata: {"pact-js": Object {"version": String("12.1.0")}, "pactRust": Object {"ffi": String("0.4.6")}}, plugin_data: [] }, mock_server_started: false, specification_version: V2 } }
      2) "after each" hook for "returns the correct response"

  0 passing (143ms)
  2 failing

  1) The Dog API
       get /dogs
         returns the correct response:
     Request failed with status code 500

  2) The Dog API
       "after each" hook for "returns the correct response":
     Error: Pact verification failed - expected interactions did not match actual.
      at new VerificationError (/Users/matthew.fellows/development/public/pact-js/dist/src/errors/verificationError.js:21:42)
      at Pact.verify (/Users/matthew.fellows/development/public/pact-js/dist/src/httpPact/index.js:224:19)
      at Context.<anonymous> (test/get-dogs.spec.js:39:28)
      at process.processImmediate (node:internal/timers:476:21)

I think this is an upstream issue, but I'll create a repro in the core to prove it first. Re-opening.

kroupacz commented 1 year ago

It looks like the JSON object is being iterated on, and each key in the JSON structure is being converted into an index

@mefellows I don't think so. The JSON string is evidently split by comma, because "curly bracket" is included in logged string "{"id":"asd-asdasd-sd"

 1.0 Mismatch with header 'X-Custom-Header': Expected '"{\"id\":\"asd-asdasd-sd\"' to be equal to '{"id":"asd-asdasd-sd"' for value at index 0

It's interesting that in my case even the real "x-info" request header (not header in interaction) is converted to array with empty string. But the real axios request contains correct "x-info" value. In your case there is splitted JSON string again.

2023-08-02T09:40:36.433335Z INFO tokio-runtime-worker pact_matching: comparing to expected HTTP Request ( method: GET, path: /api/accounts/oem_user:12345, query: None, headers: Some({"x-info": [""]}), body: Missing )

mefellows commented 1 year ago

I've also shown it's not a problem in the rust core's standard interface, so it is either:

  1. In our interop code layer
  2. In the FFI interface

I still think it's likely to be (2), as we don't do much with the headers. Still looking.

mefellows commented 1 year ago

Confirmed it's an upstream issue (see link above) and https://github.com/pact-foundation/pact-js-core/compare/repro/pact-js-issue-1058?expand=1.

joel35park commented 1 month ago

Hi @mefellows , is this fixed now?

mefellows commented 1 month ago

It doesn't look to be based on the upstream issue, but you could run a quick test of my repro (bump to latest version of Pact JS) to test that out.

kroupacz commented 1 month ago

Hello @mefellows. I just tested the latest version of @pact-foundation/pact@13 and I can confirm that the header parsing bug still exists and unfortunately we still have to use @pact-foundation/pact@9 which is the last working version.

kroupacz commented 1 month ago

I'm guessing this might be place where it's happening.