Pact-js: Pact consumer test fails with confusing error message

[smucode]

Software versions

ubuntu:17.10
@pact-foundation/pact: "^5.3.2"
@pact-foundation/pact-node: "^6.7.4"
node v8.4.0

Expected behaviour

It works fine locally, we are having problems in CI. It's been working quite stable, but seems to be a problem as the number of pacts has grown. We are running the pacts using mocha, and they are split over about 30 files with pactfileWriteMode: 'update'. The tests fail from time to time, different tests, but always similar failure as described below.

Actual behaviour

The test fails from time to time, with a confusing error message:

Actual interactions do not match expected interactions for mock MockService.

Missing requests:
    GET /api/foo/bar

Unexpected requests:
    GET /api/foo/bar

Which test reports this varies. The mock server responds with 500, but I guess that's usual behaviour in this case.

Steps to reproduce

I have not tried to create a reproducible example. I was hoping for some pointers on what to look for when I debug this first. I'm not sure it's trivial to reproduce.

Relevant log files

pact.log doesn't seem to contain any relevant info. Neither does the console output. They are both quite large and i'd rather not post them.

[bethesque]

I'm afraid we can't help you much unless you provide either a running example or the logs. One guess is that you're making the test request before setting up the interaction in the mock service. Check the ordering of the log messages.

[bethesque]

If you're running the tests in parallel, are you ensuring that each process has its own mock service as per https://github.com/pact-foundation/pact-mock_service/blob/master/README.md#mock-service-usage

[bethesque]

Also, see if you can split the logs into a separate file per instance. Let me know if the pact js interface doesn't allow you to do this, and I'll show you how to hack it ;-)

[mefellows]

One clue for me in this is that it works fine locally but not on CI, which is typically a less powerful machine. This has the smell of a promise not being properly handled, and the interaction request coming through before it was registered with the mock server.

If you could find the test case for the above interaction, and provide the code (and any associated setup stuff) that would be great.

[smucode]

I could not find any related info to the failed tests in the logs, not sure why that is. I have the log option set to a specific file. If I point it at a dir (as mentioned in the docs) it just makes pact angry (getting a Pact exited with code 1 error). Perhaps this calls for the hack?

Not running the tests in parallel btw.

[mefellows]

Thanks @smucode. The log files should contain the "Registered interaction..." and "Found interaction..." type stuff in there. This is what we are interested in, as it will help tell us the order the requests came in. Also, if you could post the JS code for these tests that would be mighty helpful to - even just the one that failed itself, in case of anything obvious.

[smucode]

The way we run the tests is roughly something along the lines of:

const provider = new Pact({
  consumer: 'frontend',
  provider: 'api',
  providerPort: 1234,
  log: path.resolve(process.cwd(), 'test/logs', 'pact.log'),
  dir: path.resolve(process.cwd(), 'test/pacts'),
  logLevel: 'WARN',
  spec: 2,
  pactfileWriteMode: 'update'
})


module.exports.apiTest = config =>
  describe(config.name, () => {
    before(() =>
      provider.setup().then(() =>
        config.interactions.forEach(i =>
          provider.addInteraction({
            // ...
          })
        )
      )
    )

    config.tests.forEach(t =>
      it(t.name, () => {
        return new Promise((resolve, reject) => {
          // ...
        })
      })
    )

    after(() => provider.verify() && provider.finalize())
  })

The apiTest is then imported and used by all 30 tests.

The whole setup code is here, if relevant: https://gist.github.com/smucode/411ce41a039e365d23b5c0ab6feaec0e

[smucode]

@mefellows Yep, i see the "Registered interaction..." stuff. But the logs only contain info about a single test, not all of them...

[bethesque]

I've recreated the symptoms of your issue here: https://github.com/pact-foundation/pact-ruby-standalone-e2e-example/commit/d52cf04512435ea6f40621e734d07410caf2a877

This issue happens when the request is executed before the interaction is set up on the mock service.

[mefellows]

Thanks @bethesque. So either there is a promise not properly handled in the client, or a promise not properly handled by the framework.

@smucode to get to the bottom of this, it might be worth some tactically placed console.log type statements in your setup and test cases to see if we can find an example where the test happens before a setup.

[smucode]

Added some logging:

const l = m => console.log('***** ' + m)

module.exports.apiTest = config =>
  describe(config.state, () => {
    before(() => {
      l('before')
      return provider.setup().then(() => {
        l('provider.setup')
        return config.interactions.forEach(i => {
          l('add interaction')
          return provider.addInteraction({
            // ...
          })
        })
      })
    })

    config.tests.forEach(t => {
      return it(t.name, function() {
        l('run test')
        return new Promise((resolve, reject) => {
          global.XMLHttpRequest = require('xhr2')
          const app = require('elm-pact-test-api').Main.worker()
          app.ports[t.elmResponsePort].subscribe(status => {
            status === 'OK' ? l('resolve') : l('reject ' + status)
            return status === 'OK' ? resolve() : reject(status)
          })
          app.ports[t.elmRequestPort].send(t.elmRequestData)
        })
      })
    })

    after(() => {
      l('after')
      return provider.verify() && provider.finalize()
    })
  })

In sucessful runs of a given tests the output is:

***** before
***** provider.setup
***** add interaction
***** run test
***** resolve
***** after

And when it fails I see:

***** before
***** provider.setup
***** add interaction
***** run test
***** reject BadStatus { status = { code = 500, message = "Internal Server Error" }, headers = Dict.fromList [("connection","Keep-Alive"),("content-length","87"),("content-type","application/json"),("date","Sun, 18 Feb 2018 23:27:06 GMT"),("server","WEBrick/1.3.1 (Ruby/2.2.2/2015-04-13) OpenSSL/1.0.2d")], url = "http://localhost:1234/api/foo", body = "{\"message\":\"No interaction found for POST /api/foo\",\"interaction_diffs\":[]}\n" }
***** after

[bethesque]

Is the code definitely blocking until all the interactions have been set up?

[smucode]

Looking through the full test run it does look like things happen in the correct order:

> rm -f test/pacts/frontend-query-api.json && mocha test/api-consumer --harmony --es_staging --timeout 15000

  given at least one previously performed action exists
***** before
***** provider.setup
***** add interaction
***** add interaction
***** add interaction
***** run test
***** resolve
    ✓ can issue an action request (138ms)
***** run test
***** resolve
    ✓ can get an action
***** run test
***** resolve
    ✓ can lists all actions
***** after

[ several successful tests... ]

  given one or more managed nodes exists
***** before
***** provider.setup
***** add interaction
***** run test
***** resolve
    ✓ a query for managed nodes will return data in the correct format
***** after

  given one or more unmanaged nodes exists
***** before
***** provider.setup
***** add interaction
***** run test
***** reject {"message":"No interaction found for POST /api/v1/graph","interaction_diffs":[]}

    1) a query for unmanaged nodes will return data in the correct format
***** after

Pact verification failed!
Registered interactions
Registered interactions
Registered interactions
Interactions matched
Cleared interactions
// ...
Registered interactions
Interactions matched
Cleared interactions
// ...
Registered interactions
Interactions matched
Cleared interactions
// ...
Registered interactions
Interactions matched
Cleared interactions
// ...
Registered interactions
Interactions matched
Cleared interactions
// ...
Registered interactions
Interactions matched
Cleared interactions
// ...
Registered interactions
Interactions matched
// ...
Cleared interactions
Registered interactions
Interactions matched
Cleared interactions
// ...
Registered interactions
Interactions matched
Cleared interactions
// ...
Registered interactions
Actual interactions do not match expected interactions for mock MockService.

Missing requests:
    POST /api/v1/graph

Unexpected requests:
    POST /api/v1/graph

See logs/pact.log for details.

(node:2765) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): Error: Pact verification failed - expected interactions did not match actual.
(node:2765) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

[ several more successful tests... ]

  28 passing (33s)
  1 pending
  1 failing

  1) given one or more unmanaged nodes exists
       a query for unmanaged nodes will return data in the correct format:
     Error: the string "{\"message\":\"No interaction found for POST /api/v1/graph\",\"interaction_diffs\":[]}\n" was thrown, throw an Error :)
      at <anonymous>
      at process._tickCallback (internal/process/next_tick.js:188:7)

[smucode]

And by making mocha bail on the first test failure, it doesn't overwrite the pact.log with data from a later successful run. Here is the pact.log for a failure:

I, [2018-02-19T06:54:58.541528 #3208]  INFO -- : Received request POST /api/v1/foo
D, [2018-02-19T06:54:58.541901 #3208] DEBUG -- : {
  "path": "/api/v1/foo",
  "query": "",
  "method": "post",
  "body": {
    // ...
  },
  "headers": {
    "Content-Length": "25",
    "Content-Type": "application/json",
    "Accept": "application/json",
    "Connection": "keep-alive",
    "Host": "localhost:1234",
    "User-Agent": "Mozilla/5.0 (Linux x64) node.js/8.9.4 v8/6.1.534.50",
    "Version": "HTTP/1.1"
  }
}
E, [2018-02-19T06:54:58.542006 #3208] ERROR -- : No matching interaction found for POST /api/v1/foo
E, [2018-02-19T06:54:58.542084 #3208] ERROR -- : Interaction diffs for that route:
E, [2018-02-19T06:54:58.542131 #3208] ERROR -- : 
I, [2018-02-19T06:54:58.549304 #3208]  INFO -- : Registered expected interaction POST /api/v1/foo
D, [2018-02-19T06:54:58.549905 #3208] DEBUG -- : {
  "description": "POST:/api/v1/foo",
  "providerState": "given multiple nodes",
  "request": {
    "method": "POST",
    "path": "/api/v1/foo",
    "headers": {
      "Accept": "application/json",
      "Content-Type": "application/json"
    },
    "body": {
      // ...
    }
  },
  "response": {
    "status": 200,
    "headers": {
      "Content-Type": "application/json; charset=utf-8"
    },
    "body": {
      // ...
    }
  }
}
W, [2018-02-19T06:54:58.556044 #3208]  WARN -- : Verifying - actual interactions do not match expected interactions. 
Missing requests:
    POST /api/v1/foo

Unexpected requests:
    POST /api/v1/foo


W, [2018-02-19T06:54:58.563765 #3208]  WARN -- : Missing requests:
    POST /api/v1/foo

Unexpected requests:
    POST /api/v1/foo


I, [2018-02-19T06:54:58.612038 #3208]  INFO -- : *****************************************************************************
I, [2018-02-19T06:54:58.612194 #3208]  INFO -- : Updating existing file ./builds/test/pacts/frontend-query-api.json as pactfile_write_mode is :update
I, [2018-02-19T06:54:58.612265 #3208]  INFO -- : Only interactions defined in this test run will be updated.
I, [2018-02-19T06:54:58.612293 #3208]  INFO -- : As interactions are identified by description and provider state, pleased note that if either of these have changed, the old interactions won't be removed from the pact file until the specs are next run with :pactfile_write_mode => :overwrite.
I, [2018-02-19T06:54:58.612320 #3208]  INFO -- : *****************************************************************************

[bethesque]

As I suspected, the logs show that the order of the requests is wrong. It
seems that the test starts without waiting for the set up to complete. What
is the piece of code that should be ensuring that? I noticed that there
didn't seem to be a "wait" at the end of the set up code, but given I am
not familiar with the framework you're using, I wasn't sure if it was just
my lack of understanding.

On 19 Feb. 2018 6:01 pm, "SMU" [e-mail] wrote:

And by making mocha bail on the first test failure, it doesn't overwrite
the pact.log with data from a later successful run. Here is the pact.log
for a failure, seems like things might be a bit off:

I, [2018-02-19T06:54:58.541528 #3208] INFO -- : Received request POST /api/v1/foo
D, [2018-02-19T06:54:58.541901 #3208] DEBUG -- : {
"path": "/api/v1/foo",
"query": "",
"method": "post",
"body": {
"agent_uuids": [
"node1"
]
},
"headers": {
"Content-Length": "25",
"Content-Type": "application/json",
"Accept": "application/json",
"Connection": "keep-alive",
"Host": "localhost:1234",
"User-Agent": "Mozilla/5.0 (Linux x64) node.js/8.9.4 v8/6.1.534.50",
"Version": "HTTP/1.1"
}
}
E, [2018-02-19T06:54:58.542006 #3208] ERROR -- : No matching interaction found for POST /api/v1/foo
E, [2018-02-19T06:54:58.542084 #3208] ERROR -- : Interaction diffs for that route:
E, [2018-02-19T06:54:58.542131 #3208] ERROR -- :
I, [2018-02-19T06:54:58.549304 #3208] INFO -- : Registered expected interaction POST /api/v1/foo
D, [2018-02-19T06:54:58.549905 #3208] DEBUG -- : {
"description": "POST:/api/v1/foo",
"providerState": "given multiple nodes",
"request": {
"method": "POST",
"path": "/api/v1/foo",
"headers": {
"Accept": "application/json",
"Content-Type": "application/json"
},
"body": {
"agent_uuids": [
"node1"
]
}
},
"response": {
"status": 200,
"headers": {
"Content-Type": "application/json; charset=utf-8"
},
"body": {}
}
}
W, [2018-02-19T06:54:58.556044 #3208] WARN -- : Verifying - actual interactions do not match expected interactions.
Missing requests:
POST /api/v1/foo

Unexpected requests:
POST /api/v1/foo

W, [2018-02-19T06:54:58.563765 #3208] WARN -- : Missing requests:
POST /api/v1/foo

Unexpected requests:
POST /api/v1/foo

I, [2018-02-19T06:54:58.612038 #3208] INFO -- : ************************
I, [2018-02-19T06:54:58.612194 #3208] INFO -- : Updating existing file ./builds/test/pacts/frontend-query-api.json as pactfile_write_mode is :update
I, [2018-02-19T06:54:58.612265 #3208] INFO -- : Only interactions defined in this test run will be updated.
I, [2018-02-19T06:54:58.612293 #3208] INFO -- : As interactions are identified by description and provider state, pleased note that if either of these have changed, the old interactions won't be removed from the pact file until the specs are next run with :pactfile_write_mode => :overwrite.
I, [2018-02-19T06:54:58.612320 #3208] INFO -- : ************************

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/pact-foundation/pact-js/issues/151#issuecomment-366603835,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAbPFLeNSi_kuv6FPQBYp3xdkMwRXbZxks5tWRxBgaJpZM4SHYVA
.

[mefellows]

If I'm reading the code correctly, he's (implicitly) returning a promise. The before(() => provider.setup... is the key bit.

Unless there is some other wrapper that's not doing that properly.

@smucode you could also consider using async and await to block execution in those steps to be doubly sure. If this doesn't work, it probably indicates a mishandled promise in the framework somewhere (I'll have a search now in relevant places).

[smucode]

We are setting up the interations in a forEach so it might be that I need to wrap that in a Promise.all? Eg change:

    before(() =>
      provider.setup().then(() =>
        config.interactions.forEach(i =>
          // ...
        )
      )
    )

to

    before(() =>
      provider.setup().then(() =>
        Promise.all(
          config.interactions.map(i =>
            // ...
          )
        )
      )
    )

Might I be doing something wrong in my after method? As mentioned, we are setting up the interactions in a forEach, and we do the same for our tests:

module.exports.apiTest = config =>
  describe(config.state, () => {

    before(() =>
      provider.setup().then(() =>
        config.interactions.forEach(i =>
          provider.addInteraction({
            //...
          })
        )
      )
    )

    config.tests.forEach(t =>
      it(t.name,() => {
        // ...
      })
    )

    after(() => provider.verify() && provider.finalize())
  })

Most test cases only contain a single interaction and a single tests though.

[smucode]

Promise.all seems to have solved the problem! 🎉

I noticed the mocha example in the readme doesn't return the promise from provider.addInteraction either, I guess it should? Also the link to the integration spec 404s.

Thanks a lot for helping me figure this out! Pact is pretty awesome, keep up the great work!

[mefellows]

Awesome @smucode! I'll check the examples/link now and get it fixed.

Glad your code is working (and that there's no issue in the framework ;) )

[mefellows]

Just looked at the readme example, it doesn't need to return the promise as it uses the done() callback. I would demonstrate promises there, but a lot of people are confused by it, don't return the promise and have issues. I've just updated the broken link too, thanks.

[smucode]

Wouldn't you need to hook done onto the promise returned from provider.addInteraction and not the one from provider.setup? Otherwise it seems to me it would just resolve once provider.setup is done and provider.addInteraction is called , but not wait for provider.addInteraction to actually finish its business?

[mefellows]

Right you are sir!