Provider tests result in failed verification for Pending Pacts - Unexpected end event for Pact

[pendsley]

Our verification results are failing to publish when pending pacts are enabled. If we disable pending pacts, everything works fine.

Using Gradle 6.5
testCompile group: 'au.com.dius.pact.provider', name: 'spring', version: '4.1.6'

2020-10-07 11:31:14.240 INFO 17216 --- [ Test worker] a.c.d.p.p.DefaultVerificationReporter : Published verification result of 'Failed(results=[{message=Request to provider failed with an exception, exception=java.lang.AssertionError: Unexpected end event for Pact between [consumer] ([consumerVersion]) and [provider] - [description]'

Redacted debug logs

2020-10-07 11:28:56.797 DEBUG 17216 --- [ Test worker] a.c.d.p.p.j.loader.PactBrokerLoader : Loading pacts from pact broker for provider [provider] and consumer version selectors [ConsumerVersionSelector(tag=develop, latest=true)]
2020-10-07 11:28:56.814 DEBUG 17216 --- [ Test worker] a.c.d.p.p.j.loader.PactBrokerLoader : Authentication: None
2020-10-07 11:28:56.825 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: /
2020-10-07 11:28:58.121 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:28:58.607 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:28:58.911 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:28:59.205 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:28:59.505 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:28:59.820 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:00.344 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:00.708 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:01.305 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:01.911 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:02.137 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:02.917 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:03.222 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:04.559 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:05.134 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:05.400 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]
2020-10-07 11:29:05.802 DEBUG 17216 --- [ Test worker] a.c.dius.pact.core.pactbroker.HalClient : Fetching: [pactUrl]

Verifying a pact between[consumer] and [provider] [PENDING]

Notices:
1) The pact at [pactUrl] is being verified because it is a 'work in progress' pact (ie. it is the pact for the latest version of Foo tagged with 'someTag' and is still in pending state). Read more at https://pact.io/wip
2) This pact is in pending state for this version of [provider] because a successful verification result for a version of [provider] with tag 'bugfix/SMCASH-240-fix-pact-provider-configuration' has not yet been published. If this verification fails, it will not cause the overall build to fail. Read more at https://pact.io/pending

[from Pact Broker [pactUrl]]
a charge request to POST to AR
2020-10-07 11:29:13.986 DEBUG 17216 --- [ Test worker] a.com.dius.pact.provider.ProviderClient : Making request for provider au.com.dius.pact.provider.ProviderInfo@113d563[name=[provider],protocol=http,host=localhost,port=57997,path=/[path]/,startProviderTask=,terminateProviderTask=,requestFilter=au.com.dius.pact.provider.junit.target.HttpTarget$getProviderInfo$1@6745904e,stateChangeRequestFilter=,createClient=,insecure=true,trustStore=,trustStorePassword=changeit,stateChangeUrl=,stateChangeUsesBody=true,stateChangeTeardown=false,isDependencyForPactVerify=true,verificationType=REQUEST_RESPONSE,packagesToScan=[],consumers=[]]:
2020-10-07 11:29:13.988 DEBUG 17216 --- [ Test worker] a.com.dius.pact.provider.ProviderClient : method: POST
path: /[path]/
query: {}
headers: {Content-Type=[application/json]}
matchers: MatchingRules(rules={})
generators: Generators(categories={})
body: PRESENT({[jsonBody]})
2020-10-07 11:29:17.240 DEBUG 17216 --- [ Test worker] a.com.dius.pact.provider.ProviderClient : Received response: HTTP/1.1 204
2020-10-07 11:29:17.243 DEBUG 17216 --- [ Test worker] a.com.dius.pact.provider.ProviderClient : Response: {statusCode=204, contentType=text/plain; charset=ISO-8859-1, headers={X-Content-Type-Options=[nosniff], X-XSS-Protection=[1; mode=block], Cache-Control=[no-cache, no-store, max-age=0, must-revalidate], Pragma=[no-cache], Expires=[0], X-Frame-Options=[DENY], Date=[Wed, 07 Oct 2020 16:29:17 GMT]}}
2020-10-07 11:29:26.253 DEBUG 17216 --- [ Test worker] au.com.dius.pact.core.matchers.Matching : No matcher for null, using equality
returns a response which
has status code 204 (OK)
has a matching body (OK)
2020-10-07 11:30:51.413 DEBUG 17216 --- [ Test worker] a.c.d.p.p.DefaultTestResultAccumulator : Received test result 'Failed(results=[{message=Request to provider failed with an exception, exception=java.lang.AssertionError: Unexpected end event for Pact between[consumer] ([consumerVersion]) and [provider] - Upon [desc] (ProviderTestClass), interactionId=3eb2eb3d470fd81356387d33d4639416c11b50ac}], description=Request to provider failed with an exception)' for Pact [provider]-[consumer] and [desc] (Pact Broker [pactUrl])

The VerificationResult is OK until it's passed to the test notifier

This is the stacktrace from the thrown exception

org.gradle.api.internal.tasks.testing.junit.JUnitTestEventAdapter.testFinished(JUnitTestEventAdapter.java:123)
org.junit.runner.notification.SynchronizedRunListener.testFinished(SynchronizedRunListener.java:56)
org.junit.runner.notification.RunNotifier$7.notifyListener(RunNotifier.java:190)
org.junit.runner.notification.RunNotifier$SafeNotifier.run(RunNotifier.java:72)
org.junit.runner.notification.RunNotifier.fireTestFinished(RunNotifier.java:187)
au.com.dius.pact.provider.junit.InteractionRunner.run(InteractionRunner.kt:163)
au.com.dius.pact.provider.junit.PactRunner.runChild(PactRunner.kt:150)
au.com.dius.pact.provider.junit.PactRunner.runChild(PactRunner.kt:56)
org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
org.junit.runners.ParentRunner.run(ParentRunner.java:363)
org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:110)
org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)
org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38)
org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:62)
org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:119)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:182)
org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:164)
org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:414)
org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64)
org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:56)
java.lang.Thread.run(Thread.java:748)

[uglyog]

Looks like this is the line that is raising the exception: https://github.com/gradle/gradle/blob/master/subprojects/testing-jvm/src/main/java/org/gradle/api/internal/tasks/testing/junit/JUnitTestEventAdapter.java#L123

From what I can tell from that class, the test description is changing from when the test is started and when it is finished. The test descriptions are cached based on a key calculated from the interaction, so I wonder if you have another test which has the same key and is updating the description while that test is running. The key is calculated based on the provider states and the description.

[pendsley]

Well, we ended up deleting all the existing pacts, and everything works now. We think it was put into a bad state when playing with things locally.

We didn't have anything meaningful, since it had not even been deployed anywhere since we added pacts. Likely, put into a bad state when teaching others or something.

[artemptushkin]

I have the same issue, pacts have no state but have descriptions. I have about twenty pacticipants in the Broker and look like it's relevant for most of them... deletion is not a good workaround for me, @uglyog what can you advice?

Verification is okay, but it pactPublish results into this in the Broker:

"exceptions": [
        {
          "exceptionClass": "java.lang.AssertionError",
          "message": "Request to provider failed with an exception: Unexpected end event for Pact between service-a (c9890e4d74e7efc33e9b5502ddfa53fdd1fd4fff) and service-b - Upon a request to get my billing account status <PENDING>(com.evbox.everon.billing.api.BaseProviderPactTest)"
        }
      ]

[uglyog]

@artemptushkin can you check that the descriptions are unique?

[artemptushkin]

@uglyog descriptions are not unique, this is relevant for a lot of different integrations. Probably appeared after PactBroker update from 2.64.** to 2.85.1.0