如何使用Apache HttpCient-5 Beta正确执行Http2

2019年7月28日 105次阅读

我试图编写一个客户端,向多个服务器(已经支持http2)发出http2请求.到目前为止,我已经写了这个独立程序,工作正常,我可以看到所有请求都通过相同的TCP连接(在wireshark的帮助下验证).我使用带有conscrypt的Apache Httpclient 5来支持jdk8中的ALPN(jdk8是我的要求,我无法升级到jdk9或更高版本)

Main块就像,

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();
}

可运行的就像,

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();
        }
    }
}

所以我在我的客户端中单独模拟了这个,它使用上面的逻辑异步调用多个服务器进行轮询.但是在这里我可以看到每个请求有一个tcp连接,并且在请求结束时连接已关闭(尽管响应头返回为HTTP / 2.0).我使用主块代码在我的应用程序启动时初始化客户端(除了线程池部分,因为它用于独立模拟多线程环境)并创建url,请求和响应对象并在线程模型中同时执行每个请求(异步多路复用).我的要求是每个域使用一个tcp连接,并长时间使用它来处理大量请求.我在这里错过了什么？

或者有人用httpclient 5处理http2的正确方法

恩迪对此有所了解.

编辑：

有两件事我跟踪异常连接关闭,

1.每次请求后关闭连接

原因：由此线引起的

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

这个setConnectTimeout应该处于请求级别,但是在15个空闲秒之后它关闭了tcp连接本身,我不知道它是一个bug还是预期的行为,因为这个配置用于根据documentation封装请求项.

删除此行可以使tcp连接保持活动状态,而不仅仅是请求.

2.由于非法HEADERS帧/协议错误/内部错误

我可以在有线日志中看到这些异常,我的tcp连接正在关闭(它随机关闭),我无法共享整个日志,因为有太多我只发布异常部分

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

和,

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

我不知道是什么导致这些异常,我尝试了静态和动态的帖子体数据,两者的行为相似

完整会话日志：

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

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

客户：
Tomcat 9.0x,
在ubuntu 16.x上使用Jdk 1.8.x(对ALPN提供支持,我们通过TLSv1.3连接它)

服务器：
Tomcat 9.0x(带有openssl实现,NIO连接器,http2支持),
Openssl 1.1.1支持TLSv1.3,
ubuntu 14.x上的JDK 10.0.2

任何帮助将不胜感激

TIA

最佳答案 案例1：服务器不按顺序发送HEADERS.

UPDATE

情况2：服务器为空闲流发送RST_STREAM

这看起来像是Tomcat中的一个错误.这是一个连接的会话日志,只是为了简洁而剪切了DATA帧的内容

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"

在消息交换结束时,服务器发送流51的RST_STREAM.没有流51.流1和3都已正确关闭.然后,无论出于何种原因,服务器决定终止空闲流51.客户端将此类操作视为严重协议违规,根据RFC 7540,第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.

请升级到最新版本的Tomcat 9,问题仍然存在,请向Tomcat开发人员报告.

点赞