Skip to content

clickhouse-r2dbc program is blocked by ClickHouseResponse #1538

Description

@wooEnrico

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:123456@127.0.0.1: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

Activity

  1. changed the title [-]clickhouse-r2dbc block by ClickHouseResponse[/-] [+]clickhouse-r2dbc program is blocked by ClickHouseResponse[/+] on Jan 31, 2024
  2. shilaidun commented on May 17, 2024

    @shilaidun

    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.

  3. added 3 commits that reference this issue on May 30, 2024
  4. wooEnrico commented on Jun 3, 2024

    @wooEnrico
    ContributorAuthor

    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

  5. added a commit that references this issue on Jun 3, 2024
  6. linked a pull request that will close this issuefix response close for getRowsUpdated(#1538) #1667on Jun 3, 2024
  7. chernser commented on Jun 3, 2024

    @chernser
    Contributor

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

  8. nmicra commented on Jul 2, 2024

    @nmicra

    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?

  9. chernser commented on Jul 3, 2024

    @chernser
    Contributor

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

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

    Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions