search

pact-foundation / pact-jvm

JVM version of Pact. Enables consumer driven contract testing, providing a mock service and DSL for the consumer project, and interaction playback and verification for the service provider project.
https://docs.pact.io
Apache License 2.0
1.09k stars 480 forks source link

4.0.x -- The target server failed to respond #969

Closed jsbournival closed 4 years ago

jsbournival commented 5 years ago

Trying to run JUnit5 consumer tests, but always get an error stating it cannot reach mock server. My test is pretty simple:

@ExtendWith(PactConsumerTestExt.class)
@PactTestFor(providerName = "my-provider")
class ConsumerContractTest {
  // ...
@Pact(consumer = "my-consumer", provider = "myprovider")
public RequestResponsePact createSuccessfulInvoiceRequestPact(PactDslWithProvider builder) { 
 //... 
}
@Test
void runTest(MockServer mockServer) throws IOException {
    HttpResponse httpResponse = Request.Get(mockServer.getUrl() + "/access/to/my/api/" + INVOICE_ID.toString() + "?locale=en_US").execute().returnResponse();
    assertThat(httpResponse.getStatusLine().getStatusCode()).isEqualTo(200);
}

I can see in the traces its attempts to reach the mock server, but I don't have more information:

2019-10-28 09:00:09.027  INFO [traceId=,spanId=]   --- [           main] o.apache.http.impl.execchain.RetryExec   : I/O exception (org.apache.http.NoHttpResponseException) caught when processing request to {}->http://localhost:54253: The target server failed to respond
2019-10-28 09:00:09.031  INFO [traceId=,spanId=]   --- [           main] o.apache.http.impl.execchain.RetryExec   : Retrying request to {}->http://localhost:54253
2019-10-28 09:00:09.033  INFO [traceId=,spanId=]   --- [           main] o.apache.http.impl.execchain.RetryExec   : I/O exception (org.apache.http.NoHttpResponseException) caught when processing request to {}->http://localhost:54253: The target server failed to respond
2019-10-28 09:00:09.033  INFO [traceId=,spanId=]   --- [           main] o.apache.http.impl.execchain.RetryExec   : Retrying request to {}->http://localhost:54253
2019-10-28 09:00:09.035  INFO [traceId=,spanId=]   --- [           main] o.apache.http.impl.execchain.RetryExec   : I/O exception (org.apache.http.NoHttpResponseException) caught when processing request to {}->http://localhost:54253: The target server failed to respond
2019-10-28 09:00:09.035  INFO [traceId=,spanId=]   --- [           main] o.apache.http.impl.execchain.RetryExec   : Retrying request to {}->http://localhost:54253
uglyog commented 5 years ago

Which version of Java are you using? Also, what OS is this running on?

If you enable debug level logs, you should see log entries showing the mock server starting. If I run this test https://github.com/DiUS/pact-jvm/blob/master/consumer/pact-jvm-consumer-junit5/src/test/java/au/com/dius/pact/consumer/junit5/ArticlesTest.java I can see the following in the logs:

13:48:24.939 [Test worker] DEBUG au.com.dius.pact.consumer.BaseJdkMockServer - Starting mock server
13:48:24.943 [Test worker] DEBUG au.com.dius.pact.consumer.BaseJdkMockServer - Mock server started: /127.0.0.1:33373
13:48:24.955 [HTTP-Dispatcher] DEBUG au.com.dius.pact.consumer.BaseJdkMockServer - Received request:    method: GET
    path: /articles.json
    query: {}
    headers: {Accept-encoding=[gzip,deflate], Connection=[Keep-Alive], Host=[localhost:33373], User-agent=[Apache-HttpClient/4.5.5 (Java/11.0.5-ea)]}
    matchers: MatchingRules(rules={})
    generators: Generators(categories={})
    body: EMPTY
jsbournival commented 5 years ago

11.0.3 on Mojave. Ok I'll try to look for the logs.

morcmarc commented 4 years ago

I've got the same problem. I've tried Java 11 and 12 (Java 8 failed because Kotlin doesn't like it).

Logs:

{"@timestamp":"2019-11-27T14:32:39.254Z","@version":"1","message":"Starting mock server","logger_name":"au.com.dius.pact.consumer.BaseJdkMockServer","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.263Z","@version":"1","message":"Mock server started: /127.0.0.1:1233","logger_name":"au.com.dius.pact.consumer.BaseJdkMockServer","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.539Z","@version":"1","message":"CookieSpec selected: default","logger_name":"org.apache.http.client.protocol.RequestAddCookies","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.556Z","@version":"1","message":"Auth cache not set in the context","logger_name":"org.apache.http.client.protocol.RequestAuthCache","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.558Z","@version":"1","message":"Get connection for route {}->http://localhost:1233","logger_name":"org.apache.http.impl.conn.BasicHttpClientConnectionManager","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.568Z","@version":"1","message":"http-outgoing-0: set socket timeout to 0","logger_name":"org.apache.http.impl.conn.DefaultManagedHttpClientConnection","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.569Z","@version":"1","message":"Opening connection {}->http://localhost:1233","logger_name":"org.apache.http.impl.execchain.MainClientExec","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.570Z","@version":"1","message":"Connecting to localhost/127.0.0.1:1233","logger_name":"org.apache.http.impl.conn.DefaultHttpClientConnectionOperator","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.572Z","@version":"1","message":"Connection established 127.0.0.1:64733<->127.0.0.1:1233","logger_name":"org.apache.http.impl.conn.DefaultHttpClientConnectionOperator","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.572Z","@version":"1","message":"Executing request OPTIONS / HTTP/1.1","logger_name":"org.apache.http.impl.execchain.MainClientExec","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.573Z","@version":"1","message":"Target auth state: UNCHALLENGED","logger_name":"org.apache.http.impl.execchain.MainClientExec","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.573Z","@version":"1","message":"Proxy auth state: UNCHALLENGED","logger_name":"org.apache.http.impl.execchain.MainClientExec","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.575Z","@version":"1","message":"http-outgoing-0 >> OPTIONS / HTTP/1.1","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.575Z","@version":"1","message":"http-outgoing-0 >> X-PACT-BOOTCHECK: true","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.575Z","@version":"1","message":"http-outgoing-0 >> Host: localhost:1233","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.576Z","@version":"1","message":"http-outgoing-0 >> Connection: Keep-Alive","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.576Z","@version":"1","message":"http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.10 (Java/12.0.1)","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.576Z","@version":"1","message":"http-outgoing-0 >> Accept-Encoding: gzip,deflate","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.576Z","@version":"1","message":"http-outgoing-0 >> \"OPTIONS / HTTP/1.1[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.576Z","@version":"1","message":"http-outgoing-0 >> \"X-PACT-BOOTCHECK: true[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.576Z","@version":"1","message":"http-outgoing-0 >> \"Host: localhost:1233[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.576Z","@version":"1","message":"http-outgoing-0 >> \"Connection: Keep-Alive[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.577Z","@version":"1","message":"http-outgoing-0 >> \"User-Agent: Apache-HttpClient/4.5.10 (Java/12.0.1)[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.577Z","@version":"1","message":"http-outgoing-0 >> \"Accept-Encoding: gzip,deflate[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.577Z","@version":"1","message":"http-outgoing-0 >> \"[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.588Z","@version":"1","message":"http-outgoing-0 << \"HTTP/1.1 200 OK[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.589Z","@version":"1","message":"http-outgoing-0 << \"Date: Wed, 27 Nov 2019 14:32:39 GMT[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.589Z","@version":"1","message":"http-outgoing-0 << \"Transfer-encoding: chunked[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.589Z","@version":"1","message":"http-outgoing-0 << \"X-pact-bootcheck: true[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.589Z","@version":"1","message":"http-outgoing-0 << \"[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.591Z","@version":"1","message":"http-outgoing-0 << HTTP/1.1 200 OK","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.592Z","@version":"1","message":"http-outgoing-0 << Date: Wed, 27 Nov 2019 14:32:39 GMT","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.592Z","@version":"1","message":"http-outgoing-0 << Transfer-encoding: chunked","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.592Z","@version":"1","message":"http-outgoing-0 << X-pact-bootcheck: true","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.596Z","@version":"1","message":"Connection can be kept alive indefinitely","logger_name":"org.apache.http.impl.execchain.MainClientExec","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.599Z","@version":"1","message":"http-outgoing-0: Close connection","logger_name":"org.apache.http.impl.conn.DefaultManagedHttpClientConnection","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.600Z","@version":"1","message":"Connection discarded","logger_name":"org.apache.http.impl.execchain.MainClientExec","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.600Z","@version":"1","message":"Releasing connection [Not bound]","logger_name":"org.apache.http.impl.conn.BasicHttpClientConnectionManager","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.672Z","@version":"1","message":"GET http://localhost:1233/mallory?status=good&name=ron","logger_name":"groovyx.net.http.RESTClient","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.694Z","@version":"1","message":"Get connection for route {}->http://localhost:1233","logger_name":"org.apache.http.impl.conn.BasicClientConnectionManager","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.699Z","@version":"1","message":"Connecting to localhost:1233","logger_name":"org.apache.http.impl.conn.DefaultClientConnectionOperator","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.703Z","@version":"1","message":"CookieSpec selected: default","logger_name":"org.apache.http.client.protocol.RequestAddCookies","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.704Z","@version":"1","message":"Auth cache not set in the context","logger_name":"org.apache.http.client.protocol.RequestAuthCache","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.704Z","@version":"1","message":"Target auth state: UNCHALLENGED","logger_name":"org.apache.http.client.protocol.RequestTargetAuthentication","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.705Z","@version":"1","message":"Proxy auth state: UNCHALLENGED","logger_name":"org.apache.http.client.protocol.RequestProxyAuthentication","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.705Z","@version":"1","message":"Attempt 1 to execute request","logger_name":"org.apache.http.impl.client.DefaultHttpClient","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.705Z","@version":"1","message":"Sending request: GET /mallory?status=good&name=ron HTTP/1.1","logger_name":"org.apache.http.impl.conn.DefaultClientConnection","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.705Z","@version":"1","message":" >> \"GET /mallory?status=good&name=ron HTTP/1.1[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.705Z","@version":"1","message":" >> \"Accept: */*[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.705Z","@version":"1","message":" >> \"Host: localhost:1233[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.706Z","@version":"1","message":" >> \"Connection: Keep-Alive[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.706Z","@version":"1","message":" >> \"[\\r][\\n]\"","logger_name":"org.apache.http.wire","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.706Z","@version":"1","message":">> GET /mallory?status=good&name=ron HTTP/1.1","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.706Z","@version":"1","message":">> Accept: */*","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.706Z","@version":"1","message":">> Host: localhost:1233","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.706Z","@version":"1","message":">> Connection: Keep-Alive","logger_name":"org.apache.http.headers","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.709Z","@version":"1","message":"Connection 0.0.0.0:64734<->127.0.0.1:1233 closed","logger_name":"org.apache.http.impl.conn.DefaultClientConnection","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.709Z","@version":"1","message":"Closing the connection.","logger_name":"org.apache.http.impl.client.DefaultHttpClient","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.709Z","@version":"1","message":"Connection 0.0.0.0:64734<->127.0.0.1:1233 closed","logger_name":"org.apache.http.impl.conn.DefaultClientConnection","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.710Z","@version":"1","message":"I/O exception (org.apache.http.NoHttpResponseException) caught when processing request to {}->http://localhost:1233: The target server failed to respond","logger_name":"org.apache.http.impl.client.DefaultHttpClient","level":"INFO","level_value":20000}
{"@timestamp":"2019-11-27T14:32:39.713Z","@version":"1","message":"The target server failed to respond","logger_name":"org.apache.http.impl.client.DefaultHttpClient","level":"DEBUG","level_value":10000,"stack_trace":"o.a.h.NoHttpResponseException: The target server failed to respond\n\tat o.a.h.i.c.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:141)\n\tat o.a.h.i.c.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)\n\tat o.a.h.i.i.AbstractMessageParser.parse(AbstractMessageParser.java:259)\n\tat o.a.h.i.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:294)\n\tat o.a.h.i.c.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:257)\n\tat o.a.h.i.c.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:207)\n\tat o.a.h.p.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)\n\tat o.a.h.p.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)\n\tat o.a.h.i.c.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:679)\n\tat o.a.h.i.c.DefaultRequestDirector.execute(DefaultRequestDirector.java:481)\n\tat o.a.h.i.c.AbstractHttpClient.doExecute(AbstractHttpClient.java:835)\n\tat o.a.h.i.c.CloseableHttpClient.execute(CloseableHttpClient.java:72)\n\tat o.a.h.i.c.CloseableHttpClient.execute(CloseableHttpClient.java:221)\n\tat o.a.h.i.c.CloseableHttpClient.execute(CloseableHttpClient.java:165)\n\tat g.n.http.HTTPBuilder.doRequest(HTTPBuilder.java:515)\n\tat g.n.http.RESTClient.get(RESTClient.java:119)\n\tat g.n.h.RESTClient$get.call(Unknown Source)\n\tat o.c.g.r.c.CallSiteArray.defaultCall(CallSiteArray.java:47)\n\tat o.c.g.r.c.AbstractCallSite.call(AbstractCallSite.java:115)\n\tat o.c.g.r.c.AbstractCallSite.call(AbstractCallSite.java:127)\n\tat c.s.g.t.c.SampleTest$_foo_closure3.doCall(SampleSpec.groovy:32)\n\tat j.i.r.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)\n\tat j.i.r.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat j.i.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat j.l.reflect.Method.invoke(Method.java:567)\n\tat o.c.g.r.CachedMethod.invoke(CachedMethod.java:101)\n\tat g.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)\n\tat o.c.g.r.m.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:263)\n\tat g.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1041)\n\tat groovy.lang.Closure.call(Closure.java:405)\n\tat groovy.lang.Closure.call(Closure.java:421)\n\tat a.c.d.p.c.g.PactBuilder$_runTest_closure5.doCall(PactBuilder.groovy:354)\n\tat j.i.r.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)\n\tat j.i.r.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat j.i.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat j.l.reflect.Method.invoke(Method.java:567)\n\tat o.c.g.r.CachedMethod.invoke(CachedMethod.java:101)\n\tat g.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)\n\tat o.c.g.r.m.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:263)\n\tat g.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1041)\n\tat groovy.lang.Closure.call(Closure.java:405)\n\tat o.c.g.r.ConvertedClosure.invokeCustom(ConvertedClosure.java:50)\n\tat o.c.g.r.ConversionHandler.invoke(ConversionHandler.java:122)\n\tat c.sun.proxy.$Proxy11.run(Unknown Source)\n\tat a.c.d.p.c.BaseMockServer.runAndWritePact(MockHttpServer.kt:110)\n\tat a.c.d.p.c.ConsumerPactRunnerKt.runConsumerTest(ConsumerPactRunner.kt:13)\n\tat a.c.d.p.c.g.PactBuilder.runTest(PactBuilder.groovy:360)\n\tat a.c.d.p.c.g.PactBuilder.runTest(PactBuilder.groovy)\n\tat a.c.d.p.c.g.PactBuilder$runTest$0.call(Unknown Source)\n\tat o.c.g.r.c.CallSiteArray.defaultCall(CallSiteArray.java:47)\n\tat o.c.g.r.c.AbstractCallSite.call(AbstractCallSite.java:115)\n\tat o.c.g.r.c.AbstractCallSite.call(AbstractCallSite.java:127)\n\tat c.s.g.t.c.SampleTest.foo(SampleSpec.groovy:30)\n\tat j.i.r.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)\n\tat j.i.r.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat j.i.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat j.l.reflect.Method.invoke(Method.java:567)\n\tat o.j.r.m.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)\n\tat o.j.i.r.m.ReflectiveCallable.run(ReflectiveCallable.java:12)\n\tat o.j.r.m.FrameworkMethod.invokeExplosively(...\n"}
...
{"@timestamp":"2019-11-27T14:32:39.725Z","@version":"1","message":"Connection 0.0.0.0:64737<->127.0.0.1:1233 closed","logger_name":"org.apache.http.impl.conn.DefaultClientConnection","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.725Z","@version":"1","message":"Closing the connection.","logger_name":"org.apache.http.impl.client.DefaultHttpClient","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.725Z","@version":"1","message":"Connection 0.0.0.0:64737<->127.0.0.1:1233 closed","logger_name":"org.apache.http.impl.conn.DefaultClientConnection","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.726Z","@version":"1","message":"Connection 0.0.0.0:64737<->127.0.0.1:1233 shut down","logger_name":"org.apache.http.impl.conn.DefaultClientConnection","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.726Z","@version":"1","message":"Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@186cb891","logger_name":"org.apache.http.impl.conn.BasicClientConnectionManager","level":"DEBUG","level_value":10000}
{"@timestamp":"2019-11-27T14:32:39.727Z","@version":"1","message":"Caught exception in mock server","logger_name":"au.com.dius.pact.consumer.BaseMockServer","level":"DEBUG","level_value":10000,"stack_trace":"o.a.h.NoHttpResponseException: localhost:1233 failed to respond\n\tat o.a.h.i.c.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:141)\n\tat o.a.h.i.c.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)\n\tat o.a.h.i.i.AbstractMessageParser.parse(AbstractMessageParser.java:259)\n\tat o.a.h.i.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:294)\n\tat o.a.h.i.c.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:257)\n\tat o.a.h.i.c.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:207)\n\tat o.a.h.p.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)\n\tat o.a.h.p.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)\n\tat o.a.h.i.c.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:679)\n\tat o.a.h.i.c.DefaultRequestDirector.execute(DefaultRequestDirector.java:481)\n\tat o.a.h.i.c.AbstractHttpClient.doExecute(AbstractHttpClient.java:835)\n\tat o.a.h.i.c.CloseableHttpClient.execute(CloseableHttpClient.java:72)\n\tat o.a.h.i.c.CloseableHttpClient.execute(CloseableHttpClient.java:221)\n\tat o.a.h.i.c.CloseableHttpClient.execute(CloseableHttpClient.java:165)\n\tat g.n.http.HTTPBuilder.doRequest(HTTPBuilder.java:515)\n\tat g.n.http.RESTClient.get(RESTClient.java:119)\n\tat g.n.h.RESTClient$get.call(Unknown Source)\n\tat o.c.g.r.c.CallSiteArray.defaultCall(CallSiteArray.java:47)\n\tat o.c.g.r.c.AbstractCallSite.call(AbstractCallSite.java:115)\n\tat o.c.g.r.c.AbstractCallSite.call(AbstractCallSite.java:127)\n\tat c.s.g.t.c.SampleTest$_foo_closure3.doCall(SampleSpec.groovy:32)\n\tat j.i.r.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)\n\tat j.i.r.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat j.i.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat j.l.reflect.Method.invoke(Method.java:567)\n\tat o.c.g.r.CachedMethod.invoke(CachedMethod.java:101)\n\tat g.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)\n\tat o.c.g.r.m.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:263)\n\tat g.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1041)\n\tat groovy.lang.Closure.call(Closure.java:405)\n\tat groovy.lang.Closure.call(Closure.java:421)\n\tat a.c.d.p.c.g.PactBuilder$_runTest_closure5.doCall(PactBuilder.groovy:354)\n\tat j.i.r.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)\n\tat j.i.r.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat j.i.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat j.l.reflect.Method.invoke(Method.java:567)\n\tat o.c.g.r.CachedMethod.invoke(CachedMethod.java:101)\n\tat g.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)\n\tat o.c.g.r.m.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:263)\n\tat g.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1041)\n\tat groovy.lang.Closure.call(Closure.java:405)\n\tat o.c.g.r.ConvertedClosure.invokeCustom(ConvertedClosure.java:50)\n\tat o.c.g.r.ConversionHandler.invoke(ConversionHandler.java:122)\n\tat c.sun.proxy.$Proxy11.run(Unknown Source)\n\tat a.c.d.p.c.BaseMockServer.runAndWritePact(MockHttpServer.kt:110)\n\tat a.c.d.p.c.ConsumerPactRunnerKt.runConsumerTest(ConsumerPactRunner.kt:13)\n\tat a.c.d.p.c.g.PactBuilder.runTest(PactBuilder.groovy:360)\n\tat a.c.d.p.c.g.PactBuilder.runTest(PactBuilder.groovy)\n\tat a.c.d.p.c.g.PactBuilder$runTest$0.call(Unknown Source)\n\tat o.c.g.r.c.CallSiteArray.defaultCall(CallSiteArray.java:47)\n\tat o.c.g.r.c.AbstractCallSite.call(AbstractCallSite.java:115)\n\tat o.c.g.r.c.AbstractCallSite.call(AbstractCallSite.java:127)\n\tat c.s.g.t.c.SampleTest.foo(SampleSpec.groovy:30)\n\tat j.i.r.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)\n\tat j.i.r.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\n\tat j.i.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n\tat j.l.reflect.Method.invoke(Method.java:567)\n\tat o.j.r.m.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)\n\tat o.j.i.r.m.ReflectiveCallable.run(ReflectiveCallable.java:12)\n\tat o.j.r.m.FrameworkMethod.invokeExplosively(Fra...\n"}
{"@timestamp":"2019-11-27T14:32:39.744Z","@version":"1","message":"Mock server shutdown","logger_name":"au.com.dius.pact.consumer.BaseJdkMockServer","level":"DEBUG","level_value":10000}

Assertion failed:

assert result instanceof PactVerificationResult.Ok
       |      |
       |      false
       Error(error=org.apache.http.NoHttpResponseException: localhost:1233 failed to respond, mockServerState=ExpectedButNotReceived(expectedRequests=[ method: get
        path: /mallory
        query: {name=[ron], status=[good]}
        headers: {}
        matchers: MatchingRules(rules={})
        generators: Generators(categories={})
        body: MISSING]))

Looks like the mock server is throwing an exception while parsing the headers. Not sure why, I'll try to do some more digging around.

sycyhy commented 4 years ago

Same issue in here, jdk 11.0.5 (zulu) with the example copied from the README.md for groovy-consumer.

mwohllebe commented 4 years ago

Same issue here when running ArticlesTest (in Eclipse) with OpenJDK Runtime Environment 18.9 (build 11.0.5+10) (Windows 10)

Logs: 16:45:22.597 [main] DEBUG au.com.dius.pact.consumer.junit5.PactConsumerTestExt - Found @PactTestFor annotation on test method 16:45:22.604 [main] DEBUG au.com.dius.pact.consumer.junit5.PactConsumerTestExt - Found @PactTestFor annotation on test class 16:45:22.604 [main] DEBUG au.com.dius.pact.consumer.junit5.PactConsumerTestExt - providerInfo = ProviderInfo(providerName=ArticlesProvider, hostInterface=, port=1234, pactVersion=null, providerType=null) 16:45:22.607 [main] DEBUG au.com.dius.pact.consumer.junit5.PactConsumerTestExt - Looking for @Pact method named 'articlesDoNotExist' for provider 'ArticlesProvider' 16:45:22.609 [main] DEBUG au.com.dius.pact.consumer.junit5.PactConsumerTestExt - Invoking method 'articlesDoNotExist' to get Pact for the test 'testArticlesDoNotExist' 16:45:23.006 [main] DEBUG au.com.dius.pact.consumer.BaseJdkMockServer - Starting mock server 16:45:23.008 [main] DEBUG au.com.dius.pact.consumer.BaseJdkMockServer - Mock server started: /127.0.0.1:1234 16:45:23.268 [main] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: default 16:45:23.281 [main] DEBUG org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context 16:45:23.282 [main] DEBUG org.apache.http.impl.conn.BasicHttpClientConnectionManager - Get connection for route {}->http://127.0.0.1:1234 16:45:23.305 [main] DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 0 16:45:23.306 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Opening connection {}->http://127.0.0.1:1234 16:45:23.307 [main] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connecting to /127.0.0.1:1234 16:45:23.309 [main] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:54635<->127.0.0.1:1234 16:45:23.309 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Executing request OPTIONS / HTTP/1.1 16:45:23.309 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED 16:45:23.310 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED 16:45:23.311 [main] DEBUG org.apache.http.headers - http-outgoing-0 >> OPTIONS / HTTP/1.1 16:45:23.311 [main] DEBUG org.apache.http.headers - http-outgoing-0 >> X-PACT-BOOTCHECK: true 16:45:23.311 [main] DEBUG org.apache.http.headers - http-outgoing-0 >> Host: 127.0.0.1:1234 16:45:23.311 [main] DEBUG org.apache.http.headers - http-outgoing-0 >> Connection: Keep-Alive 16:45:23.311 [main] DEBUG org.apache.http.headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.6 (Java/11.0.5) 16:45:23.311 [main] DEBUG org.apache.http.headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate 16:45:23.311 [main] DEBUG org.apache.http.wire - http-outgoing-0 >> "OPTIONS / HTTP/1.1[\r][\n]" 16:45:23.311 [main] DEBUG org.apache.http.wire - http-outgoing-0 >> "X-PACT-BOOTCHECK: true[\r][\n]" 16:45:23.311 [main] DEBUG org.apache.http.wire - http-outgoing-0 >> "Host: 127.0.0.1:1234[\r][\n]" 16:45:23.311 [main] DEBUG org.apache.http.wire - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]" 16:45:23.311 [main] DEBUG org.apache.http.wire - http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/11.0.5)[\r][\n]" 16:45:23.312 [main] DEBUG org.apache.http.wire - http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]" 16:45:23.312 [main] DEBUG org.apache.http.wire - http-outgoing-0 >> "[\r][\n]" 16:45:23.334 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]" 16:45:23.334 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "Date: Mon, 06 Jan 2020 15:45:23 GMT[\r][\n]" 16:45:23.334 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "Transfer-encoding: chunked[\r][\n]" 16:45:23.334 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "X-pact-bootcheck: true[\r][\n]" 16:45:23.334 [main] DEBUG org.apache.http.wire - http-outgoing-0 << "[\r][\n]" 16:45:23.337 [main] DEBUG org.apache.http.headers - http-outgoing-0 << HTTP/1.1 200 OK 16:45:23.337 [main] DEBUG org.apache.http.headers - http-outgoing-0 << Date: Mon, 06 Jan 2020 15:45:23 GMT 16:45:23.337 [main] DEBUG org.apache.http.headers - http-outgoing-0 << Transfer-encoding: chunked 16:45:23.337 [main] DEBUG org.apache.http.headers - http-outgoing-0 << X-pact-bootcheck: true 16:45:23.341 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Connection can be kept alive indefinitely 16:45:23.344 [main] DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-0: Close connection 16:45:23.344 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Connection discarded 16:45:23.344 [main] DEBUG org.apache.http.impl.conn.BasicHttpClientConnectionManager - Releasing connection [Not bound] 16:45:23.373 [main] DEBUG org.apache.http.client.protocol.RequestAddCookies - CookieSpec selected: default 16:45:23.373 [main] DEBUG org.apache.http.client.protocol.RequestAuthCache - Auth cache not set in the context 16:45:23.374 [main] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection request: [route: {}->http://127.0.0.1:1234][total kept alive: 0; route allocated: 0 of 100; total allocated: 0 of 200] 16:45:23.376 [main] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection leased: [id: 0][route: {}->http://127.0.0.1:1234][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 200] 16:45:23.377 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Opening connection {}->http://127.0.0.1:1234 16:45:23.377 [main] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connecting to /127.0.0.1:1234 16:45:23.377 [main] DEBUG org.apache.http.impl.conn.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:54636<->127.0.0.1:1234 16:45:23.377 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Executing request GET /articles.json HTTP/1.1 16:45:23.377 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Target auth state: UNCHALLENGED 16:45:23.377 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Proxy auth state: UNCHALLENGED 16:45:23.377 [main] DEBUG org.apache.http.headers - http-outgoing-1 >> GET /articles.json HTTP/1.1 16:45:23.377 [main] DEBUG org.apache.http.headers - http-outgoing-1 >> Host: 127.0.0.1:1234 16:45:23.377 [main] DEBUG org.apache.http.headers - http-outgoing-1 >> Connection: Keep-Alive 16:45:23.377 [main] DEBUG org.apache.http.headers - http-outgoing-1 >> User-Agent: Apache-HttpClient/4.5.6 (Java/11.0.5) 16:45:23.377 [main] DEBUG org.apache.http.headers - http-outgoing-1 >> Accept-Encoding: gzip,deflate 16:45:23.377 [main] DEBUG org.apache.http.wire - http-outgoing-1 >> "GET /articles.json HTTP/1.1[\r][\n]" 16:45:23.377 [main] DEBUG org.apache.http.wire - http-outgoing-1 >> "Host: 127.0.0.1:1234[\r][\n]" 16:45:23.378 [main] DEBUG org.apache.http.wire - http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]" 16:45:23.378 [main] DEBUG org.apache.http.wire - http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/11.0.5)[\r][\n]" 16:45:23.378 [main] DEBUG org.apache.http.wire - http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]" 16:45:23.378 [main] DEBUG org.apache.http.wire - http-outgoing-1 >> "[\r][\n]" 16:45:23.383 [main] DEBUG org.apache.http.wire - http-outgoing-1 << "end of stream" 16:45:23.384 [main] DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-1: Close connection 16:45:23.384 [main] DEBUG org.apache.http.impl.conn.DefaultManagedHttpClientConnection - http-outgoing-1: Shutdown connection 16:45:23.384 [main] DEBUG org.apache.http.impl.execchain.MainClientExec - Connection discarded 16:45:23.384 [main] DEBUG org.apache.http.impl.conn.PoolingHttpClientConnectionManager - Connection released: [id: 0][route: {}->http://127.0.0.1:1234][total kept alive: 0; route allocated: 0 of 100; total allocated: 0 of 200] 16:45:23.387 [main] INFO org.apache.http.impl.execchain.RetryExec - I/O exception (org.apache.http.NoHttpResponseException) caught when processing request to {}->http://127.0.0.1:1234: The target server failed to respond 16:45:23.389 [main] DEBUG org.apache.http.impl.execchain.RetryExec - The target server failed to respond org.apache.http.NoHttpResponseException: The target server failed to respond at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:141) at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56) at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165) at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) at org.apache.http.client.fluent.Request.internalExecute(Request.java:173) at org.apache.http.client.fluent.Request.execute(Request.java:177)

ahsankarimbhai commented 4 years ago

@uglyog I am seeing the same issue with ArticlesTest.

Getting the same error:

com.trendmicro.np.ms.aggregator.contracttests.ArticlesTest > testArticles(MockServer) FAILED org.apache.http.NoHttpResponseException: 127.0.0.1:1234 failed to respond

java --version output openjdk 11.0.2 2019-01-15 LTS OpenJDK Runtime Environment Zulu11.29+10-SA (build 11.0.2+7-LTS) OpenJDK 64-Bit Server VM Zulu11.29+10-SA (build 11.0.2+7-LTS, mixed mode)

Pact Version in gradle: testCompile "au.com.dius:pact-jvm-consumer-junit5:4.0.4"

sycyhy commented 4 years ago

I was able to solve my problem few weeks back. As far I remember it was related with the fact that one of the other dependencies was overriding the version for Kotlin to older version which did not support features that the pact library is using. After forcing the same version between both of the deps everything started working properly.

ahsankarimbhai commented 4 years ago

I was able to solve the problem by pointing to au.com.dius:pact-jvm-consumer-junit5_2.12:3.6.13 library. Any version above that seems to be broken.

uglyog commented 4 years ago

@ahsankarimbhai you need to check your dependencies. Pact-JVM 4.0.x requires Kotlin 1.3, if another dependency is bringing in Kotlin 1.2 you may get this error (as @sycyhy mentioned).

eloo commented 4 years ago

sorry for resurrecting this issues but i want to confirm @uglyog hint. i had the same issue and bumping my kotlin version to 1.3 fixed it 👍 thanks

paucls commented 3 years ago

I encountered the same issue in a Kotlin SpringBoot 2.3 project. In my case I define the port I want the provider mock to use.

I/O error on POST request for "http://localhost:9081/products/10/favourite": localhost:9081 failed to respond; nested exception is org.apache.http.NoHttpResponseException: localhost:9081 failed to respond

I tried different versions of pact junit5 and kotlin with no success.

I have 3 tests, it only fails in the one for a POST request.

My quick/ugly workaround was to separate GET and POST test methods in different classes.