Closed Jarema closed 4 years ago
mefellows
commented
4 years ago Sorry to hear this! Thanks for the report. I'll have a look at some of the areas that may be responsible for a deadlock, that may be a starting point.
Are you able to share anything about the test setup that could be helpful?
If you set the log level to debug you should get more output to the terminal that may help - feel free to post the whole thing and we can dig through it.
Jarema
commented
4 years ago I will provide logs a little later, when I anonymise them.
About setup:
VerifyProvider against spun up routerVerifyProvider deadlocks.EDIT: All worked as intened until recently, when it started hitting that deadlock.
Jarema
commented
4 years ago additional logs (anonymised)
env PACT_URL=https://pact.non-prd.org.net env VERSION=2.114.0 PACT_USERNAME=xxx env PACT_PASSWORD=xxx env PACT_PUBLISH_VERIFICATION_RESULT=true go test -tags=pact -v ./tests/pact/provider_test.go
=== RUN TestProvider
12:55PM INF services initialized, initializing customers service_name=app version=2.114.0
12:55PM INF setting up server service_name=app version=2.114.0
12:55PM ERR The flag false has to be removed from configuration after date 2020-01-06 00:00:00 +0000 UTC service_name=app version=2.114.0
12:55PM INF With specific config for current environment:
service_name=app version=2.114.0
12:55PM WRN starting router WITHOUT authentication middleware service_name=app version=2.114.0
12:55PM WRN starting router WITHOUT authentication middleware service_name=app version=2.114.0
12:55PM WRN starting router WITHOUT authentication middleware service_name=app version=2.114.0
12:55PM WRN starting router WITHOUT authentication middleware service_name=app version=2.114.0
12:55PM WRN attempt to start a router without TLS support service_name=app version=2.114.0
TestProvider: provider_test.go:238: checking if router is running
12:55PM INF handled http request client_ip=::1 duration=0.105 method=GET path=/v1/app/path
TestProvider: provider_test.go:248: router started
12:55PM INF laoding states service_name=app version=2.114.0
12:55PM INF states loaded service_name=app version=2.114.0
12:55PM INF start provider verification service_name=app version=2.114.0
[DEBUG] pact setup logging
[DEBUG] pact setup
[DEBUG] checking CLI compatability
[INFO] checking pact-mock-service within range >= 3.5.0, < 4.0.0
[DEBUG] running binary pact-mock-service
[DEBUG] checking version for binary pact-mock-service version 3.6.0
[DEBUG] checking if version 3.6.0 within semver range >= 3.5.0, < 4.0.0
[DEBUG] 3.6.0 satisfies constraints 3.6.0 >= 3.5.0, < 4.0.0
[INFO] checking pact-provider-verifier within range >= 1.30.0, < 2.0.0
[DEBUG] running binary pact-provider-verifier
[DEBUG] checking version for binary pact-provider-verifier version 1.30.0
[DEBUG] checking if version 1.30.0 within semver range >= 1.30.0, < 2.0.0
[DEBUG] 1.30.0 satisfies constraints 1.30.0 >= 1.30.0, < 2.0.0
[INFO] checking pact-broker within range >= 1.22.3
[DEBUG] running binary pact-broker
[DEBUG] checking version for binary pact-broker version 1.25.1
[DEBUG] checking if version 1.25.1 within semver range >= 1.22.3
[DEBUG] 1.25.1 satisfies constraints 1.25.1 >= 1.22.3
[DEBUG] setting up a service manager
[DEBUG] setting up a service manager
[DEBUG] setting up a service manager
[DEBUG] setting up a service manager
[DEBUG] starting service removal monitor
[DEBUG] starting service creation monitor
[DEBUG] starting service creation monitor
[DEBUG] starting service removal monitor
[DEBUG] starting service creation monitor
[DEBUG] starting service removal monitor
[DEBUG] starting service creation monitor
[DEBUG] starting service removal monitor
[DEBUG] starting new proxy with opts {http localhost:8085 0 [0x4420190] /__setup <nil>}
[DEBUG] starting reverse proxy on port 56827
[DEBUG] waiting for port 56827 to become available
[DEBUG] pact provider verification
[DEBUG] client: verifying a provider
[DEBUG] waiting for port 56827 to become available
[DEBUG] starting verification service with args: [--custom-provider-header X-Request-Id: 32758736-cfd4-4874-9110-975947c99bb7 --format json --provider-base-url http://localhost:56827 --provider-states-setup-url http://localhost:56827/__setup --broker-username xxx --broker-password xxx --pact-broker-base-url https://pact.non-prd.org.net --provider_app_version 2.114.0 --provider app --publish_verification_results true]
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56835 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=1.177871 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56842 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
INF Evaluating node XXXX data
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF handled http request client_ip=127.0.0.1 duration=2.408147 flow_execution_summary=[{"exit_id":"60","flow_id":"xxx","order":1,"path":""}] flow_id=xxx method=POST path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56845 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.244352 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56848 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.175314 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56851 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.30711 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56854 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.281221 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56859 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.154285 method=GET path=/v1/app/path
[WARN] state handler not found for state:
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56866 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM WRN error="customer not found" requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
12:55PM WRN handled http request client_ip=127.0.0.1 duration=0.321454 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56871 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.2489 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56876 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.182651 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56879 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=2.141458 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56885 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.19419 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56891 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.434439 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56896 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.115197 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56901 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.193961 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56904 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.125048 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56907 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.097459 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56910 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
INF Evaluating node XXXX data
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF Evaluating node: XXX-node
12:55PM INF handled http request client_ip=127.0.0.1 duration=1.265109 flow_execution_summary=[{"exit_id":"10","flow_id":"xxx","order":1,"path":"xxx"}] flow_id=xxx method=POST path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56913 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.138764 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56916 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.132246 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56919 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.771945 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56922 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.689886 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56925 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=1.28551 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56928 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.260811 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56931 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.172031 method=GET path=/v1/app/path
12:55PM INF load state: state-name service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56934 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=0.381242 method=GET path=/v1/app/path
[WARN] state handler not found for state: retail-with-premium-package
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:56937 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
12:55PM INF handled http request client_ip=127.0.0.1 duration=2.311325 flow_execution_summary=[] flow_id=xxx method=POST path=/v1/app/pathThanks for that - are you able to share the anonymised provider test also? I suspect it won't change much, but best to rule it out too.
Jarema
commented
4 years ago also: anonymised test run for same setup, just different provider name (I added in broker just sample consumer contract that I know is correct):
== RUN TestProvider
1:10PM INF services initialized, initializing customers service_name=app version=2.114.0
1:10PM INF setting up server service_name=app version=2.114.0
1:10PM ERR The flag false has to be removed from configuration after date 2020-01-06 00:00:00 +0000 UTC service_name=app version=2.114.0
service_name=app version=2.114.0
1:10PM WRN starting router WITHOUT authentication middleware service_name=app version=2.114.0
1:10PM WRN starting router WITHOUT authentication middleware service_name=app version=2.114.0
1:10PM WRN starting router WITHOUT authentication middleware service_name=app version=2.114.0
1:10PM WRN starting router WITHOUT authentication middleware service_na§me=app version=2.114.0
1:10PM WRN attempt to start a router without TLS support service_name=app version=2.114.0
TestProvider: provider_test.go:238: checking if router is running
1:10PM INF handled http request client_ip=::1 duration=0.365994 method=GET path=/v1/app/path requestID=aa3fe223-9c7e-4439-822d-cf9be7b21771 request_protocol=HTTP/1.1 service_name=app status=200 user_agent=Go-http-client/1.1 version=2.114.0
TestProvider: provider_test.go:248: router started
1:10PM INF ladoing states service_name=app version=2.114.0
1:10PM INF states loaded service_name=app version=2.114.0
1:10PM INF start provider verification service_name=app version=2.114.0
[DEBUG] pact setup logging
[DEBUG] pact setup
[DEBUG] checking CLI compatability
[INFO] checking pact-mock-service within range >= 3.5.0, < 4.0.0
[DEBUG] running binary pact-mock-service
[DEBUG] checking version for binary pact-mock-service version 3.6.0
[DEBUG] checking if version 3.6.0 within semver range >= 3.5.0, < 4.0.0
[DEBUG] 3.6.0 satisfies constraints 3.6.0 >= 3.5.0, < 4.0.0
[INFO] checking pact-provider-verifier within range >= 1.30.0, < 2.0.0
[DEBUG] running binary pact-provider-verifier
[DEBUG] checking version for binary pact-provider-verifier version 1.30.0
[DEBUG] checking if version 1.30.0 within semver range >= 1.30.0, < 2.0.0
[DEBUG] 1.30.0 satisfies constraints 1.30.0 >= 1.30.0, < 2.0.0
[INFO] checking pact-broker within range >= 1.22.3
[DEBUG] running binary pact-broker
[DEBUG] checking version for binary pact-broker version 1.25.1
[DEBUG] checking if version 1.25.1 within semver range >= 1.22.3
[DEBUG] 1.25.1 satisfies constraints 1.25.1 >= 1.22.3
[DEBUG] setting up a service manager
[DEBUG] setting up a service manager
[DEBUG] setting up a service manager
[DEBUG] setting up a service manager
[DEBUG] starting service removal monitor
[DEBUG] starting service creation monitor
[DEBUG] starting service creation monitor
[DEBUG] starting service removal monitor
[DEBUG] starting service removal monitor
[DEBUG] starting service creation monitor
[DEBUG] starting service creation monitor
[DEBUG] starting service removal monitor
[DEBUG] starting new proxy with opts {http localhost:8085 0 [0x4420190] /__setup <nil>}
[DEBUG] starting reverse proxy on port 57061
[DEBUG] waiting for port 57061 to become available
[DEBUG] pact provider verification
[DEBUG] client: verifying a provider
[DEBUG] waiting for port 57061 to become available
[DEBUG] starting verification service with args: [--custom-provider-header X-Request-Id: 32758736-cfd4-4874-9110-975947c99bb7 --format json --provider-base-url http://localhost:57061 --provider-states-setup-url http://localhost:57061/__setup --broker-username pact --broker-password bDDpozTdP9y99KS7 --pact-broker-base-url https://pact.non-prd.org.net --provider_app_version 2.114.0 --provider app2 --publish_verification_results true]
1:10PM INF load state: retail-customer-with-card-token service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:57069 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
1:10PM INF handled http request client_ip=127.0.0.1 duration=2.86124 method=POST path=/v1/app/path requestID=32758736-cfd4-4874-9110-975947c99bb7 request_protocol=HTTP/1.1 service_name=app status=200 user_agent="Pact Go" version=2.114.0 x_forwarded_for="127.0.0.1, ::1"
1:10PM INF load state: retail-customer-with-card-token service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:57074 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
1:10PM WRN Validation failed! Dictionary name not provide field_name=Status requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app struct_type=*types.CardToken version=2.114.0
1:10PM INF Evaluating tree: 2A6B, flowID: tokenization idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_I_0 (Does the card exist) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_K_0 (Is the card not closed or restricted?) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_M_0 (Does the token exist?) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_O_0 (What is the customer package) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_Q_0 (Is it a joint type?) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_S_0 (Get number) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_U_0 (End of logic leading to result) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM ERR used not existing language error="dictionaryItem or dictionary not found" idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF handled http request client_ip=127.0.0.1 duration=2.170922 method=POST path=/v1/app/path requestID=32758736-cfd4-4874-9110-975947c99bb7 request_protocol=HTTP/1.1 service_name=app status=200 user_agent="Pact Go" version=2.114.0 x_forwarded_for="127.0.0.1, ::1"
1:10PM INF load state: retail-customer-with-card-token service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:57077 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
1:10PM WRN Validation failed! Dictionary name not provide field_name=Status requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app struct_type=*types.CardToken version=2.114.0
1:10PM INF Evaluating tree: 2A6B, flowID: tokenization idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_I_0 (Does the card exist) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_K_0 (Is the card not closed or restricted?) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_M_0 (Does the token exist?) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_O_0 (What is the customer package) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_Q_0 (Is it a joint type?) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_S_0 (Get number) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF Evaluating node: 2A6B_U_0 (End of logic leading to result) idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF handled http request client_ip=127.0.0.1 duration=1.564803 method=POST path=/v1/app/path requestID=32758736-cfd4-4874-9110-975947c99bb7 request_protocol=HTTP/1.1 service_name=app status=200 user_agent="Pact Go" version=2.114.0 x_forwarded_for="127.0.0.1, ::1"
1:10PM ERR used not existing language error="dictionaryItem or dictionary not found" idempotence_key= requestID=32758736-cfd4-4874-9110-975947c99bb7 service_name=app version=2.114.0
1:10PM INF load state: retail-customer-with-card-token service_name=app version=2.114.0
[DEBUG] skipping state handler for request /v1/app/path
[DEBUG] http reverse proxy received connection from [::1]:57080 on path /v1/app/path
[DEBUG] setting proxy to target
[DEBUG] incoming request /v1/app/path
[DEBUG] outgoing request http://localhost:8085/v1/app/path
1:10PM INF handled http request client_ip=127.0.0.1 duration=0.603642 method=GET path=/v1/app/path requestID=32758736-cfd4-4874-9110-975947c99bb7 request_protocol=HTTP/1.1 service_name=app status=200 user_agent="Pact Go" version=2.114.0 x_forwarded_for="127.0.0.1, ::1"
=== RUN TestProvider/Pact_between__and__
=== RUN TestProvider/has_status_code_200
TestProvider/has_status_code_200: pact.go:622: Verifying a pact between consumer-app and app2 state activate tokenization with POST /v1/app/path returns a response which has status code 200
=== RUN TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"
TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8": pact.go:622: Verifying a pact between consumer-app and app2 state activate tokenization with POST /v1/app/path returns a response which includes headers "Content-Type" which equals "application/json; charset=utf-8"
=== RUN TestProvider/has_status_code_200#01
TestProvider/has_status_code_200#01: pact.go:622: Verifying a pact between consumer-app and app2 state complete tokenization with POST /v1/app/path returns a response which has status code 200
=== RUN TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#01
TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#01: pact.go:622: Verifying a pact between consumer-app and app2 state complete tokenization with POST /v1/app/path returns a response which includes headers "Content-Type" which equals "application/json; charset=utf-8"
=== RUN TestProvider/has_status_code_200#02
TestProvider/has_status_code_200#02: pact.go:622: Verifying a pact between consumer-app and app2 state complete tokenization with nullable field with POST /v1/app/path returns a response which has status code 200
=== RUN TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#02
TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#02: pact.go:622: Verifying a pact between consumer-app and app2 state complete tokenization with nullable field with POST /v1/app/path returns a response which includes headers "Content-Type" which equals "application/json; charset=utf-8"
=== RUN TestProvider/has_status_code_200#03
TestProvider/has_status_code_200#03: pact.go:622: Verifying a pact between consumer-app and app2 state get cards by rbs with GET /v1/app/path returns a response which has status code 200
=== RUN TestProvider/has_a_matching_body
TestProvider/has_a_matching_body: pact.go:622: Verifying a pact between consumer-app and app2 state get cards by rbs with GET /v1/app/path returns a response which has a matching body
=== RUN TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#03
TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#03: pact.go:622: Verifying a pact between consumer-app and app2 state get cards by rbs with GET /v1/app/path returns a response which includes headers "Content-Type" which equals "application/json; charset=utf-8"
1:10PM INF pacts verification finished service_name=app version=2.114.0
--- PASS: TestProvider (10.40s)
--- PASS: TestProvider/has_status_code_200 (0.00s)
--- PASS: TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8" (0.00s)
--- PASS: TestProvider/has_status_code_200#01 (0.00s)
--- PASS: TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#01 (0.00s)
--- PASS: TestProvider/has_status_code_200#02 (0.00s)
--- PASS: TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#02 (0.00s)
--- PASS: TestProvider/has_status_code_200#03 (0.00s)
--- PASS: TestProvider/has_a_matching_body (0.00s)
--- PASS: TestProvider/"Content-Type"_which_equals_"application/json;_charset=utf-8"#03 (0.00s)
--- PASS: TestProvider/Pact_between__and__ (0.00s)
PASS
ok command-line-arguments 10.451sstripped down code:
// +build pact
package pact
import (
"context"
"fmt"
"github.com/coreos/etcd/pkg/fileutil"
"github.com/pact-foundation/pact-go/dsl"
"github.com/pact-foundation/pact-go/types"
"github.com/spf13/afero"
"github.com/stretchr/testify/require"
"honnef.co/go/tools/config"
"io"
"net/http"
"os"
"path/filepath"
"strconv"
"testing"
"time"
)
const (
statesPath = "states"
defaultPort = 8085
defaultProvider = "app"
defaultWaitForProviderDuration = time.Second * 30
pactUsernameEnv = "PACT_USERNAME"
pactPasswordEnv = "PACT_PASSWORD"
pactURLEnv = "PACT_URL"
pactPublishVerificationEnv = "PACT_PUBLISH_VERIFICATION_RESULT"
providerVersionEnv = "VERSION"
tempStatePath = ".temp-state"
)
var dir, _ = os.Getwd()
var pactDir = fmt.Sprintf("%s/provider-pacts", dir)
var pactURL = os.Getenv(pactURLEnv)
// Provider Pact: How to run
// 2. go test -v -run TestProvider
func TestProvider(t *testing.T) {
pactUsername := os.Getenv(pactUsernameEnv)
pactPassword := os.Getenv(pactPasswordEnv)
ctx := context.Background()
// Create Pact connecting to local Daemon
pact := &dsl.Pact{
LogLevel:"DEBUG",
Provider: defaultProvider,
}
// basic config
cfg := config.Config{
Port: defaultPort,
}
go web.StartRouter(ctx, logger, r, cfg)
waitForProvider(t, defaultWaitForProviderDuration)
logger.Info(ctx, log.WithMessage("ladoing states"))
// load all states from states folder
states, err := loadStates("states", storage, customers, logger)
require.NoError(t, err)
logger.Info(ctx, log.WithMessage("states loaded"))
defer func() {
if err := os.Remove(filepath.Join(statesPath, tempStatePath)); err != nil {
logger.Error(ctx, log.WithError(err), log.WithMessage("remove temp state file"))
}
}()
var publish bool
if publishEnv := os.Getenv(pactPublishVerificationEnv); publishEnv != "" {
publish, err = strconv.ParseBool(publishEnv)
require.NoError(t, err)
}
version := os.Getenv(providerVersionEnv)
if version == "" {
version = config.AppVersion
}
logger.Info(ctx, log.WithMessage("start provider verification"))
// Verify the Provider with local Pact Files
_, err = pact.VerifyProvider(t, types.VerifyRequest{
ProviderBaseURL: fmt.Sprintf("http://localhost:%d", defaultPort),
BrokerURL: pactURL,
BrokerUsername: pactUsername,
BrokerPassword: pactPassword,
PublishVerificationResults: publish,
CustomProviderHeaders: []string{"X-Request-Id: 32758736-cfd4-4874-9110-975947c99bb7"},
StateHandlers: states,
ProviderVersion: version,
EnablePending:false,
})
logger.Info(ctx, log.WithMessage("pacts verification finished"))
require.NoError(t, err)
}
func loadState(stateName string, storage StoreWithReloader, customers customer.Customers, logger log.Logger) error {
logger.Info(context.Background(), log.WithMessage("load state: %v", stateName))
if err := copyState(stateName, logger); err != nil {
return fmt.Errorf("prepare temporary state: %w", err)
}
if err := storage.Reload("states", afero.NewOsFs(), file.WithLedgerFilename(tempStatePath)); err != nil {
return err
}
if _, err := customers.Reload(1, storage); err != nil {
return err
}
return nil
}
func loadStates(path string, storage StoreWithReloader, customers customer.Customers, logger log.Logger) (types.StateHandlers, error) {
handlers := make(types.StateHandlers)
states, err := fileutil.ReadDir(path)
if err != nil {
return types.StateHandlers{}, err
}
for _, state := range states {
func(state string) {
handlers[state] = func() error {
return loadState(state, storage, customers, logger)
}
}(state)
}
return handlers, nil
}
func waitForProvider(t *testing.T, ttl time.Duration) {
ttlReached := make(chan struct{})
go func() {
<-time.After(ttl)
ttlReached <- struct{}{}
}()
for {
select {
case <-ttlReached:
t.Error("provider did not start in given time")
t.Fatal()
return
case <-time.After(time.Millisecond * 500):
t.Log("checking if router is running")
req, err := http.NewRequest("GET", "http://localhost:8085/v1/version", nil)
require.NoError(t, err)
req.Header.Add("X-Request-Id", "aa3fe223-9c7e-4439-822d-cf9be7b21771")
client := &http.Client{}
resp, err := client.Do(req)
if err != nil {
t.Log("router not yet running")
}
if err == nil && resp.StatusCode == http.StatusOK {
t.Log("router started")
return
}
}
}
}
func copyState(stateName string, logger log.Logger) error {
src := filepath.Join(statesPath, stateName)
dst := filepath.Join(statesPath, tempStatePath)
sourceFileStat, err := os.Stat(src)
if err != nil {
return err
}
if !sourceFileStat.Mode().IsRegular() {
return fmt.Errorf("%s is not a regular file", src)
}
source, err := os.Open(src)
if err != nil {
return err
}
defer func() {
if err := source.Close(); err != nil {
logger.Error(context.Background(), log.WithError(err), log.WithMessage("copyState: close source file"))
}
}()
destination, err := os.Create(dst)
if err != nil {
return err
}
defer func() {
if err := destination.Close(); err != nil {
logger.Error(context.Background(), log.WithError(err), log.WithMessage("copyState: close destination file"))
}
}()
_, err = io.Copy(destination, source)
return err
}I removed whole router and DI setup. States are files that represent DB states that are loaded whenever given consumer pact requires that state (this is state-heavy app).
This code will obviously not work. It's just to help you debug the issue.
Jarema
commented
4 years ago @mefellows is there any chance for update on this topic?
mefellows
commented
4 years ago Hi @Jarema, apologies I hadn't had a chance until today. OK, so I have been able to reproduce so far. Here is what I've done:
Need to dig into why this is of course, but at least I can repro it!
Jarema
commented
4 years ago @mefellows thanks for the update! Thats actually very good info. I was worried about reproducing, as I was not able to deliver specific scenario myself. I'm looking forward into updates! Seems that it it about quantity, rather than specific logic in contracts.
Jarema
commented
4 years ago @mefellows did you find some time to investigate the issue?
Jarema
commented
4 years ago @mefellows hey, is there any chance for follow up? Our org ci/cd flow is heavily degraded by this bug.
mefellows
commented
4 years ago Sorry Tomasz I haven't been able to fix just yet. I'll have some time later in the week.
If you'd like to chat at slack.pact.io we might be able to find a workaround for you in the meantime.
On Mon, May 11, 2020, 9:09 PM Tomasz notifications@github.com wrote:
@mefellows https://github.com/mefellows hey, is there any chance for follow up? Our org ci/cd flow is heavily degraded by this bug.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/pact-foundation/pact-go/issues/128#issuecomment-626636653, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAANFDFIKT4UN7UEN2X2GYDRQ7MG5ANCNFSM4MMMVVCA .
Jarema
commented
4 years ago Thanks for update. I'll join the chat to look for workaround.
Jarema
commented
3 years ago @mefellows unfortunately, today bug appeared again.
There were few changes since our last conversation: pact version: 1.88.14 number of pacts with our provider increased significantly
Software versions
1.14go envGO111MODULE="" 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:
logs:
There are many of those, but all looks similar.