clickhouse-java icon indicating copy to clipboard operation
clickhouse-java copied to clipboard
verified publisher icon ClickHouse

clickhouse-r2dbc program is blocked by ClickHouseResponse

Open wooEnrico opened this issue 1 year ago • 1 comments

Describe the bug

The Code example is plan to execute 100 times insert, but only 10 times, and the program is blocked. Then got timeout

I am trying to solve this problem locally and seem to have found the cause. When executingcom.clickhouse.r2dbc.ClickHouseResult#getRowsUpdated it is necessary to manually execute com.clickhouse.client.ClickHouseResponse#close.

Expected behaviour

expected execute insert 100 times

Code example

        ConnectionFactory connectionFactory = ConnectionFactories
                .get("r2dbc:pool:clickhouse:http://root:[email protected]:8123/test");

        Mono.from(connectionFactory.create()).flatMapMany(connection -> {
            return Flux.range(0, 100).flatMap(integer -> {
                return Mono.from(connection.createStatement("insert into uk(u, k) values(:u, :k)")
                        .bind("u", UUID.randomUUID().toString())
                        .bind("k", integer)
                        .execute()).flatMap(result -> Mono.from(result.getRowsUpdated()));
            }).doOnNext(System.out::println);
        }).blockLast();

Error log

1
1
1
1
1
1
1
1
1
1
10:00:31.457 [ClickHouseWorker-16] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('f37b5c84-cf57-4dc0-a039-dbd8e55e175b', 24)
10:00:31.456 [ClickHouseWorker-14] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('db133869-ed7b-4035-ae2f-35ec69abeae3', 20)
10:00:31.458 [ClickHouseWorker-8] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('cce4aa17-e0d9-4826-bd0a-a24363ee6993', 21)
10:00:31.456 [ClickHouseWorker-12] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('49f8210c-eaeb-4e5d-95b6-8a03cbdc71a4', 22)
10:00:31.456 [ClickHouseWorker-15] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('dfd0a040-0dae-48ed-9dbb-5e366338bde7', 25)
10:00:31.457 [ClickHouseWorker-1] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('885b8ccd-97fa-4574-a40a-26a317070dfe', 18)
10:00:31.458 [ClickHouseWorker-7] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('dde93e3e-8642-48d6-9f42-1c7e09c36374', 23)
10:00:31.457 [ClickHouseWorker-13] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('075893bb-c3e1-43ce-a245-6c597c1602b0', 19)
10:00:31.456 [ClickHouseWorker-17] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('9fc5f6b6-e64a-4d19-bdd9-5fdcee2d3eb4', 26)
10:00:31.457 [ClickHouseWorker-4] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('aaa80c7f-be4e-4ff2-a00c-e0900d9f78b4', 17)
10:00:31.471 [ClickHouseWorker-12] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000021 preparing request execution
10:00:31.471 [ClickHouseWorker-1] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000023 preparing request execution
10:00:31.470 [ClickHouseWorker-8] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000020 preparing request execution
10:00:31.471 [ClickHouseWorker-13] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000018 preparing request execution
10:00:31.471 [ClickHouseWorker-14] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000019 preparing request execution
10:00:31.471 [ClickHouseWorker-17] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000022 preparing request execution
10:00:31.473 [ClickHouseWorker-15] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000024 preparing request execution
10:00:31.474 [ClickHouseWorker-16] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000026 preparing request execution
10:00:31.474 [ClickHouseWorker-7] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000025 preparing request execution
10:00:31.475 [ClickHouseWorker-12] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000021 target auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-1] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000023 target auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-12] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000021 proxy auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-1] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000023 proxy auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-13] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000018 target auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-13] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000018 proxy auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-14] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000019 target auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-13] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000018 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.475 [ClickHouseWorker-14] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000019 proxy auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-4] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000027 preparing request execution
10:00:31.475 [ClickHouseWorker-17] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000022 target auth state: UNCHALLENGED
10:00:31.475 [ClickHouseWorker-8] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000020 target auth state: UNCHALLENGED
10:00:31.476 [ClickHouseWorker-14] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000019 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.476 [ClickHouseWorker-17] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000022 proxy auth state: UNCHALLENGED
10:00:31.476 [ClickHouseWorker-8] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000020 proxy auth state: UNCHALLENGED
10:00:31.476 [ClickHouseWorker-17] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000022 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.476 [ClickHouseWorker-8] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000020 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.475 [ClickHouseWorker-12] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000021 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.475 [ClickHouseWorker-1] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000023 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.476 [ClickHouseWorker-8] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000020 acquiring endpoint (3 MINUTES)
10:00:31.476 [ClickHouseWorker-14] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000019 acquiring endpoint (3 MINUTES)
10:00:31.476 [ClickHouseWorker-17] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000022 acquiring endpoint (3 MINUTES)
10:00:31.476 [ClickHouseWorker-1] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000023 acquiring endpoint (3 MINUTES)
10:00:31.476 [ClickHouseWorker-13] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000018 acquiring endpoint (3 MINUTES)
10:00:31.476 [ClickHouseWorker-12] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000021 acquiring endpoint (3 MINUTES)
10:00:31.480 [ClickHouseWorker-8] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000020 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.481 [ClickHouseWorker-13] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000018 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.480 [ClickHouseWorker-1] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000023 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.483 [ClickHouseWorker-14] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000019 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.483 [ClickHouseWorker-12] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000021 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.482 [ClickHouseWorker-17] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000022 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.484 [ClickHouseWorker-15] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000024 target auth state: UNCHALLENGED
10:00:31.484 [ClickHouseWorker-15] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000024 proxy auth state: UNCHALLENGED
10:00:31.484 [ClickHouseWorker-15] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000024 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.484 [ClickHouseWorker-15] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000024 acquiring endpoint (3 MINUTES)
10:00:31.484 [ClickHouseWorker-15] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000024 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.485 [ClickHouseWorker-7] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000025 target auth state: UNCHALLENGED
10:00:31.485 [ClickHouseWorker-7] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000025 proxy auth state: UNCHALLENGED
10:00:31.485 [ClickHouseWorker-7] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000025 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.485 [ClickHouseWorker-16] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000026 target auth state: UNCHALLENGED
10:00:31.485 [ClickHouseWorker-16] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000026 proxy auth state: UNCHALLENGED
10:00:31.485 [ClickHouseWorker-16] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000026 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.485 [ClickHouseWorker-4] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000027 target auth state: UNCHALLENGED
10:00:31.485 [ClickHouseWorker-4] DEBUG org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-0000000027 proxy auth state: UNCHALLENGED
10:00:31.485 [ClickHouseWorker-4] DEBUG org.apache.hc.client5.http.impl.classic.ConnectExec - ex-0000000027 acquiring connection with route {}->http://127.0.0.1:8123
10:00:31.485 [ClickHouseWorker-4] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000027 acquiring endpoint (3 MINUTES)
10:00:31.485 [ClickHouseWorker-7] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000025 acquiring endpoint (3 MINUTES)
10:00:31.485 [ClickHouseWorker-16] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000026 acquiring endpoint (3 MINUTES)
10:00:31.485 [ClickHouseWorker-4] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000027 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.485 [ClickHouseWorker-7] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000025 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:00:31.485 [ClickHouseWorker-16] DEBUG org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-0000000026 endpoint lease request (3 MINUTES) [route: {}->http://127.0.0.1:8123][total available: 0; route allocated: 10 of 10; total allocated: 10 of 10]
10:03:31.092 [ClickHouseWorker-5] DEBUG com.clickhouse.client.ClickHouseClientBuilder$Agent - Handling com.clickhouse.client.ClickHouseException: Timeout deadline: 180000 MILLISECONDS, actual: 180012 MILLISECONDS, server ClickHouseNode [uri=http://127.0.0.1:8123/test]@455715567(failover=0, retry=0)
10:03:31.093 [ClickHouseWorker-3] DEBUG com.clickhouse.client.ClickHouseClientBuilder$Agent - Handling com.clickhouse.client.ClickHouseException: Timeout deadline: 180000 MILLISECONDS, actual: 180007 MILLISECONDS, server ClickHouseNode [uri=http://127.0.0.1:8123/test]@455715567(failover=0, retry=0)
10:03:31.093 [ClickHouseWorker-10] DEBUG com.clickhouse.client.ClickHouseClientBuilder$Agent - Handling com.clickhouse.client.ClickHouseException: Timeout deadline: 180000 MILLISECONDS, actual: 180007 MILLISECONDS, server ClickHouseNode [uri=http://127.0.0.1:8123/test]@455715567(failover=0, retry=0)
10:03:31.093 [ClickHouseWorker-11] DEBUG com.clickhouse.client.ClickHouseClientBuilder$Agent - Handling com.clickhouse.client.ClickHouseException: Timeout deadline: 180000 MILLISECONDS, actual: 180012 MILLISECONDS, server ClickHouseNode [uri=http://127.0.0.1:8123/test]@455715567(failover=0, retry=0)
10:03:31.092 [ClickHouseWorker-2] DEBUG com.clickhouse.client.ClickHouseClientBuilder$Agent - Handling com.clickhouse.client.ClickHouseException: Timeout deadline: 180000 MILLISECONDS, actual: 180012 MILLISECONDS, server ClickHouseNode [uri=http://127.0.0.1:8123/test]@455715567(failover=0, retry=0)
10:03:31.094 [ClickHouseWorker-6] DEBUG com.clickhouse.client.ClickHouseClientBuilder$Agent - Handling com.clickhouse.client.ClickHouseException: Timeout deadline: 180000 MILLISECONDS, actual: 180010 MILLISECONDS, server ClickHouseNode [uri=http://127.0.0.1:8123/test]@455715567(failover=0, retry=0)
10:03:31.092 [ClickHouseWorker-9] DEBUG com.clickhouse.client.ClickHouseClientBuilder$Agent - Handling com.clickhouse.client.ClickHouseException: Timeout deadline: 180000 MILLISECONDS, actual: 180008 MILLISECONDS, server ClickHouseNode [uri=http://127.0.0.1:8123/test]@455715567(failover=0, retry=0)
10:03:31.124 [ClickHouseWorker-2] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('6b23973b-172a-4094-9da0-570b05185ae2', 27)
10:03:31.146 [ClickHouseWorker-10] DEBUG com.clickhouse.client.http.ClickHouseHttpClient - Query: insert into uk(u, k) values('48043c13-ad01-4688-8b93-a10e53326fab', 28)
10:03:31.147 [ClickHouseWorker-2] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000028 preparing request execution
10:03:31.152 [ClickHouseWorker-10] DEBUG org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-0000000029 preparing request execution
10:03:31.159 [ClickHouseWorker-6] ERROR reactor.core.publisher.Operators - Operator called default onErrorDropped
com.clickhouse.client.ClickHouseException: Timeout deadline: 180000 MILLISECONDS, actual: 180010 MILLISECONDS, server ClickHouseNode [uri=http://127.0.0.1:8123/test]@455715567
	at com.clickhouse.client.ClickHouseException.of(ClickHouseException.java:168)
	at com.clickhouse.client.AbstractClient.lambda$execute$0(AbstractClient.java:275)
	at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.hc.core5.http.ConnectionRequestTimeoutException: Timeout deadline: 180000 MILLISECONDS, actual: 180010 MILLISECONDS
	at org.apache.hc.client5.http.impl.classic.InternalExecRuntime.acquireEndpoint(InternalExecRuntime.java:120)
	at org.apache.hc.client5.http.impl.classic.ConnectExec.execute(ConnectExec.java:125)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.ProtocolExec.execute(ProtocolExec.java:192)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.HttpRequestRetryExec.execute(HttpRequestRetryExec.java:96)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.RedirectExec.execute(RedirectExec.java:115)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.InternalHttpClient.doExecute(InternalHttpClient.java:170)
	at org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute(CloseableHttpClient.java:123)
	at com.clickhouse.client.http.ApacheHttpConnectionImpl.post(ApacheHttpConnectionImpl.java:241)
	at com.clickhouse.client.http.ClickHouseHttpClient.send(ClickHouseHttpClient.java:118)
	at com.clickhouse.client.AbstractClient.sendAsync(AbstractClient.java:161)
	at com.clickhouse.client.AbstractClient.lambda$execute$0(AbstractClient.java:273)
	... 4 common frames omitted

Configuration

Environment

  • Client version: 0.6.0
  • Language version: Java17
  • OS: MACOS

ClickHouse server

  • ClickHouse Server version: 22.3.3.44
  • ClickHouse Server non-default settings, if any:
  • CREATE TABLE statements for tables involved:
  • Sample data for all these tables, use clickhouse-obfuscator if necessary

wooEnrico avatar Jan 30 '24 02:01 wooEnrico

Can this be fixed in version v0.6.0, I think it's a CRITICAL bug, Waiting for new version, connection.close() also reproduced this issue.

shilaidun avatar May 17 '24 04:05 shilaidun

I am very pleased to receive your reply. I am also very sorry that I did not conduct complete unit testing in my previous development. I have improved the submission and passed the unit test. And I hope you can review it again @chernser

wooEnrico avatar Jun 03 '24 08:06 wooEnrico

Good day, @wooEnrico ! Thank you very much for your contribution. I've merged it! Thank you!

chernser avatar Jun 03 '24 15:06 chernser

I'm getting same error as above Caused by: org.apache.hc.core5.http.ConnectionRequestTimeoutException: Timeout deadline: 180000 MILLISECONDS with client implementation("com.clickhouse:clickhouse-jdbc:0.6.2") , can someone suggest in which version it supposed to be fixed?

nmicra avatar Jul 02 '24 12:07 nmicra

Good day, @nmicra! Would you please give more details:

  1. scenario or test how to reproduce
  2. full stacktrace

Thanks!

chernser avatar Jul 03 '24 04:07 chernser