pact-go Deadlock while running pact provider

Deadlock while running pact provider

Open Jarema opened this issue 3 years ago • 4 comments

Software versions

OS: e.g. Mac OSX 10.14.6
Provider Pact library: e.g. github.com/pact-foundation/pact-go v1.4.1
** pact standalone: pact-1.88.14
Golang Version: 1.14
Golang environment: Provide output of go env GO111MODULE="" GOARCH="amd64" GOBIN="" GOCACHE="/Users/name/Library/Caches/go-build" GOENV="/Users/name/Library/Application Support/go/env" GOEXE="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="darwin" GOINSECURE="" GONOPROXY="" GONOSUMDB="" GOOS="darwin" GOPATH="/Users/name/go" GOPRIVATE="" GOPROXY="https://proxy.golang.org,direct" GOROOT="/usr/local/Cellar/go/1.14/libexec" GOSUMDB="sum.golang.org" GOTMPDIR="" GOTOOLDIR="/usr/local/Cellar/go/1.14/libexec/pkg/tool/darwin_amd64" GCCGO="gccgo" AR="ar" CC="clang" CXX="clang++" CGO_ENABLED="1" GOMOD="/Users/user/coding/app/go.mod" CGO_CFLAGS="-g -O2" CGO_CPPFLAGS="" CGO_CXXFLAGS="-g -O2" CGO_FFLAGS="-g -O2" CGO_LDFLAGS="-g -O2" PKG_CONFIG="pkg-config" GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/n5/s6wxlf0j40v9q8jvrmjb3btc0000gp/T/go-build411187154=/tmp/go-build -gno-record-gcc-switches -fno-common"

Expected behaviour

No deadlock, erronous contracts are failing, no useful logs

Actual behaviour

Running pact provider verification against pact broker started to deadlock itself. There are no logs that can hint to the right direction

Steps to reproduce

Thats the biggest issue: I'm not even able to reproduce for you, as I have no idea which contract is causing this. Cutting all contracts and adding one by one works. Its increadibly time consuming to find broken contract in such manual fashion, as there are hundreds of them.

Relevent log files

stack trace:

8AM INF copying state from states/primary-account-with-funds to states/.temp-state service_name=app version=1.0.0
7:58AM INF handled http request client_ip=127.0.0.1 duration=0.169894 method=GET path=/v1/products requestID=32758736-cfd4-4874-9110-975947c99bb7 request_protocol=HTTP/1.1 service_name=app status=200 user_agent="Pact Go" version=1.0.0 x_forwarded_for="127.0.0.1, 127.0.0.1"
panic: test timed out after 10m0s
goroutine 2873 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:1514 +0xdf
created by time.goFunc
	/usr/local/go/src/time/sleep.go:168 +0x44
goroutine 1 [chan receive, 10 minutes]:
testing.(*T).Run(0xc0004fe480, 0x12a7c8b, 0xc, 0x12fbda8, 0x491f86)
	/usr/local/go/src/testing/testing.go:1096 +0x2b2
testing.runTests.func1(0xc0004fe360)
	/usr/local/go/src/testing/testing.go:1339 +0x78
testing.tRunner(0xc0004fe360, 0xc00087be10)
	/usr/local/go/src/testing/testing.go:1050 +0xdc
testing.runTests(0xc00051b040, 0x1d59f10, 0x1, 0x1, 0x0)
	/usr/local/go/src/testing/testing.go:1337 +0x2c3
testing.(*M).Run(0xc00005a380, 0x0)
	/usr/local/go/src/testing/testing.go:1252 +0x15f
main.main()
	_testmain.go:44 +0x135
goroutine 6 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc0000bbf90)
	/go/pkg/mod/[email protected]/stats/view/worker.go:154 +0x100
created by go.opencensus.io/stats/view.init.0
	/go/pkg/mod/[email protected]/stats/view/worker.go:32 +0x57
goroutine 68 [syscall, 9 minutes]:
syscall.Syscall6(0xf7, 0x1, 0x21ff, 0xc0058c43b8, 0x1000004, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/syscall/asm_linux_amd64.s:41 +0x5
os.(*Process).blockUntilWaitable(0xc004fc81e0, 0x0, 0x12fd038, 0xc000061000)
	/usr/local/go/src/os/wait_waitid.go:31 +0x98
os.(*Process).wait(0xc004fc81e0, 0xc0004f9d08, 0xc004dc6598, 0xc0004f9db8)
	/usr/local/go/src/os/exec_unix.go:22 +0x39
os.(*Process).Wait(...)
	/usr/local/go/src/os/exec.go:125
os/exec.(*Cmd).Wait(0xc004f862c0, 0x0, 0x0)
	/usr/local/go/src/os/exec/exec.go:507 +0x60
github.com/pact-foundation/pact-go/dsl.(*PactClient).VerifyProvider(0xc0050a8080, 0xc0020f8ca0, 0x16, 0x0, 0x0, 0x0, 0xc00003e0c9, 0x1f, 0x0, 0x0, ...)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/dsl/client.go:219 +0x558
github.com/pact-foundation/pact-go/dsl.(*Pact).VerifyProviderRaw(0xc00038b408, 0xc0020f87a0, 0x15, 0x0, 0x0, 0x0, 0xc00003e0c9, 0x1f, 0x0, 0x0, ...)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/dsl/pact.go:396 +0x91e
github.org.net/org/app/app_v2/v2/tests/pact.TestProvider(0xc0004fe480)
	/builds/org/app/app-provider-tests/service_repo/tests/pact/provider_test.go:160 +0x13a0
testing.tRunner(0xc0004fe480, 0x12fbda8)
	/usr/local/go/src/testing/testing.go:1050 +0xdc
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1095 +0x28b
goroutine 66 [select]:
go.elastic.co/apm.(*Tracer).loop(0xc000001b00)
	/go/pkg/mod/go.elastic.co/[email protected]/tracer.go:768 +0xab0
created by go.elastic.co/apm.newTracer
	/go/pkg/mod/go.elastic.co/[email protected]/tracer.go:410 +0x76c
goroutine 35 [select]:
go.elastic.co/apm.(*Tracer).loop.func1(0xc0005a2060, 0x14c0a20, 0xc000504a40, 0xc000114a20, 0xc000001b00, 0xc0005900d0)
	/go/pkg/mod/go.elastic.co/[email protected]/tracer.go:713 +0x2cf
created by go.elastic.co/apm.(*Tracer).loop
	/go/pkg/mod/go.elastic.co/[email protected]/tracer.go:709 +0x33f
goroutine 67 [select, 5 minutes]:
go.elastic.co/apm/transport.(*HTTPTransport).WatchConfig.func1(0xc00004e540, 0x14c0a20, 0xc000284400, 0xc000286900, 0xc000600ea0, 0x9, 0x0, 0x0)
	/go/pkg/mod/go.elastic.co/[email protected]/transport/http.go:386 +0x1db
created by go.elastic.co/apm/transport.(*HTTPTransport).WatchConfig
	/go/pkg/mod/go.elastic.co/[email protected]/transport/http.go:378 +0xae
goroutine 75 [chan send, 9 minutes]:
github.org.net/org/app/app_v2/v2/tests/pact.waitForProvider.func1(0x12a05f200, 0xc004b334a0)
	/builds/org/app/app-provider-tests/service_repo/tests/pact/provider_test.go:252 +0x5d
created by github.org.net/org/app/app_v2/v2/tests/pact.waitForProvider
	/builds/org/app/app-provider-tests/service_repo/tests/pact/provider_test.go:250 +0x7c
goroutine 98 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7fed3542ffd8, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc004e74218, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc004e74200, 0xc004e63000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
net.(*netFD).Read(0xc004e74200, 0xc004e63000, 0x1000, 0x1000, 0x3, 0x0, 0x51d132)
	/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc004ce71c8, 0xc004e63000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:184 +0x8e
net/http.(*connReader).Read(0xc004c95200, 0xc004e63000, 0x1000, 0x1000, 0x2, 0xc, 0x0)
	/usr/local/go/src/net/http/server.go:797 +0xf4
bufio.(*Reader).fill(0xc005098a80)
	/usr/local/go/src/bufio/bufio.go:100 +0x103
bufio.(*Reader).ReadSlice(0xc005098a80, 0xc004edd90a, 0x440abf, 0xc004edd9c0, 0x40e1f6, 0xc004e7c400, 0x100)
	/usr/local/go/src/bufio/bufio.go:359 +0x3d
bufio.(*Reader).ReadLine(0xc005098a80, 0xc004edd9c8, 0xc000580000, 0x7fed5e8f9108, 0x0, 0x0, 0xc004e7a000)
	/usr/local/go/src/bufio/bufio.go:388 +0x34
net/textproto.(*Reader).readLineSlice(0xc004c95230, 0xc004e7c400, 0x0, 0x4394bc, 0xc004edda28, 0x0)
	/usr/local/go/src/net/textproto/reader.go:58 +0x6c
net/textproto.(*Reader).ReadLine(...)
	/usr/local/go/src/net/textproto/reader.go:39
net/http.readRequest(0xc005098a80, 0x0, 0xc004e7c400, 0x0, 0x0)
	/usr/local/go/src/net/http/request.go:1015 +0xa4
net/http.(*conn).readRequest(0xc004c02280, 0x14c0a20, 0xc004e68340, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:983 +0x191
net/http.(*conn).serve(0xc004c02280, 0x14c0a20, 0xc004e68340)
	/usr/local/go/src/net/http/server.go:1850 +0x6d4
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2962 +0x35c
goroutine 76 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7fed35430198, 0x72, 0x0)
	/usr/local/go/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc004e51d18, 0x72, 0x0, 0x0, 0x12a1bff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc004e51d00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:384 +0x1d4
net.(*netFD).accept(0xc004e51d00, 0x10026a279ab591b9, 0x0, 0x10026a279ab591b9)
	/usr/local/go/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc004e58c20, 0x5f8d4729, 0xc0005b3d78, 0x491f86)
	/usr/local/go/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc004e58c20, 0xc0005b3dc8, 0x18, 0xc000703200, 0x732cac)
	/usr/local/go/src/net/tcpsock.go:261 +0x64
net/http.(*Server).Serve(0xc0040ee0e0, 0x14bbb20, 0xc004e58c20, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:2930 +0x25d
net/http.(*Server).ListenAndServe(0xc0040ee0e0, 0x14c0a60, 0xc000042100)
	/usr/local/go/src/net/http/server.go:2859 +0xb7
github.org.net/org/app/app_v2/v2/web.StartRouter.func1(0xc00156e480, 0x14cace0, 0xc000297290, 0x14c0a60, 0xc000042100, 0xc0040ee0e0, 0xc004b33500)
	/builds/org/app/app-provider-tests/service_repo/web/router.go:233 +0x392
created by github.org.net/org/app/app_v2/v2/web.StartRouter
	/builds/org/app/app-provider-tests/service_repo/web/router.go:222 +0x1cd
goroutine 86 [select, 9 minutes]:
net/http.(*persistConn).readLoop(0xc000bb6120)
	/usr/local/go/src/net/http/transport.go:2158 +0x9a0
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1706 +0xc56
goroutine 87 [select, 9 minutes]:
net/http.(*persistConn).writeLoop(0xc000bb6120)
	/usr/local/go/src/net/http/transport.go:2336 +0x11c
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1707 +0xc7b
goroutine 38 [chan receive, 9 minutes]:
github.com/pact-foundation/pact-go/client.(*ServiceManager).addServiceMonitor(0xc00046e000)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:40 +0x8b
created by github.com/pact-foundation/pact-go/client.(*ServiceManager).Setup
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:31 +0x10e
goroutine 39 [chan receive, 9 minutes]:
github.com/pact-foundation/pact-go/client.(*ServiceManager).removeServiceMonitor(0xc00046e000)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:54 +0x8b
created by github.com/pact-foundation/pact-go/client.(*ServiceManager).Setup
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:32 +0x130
goroutine 40 [chan receive, 9 minutes]:
github.com/pact-foundation/pact-go/client.(*ServiceManager).addServiceMonitor(0xc00046e0e0)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:40 +0x8b
created by github.com/pact-foundation/pact-go/client.(*ServiceManager).Setup
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:31 +0x10e
goroutine 41 [chan receive, 9 minutes]:
github.com/pact-foundation/pact-go/client.(*ServiceManager).removeServiceMonitor(0xc00046e0e0)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:54 +0x8b
created by github.com/pact-foundation/pact-go/client.(*ServiceManager).Setup
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:32 +0x130
goroutine 42 [chan receive, 9 minutes]:
github.com/pact-foundation/pact-go/client.(*ServiceManager).addServiceMonitor(0xc00046e230)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:40 +0x8b
created by github.com/pact-foundation/pact-go/client.(*ServiceManager).Setup
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:31 +0x10e
goroutine 43 [chan receive, 9 minutes]:
github.com/pact-foundation/pact-go/client.(*ServiceManager).removeServiceMonitor(0xc00046e230)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:54 +0x8b
created by github.com/pact-foundation/pact-go/client.(*ServiceManager).Setup
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:32 +0x130
goroutine 44 [chan receive, 9 minutes]:
github.com/pact-foundation/pact-go/client.(*ServiceManager).addServiceMonitor(0xc00046e310)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:40 +0x8b
created by github.com/pact-foundation/pact-go/client.(*ServiceManager).Setup
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:31 +0x10e
goroutine 45 [chan receive, 9 minutes]:
github.com/pact-foundation/pact-go/client.(*ServiceManager).removeServiceMonitor(0xc00046e310)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:54 +0x8b
created by github.com/pact-foundation/pact-go/client.(*ServiceManager).Setup
	/go/pkg/mod/github.com/pact-foundation/[email protected]/client/service_manager.go:32 +0x130
goroutine 48 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7fed3542fef8, 0x72, 0x0)
	/usr/local/go/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc0050a8518, 0x72, 0x0, 0x0, 0x12a1bff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc0050a8500, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:384 +0x1d4
net.(*netFD).accept(0xc0050a8500, 0xd2878c7f4dedc554, 0x0, 0xd2878c7f4dedc554)
	/usr/local/go/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc0020f6740, 0x5f8d4729, 0xc004f71de8, 0x491f86)
	/usr/local/go/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).Accept(0xc0020f6740, 0xc004f71e38, 0x18, 0xc000583080, 0x732cac)
	/usr/local/go/src/net/tcpsock.go:261 +0x64
net/http.(*Server).Serve(0xc0050ba380, 0x14bbb20, 0xc0020f6740, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:2930 +0x25d
net/http.(*Server).ListenAndServe(0xc0050ba380, 0xc0050ba380, 0x0)
	/usr/local/go/src/net/http/server.go:2859 +0xb7
net/http.ListenAndServe(0xc0020f43b0, 0x6, 0x14a0b00, 0xc004ca8d20, 0x6, 0x4)
	/usr/local/go/src/net/http/server.go:3115 +0x74
created by github.com/pact-foundation/pact-go/proxy.HTTPReverseProxy
	/go/pkg/mod/github.com/pact-foundation/[email protected]/proxy/http.go:102 +0x397
goroutine 29 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7fed3542f8d8, 0x72, 0xffffffffffffffff)
	/usr/local/go/src/runtime/netpoll.go:203 +0x55
internal/poll.(*pollDesc).wait(0xc004f8c798, 0x72, 0xb01, 0xb66, 0xffffffffffffffff)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc004f8c780, 0xc004e7b49a, 0xb66, 0xb66, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:169 +0x19b
os.(*File).read(...)
	/usr/local/go/src/os/file_unix.go:263
os.(*File).Read(0xc004f8a050, 0xc004e7b49a, 0xb66, 0xb66, 0x4758d2, 0x2, 0x1d5b260)
	/usr/local/go/src/os/file.go:116 +0x71
bufio.(*Scanner).Scan(0xc004fb8480, 0x1d1616a)
	/usr/local/go/src/bufio/scan.go:213 +0xa4
github.com/pact-foundation/pact-go/dsl.(*PactClient).VerifyProvider.func2(0xc004fb8480, 0xc004fa62c0, 0xc004fb8400, 0xc004fac420)
	/go/pkg/mod/github.com/pact-foundation/[email protected]/dsl/client.go:204 +0x32
created by github.com/pact-foundation/pact-go/dsl.(*PactClient).VerifyProvider
	/go/pkg/mod/github.com/pact-foundation/[email protected]/dsl/client.go:203 +0x509
FAIL	github.org.net/org/app/app_v2/v2/tests/pact	600.117s

This is reappearance of https://github.com/pact-foundation/pact-go/issues/128

Additionally, it's pretty easy to get too many open files error while replicating locally.

Oct 19 '20 14:10 Jarema

Ah! How frustrating. Have you tried the latest release (1.5.1)? There are a few changes in that for provider verification also. I did recall testing this against 250 (or was it 500?) integrations and being able to reproduce it.

As an FYI, I've made some good progress on integrating our reference library into Pact Go. If the verification process is still causing issues for you, it might be faster for me to prioritise the provider side of that and just migrate to that. It will have the benefit of being able to verify v2 and v3 pacts, and should be a lot faster (the core module is written in Rust, not Ruby).

Oct 19 '20 22:10 mefellows

Could this be related to the issue of the WaitGroup Add instructions that are inside stdout/stderr scanner goroutines which is a being raised to me as a linting concern?

SA2000: should call wg.Add(1) before starting the goroutine to avoid a race (staticcheck)go-lint

https://github.com/pact-foundation/pact-go/blob/master/dsl/client.go#L199

And

https://github.com/pact-foundation/pact-go/blob/master/dsl/client.go#L212

Oct 29 '20 17:10 jamiecuthill

Thanks, good spot. And also apologies, I thought I'd responded to this last week. I actually started adding the metalinter to the project but forgot to respond here.

That is task #1, because it would catch basic errors like this.

Nov 07 '20 03:11 mefellows

Just making a note that this should be addressed in the new v2.x.x release.

Jun 12 '21 12:06 mefellows

Closing as won't fix, as the 2.x.x branch should address this problem.

Mar 07 '23 11:03 mefellows

pact-go pact-go copied to clipboard

Deadlock while running pact provider

Software versions

Expected behaviour

Actual behaviour

Steps to reproduce

Relevent log files

stack trace:

pact-go
pact-go copied to clipboard