Verifier.verifyProvider(): Failed Publish Step for Large Contract #583
Labels
bug
Indicates an unexpected problem or unintended behavior
Comments
|
Thanks. Do you happen to have the logs for your pact broker? The issue seems remote to Pact itself. It could be a payload size issue or timeout |
|
We do. We haven't seen any errors in the pact broker logs. |
|
In our Broker logs, we are seeing no errors.
As for our timeout and request size concerns... This run sent a 32kB request, had a ~1ms response time from the broker, and a 500 response. This has been the behaviour for all but one time: |
|
Here is the relevant broker logs: |
|
Thanks!
Strange. The 1ms response time strikes me as interesting - are you sure it made it to the broker itself? 1ms is unlikely enough time for it to even speak to the db, so it's either a) failing to parse the body or something else strange. Is it possible your load balancer is rejecting it? I think we're going to need to see the verification results themselves (and possible the contract) to be able to reproduce it. In either case, it seems like a downstream issue (i.e. unrelated to Pact JS) - either in the CLI tools we use to send these results, or the broker itself. |
|
What infrastructure are you using to deploy your broker? Is it the dius Docker image or the pactfoundation one? |
|
Our broker is deployed on the |
|
Can you try uploading the problem pact with a curl request? The docs are here https://docs.pact.io/pact_broker/publishing_and_retrieving_pacts#publish-using-http-requests |
|
Uploading the pact to the broker via curl returned 200 OK and I can see the pact in the pact broker webpage. |
|
My understanding is that the issue is not publishing a pact (this is a provider verification right?), but publishing the provider verification results. So uploading a pact via curl won't help diagnose this issue. We need to see the verbose logs of the underlying Ruby process. can you please enable debug and verbose logging https://github.com/pact-foundation/pact-js#verification-options and share that? |
|
Here is another section of the logs, with the npm installation information left out (it will take more time to clean that up). ... logs continue until the stack trace shared above |
|
Can you include the verbose logs of the actual call that causes the error please. |
|
Ah, thank you. Unfortunately, I am not seeing any error logs other than the stack trace from my original response. |
|
Hm, maybe the verbose flag isn't passed through to that call. I'll have a look. |
|
The flag wasn't being passed through to the verification publication bit. I've updated that, and there will be a new release of the standalone out in a few minutes. We'll need to put out a new release of pact node to get that code. |
|
I'll get that out today, and will update here when it's done. |
mefellows
added a commit
that referenced
this issue
Jan 27, 2021
mefellows
added a commit
that referenced
this issue
Jan 28, 2021
mefellows
added
Awaiting feedback
bug
|
@pfesenmeier apologies for the delay, the latest version is now out which should correctly pass through the verbose flag. Could you please get us a verbose log with the verification results bit so we can see what's happening? |
|
After running the process several times, I'm mostly getting the same failure with the same logging results in my original post. Verification fails in seconds, with no verbose logging output. I'll describe a couple other runs, just for thoroughness, though I cannot know how they relate to the common output above:
|
|
Can you tell us about how you've deployed your broker? What infrastructure is it running on? Is there a reverse proxy running in front of it? @mefellows I triggered the pact gem release and then didn't check that it had actually released, and it hadn't. Triggering a new release now. New standalone should be out with that verbose logging in it in a few minutes. |
|
Thanks Beth. Will get another release out this side today then - sorry @pfesenmeier |
|
Latest version of |
TimothyJones
pushed a commit
that referenced
this issue
Feb 1, 2021
TimothyJones
pushed a commit
that referenced
this issue
Feb 1, 2021
|
Thanks! Right before publication error, this is logged: It is perhaps notable that the normal logging says "52 interactions, 0 failures", while this has "testCount: 152". After stack trace, this is logged: |
|
Beth, we are running the broker on the pact-broker-docker image on AWS behind an ALB. |
|
What I'm looking for in the response headers is any indication of where the error is occurring - did it hit the Ruby code at all? If it did, there will be some headers that indicate this, and if there is a application error, there should have been a JSON response body that details it, which there doesn't seem to be. Can you paste all the request and response headers please? Are you using the pactfoundation/pact-broker or the dius/pact-broker image?
This is just because the text output does some smarts on the tests and summarises them at the interaction level, where as the JSON results don't. It won't have anything to do with the error, but thanks for sharing it. |
|
There another way that we could debug if it's an issue with the Ruby code or something to do with the deployment infrastructure, if you're up for it @pfesenmeier. You could sign up for a free Pactflow account and try publishing the pact and results there. |
|
Right before my previous log, there are these logs. Are these what you are looking for? (edit) |
|
Notice the difference between the response headers for the successful response and the error one. Success: Error: See that the X-Pact-Broker-Version and Server headers are missing. If there had been a 500 error in the Ruby code, those headers would be present. That makes me pretty certain that the error is happening outside of the Broker codebase. I'd be looking at the ALB logs. |
|
Are you using the pactfoundation/pact-broker or the dius/pact-broker image? If it's pactfoundation, it might be a puma issue, and if it's dius then it might be a passenger one. |
|
Wow, I see. We are using the |
|
To follow up on this, the root cause of the issue was that we had set the root filesystem of the docker container to be read-only. For certain contracts, the verification results were large enough that Puma was attempting to write files to /tmp. This is why we were getting 500 responses back from Puma and the request was never reaching the Pact Broker. This log message was what led us to this conclusion: I believe this issue can be closed. |
|
@mefellows @bethesque Thank you for all your help. |
|
Thanks for letting us know! I think that might be documentation worthy over at the docker repos. Glad you got to the bottom of it though! |
|
I'l see if the tmp file location can be changed to a writeable location. Definitely worth documenting. |
|
The tmp file location can't be configured. https://github.com/puma/puma/blob/475f8606dcd1811f409374bd1c8bd4164184626c/lib/puma/client.rb#L297 Will add it to the docs. |
|
Were you able to fix it by just making the /tmp directory writeable, or did you have to make the whole root filesystem writeable? |
|
We are using Fargate with AWS ECS which doesn't support using tmpfs so unfortunately we couldn't just make /tmp writable. We elected to make the entire root filesystem writable to move past this issue. |
|
Thanks for confirming! |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Issue Classification
Bug Report
Software versions
Issue Checklist
Confirm the following:
Expected behaviour
Verify 52 interactions and publish the results
Actual behaviour
Verify 52 interactions and receive an error at the publish step
Steps to reproduce
Unfortunately, my source code is closed source.
In our CI 'Contract Test' step, our provider verifies two consumer contracts, one of ~7 interactions, and then one of ~50 interactions. The smaller one is verified and published successfully, then the larger one is verified and the fails on publication.
Are there any known capability limits to the publish step as this time?
Relevant log files
For the latest version of @pact-foundation/pact:
Earlier, using @pact-foundation/pact 9.11.0, I got a little better output with 'trace' logging:
The text was updated successfully, but these errors were encountered: