I have a Tomcat server configured for HTTP1.1 and HTTP/2 on port 8002, and also HTTPS on port 8003 to allow me to test against. I am writing Java code using Apache HTTP Client 5.0 to talk HTTP/2 to the server and having issues. Ultimately, I want to be able to POST a message with content to the server using HTTP/2, but I'm having issues so I've stripped down my code to a simple example based on one of the Apache shipped examples - H2TlsAlpnRequestExecutionExample.
The given example is hitting the https://nghttp2.org using a GET request, and I can get that to work. Changing to a POST request also works - although you get a HTTP 405 (Method not allowed) response the call was made. If I point the exact same example to my server then I can GET and POST successfully to the regular HTTP/1.1 port (8002) using HTTP/2. However attempts to GET or POST to HTTPS on port 8003 fail - although GET/POST using HTTPv1.1 (rather then HTTP/2) work to HTTPS/8003 too.
With DEBUG on I don't see much debug info from the apache libraries, but I do see that my log messages saying my cert was trusted in both cases, so obviously some initial call negotiation is done.
This is the log for a HTTP2 call to nghttp2.org (which I see is using HTTP/2 from a line in the log):
javax.net.ssl|DEBUG|01|main|2021-03-04 12:37:29.021 GMT|SSLCipher.java:438|jdk.tls.keyLimits: entry = AES/GCM/NoPadding KeyUpdate 2^37. AES/GCM/NOPADDING:KEYUPDATE = 137438953472
0 [main] DEBUG com.test.HTTP2Tester - Making requst to https://nghttp2.org:443
422 [main] INFO com.test.HTTP2Tester - Awaiting latch to countdown ....
javax.net.ssl|DEBUG|0E|requester-dispatch-1|2021-03-04 12:37:30.345 GMT|SSLCipher.java:1840|KeyLimit read side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|DEBUG|0E|requester-dispatch-1|2021-03-04 12:37:30.347 GMT|SSLCipher.java:1994|KeyLimit write side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
725 [requester-dispatch-1] INFO com.test.HTTP2Tester - Trusting certificate from CN=nghttp2.org
javax.net.ssl|DEBUG|0E|requester-dispatch-1|2021-03-04 12:37:30.378 GMT|SSLCipher.java:1840|KeyLimit read side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
javax.net.ssl|DEBUG|0E|requester-dispatch-1|2021-03-04 12:37:30.379 GMT|SSLCipher.java:1994|KeyLimit write side: algorithm = AES/GCM/NOPADDING:KEYUPDATE
countdown value = 137438953472
942 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - 0 <<[type=4, flags=0, streamId=0, payoad=java.nio.HeapByteBuffer[pos=9 lim=33 cap=65545]]
943 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - 0 <<[type=4, flags=0, streamId=0, payoad=java.nio.HeapByteBuffer[pos=9 lim=33 cap=65545]]
958 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) >> :method: POST
958 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) >> :scheme: https
959 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) >> :authority: nghttp2.org:443
959 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) >> :path: /httpbin/ip
959 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) >> user-agent: Apache-HttpCore/5.0.2 (Java/11.0.10)
966 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - 0 <<[type=4, flags=1, streamId=0, payoad=null]
966 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - 0 <<[type=4, flags=1, streamId=0, payoad=null]
1168 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - 1 <<[type=1, flags=4, streamId=1, payoad=java.nio.HeapByteBuffer[pos=9 lim=258 cap=65545]]
1169 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - 1 <<[type=1, flags=4, streamId=1, payoad=java.nio.HeapByteBuffer[pos=9 lim=258 cap=65545]]
1170 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << :status: 405
1170 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << date: Thu, 04 Mar 2021 12:37:30 GMT
1172 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << content-type: text/html
1173 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << allow: GET, HEAD, OPTIONS
1173 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << content-length: 178
1173 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << access-control-allow-origin: *
1174 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << access-control-allow-credentials: true
1175 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << x-backend-header-rtt: 0.002696
1176 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << strict-transport-security: max-age=31536000
1176 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << server: nghttpx
1176 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << via: 1.1 nghttpx
1177 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << alt-svc: h3-29=":443"; ma=3600
1177 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << x-frame-options: SAMEORIGIN
1177 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << x-xss-protection: 1; mode=block
1178 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - nghttp2.org/139.162.123.134:443 (1) << x-content-type-options: nosniff
1186 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - 1 <<[type=0, flags=1, streamId=1, payoad=java.nio.HeapByteBuffer[pos=267 lim=445 cap=65545]]
1186 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - 1 <<[type=0, flags=1, streamId=1, payoad=java.nio.HeapByteBuffer[pos=267 lim=445 cap=65545]]
1188 [requester-dispatch-1] INFO com.test.HTTP2Tester - Complete : /httpbin/ip->405 HTTP/2.0
1189 [requester-dispatch-1] DEBUG com.test.HTTP2Tester - <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2 Final//EN">
<title>405 Method Not Allowed</title>
<h1>Method Not Allowed</h1>
<p>The method is not allowed for the requested URL.</p>
1189 [main] INFO com.test.HTTP2Tester - Awaiting latch to countdown .... done
This is the log from when I point to my server. You can see it says it trusted the certificate so it must have connected and done some negotiation, but nothing happens after that.
javax.net.ssl|DEBUG|01|main|2021-03-04 14:51:36.352 GMT|SSLCipher.java:438|jdk.tls.keyLimits: entry = AES/GCM/NoPadding KeyUpdate 2^37. AES/GCM/NOPADDING:KEYUPDATE = 137438953472
0 [main] DEBUG com.test.HTTP2Tester - Making requst to https://localhost:8003
54 [main] INFO com.test.HTTP2Tester - Awaiting latch to countdown ....
117 [requester-dispatch-1] INFO com.test.HTTP2Tester - Trusting certificate from EMAILADDRESS=john.fergus@......
javax.net.ssl|DEBUG|0E|requester-dispatch-1|2021-03-04 14:51:37.145 GMT|Alert.java:238|Received alert message (
"Alert": {
"level" : "warning",
"description": "close_notify"
}
)
182 [requester-dispatch-1] WARN com.test.HTTP2Tester - Failed : /VSFTestMT_Test/Test/Test_EchoHttpGet->org.apache.hc.core5.http.ConnectionClosedException: Connection is closed
183 [main] INFO com.test.HTTP2Tester - Awaiting latch to countdown .... done
This is the code.
public void testWithHTTP2() throws Exception {
final String testName = "testWithHTTP2";
String content = "Code=99&Message=Goodbye";
String contentType = "application.x_www_form_urlencoded";
final SSLContext sslcontext = SSLContexts.custom()
.loadTrustMaterial(new TrustStrategy() {
@Override
public boolean isTrusted(X509Certificate[] chain, String authType)
throws CertificateException {
final X509Certificate cert = chain[0];
Log.info("Trusting certificate from "+cert.getSubjectDN());
return true;
}
})
.build();
final TlsStrategy tlsStrategy = ClientTlsStrategyBuilder.create()
.setSslContext(sslcontext)
// IMPORTANT uncomment the following method when running Java 9 or older
// in order for ALPN support to work and avoid the illegal reflective
// access operation warning
.setTlsDetailsFactory(new Factory<SSLEngine, TlsDetails>() {
@Override
public TlsDetails create(final SSLEngine sslEngine) {
return new TlsDetails(sslEngine.getSession(), sslEngine.getApplicationProtocol());
}
})
.build();
final H2Config h2Config = H2Config.custom()
.setPushEnabled(false)
.build();
HttpAsyncRequester requester = H2RequesterBootstrap.bootstrap()
.setH2Config(h2Config)
.setIOReactorConfig(IOReactorConfig.custom()
.setSoTimeout(Timeout.ofSeconds(5))
.build())
.setTlsStrategy(tlsStrategy)
.setVersionPolicy(HttpVersionPolicy.FORCE_HTTP_2)
.setStreamListener(new H2StreamListener() {
//final FramePrinter framePrinter = new FramePrinter();
private void logFrameInfo(final String prefix, final RawFrame frame) {
Log.debug(prefix);
Log.debug(frame.toString());
}
private void logFramePayload(final String prefix, final RawFrame frame) {
Log.debug(prefix);
Log.debug(frame.getPayload());
}
@Override
public void onHeaderInput(final HttpConnection connection, final int streamId, final List<? extends Header> headers) {
for (int i = 0; i < headers.size(); i++) {
Log.debug(connection.getRemoteAddress() + " (" + streamId + ") << " + headers.get(i));
}
}
@Override
public void onHeaderOutput(final HttpConnection connection, final int streamId, final List<? extends Header> headers) {
for (int i = 0; i < headers.size(); i++) {
Log.debug(connection.getRemoteAddress() + " (" + streamId + ") >> " + headers.get(i));
}
}
@Override
public void onFrameInput(final HttpConnection connection, final int streamId, final RawFrame frame) {
if (Log.isDebugEnabled()) {
Log.debug(streamId + " <<" + frame);
}
if (Log.isDebugEnabled()) {
Log.debug(streamId + " <<" + frame);
}
}
@Override
public void onFrameOutput(final HttpConnection connection, final int streamId, final RawFrame frame) {
}
@Override
public void onInputFlowControl(final HttpConnection connection, final int streamId, final int delta, final int actualSize) {
}
@Override
public void onOutputFlowControl(final HttpConnection connection, final int streamId, final int delta, final int actualSize) {
}
})
.create();
CountDownLatch countDownLatch = new CountDownLatch(1);
requester.start();
// This tells me it trusts the cert, but get no further - just a "connection is closed" failure
final HttpHost target = new HttpHost("https", "localhost", 8003);
final String requestUri = "/VSFTestMT_Test/Test/Test_EchoHttpGet";
// This works fine ... get a 405 saying POST is not allowed.
// final HttpHost target = new HttpHost("https", "nghttp2.org", 443);
// final String requestUri = "/httpbin/ip";
Log.debug("Making requst to "+target);
final Future<AsyncClientEndpoint> future = requester.connect(target, Timeout.ofSeconds(5));
final AsyncClientEndpoint clientEndpoint = future.get();
final Future<Message<HttpResponse, String>> resultFuture1 = clientEndpoint.execute(
new BasicRequestProducer(
Method.POST, target, requestUri, new StringAsyncEntityProducer(content, ContentType.create(contentType))),
new BasicResponseConsumer<>(new StringAsyncEntityConsumer()),
new FutureCallback<Message<HttpResponse, String>>() {
@Override
public void completed(final Message<HttpResponse, String> message) {
clientEndpoint.releaseAndReuse();
final HttpResponse response = message.getHead();
final String body = message.getBody();
Log.info("Complete : "+requestUri + "->" + response.getCode() + " " + response.getVersion());
Log.debug(body);
countDownLatch.countDown();
}
@Override
public void failed(final Exception ex) {
clientEndpoint.releaseAndDiscard();
Log.warn("Failed : "+requestUri + "->" + ex);
countDownLatch.countDown();
}
@Override
public void cancelled() {
clientEndpoint.releaseAndDiscard();
Log.warn("Cancelled : "+requestUri );
countDownLatch.countDown();
}
});
Log.info("Awaiting latch to countdown ....");
countDownLatch.await();
Log.info("Awaiting latch to countdown .... done");
Message<HttpResponse, String> response = resultFuture1.get();
Assert.assertNotNull(response);
final HttpResponse response1 = response.getHead();
final String entity1 = response.getBody();
Assert.assertNotNull(response1);
Assert.assertEquals(200, response1.getCode());
assertTrue("Check we get Message Success back",response.getBody().contains("Success"));
assertTrue("Check we get Message Goodbye back",response.getBody().contains("Goodbye"));
Log.info("Shutting down I/O reactor");
requester.initiateShutdown();
}
Has anyone got any ideas how to debug the issue or resolve it? I think my Tomcat server setup is OK - is there anything or tool I can use to verify it is? Can I see any more debug/log info to find out why the connection is closed and what happened to close it?
