4

HI I m trying to write a client that makes http2 request to multiple servers(which already supports http2). so far I have written this standalone program which works fine that I can see all requests goes via same tcp connection(verified with the help of wireshark). I use Apache Httpclient 5 with conscrypt to support ALPN in jdk8 (jdk8 is my requirement, I cannot upgrade to jdk9 or later)

The Main block goes like,

try {
    TrustManager[] trustAllCerts = new TrustManager[]{
        new X509TrustManager(){
            public X509Certificate[] getAcceptedIssuers(){ return null; }
            public void checkClientTrusted(X509Certificate[] certs, String authType) {}
            public void checkServerTrusted(X509Certificate[] certs, String authType) {}
        }
    };
    Provider provider = Conscrypt.newProvider();
        
    SSLContext sslContext = SSLContext.getInstance("TLSv1.3", provider);
    sslContext.init(null, trustAllCerts, new SecureRandom());
        
    client = Http2AsyncClientBuilder.create().setTlsStrategy(new ConscryptClientTlsStrategy(sslContext)).setH2Config(H2Config.DEFAULT).build();
    client.start();
        
    ThreadPoolExecutor tpe = (ThreadPoolExecutor)Executors.newFixedThreadPool(50);
    for (int i=0; i < 50; i++) {
        Runnable worker = new WorkerClass(client, i);
        tpe.execute(worker);
    }
} catch (Exception e) {
    e.printStackTrace();
}

The runnable goes like,

static class WorkerClass implements Runnable {
    CloseableHttpAsyncClient client = null;
    int i = 0;
    WorkerClass(CloseableHttpAsyncClient client, int i) {
        this.client = client;
        this.i = i;
    }
    public void run() {
        RequestConfig requestConfig = RequestConfig.custom()
                .setConnectTimeout(Timeout.of(15, TimeUnit.SECONDS))//Determines the timeout until a new connection is fully established.
                .setConnectionRequestTimeout(Timeout.of(60, TimeUnit.SECONDS))//Returns the connection lease request timeout used when requesting a connection from the connection manager.
                .setResponseTimeout(Timeout.of(60, TimeUnit.SECONDS))//Determines the timeout until arrival of a response from the opposite endpoint.
                .build();
        
        String url = "https://localhost:8081/myagent/getOutput?"+System.currentTimeMillis();
        String cachedXMLRequest = "<?xml version=\"1.0\" standalone=\"no\"?><My XML REQUEST GOES HERE>";
        SimpleHttpRequest request= SimpleHttpRequests.POST.create(url);         
        request.setBodyText(cachedXMLRequest, ContentType.APPLICATION_JSON);
        request.setConfig(requestConfig);           
        final CountDownLatch latch = new CountDownLatch(1);         
        client.execute(request, new FutureCallback<SimpleHttpResponse>() {
            @Override
            public void cancelled() {
                System.out.println("Cancelled");
                latch.countDown();
            }

            @Override
            public void completed(SimpleHttpResponse arg0) {
                System.out.println("Completed "+arg0.getBodyText());
                latch.countDown();
            }

            @Override
            public void failed(Exception exception) {
                System.out.println("Failed ");
                exception.printStackTrace();
                latch.countDown();
            }
        });
        
        try {
            latch.await(60, TimeUnit.SECONDS);
        } catch (InterruptedException e) {
            // TODO Auto-generated catch block
            e.printStackTrace();
        }
    }
}

So I simulated this standalone in my client which asynchronously calls multiple servers for polling using the above logic. But here I can see one tcp connection per request and the connection is closed at the end of the request(Though the response header returns as HTTP/2.0). I use the main block code to initialize the client at the startup of my application(Except threadpool part, as it is used to simulate multithreaded environment in standalone) and create the url, request and response objects and execute each request simultaneously in a threaded model(Asynchronous multiplexing). My requirement is to use one tcp connection per domain and use it for prolonged time for handling high number of requests. What am I missing here?

Or someone hep me with the proper way fo handling http2 using httpclient 5

Kindy shed some light on it.

Edited:

There are two things I tracked down for abnormal connection closes,

1. The connection is closed after every single request

Reason: caused by this line

RequestConfig requestConfig = RequestConfig.custom().setConnectTimeout(Timeout.of(15, TimeUnit.SECONDS))...

This setConnectTimeout is supposed to be at request level, but after 15 idle seconds it closes the tcp connection itself, I don't know whether it is a bug or expected behaviour as this configuration is for encapsulating request items as per the documentation.

Removing this line allows the tcp connection to be kept alive for more than a request.

2. Due to Illegal HEADERS frame/Protocol ERROR/INTERNAL ERROR

I can see these exception in wire log exactly where my tcp connection is getting closed(it closes randomly), I could not share the whole logs as there are too many I just post the exception part

0x0][0x1][0x0][0x0][0x4][0xffffffc9]"

2019-02-07 16:05:08,666 DEBUG - i/o-0000001B << stream 0 frame: WINDOW_UPDATE (0x8); flags: (0x0); length: 4

2019-02-07 16:05:08,666 DEBUG - i/o-0000001B << Increment 1225

2019-02-07 16:05:08,666 DEBUG - i/o-0000001B >> stream 0 flow control 1225 -> 65535

2019-02-07 16:05:08,666 DEBUG - i/o-0000001B << stream 1 frame: WINDOW_UPDATE (0x8); flags: (0x0); length: 4

2019-02-07 16:05:08,666 DEBUG - i/o-0000001B << Increment 1225

2019-02-07 16:05:08,666 DEBUG - i/o-0000001B >> stream 1 flow control 1225 -> 65535

2019-02-07 16:05:08,827 DEBUG - i/o-0000001B << "[0x0][0x0][0x1d][0x1][0x4][0x0][0x0][0x0][0x5]?[0xffffffe1]?[0xffffff88][0x1f][0x12][0xffffff96][0xffffffdf]=[0xffffffbf]J[0x1][0xffffffd5]0[0xffffff96]5[0x4][0x0][0xffffffbe][0xffffffa0]Aq[0xffffff91][0x10][0xffffff94][0xffffffc5][0xffffffa3][0x0][0x3]E[0x0][0x1][0x0][0x0][0x0][0x5][\n]"

2019-02-07 16:05:08,827 DEBUG - i/o-0000001B << "[\n]"

2019-02-07 16:05:08,827 DEBUG - i/o-0000001B << ""

2019-02-07 16:05:08,827 DEBUG - i/o-0000001B << stream 5 frame: HEADERS (0x1); flags: END_HEADERS (0x4); length: 29

2019-02-07 16:05:08,828 DEBUG - i/o-0000001B << ?.?. ...=.J..0.5 3f e1 3f 88 1f 12 96 df 3d bf 4a 01 d5 30 96 35

2019-02-07 16:05:08,828 DEBUG - i/o-0000001B << ....Aq..... 04 00 be a0 41 71 91 5c 10 94 c5 a3 7f

2019-02-07 16:05:08,828 DEBUG - i/o-0000001B >> stream 0 frame: GOAWAY (0x7); flags: (0x0); length: 29

2019-02-07 16:05:08,828 DEBUG - i/o-0000001B >> Last stream 0

2019-02-07 16:05:08,829 DEBUG - i/o-0000001B >> Code PROTOCOL_ERROR

2019-02-07 16:05:08,829 DEBUG - i/o-0000001B >> Illegal HEADERS frame

2019-02-07 16:05:08,829 DEBUG - i/o-0000001B >> "[0x0][0x0][0x1d][0x7][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x1]Illegal HEADERS frame"

2019-02-07 16:05:10,401 DEBUG - ex-0000018D: preparing request execution

and,

2019-02-07 16:17:17,519 DEBUG - i/o-0000000C << stream 0 frame: WINDOW_UPDATE (0x8); flags: (0x0); length: 4

2019-02-07 16:17:17,519 DEBUG - i/o-0000000C << Increment 1208

2019-02-07 16:17:17,519 DEBUG - i/o-0000000C >> stream 0 flow control 1208 -> 65535

2019-02-07 16:17:17,519 DEBUG - i/o-0000000C << stream 1 frame: WINDOW_UPDATE (0x8); flags: (0x0); length: 4

2019-02-07 16:17:17,519 DEBUG - i/o-0000000C << Increment 1208

2019-02-07 16:17:17,519 DEBUG - i/o-0000000C >> stream 1 flow control 1208 -> 65535

2019-02-07 16:17:17,569 DEBUG - i/o-0000000C << "[0x0][0x0][0x4][0x3][0x0][0x0][0x0][0x0][0x3][0x0][0x0][0x0][0x2]"

2019-02-07 16:17:17,569 DEBUG - i/o-0000000C << stream 3 frame: RST_STREAM (0x3); flags: (0x0); length: 4

2019-02-07 16:17:17,569 DEBUG - i/o-0000000C << Code INTERNAL_ERROR

2019-02-07 16:17:17,569 DEBUG - i/o-0000000C >> stream 0 frame: GOAWAY (0x7); flags: (0x0); length: 31

2019-02-07 16:17:17,569 DEBUG - i/o-0000000C >> Last stream 0

2019-02-07 16:17:17,569 DEBUG - i/o-0000000C >> Code PROTOCOL_ERROR

2019-02-07 16:17:17,569 DEBUG - i/o-0000000C >> Unexpected stream id: 3

I don't know what causes these exceptions I tried with both static and dynamic post body data and both behaves similarly

Full Session logs:

https://drive.google.com/open?id=12y8HnaMTrPo-NBeLaoCYpK6zklJBL56T

https://drive.google.com/open?id=16KHgqLWrwz3Z3ls3Yvpp58zOI3SUNATM

Client: Tomcat 9.0x, Jdk 1.8.x(with conscrypt for ALPN support, and we connect it via TLSv1.3) on ubuntu 16.x

Server: Tomcat 9.0x (with openssl implementation, NIO connector, http2 support), Openssl 1.1.1 for TLSv1.3 support, JDK 10.0.2 on ubuntu 14.x

Any help will be appreciated

TIA

Community
  • 1
  • 1
Zyber
  • 428
  • 4
  • 21
  • It is unclear what exactly the problem you are having. Is it that connections get closed after one message exchange? Please post wire log of the session http://hc.apache.org/httpcomponents-client-5.0.x/logging.html – ok2c Feb 06 '19 at 07:49
  • @oleg I have updated the question with wire logs, kindly have a look – Zyber Feb 07 '19 at 12:05

1 Answers1

1

Case 1: Server sends HEADERS out of sequence.

UPDATE

Case 2: Server sends RST_STREAM for an idle stream

This looks like a bug in Tomcat. Here is a session log for one connection with just content of DATA frame snipped for brevity

2019-02-07 16:15:47,389 DEBUG - i/o-00000003 >> stream 0 frame: SETTINGS (0x4); flags: (0x0); length: 36
2019-02-07 16:15:47,389 DEBUG - i/o-00000003 >> HEADER_TABLE_SIZE: 8192
2019-02-07 16:15:47,389 DEBUG - i/o-00000003 >> ENABLE_PUSH: 0
2019-02-07 16:15:47,389 DEBUG - i/o-00000003 >> MAX_CONCURRENT_STREAMS: 100
2019-02-07 16:15:47,389 DEBUG - i/o-00000003 >> INITIAL_WINDOW_SIZE: 65535
2019-02-07 16:15:47,389 DEBUG - i/o-00000003 >> MAX_FRAME_SIZE: 65536
2019-02-07 16:15:47,389 DEBUG - i/o-00000003 >> MAX_HEADER_LIST_SIZE: 16777215
2019-02-07 16:15:47,389 DEBUG - i/o-00000003 >> "[0x0][0x0]$[0x4][0x0][0x0][0x0][0x0][0x0][0x0][0x1][0x0][0x0] [0x0][0x0][0x2][0x0][0x0][0x0][0x0][0x0][0x3][0x0][0x0][0x0]d[0x0][0x4][0x0][0x0][0xffffffff][0xffffffff][0x0][0x5][0x0][0x1][0x0][0x0][0x0][0x6][0x0][0xffffffff][0xffffffff][0xffffffff]"
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 << "[0x0][0x0][0x6][0x4][0x0][0x0][0x0][0x0][0x0][0x0][0x3][0x0][0x0][0x0][0xffffffc8][0x0][0x0][0x0][0x4][0x1][0x0][0x0][0x0][0x0][0x0][0x0][0x8][0x6][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x1]"
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 << stream 0 frame: SETTINGS (0x4); flags: (0x0); length: 6
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 << MAX_CONCURRENT_STREAMS: 200
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> stream 0 frame: SETTINGS (0x4); flags: ACK (0x1); length: 0
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> "[0x0][0x0][0x0][0x4][0x1][0x0][0x0][0x0][0x0]"
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 << stream 0 frame: SETTINGS (0x4); flags: ACK (0x1); length: 0
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 << stream 0 frame: PING (0x6); flags: (0x0); length: 8
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 << ........          00 00 00 00 00 00 00 01
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> stream 0 frame: PING (0x6); flags: ACK (0x1); length: 8
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> ........          00 00 00 00 00 00 00 01
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> "[0x0][0x0][0x8][0x6][0x1][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x1]"
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> :method: POST
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> :scheme: https
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> :authority: 172.21.170.214:8999
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> :path: /monitoragent/getdcoutput?1000000004286_1520339351002_1549536347382
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> user-agent: Apache-HttpAsyncClient/5.0-beta3 (Java/1.8.0_162)
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> content-type: application/json; charset=UTF-8
2019-02-07 16:15:47,393 DEBUG - i/o-00000003 >> stream 1 frame: HEADERS (0x1); flags: END_HEADERS (0x4); length: 130
...
2019-02-07 16:15:47,394 DEBUG - i/o-00000003 >> stream 1 frame: DATA (0x0); flags: (0x0); length: 1208
...
2019-02-07 16:15:47,394 DEBUG - i/o-00000003 >> stream 0 flow control -1208 -> 64327
2019-02-07 16:15:47,394 DEBUG - i/o-00000003 >> stream 1 flow control -1208 -> 64327
...
2019-02-07 16:15:47,394 DEBUG - i/o-00000003 >> stream 1 frame: DATA (0x0); flags: END_STREAM (0x1); length: 0
2019-02-07 16:15:47,394 DEBUG - i/o-00000003 >> "[0x0][0x0][0x0][0x0][0x1][0x0][0x0][0x0][0x1]"
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> :method: POST
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> :scheme: https
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> :authority: 172.21.170.214:8999
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> :path: /monitoragent/getdcoutput?1000000004286_1520339351002_1549536347382
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> user-agent: Apache-HttpAsyncClient/5.0-beta3 (Java/1.8.0_162)
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> content-type: application/json; charset=UTF-8
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> stream 3 frame: HEADERS (0x1); flags: END_HEADERS (0x4); length: 6
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> ......            83 87 c1 c0 bf be
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> "[0x0][0x0][0x6][0x1][0x4][0x0][0x0][0x0][0x3][0xffffff83][0xffffff87][0xffffffc1][0xffffffc0][0xffffffbf][0xffffffbe]"
...
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> stream 0 flow control -1208 -> 63119
2019-02-07 16:15:47,395 DEBUG - i/o-00000003 >> stream 3 flow control -1208 -> 64327
...
2019-02-07 16:15:47,396 DEBUG - i/o-00000003 >> stream 3 frame: DATA (0x0); flags: END_STREAM (0x1); length: 0
2019-02-07 16:15:47,396 DEBUG - i/o-00000003 >> "[0x0][0x0][0x0][0x0][0x1][0x0][0x0][0x0][0x3]"
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << "[0x0][0x0][0x4][0x8][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x4][0xffffffb8][0x0][0x0][0x4][0x8][0x0][0x0][0x0][0x0][0x3][0x0][0x0][0x4][0xffffffb8]"
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << stream 0 frame: WINDOW_UPDATE (0x8); flags: (0x0); length: 4
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << Increment 1208
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 >> stream 0 flow control 1208 -> 64327
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << stream 3 frame: WINDOW_UPDATE (0x8); flags: (0x0); length: 4
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << Increment 1208
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 >> stream 3 flow control 1208 -> 65535
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << "[0x0][0x0][0x4][0x8][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x4][0xffffffb8][0x0][0x0][0x4][0x8][0x0][0x0][0x0][0x0][0x1][0x0][0x0][0x4][0xffffffb8]"
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << stream 0 frame: WINDOW_UPDATE (0x8); flags: (0x0); length: 4
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << Increment 1208
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 >> stream 0 flow control 1208 -> 65535
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << stream 1 frame: WINDOW_UPDATE (0x8); flags: (0x0); length: 4
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 << Increment 1208
2019-02-07 16:15:47,399 DEBUG - i/o-00000003 >> stream 1 flow control 1208 -> 65535
2019-02-07 16:15:47,503 DEBUG - i/o-00000003 << "[0x0][0x0][0x4][0x3][0x0][0x0][0x0][0x0]3[0x0][0x0][0x0][0x2]"
2019-02-07 16:15:47,503 DEBUG - i/o-00000003 << stream 51 frame: RST_STREAM (0x3); flags: (0x0); length: 4
2019-02-07 16:15:47,503 DEBUG - i/o-00000003 << Code INTERNAL_ERROR
2019-02-07 16:15:47,503 DEBUG - i/o-00000003 >> stream 0 frame: GOAWAY (0x7); flags: (0x0); length: 32
2019-02-07 16:15:47,503 DEBUG - i/o-00000003 >> Last stream 0
2019-02-07 16:15:47,503 DEBUG - i/o-00000003 >> Code PROTOCOL_ERROR
2019-02-07 16:15:47,503 DEBUG - i/o-00000003 >> Unexpected stream id: 51
2019-02-07 16:15:47,504 DEBUG - i/o-00000003 >> "[0x0][0x0] [0x7][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0x1]Unexpected stream id: 51"  

At the end of the message exchange the server sends RST_STREAM for stream 51. There was no stream 51. There were streams 1 and 3 both of which have been correctly closed. Then, for whatever reason the server decides to terminate idle stream 51. The client treats such action as a severe protocol violation as per RFC 7540, section 6.4

RST_STREAM frames MUST NOT be sent for a stream in the "idle" state.
If a RST_STREAM frame identifying an idle stream is received, the
recipient MUST treat this as a connection error (Section 5.4.1) of
type PROTOCOL_ERROR.

Please upgrade to the latest version of Tomcat 9 and of the problem persists report it to Tomcat developers.

ok2c
  • 26,450
  • 5
  • 63
  • 71
  • I have updated the full logs in the question, kindly have a look, this server configuration is already in production which is serving http1.1 requests. What may be causing these exceptions? How to avoid these? – Zyber Feb 08 '19 at 03:29
  • See my update. I will not look into the case 1. It is likely related. – ok2c Feb 08 '19 at 10:50