Feature request: improve verification error handling when invalid JSON provided

[antweiss]

Software versions

• OS: Mac OSX 10.11.16
• Provider Pact library: Pact go v0.0.8
• Golang Version: go version go1.9 darwin/amd64
• Golang environment: GOARCH="amd64"
  GOBIN=""
  GOEXE=""
  GOHOSTARCH="amd64"
  GOHOSTOS="darwin"
  GOOS="darwin"
  GOPATH="/Users/antweiss/go_workspace"
  GORACE=""
  GOROOT="/usr/local/Cellar/go/1.9/libexec"
  GOTOOLDIR="/usr/local/Cellar/go/1.9/libexec/pkg/tool/darwin_amd64"
  GCCGO="gccgo"
  CC="clang"
  GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/g1/jt9j95dj12nd6blfhdr5w7xw0000gn/T/go-build264207708=/tmp/go-build -gno-record-gcc-switches -fno-common"
  CXX="clang++"
  CGO_ENABLED="1"
  CGO_CFLAGS="-g -O2"
  CGO_CPPFLAGS=""
  CGO_CXXFLAGS="-g -O2"
  CGO_FFLAGS="-g -O2"
  CGO_LDFLAGS="-g -O2"
  PKG_CONFIG="pkg-config"

Expected behaviour

Test succeeds to run

Actual behaviour

provider antweiss$ go test -v
=== RUN TestPact_Provider
2017/10/03 16:19:42 [DEBUG] pact setup logging
2017/10/03 16:19:42 [DEBUG] pact setup
2017/10/03 16:19:42 API starting: port 61911 ([::]:61911)
2017/10/03 16:19:42 [DEBUG] pact provider verification
2017/10/03 16:19:42 [DEBUG] client: verifying a provider
2017/10/03 16:19:42 [DEBUG] waiting for port 61911 to become available
2017/10/03 16:19:42 [DEBUG] creating an HTTP client
2017/10/03 16:19:42 [DEBUG] waiting for port 6666 to become available
2017/10/03 16:19:42 [TRACE] response from Ruby process pre-sanitisation:
2017/10/03 16:19:42
--- FAIL: TestPact_Provider (0.12s)
user_service_test.go:34: Error: provider verification failed:
FAIL
exit status 1
FAIL github.com/pact-foundation/pact-go/examples/mux/provider 0.137s

Steps to reproduce

Follow the instructions in README

[mefellows]

Thanks for this, by any chance did you run the consumer tests first? The pact files probably don't yet exist.

[antweiss]

I do have the pact file in examples/pacts/billy-bobby.json. See the screenshot attached.

Isn't this the right location for the file? Or is this an issue with the file format?
Here's the pact file : https://gist.github.com/antweiss/91a7f012f77c309425105e96908e2a01

[antweiss]

I actually tried to use this example to write a test for a service of my own, but hit the same issue. So I tried to run the example and failed again. I realize I'm probably missing something, but what?

[mefellows]

Yeah, that looks OK to me.

What does logs/pact.log have to say? You might want to add Verbose: true to the pact.VerifyProvider(...) line.

[mefellows]

I'm actually still running go 1.8, i'll upgrade to see if that has any bearing on things (unlikely).

[mefellows]

OK, as expected that didn't matter :)

[antweiss]

Added Verbose: true, still getting the same result.
And nothing gets written to the log.

[mefellows]

Any output in the terminal where you are running pact-go daemon -v -l DEBUG?

[antweiss]

2017/10/06 14:44:40 [DEBUG] daemon - verifying provider
2017/10/06 14:44:40 [DEBUG] starting verification service with args: [--provider-base-url http://localhost:52467 --pact-urls /Users/antweiss/go_workspace/src/github.com/pact-foundation/pact-go/examples/mux/provider/../../pacts/billy-bobby.json --provider-states-setup-url http://localhost:52467/setup --verbose true]
2017/10/06 14:44:40 [DEBUG] starting service

[antweiss]

The daemon does say this at startup:
017/10/06 14:44:05 method Shutdown has wrong number of ins: 1
2017/10/06 14:44:05 method StartDaemon has wrong number of ins: 4

[mefellows]

Hmm something is a bit weird.

At this point, I'm going to ask you to try running the verifier via the CLI directly (not something we'd normally want to do).

Next to the pact-go binary that you downloaded, there should be a pact directory. Could you please run the following and paste the output?

./pact/bin/pact-provider-verifier --pact-urls ../examples/pacts/billy-bobby.json  --provider-base-url localhost:8000

(update the path to the json file as appropriate).

It should produce a nice big stack trace.

[antweiss]

Ok, so I found out I had some issues with the JSON - got parsing errors. Fixed them all.
What I did:

1. started the user service :

provider antweiss$ go run cmd/usersvc/main.go 
2017/10/06 15:05:55 API starting: port 53105 ([::]:53105)

2. Ran pact veirfier in another shell:
   antweiss$ pact-verifier --pact-urls ~/go_workspace/src/github.com/pact-foundation/pact-go/examples/pacts/billy-bobby.json --provider-base-url http://localhost:52917

I got:

Reading pact at /Users/antweiss/go_workspace/src/github.com/pact-foundation/pact-go/examples/pacts/billy-bobby.json

Verifying a pact between billy and bobby
Given User billy exists
Mytest
with POST /users/login
returns a response which
WARN: Skipping set up for provider state 'User billy exists' for consumer 'billy' as there is no --provider-states-setup-url specified.
has status code 200

1 interaction, 0 failures

[mefellows]

oh - did you modify the pact file manually??

[antweiss]

Yes, guilty. :)
Just did another test - inserted a sleep before the pact.VerifyProvider line.
And ran pact-verifier with :
antweiss$ pact-verifier --pact-urls ~/go_workspace/src/github.com/pact-foundation/pact-go/examples/pacts/billy-bobby.json --provider-base-url http://localhost:53521 --provider-states-setup-url http://localhost:53521/setup
which also works fine:

Reading pact at /Users/antweiss/go_workspace/src/github.com/pact-foundation/pact-go/examples/pacts/billy-bobby.json

Verifying a pact between billy and bobby
Given User billy exists
Mytest
with POST /users/login
returns a response which
has status code 200

1 interaction, 0 failures

[antweiss]

So the setup also works fine

[mefellows]

OK, well that explains it, albeit it would be nice to get an error message as to why it fails right!?

Leave this open for now, I'll raise a defect in the upstream project where this logic resides.

Glad to hear it's up and working.

[antweiss]

Wait!
Running go test stil fails in the same fashion!

[antweiss]

It's only pact-verifier verification that succeeds now.

I've updated my gist with the valid json. here

[antweiss]

By the way - it's the same in my own service - I succeed in verifying provider with pact-verifier but fail running the test with go test ...

[antweiss]

@mefellows thank you for being so responsive and suggesting things, but the truth is I'm still stuck. :(
Would love to get more ideas as to how to help you with analysing this.

[mefellows]

hmmm, did you reset all of the changes in your checked out code and run it with a clean environment?

It's a bit strange that you can run the verifier but pact can't.

Also FWIW the Verbose flag just adds more noise to the terminal, the verifier process doesn't log to file.

[antweiss]

I already tried regenerating the json from consumer tests. Didn't help...
I'll reset everything and try again. Will update.

[antweiss]

@mefellows I have to admit I've wasted your time. After resetting everything, building from scratch and running tests - it all works.
But I agree - improvements in error handling and notifications are necessary. So that a newbie like myslef can work it out easier without bugging maintainers :)
Thanks for all the help.

[mefellows]

Not a waste at all, we've found an improvement to make and hopefully a new user of Pact. Others might have just got frustrated and give up.

Let's leave it open and I'll raise an enhancement in the upstream library.

[antweiss]

Cool. Meanwhile I wrote a blog post on using Pact. Hope this will get more newbies to try it. :) Feel free to share and comment: https://codefresh.io/blog/how-to-test-microservice-integration-with-pact/

[mefellows]

There has been significant re-work in the latest 1.x.x line, including on the verification. Here is an example of a verification failure with an invalid JSON document:

matt ~/go/src/github.com/pact-foundation/pact-go/examples/mux/provider λ vim ../../pacts/billy-bobby.json
matt ~/go/src/github.com/pact-foundation/pact-go/examples/mux/provider λ go test -v .
=== RUN   TestPact_MuxProvider
2018/07/14 13:53:18 [INFO] checking pact-mock-service within range >= 2.9.2, < 3.0.0
2018/07/14 13:53:18 API starting: port 58564 ([::]:58564)
2018/07/14 13:53:19 [INFO] checking pact-provider-verifier within range >= 1.15.0, < 3.0.0
2018/07/14 13:53:19 [INFO] checking pact-broker within range >= 1.14.0, < 2.0.0
--- PASS: TestPact_MuxProvider (1.94s)
	user_service_test.go:72: Skipping pulling from broker as PACT_INTEGRATED_TESTS is not set
PASS
ok  	github.com/pact-foundation/pact-go/examples/mux/provider	1.996s
matt ~/go/src/github.com/pact-foundation/pact-go/examples/mux/provider λ go test -v .
=== RUN   TestPact_MuxProvider
2018/07/14 13:53:54 [INFO] checking pact-mock-service within range >= 2.9.2, < 3.0.0
2018/07/14 13:53:54 API starting: port 58629 ([::]:58629)
2018/07/14 13:53:54 [INFO] checking pact-provider-verifier within range >= 1.15.0, < 3.0.0
2018/07/14 13:53:55 [INFO] checking pact-broker within range >= 1.14.0, < 2.0.0
--- FAIL: TestPact_MuxProvider (1.57s)
	user_service_test.go:34: error verifying provider: exit status 1

		STDERR:
		INFO: Reading pact at /Users/mfellows/go/src/github.com/pact-foundation/pact-go/examples/mux/provider/../../pacts/billy-bobby.json
		/opt/pact/lib/vendor/ruby/2.2.0/gems/json-2.1.0/lib/json/common.rb:156:in `parse': 757: unexpected token at '{ (JSON::ParserError)
		  "consumer": {
		    "name": "billy"
		  },
		  "provider": {
		    "name": "bobby"
		  },
		  "interactions": [
		    {
		      "description": "A request to login with user 'billy'",
		      "providerState": "User billy exists",
		      "request": {
...

Also see pact-foundation/pact-provider-verifier#25 (comment), which should see other improvements. Closing this for now.