Header is parsed incorrectly #1058

GeorgeTailor · 2023-02-08T10:37:49Z

Software versions

Please provide at least OS and version of pact-js

OS: e.g. Mac OSX 12.6.3
Consumer Pact library: "@pact-foundation/pact": "10.4.1",
Node Version: v16.13.1

Issue Checklist

Please confirm the following:

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

Expected behaviour

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

The text was updated successfully, but these errors were encountered:

TimothyJones · 2023-02-09T00:38:47Z

I agree, this isn't the right behaviour.

TimothyJones · 2023-02-09T00:41:37Z

Possibly downgrading to 10.4.0 will allow you to work around this - as it looks like this commit is the culprit: 9c7939e (cc @mefellows)

mefellows · 2023-02-09T02:01:33Z

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 · 2023-02-09T02:02:48Z

See also #1031

TimothyJones · 2023-02-09T02:03:27Z

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

mefellows · 2023-02-09T02:03:41Z

Yes, that might be the way about it.

GeorgeTailor · 2023-02-10T12:28:04Z

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

mefellows · 2023-02-13T04:04:09Z

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 · 2023-02-13T04:16:06Z

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 · 2023-02-13T07:30:15Z

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 · 2023-02-13T10:34:32Z

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 · 2023-02-14T10:11:14Z

(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 · 2023-02-15T14:52:41Z

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 · 2023-02-15T20:52:27Z

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 · 2023-02-16T07:57:54Z

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 · 2023-02-16T11:41:30Z

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

mefellows · 2023-02-16T11:42:41Z

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 · 2023-03-15T11:41:31Z

@rholshausen does pact-foundation/pact-reference#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 · 2023-03-15T22:29:26Z

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 · 2023-04-05T08:34:24Z

We we have any update on this one?

Reverts the core change in 9c7939e Relates to #1031 Fixes #1058

mefellows · 2023-07-08T13:00:16Z

See upstream issue here: pact-foundation/pact-reference#300

Reverts the core change in 9c7939e Relates to #1031 Fixes #1058 chore: allow v4 tests to run without env var for contributors chore: update debug message for headers chore: update mocha test to use correct multi-valued header syntax

mefellows · 2023-07-08T13:11:09Z

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

Reverts the core change in 9c7939e Relates to #1031 Fixes #1058 chore: allow v4 tests to run without env var for contributors chore: update debug message for headers chore: update mocha test to use correct multi-valued header syntax

kroupacz · 2023-08-02T10:10:34Z

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 · 2023-08-02T11:47:11Z

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 · 2023-08-02T12:46:38Z

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 · 2023-08-02T21:05:47Z

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

In our interop code layer
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 · 2023-08-03T06:11:06Z

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.

GeorgeTailor added the bug Indicates an unexpected problem or unintended behavior label Feb 8, 2023

mefellows added smartbear-supported and removed smartbear-supported labels Feb 15, 2023

mefellows added the smartbear-supported label Feb 16, 2023

mefellows mentioned this issue Mar 3, 2023

Invalid pact file created after migration to pact v10: pact:matcher:type in response body #950

Closed

5 tasks

sergeyklay mentioned this issue Mar 12, 2023

Header is parsed incorrectly pact-foundation/pact-reference#259

Closed

mefellows added a commit that referenced this issue Jul 8, 2023

fix: do not split headers by comma

a2fbddf

Reverts the core change in 9c7939e Relates to #1031 Fixes #1058

mefellows added a commit that referenced this issue Jul 8, 2023

chore: add example test for #1058

641b79b

mefellows closed this as completed in fccaa07 Jul 10, 2023

mefellows added a commit that referenced this issue Aug 2, 2023

chore: add example test for #1058

ac9b1e0

mefellows added the upstream Indicates that an issue relates to an upstream problem (such as in pact-reference) label Aug 2, 2023

mefellows reopened this Aug 2, 2023

mefellows added a commit to pact-foundation/pact-reference that referenced this issue Aug 3, 2023

repro: reproduces pact-foundation/pact-js#1058

7d2ff9b

mefellows mentioned this issue Aug 3, 2023

headers with JSON values are incorrectly handled in FFI pact-foundation/pact-reference#306

Open

mefellows added a commit to pact-foundation/pact-js-core that referenced this issue Aug 3, 2023

repro: pact-foundation/pact-js#1058

4223159

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Header is parsed incorrectly #1058

Header is parsed incorrectly #1058

GeorgeTailor commented Feb 8, 2023

TimothyJones commented Feb 9, 2023

TimothyJones commented Feb 9, 2023

mefellows commented Feb 9, 2023

mefellows commented Feb 9, 2023

TimothyJones commented Feb 9, 2023

mefellows commented Feb 9, 2023

GeorgeTailor commented Feb 10, 2023

mefellows commented Feb 13, 2023

rholshausen commented Feb 13, 2023

TimothyJones commented Feb 13, 2023

mefellows commented Feb 13, 2023

mefellows commented Feb 14, 2023

mslowiak commented Feb 15, 2023

mefellows commented Feb 15, 2023

mslowiak commented Feb 16, 2023

github-actions bot commented Feb 16, 2023

mefellows commented Feb 16, 2023

mefellows commented Mar 15, 2023

rholshausen commented Mar 15, 2023

webcodesailor commented Apr 5, 2023

mefellows commented Jul 8, 2023

mefellows commented Jul 8, 2023

kroupacz commented Aug 2, 2023 •

edited

Loading

mefellows commented Aug 2, 2023

kroupacz commented Aug 2, 2023

mefellows commented Aug 2, 2023

mefellows commented Aug 3, 2023

Header is parsed incorrectly #1058

Header is parsed incorrectly #1058

Comments

GeorgeTailor commented Feb 8, 2023

Software versions

Issue Checklist

Expected behaviour

Actual behaviour

Steps to reproduce

Relevant log files

TimothyJones commented Feb 9, 2023

TimothyJones commented Feb 9, 2023

mefellows commented Feb 9, 2023

mefellows commented Feb 9, 2023

TimothyJones commented Feb 9, 2023

mefellows commented Feb 9, 2023

GeorgeTailor commented Feb 10, 2023

mefellows commented Feb 13, 2023

rholshausen commented Feb 13, 2023

TimothyJones commented Feb 13, 2023

mefellows commented Feb 13, 2023

mefellows commented Feb 14, 2023

mslowiak commented Feb 15, 2023

mefellows commented Feb 15, 2023

mslowiak commented Feb 16, 2023

github-actions bot commented Feb 16, 2023

mefellows commented Feb 16, 2023

mefellows commented Mar 15, 2023

rholshausen commented Mar 15, 2023

webcodesailor commented Apr 5, 2023

mefellows commented Jul 8, 2023

mefellows commented Jul 8, 2023

kroupacz commented Aug 2, 2023 • edited Loading

mefellows commented Aug 2, 2023

kroupacz commented Aug 2, 2023

mefellows commented Aug 2, 2023

mefellows commented Aug 3, 2023

kroupacz commented Aug 2, 2023 •

edited

Loading