[BUG] Illumos ClickHouse binary has issues with the keeper functionality

[karencfv]

When running a 2 replica 3 coordinator (keeper) clickhouse set up on Helios I came across an issue where the Clickhouse servers were unable to sync with the keepers.

The 3 keepers were healthy and had formed a quorum. But the servers kept timing out. I could not find any issues with the configuration files.

I decided to run the same config and install all of the replica and keeper nodes on a single server (to rule out any networking issues) on both Helios and Linux.

Turns out, the same configuration works with the Linux binary (the one created by the garbage compactor), but errors out with the Helios binary:

On Linux:

coatlicue@pop-os:~/src/ch-test/22.8.9.24-linux/oximeter_cluster/r1$ ./clickhouse client --port 9001
ClickHouse client version 22.8.9.24 (official build).
Connecting to localhost:9001 as user default.
Connected to ClickHouse server version 22.8.9 revision 54460.

oximeter_cluster node 1 :) SHOW CLUSTERS

SHOW CLUSTERS

Query id: 8726842f-c2ce-4f1f-b139-b4119c792e3d

┌─cluster──────────┐
│ oximeter_cluster │
└──────────────────┘

1 row in set. Elapsed: 0.002 sec. 

oximeter_cluster node 1 :) CREATE DATABASE IF NOT EXISTS oximeter ON CLUSTER oximeter_cluster;

CREATE DATABASE IF NOT EXISTS oximeter ON CLUSTER oximeter_cluster

Query id: fd1fcc1b-6f25-48f7-8533-884e0acd7f99

┌─host──────┬─port─┬─status─┬─error─┬─num_hosts_remaining─┬─num_hosts_active─┐
│ 127.0.0.1 │ 9002 │      0 │       │                   1 │                0 │
│ 127.0.0.1 │ 9001 │      0 │       │                   0 │                0 │
└───────────┴──────┴────────┴───────┴─────────────────────┴──────────────────┘

2 rows in set. Elapsed: 0.135 sec. 

oximeter_cluster node 1 :) exit
Bye.
coatlicue@pop-os:~/src/ch-test/22.8.9.24-linux/oximeter_cluster/r1$ ./clickhouse client --port 9002
ClickHouse client version 22.8.9.24 (official build).
Connecting to localhost:9002 as user default.
Connected to ClickHouse server version 22.8.9 revision 54460.

oximeter_cluster node 2 :) SHOW DATABASES

SHOW DATABASES

Query id: c6f390cf-cd8f-4062-980a-5e920f945216

┌─name───────────────┐
│ INFORMATION_SCHEMA │
│ default            │
│ information_schema │
│ oximeter           │<-- Database just created from the other node
│ system             │
└────────────────────┘

5 rows in set. Elapsed: 0.002 sec.

On Helios:

karen@atrium ~/src/ch-testing/r1 $ ./clickhouse client --port 9001
ClickHouse client version 22.8.9.1.
Connecting to localhost:9001 as user default.
Connected to ClickHouse server version 22.8.9 revision 54460.

oximeter_cluster node 1 :) SHOW CLUSTERS

SHOW CLUSTERS

Query id: 7e2155b8-73d6-497b-af1c-30932e5e6442

┌─cluster──────────┐
│ oximeter_cluster │
└──────────────────┘

1 row in set. Elapsed: 0.002 sec. 

oximeter_cluster node 1 :) CREATE DATABASE IF NOT EXISTS oximeter ON CLUSTER oximeter_cluster;

CREATE DATABASE IF NOT EXISTS oximeter ON CLUSTER oximeter_cluster

Query id: af5bde07-3f38-484d-b7e7-1b49ae92e105


0 rows in set. Elapsed: 16.256 sec. 

Received exception from server (version 22.8.9):
Code: 999. DB::Exception: Received from localhost:9001. Coordination::Exception. Coordination::Exception: Session expired (Session expired). (KEEPER_EXCEPTION)

From the logs on the Helios machine:

2023.07.28 04:39:35.201191 [ 212 ] {} <Error> ZooKeeperClient: Code: 999. Coordination::Exception: Operation timeout (no response) for request Get for path: /keeper/api_version (Operation timeout). (KEEPER_EXCEPTION), Stack trace (when copying this message, always include the lines below):

0. Poco::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) @ 14a9c432 in /home/karen/src/ch-testing/r1/clickhouse
1. DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int, bool) @ d3f0b20 in /home/karen/src/ch-testing/r1/clickhouse
2. Coordination::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, Coordination::Error, int) @ 12d7055a in /home/karen/src/ch-testing/r1/clickhouse
3. Coordination::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, Coordination::Error) @ 12d7076a in /home/karen/src/ch-testing/r1/clickhouse
4. Coordination::ZooKeeper::receiveThread() @ 12da20ee in /home/karen/src/ch-testing/r1/clickhouse
5. void std::__1::__function::__policy_invoker<void ()>::__call_impl<std::__1::__function::__default_alloc_func<ThreadFromGlobalPool::ThreadFromGlobalPool<Coordination::ZooKeeper::ZooKeeper(std::__1::vector<Coordination::ZooKeeper::Node, std::__1::allocator<Coordination::ZooKeeper::Node> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, Poco::Timespan, Poco::Timespan, Poco::Timespan, std::__1::shared_ptr<DB::ZooKeeperLog>)::$_1>(Coordination::ZooKeeper::ZooKeeper(std::__1::vector<Coordination::ZooKeeper::Node, std::__1::allocator<Coordination::ZooKeeper::Node> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, Poco::Timespan, Poco::Timespan, Poco::Timespan, std::__1::shared_ptr<DB::ZooKeeperLog>)::$_1&&)::'lambda'(), void ()> >(std::__1::__function::__policy_storage const*) @ 12da6133 in /home/karen/src/ch-testing/r1/clickhouse
6. ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>) @ 1468ddd4 in /home/karen/src/ch-testing/r1/clickhouse
7. void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void ThreadPoolImpl<std::__1::thread>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda0'()> >(void*) @ 1468fc35 in /home/karen/src/ch-testing/r1/clickhouse
8. _thrp_setup @ 111da7 in /lib/amd64/libc.so.1
 (version 22.8.9.1)
2023.07.28 04:39:35.201493 [ 194 ] {} <Trace> ZooKeeperClient: Failed to get API version
2023.07.28 04:39:35.201593 [ 194 ] {} <Trace> ZooKeeper: Initialized, hosts: 127.0.0.1:9181,127.0.0.1:9182,127.0.0.1:9183
2023.07.28 04:39:35.202108 [ 194 ] {} <Error> virtual bool DB::DDLWorker::initializeMainThread(): Code: 999. Coordination::Exception: Session expired (Session expired). (KEEPER_EXCEPTION), Stack trace (when copying this message, always include the lines below):

0. Poco::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) @ 14a9c432 in /home/karen/src/ch-testing/r1/clickhouse
1. DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int, bool) @ d3f0b20 in /home/karen/src/ch-testing/r1/clickhouse
2. Coordination::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, Coordination::Error, int) @ 12d7055a in /home/karen/src/ch-testing/r1/clickhouse
3. Coordination::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, Coordination::Error) @ 12d7076a in /home/karen/src/ch-testing/r1/clickhouse
4. Coordination::ZooKeeper::pushRequest(Coordination::ZooKeeper::RequestInfo&&) @ 12da3917 in /home/karen/src/ch-testing/r1/clickhouse
5. Coordination::ZooKeeper::create(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, bool, bool, std::__1::vector<Coordination::ACL, std::__1::allocator<Coordination::ACL> > const&, std::__1::function<void (Coordination::CreateResponse const&)>) @ 12da428b in /home/karen/src/ch-testing/r1/clickhouse
6. zkutil::ZooKeeper::asyncTryCreateNoThrow(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) @ 12d769e4 in /home/karen/src/ch-testing/r1/clickhouse
7. zkutil::ZooKeeper::createImpl(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&) @ 12d7654f in /home/karen/src/ch-testing/r1/clickhouse
8. zkutil::ZooKeeper::createIfNotExists(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) @ 12d76e4a in /home/karen/src/ch-testing/r1/clickhouse
9. zkutil::ZooKeeper::createAncestors(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) @ 12d76f96 in /home/karen/src/ch-testing/r1/clickhouse
10. DB::DDLWorker::initializeMainThread() @ 1162e832 in /home/karen/src/ch-testing/r1/clickhouse
11. DB::DDLWorker::runMainThread() @ 116203c0 in /home/karen/src/ch-testing/r1/clickhouse
12. ThreadFromGlobalPool::ThreadFromGlobalPool<void (DB::DDLWorker::*)(), DB::DDLWorker*>(void (DB::DDLWorker::*&&)(), DB::DDLWorker*&&)::'lambda'()::operator()() @ 116302b4 in /home/karen/src/ch-testing/r1/clickhouse
13. ThreadPoolImpl<std::__1::thread>::worker(std::__1::__list_iterator<std::__1::thread, void*>) @ 1468ddd4 in /home/karen/src/ch-testing/r1/clickhouse
14. void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void ThreadPoolImpl<std::__1::thread>::scheduleImpl<void>(std::__1::function<void ()>, int, std::__1::optional<unsigned long>)::'lambda0'()> >(void*) @ 1468fc35 in /home/karen/src/ch-testing/r1/clickhouse
15. _thrp_setup @ 111da7 in /lib/amd64/libc.so.1
 (version 22.8.9.1)

I have absolutely no idea how debug/fix the garbage compactor build scripts. Would be happy to sync up with someone who can spare a bit of time to help me perhaps @citrus-it, @jclulow or @davepacheco ?

[citrus-it]

I'll spin up a cluster on a test machine and see if I can work out what's going wrong on helios.

[citrus-it]

I built a two-node, three-keeper cluster on a bench gimlet and saw the same errors. The zookeeper client in clickhouse is not able to retrieve the API version from the keeper servers and reports a timeout. A snoop shows a TCP connection being established and the request being sent:

0000   01 1a 00 02 00 00 00 6c 00 00 00 01 00 00 00 00   .......l........
0010   00 00 00 00 00 00 00 00 60 00 00 00 00 44 06 3c   ........`....D.<
0020   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01   ................
0030   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01   ................
0040   fb 0c 23 de 8f 38 89 e1 33 f0 5f 28 80 18 88 00   ..#..8..3._(....
0050   00 44 00 00 01 01 08 0a 1a 65 27 58 1a 65 27 55   .D.......e'X.e'U
0060   00 00 00 20 00 00 00 01 00 00 00 04 00 00 00 13   ... ............
0070   2f 6b 65 65 70 65 72 2f 61 70 69 5f 76 65 72 73   /keeper/api_vers
0080   69 6f 6e 00                                       ion.

but I don't see a reply.

I also set up a cluster on MacOS using the official clickhouse binary, and it behaved in the same way, although I want to do re-test this with the same configuration that Karen used on Linux.

[citrus-it]

Using Karen's test oximeter_cluster configuration on MacOS produces the same errors:

2023.07.31 11:58:46.943669 [ 198859 ] {} <Trace> ZooKeeperClient: Failed to get API version: timeout
2023.07.31 11:58:46.943711 [ 198859 ] {} <Trace> ZooKeeper: Initialized, hosts: 127.0.0.1:9181,127.0.0.1:9182,127.0.0.1:9183
2023.07.31 11:58:46.943999 [ 198868 ] {} <Error> ZooKeeperClient: Code: 999. Coordination::Exception: Operation timeout (no response) for request Get for path: /keeper/api_version (Operation timeout). (KEEPER_EXCEPTION), Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 22.8.9.24 (official build))
2023.07.31 11:58:46.944653 [ 198859 ] {} <Error> virtual bool DB::DDLWorker::initializeMainThread(): Code: 999. Coordination::Exception: Connection loss, path: /clickhouse. (KEEPER_EXCEPTION), Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 22.8.9.24 (official build))

[citrus-it]

Back on a gimlet, with just the three-node keeper cluster running, I can use a zookeeper CLI to talk to one of the servers. Responses are pretty slow.

gimlet-sn06 # time bin/zkcli -s=127.0.0.1:9181 ls
[keeper]

real    0m4.356s
user    0m0.008s
sys     0m0.016s

gimlet-sn06 # time bin/zkcli -s=127.0.0.1:9181 get /keeper/api_version
1
cZxid = 0x0
ctime = Thu Jan 01 00:00:00 GMT 1970
mZxid = 0x0
mtime = Thu Jan 01 00:00:00 GMT 1970
pZxid = 0x0
cversion = 0
dataVersion = 0
aclVersion = 0
ephemeralOwner = 0x0
dataLength = 0
numChildren = 0

real    0m4.356s
user    0m0.009s
sys     0m0.018s

The keeper log shows:

2023.07.31 11:14:57.683413 [ 3 ] {} <Trace> KeeperTCPHandlerFactory: Keeper request. Address: 127.0.0.1:65244
2023.07.31 11:14:57.683626 [ 3 ] {} <Information> KeeperTCPHandler: Requesting session ID for the new client
2023.07.31 11:14:57.684786 [ 138 ] {} <Debug> KeeperStateMachine: Session ID response 4 with timeout 10000
2023.07.31 11:14:57.684880 [ 3 ] {} <Information> KeeperTCPHandler: Received session ID 4
2023.07.31 11:15:01.018445 [ 3 ] {} <Trace> KeeperTCPHandler: Received heartbeat for session #4
2023.07.31 11:15:01.018868 [ 3 ] {} <Debug> KeeperTCPHandler: Received close event with xid 2 for session id #4
2023.07.31 11:15:02.019565 [ 3 ] {} <Debug> KeeperTCPHandler: Session #4 successfully closed

Part of the zookeeper protocol is that the client sends a heartbeat message every third of the total timeout, which is what we're seeing in the log here. Let's look at the network traffic:

These two packets are the initial handshake, not much of interest here but I've annotated some bits:

gimlet-sn06 # snoop -tr -d lo0 -s 8192 -x 76 port 9181
...
  0.00017    localhost -> localhost    TCP D=9181 S=53961 Push Ack=2648774544 Seq=2208598868 Len=48 Win=34816 Options=<nop,nop,tstamp 521589324 521589323>

           0: 0000 002c 0000 0000 0000 0000 0000 0000    ...,............
          16: 0000 03e8 0000 0000 0000 0000 0000 0010    ................      <-- 03e8 is the timeout in ms (1s)
          32: 0000 0000 0000 0000 0000 0000 0000 0000    ................

  0.00150    localhost -> localhost    TCP D=53961 S=9181 Push Ack=2208598868 Seq=2648774544 Len=40 Win=65440 Options=<nop,nop,tstamp 521589325 521589323>

           0: 0000 0024 0000 0000 0000 2710 0000 0000    ...$......'.....     <-- 2710 is the timeout in ms (10s)
          16: 0000 0012 0000 0010 0000 0000 0000 0000    ................
          32: 0000 0000 0000 0000                        ........

The final negotiated timeout is 10s.

The client then quickly sends a get command for the api version. Manually decoding this looks right. The client has tagged this with xid 1.

  0.00564    localhost -> localhost    TCP D=9181 S=53961 Push Ack=2648774544 Seq=2208598916 Len=36 Win=34816 Options=<nop,nop,tstamp 521589329 521589323>

           0: 0000 0020 0000 0001 0000 0004 0000 0013    ... ............
          16: 2f6b 6565 7065 722f 6170 695f 7665 7273    /keeper/api_vers
          32: 696f 6e00                                  ion.

3.33 seconds later (timeout / 3), the client sends a heartbeat:

  3.33894    localhost -> localhost    TCP D=9181 S=53961 Push Ack=2648774544 Seq=2208598952 Len=12 Win=34816 Options=<nop,nop,tstamp 521592662 521589323>

           0: 0000 0008 ffff fffe 0000 000b              ............

and the server immediately replies with the API version response:

  3.33904    localhost -> localhost    TCP D=53961 S=9181 Push Ack=2208598868 Seq=2648774584 Len=93 Win=65440 Options=<nop,nop,tstamp 521592662 521589323>

           0: 0000 0059 0000 0001 0000 0000 0000 0021    ...Y...........!       <--  xid 1
          16: 0000 0000 0000 0001 3100 0000 0000 0000    ........1.......      <-- no error, and API version 1
          32: 0000 0000 0000 0000 0000 0000 0000 0000    ................
          48: 0000 0000 0000 0000 0000 0000 0000 0000    ................
          64: 0000 0000 0000 0000 0000 0000 0000 0000    ................
          80: 0000 0000 0000 0000 0000 0000 00           .............

That's interesting, is the server somehow waiting for the heartbeat before sending the response? Let's look at the traffic from the real clickhouse node, where we know the configured timeout is 30s and we can see that that is the final timeout after negotiation:

  5.00093    localhost -> localhost    TCP D=9181 S=50582 Push Ack=2095450000 Seq=554463957 Len=48 Win=34816 Options=<nop,nop,tstamp 522426585 522426585>

           0: 0000 002c 0000 0000 0000 0000 0000 0000    ...,............
          16: 0000 7530 0000 0000 0000 0000 0000 0010    ..u0............    <-- 30s
          32: 0000 0000 0000 0000 0000 0000 0000 0000    ................

  5.00311    localhost -> localhost    TCP D=50582 S=9181 Push Ack=554463957 Seq=2095450000 Len=40 Win=65440 Options=<nop,nop,tstamp 522426587 522426585>

           0: 0000 0024 0000 0000 0000 7530 0000 0000    ...$......u0....     <-- 30s
          16: 0000 0007 0000 0010 0000 0000 0000 0000    ................
          32: 0000 0000 0000 0000                        ........

and the same thing happens. The server does not respond until the client sends a keepalive. However, the client closes the connection immediately after sending the keepalive (10s this time, as expected):

  5.00321    localhost -> localhost    TCP D=9181 S=50582 Push Ack=2095450000 Seq=554464005 Len=36 Win=34816 Options=<nop,nop,tstamp 522426587 522426585>

           0: 0000 0020 0000 0001 0000 0004 0000 0013    ... ............
          16: 2f6b 6565 7065 722f 6170 695f 7665 7273    /keeper/api_vers
          32: 696f 6e00                                  ion.

 15.00283    localhost -> localhost    TCP D=9181 S=50582 Push Ack=2095450000 Seq=554464041 Len=12 Win=34816 Options=<nop,nop,tstamp 522436587 522426585>

           0: 0000 0008 7fff ffff ffff fff5              ............

 15.00289    localhost -> localhost    TCP D=9181 S=50582 Fin Ack=2095450040 Seq=554464053 Len=0 Win=34816 Options=<nop,nop,tstamp 522436587 522426585>


 15.00292    localhost -> localhost    TCP D=50582 S=9181 Ack=554464054 Seq=2095450040 Len=0 Win=65440 Options=<nop,nop,tstamp 522436587 522436587>


 15.00296    localhost -> localhost    TCP D=50582 S=9181 Push Ack=554464054 Seq=2095450040 Len=93 Win=65440 Options=<nop,nop,tstamp 522436587 522436587>

           0: 0000 0059 0000 0001 0000 0000 0000 000a    ...Y............
          16: 0000 0000 0000 0001 3100 0000 0000 0000    ........1.......
          32: 0000 0000 0000 0000 0000 0000 0000 0000    ................
          48: 0000 0000 0000 0000 0000 0000 0000 0000    ................
          64: 0000 0000 0000 0000 0000 0000 0000 0000    ................
          80: 0000 0000 0000 0000 0000 0000 00           .............

This then looks like at least two bugs, one in the keeper client and one in the keeper server:

• The keeper server is not replying to the request until the client sends a heartbeart;
• The keeper client closes the connection immediately after sending the first heartbeat message, when only 1/3 of the timeout interval has elapsed.

[citrus-it]

The official MacOS 23.3.8.21 binary does the same, dashing the faint hope that an upgrade to the latest LTS might resolve this:

2023.07.31 13:45:59.790513 [ 248128 ] {} <Information> ZooKeeperClient: Connected to ZooKeeper at 127.0.0.1:9183 with session_id 1
2023.07.31 13:46:09.791570 [ 248129 ] {} <Error> ZooKeeperClient: Code: 999. Coordination::Exception: Operation timeout (deadline already expired) for path: /keeper/api_version (Operation timeout). (KEEPER_EXCEPTION), Stack trace (when copying this message, always include the lines below):

<Empty trace>
 (version 23.3.8.21 (official build))
2023.07.31 13:46:09.791630 [ 248129 ] {} <Information> ZooKeeperClient: Finalizing session 1. finalization_started: false, queue_finished: false, reason: 'Exception in receiveThread'
2023.07.31 13:46:09.791785 [ 248128 ] {} <Trace> ZooKeeperClient: Failed to get API version

pptang% time zkcli -s="127.0.0.1:9181" get /keeper/api_version
2
zkcli -s="127.0.0.1:9181" get /keeper/api_version  0.01s user 0.00s system 0% cpu 4.349 total

On the plus side, this does make it seem like there is value in opening an upstream bug against this on MacOS.

[citrus-it]

The client closing the connection early is due to the interaction of the session_timeout and operation_timeout.
Remember that the client sends a heartbeat every session_timeout/3 and that the issue in the keeper server means that the response is not sent until the heartbeat arrives. However, the client closes the connection once the operation_timeout is exceeded. With the default values of 30 and 10 for the session and operation timeouts respectively, we never see the server's reply.

I extended the <zookeeper> configuration in my test cluster as follows:

    <zookeeper>
        <node>
            <host>127.0.0.1</host>
            <port>9181</port>
        </node>
        <node>
            <host>127.0.0.1</host>
            <port>9182</port>
        </node>
        <node>
            <host>127.0.0.1</host>
            <port>9183</port>
        </node>
+       <session_timeout_ms>30000</session_timeout_ms>
+       <operation_timeout_ms>15000</operation_timeout_ms>
    </zookeeper>

and now the cluster is able to talk to keeper.

2023.07.31 13:11:13.530920 [ 180 ] {} <Trace> ZooKeeperClient: Detected server's API version: WITH_FILTERED_LIST
2023.07.31 13:11:13.531052 [ 180 ] {} <Trace> ZooKeeper: Initialized, hosts: 127.0.0.1:9181,127.0.0.1:9182,127.0.0.1:9183

This doesn't resolve the keeper delay issue, we're still getting a 10s latency on all requests.

[citrus-it]

With the above change, the cluster database creation does appear to work, although it takes a long time with every keeper transaction taking 10s!

oximeter_cluster node 1 :) show clusters;

SHOW CLUSTERS

Query id: 6377b0d2-4518-4430-bafe-d2e08fc1a20c

┌─cluster──────────┐
│ oximeter_cluster │
└──────────────────┘

1 row in set. Elapsed: 0.002 sec.

oximeter_cluster node 1 :) CREATE DATABASE IF NOT EXISTS oximeter ON CLUSTER oximeter_cluster;

CREATE DATABASE IF NOT EXISTS oximeter ON CLUSTER oximeter_cluster

Query id: a62c3501-6935-4a37-ab0f-394c0dbb931b

┌─host────┬─port─┬─status─┬─error─┬─num_hosts_remaining─┬─num_hosts_active─┐
│ fd01::1 │ 9000 │      0 │       │                   1 │                1 │
└─────────┴──────┴────────┴───────┴─────────────────────┴──────────────────┘
↖ Progress: 1.00 rows, 51.00 B (0.00 rows/s., 0.22 B/s.)  49%
1 row in set. Elapsed: 235.733 sec.

Received exception from server (version 22.8.9):
Code: 159. DB::Exception: Received from fd01::1:9000. DB::Exception: Watching task /clickhouse/task_queue/ddl/query-0000000000 is executing longer than distributed_ddl_task_timeout (=180) seconds. There are 1 unfinished hosts (1 of them are currently active), they are going to execute the query in background. (TIMEOUT_EXCEEDED)

oximeter_cluster node 1 :)

oximeter_cluster node 2 :) show databases;

SHOW DATABASES

Query id: 7e8e92d5-fa1d-4b0f-ae42-aab34e695f05

┌─name───────────────┐
│ INFORMATION_SCHEMA │
│ default            │
│ information_schema │
│ oximeter           │
│ system             │
└────────────────────┘

5 rows in set. Elapsed: 0.001 sec.

[citrus-it]

Truss output:

Base time stamp:  1690812280.8194  [ Mon Jul 31 14:04:40 UTC 2023 ]
211238/1:       psargs: ./bin/clickhouse keeper -C keeper_solo/config.xml

# Connection

211238/142:      1.8417 accept(28, 0xFFFFF5FFB9176D80, 0xFFFFF5FFB9176EA4, SOV_DEFAULT, 0) = 29
211238/142:      1.8417 getsockname(29, 0xFFFFF5FFB9176DD0, 0xFFFFF5FFB9176EEC, SOV_DEFAULT) = 0
211238/142:      1.8418 setsockopt(29, tcp, TCP_NODELAY, 0xFFFFF5FFB9176EFC, 4, SOV_DEFAULT) = 0
211238/142:      1.8428 lwp_unpark(3)                                   = 0
211238/3:        1.8428 lwp_park(0xFFFFF5FFEE1C5D10, 0)                 = 0
211238/3:        1.8429 getpeername(29, 0xFFFFF5FFEE1C5C30, 0xFFFFF5FFEE1C5D4C, SOV_DEFAULT) = 0
211238/3:        1.8429 getpeername(29, 0xFFFFF5FFEE1C5C30, 0xFFFFF5FFEE1C5D4C, SOV_DEFAULT) = 0
211238/3:        1.8430 getpid()                                        = 211238 [210808]
211238/3:        1.8430 lseek(5, 0, SEEK_CUR)                           = 12959
211238/3:        1.8431 write(5, 0x184F1910, 110)                       = 110
211238/3:          2 0 2 3 . 0 7 . 3 1   1 4 : 0 4 : 4 2 . 6 6 2 3 9 1   [   3   ]
211238/3:            { }   < T r a c e >   K e e p e r T C P H a n d l e r F a c t
211238/3:          o r y :   K e e p e r   r e q u e s t .   A d d r e s s :   1 2
211238/3:          7 . 0 . 0 . 1 : 6 1 0 0 6\n
211238/3:        1.8433 pipe([30,31], O_CLOEXEC)                        = 0
211238/3:        1.8433 fcntl(30, F_GETFL)                              = 2
211238/3:        1.8434 fcntl(30, F_SETFL, FWRITE|FNONBLOCK)            = 0
211238/3:        1.8434 fcntl(31, F_GETFL)                              = 2
211238/3:        1.8435 fcntl(31, F_SETFL, FWRITE|FNONBLOCK)            = 0
211238/3:        1.8435 open("/proc/self/lwp/3/lwpname", O_WRONLY)      = 32
211238/3:        1.8436 write(32, 0x16CBAA05, 14)                       = 14
211238/3:          K e e p e r H a n d l e r\0
211238/3:        1.8438 close(32)                                       = 0
211238/3:        1.8439 setsockopt(29, SOL_SOCKET, SO_RCVTIMEO, 0xFFFFF5FFEE1C59F0, 16, SOV_DEFAULT) = 0
211238/3:        1.8439 setsockopt(29, SOL_SOCKET, SO_SNDTIMEO, 0xFFFFF5FFEE1C59F0, 16, SOV_DEFAULT) = 0
211238/3:        1.8439 setsockopt(29, tcp, TCP_NODELAY, 0xFFFFF5FFEE1C5A0C, 4, SOV_DEFAULT) = 0
211238/3:        1.8440 getpeername(29, 0xFFFFF5FFEE1C5880, 0xFFFFF5FFEE1C599C, SOV_DEFAULT) = 0
211238/3:        1.8440 getpeername(29, 0xFFFFF5FFEE1C58B0, 0xFFFFF5FFEE1C59CC, SOV_DEFAULT) = 0
211238/3:        1.8441 pollsys(0xFFFFF5FFEE1C5850, 1, 0xFFFFF5FFEE1C57E0, 0x00000000) = 1

# Client handshake

211238/3:        1.8441 recv(29, 0x187F9200, 1048576, 0)                = 48
211238/3:         \0\0\0 ,\0\0\0\0\0\0\0\0\0\0\0\0\0\003E8\0\0\0\0\0\0\0\0\0\0\010
211238/3:         \0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0
211238/3:        1.8441 getpid()                                        = 211238 [210808]
211238/3:        1.8442 lseek(5, 0, SEEK_CUR)                           = 13069
211238/3:        1.8442 write(5, 0x184F1910, 109)                       = 109
211238/3:          2 0 2 3 . 0 7 . 3 1   1 4 : 0 4 : 4 2 . 6 6 3 5 5 2   [   3   ]
211238/3:            { }   < I n f o r m a t i o n >   K e e p e r T C P H a n d l
211238/3:          e r :   R e q u e s t i n g   s e s s i o n   I D   f o r   t h
211238/3:          e   n e w   c l i e n t\n
211238/3:        1.8442 lwp_unpark(6)                                   = 0
211238/6:        1.8443 lwp_park(0xFFFFF5FFEDECB910, 0)                 = 0
211238/6:        1.8444 write(23, 0x18F8F010, 29)                       = 29
211238/6:         D4\0\0 x e9C (B01110\bC8011204 'F7 C\v0510\0 $AEE10E1912 $
211238/6:        1.8448 fdsync(23, FDSYNC)                              = 0
211238/6:        1.8448 lwp_unpark(139)                                 = 0
211238/139:      1.8448 lwp_park(0x00000000, 0)                         = 0
211238/139:      1.8449 lwp_unpark(138)                                 = 0
211238/138:      1.8449 lwp_park(0x00000000, 0)                         = 0
211238/138:      1.8449 getpid()                                        = 211238 [210808]
211238/138:      1.8450 lseek(5, 0, SEEK_CUR)                           = 13178
211238/138:      1.8450 write(5, 0x184F1910, 107)                       = 107
211238/138:        2 0 2 3 . 0 7 . 3 1   1 4 : 0 4 : 4 2 . 6 6 4 3 6 9   [   1 3 8
211238/138:          ]   { }   < D e b u g >   K e e p e r S t a t e M a c h i n e
211238/138:        :   S e s s i o n   I D   r e s p o n s e   6   w i t h   t i m
211238/138:        e o u t   1 0 0 0 0\n
211238/138:      1.8451 lwp_unpark(7)                                   = 0
211238/7:        1.8451 lwp_park(0xFFFFF5FFED6B99F0, 0)                 = 0
211238/7:        1.8451 lwp_unpark(3)                                   = 0
211238/3:        1.8452 lwp_park(0xFFFFF5FFEE1C57D0, 0)                 = 0
211238/3:        1.8452 getpid()                                        = 211238 [210808]
211238/3:        1.8452 lseek(5, 0, SEEK_CUR)                           = 13285
211238/3:        1.8453 write(5, 0x184F1910, 90)                        = 90
211238/3:          2 0 2 3 . 0 7 . 3 1   1 4 : 0 4 : 4 2 . 6 6 4 6 2 3   [   3   ]
211238/3:            { }   < I n f o r m a t i o n >   K e e p e r T C P H a n d l
211238/3:          e r :   R e c e i v e d   s e s s i o n   I D   6\n
211238/3:        1.8453 pollsys(0xFFFFF5FFEE1C5810, 1, 0xFFFFF5FFEE1C57A0, 0x00000000) = 1

# Server response

211238/3:        1.8454 send(29, 0x188F9220, 40, 0)                     = 40
211238/3:         \0\0\0 $\0\0\0\0\0\0 '10\0\0\0\0\0\0\006\0\0\010\0\0\0\0\0\0\0\0
211238/3:         \0\0\0\0\0\0\0\0

# Client request

211238/3:        1.8498 pollsys(0xFFFFF5FFEE1C59D0, 2, 0xFFFFF5FFEE1C5970, 0x00000000) = 1
211238/3:        1.8498 pollsys(0xFFFFF5FFEE1C5850, 1, 0xFFFFF5FFEE1C57E0, 0x00000000) = 1
211238/3:        1.8499 recv(29, 0x187F9200, 1048576, 0)                = 36
211238/3:         \0\0\0  \0\0\001\0\0\004\0\0\013 / k e e p e r / a p i _ v e r s
211238/3:          i o n\0
211238/3:        1.8499 lwp_unpark(6)                                   = 0
211238/6:        1.8499 lwp_park(0xFFFFF5FFEDECB910, 0)                 = 0
211238/6:        1.8500 lwp_unpark(7)                                   = 0
211238/7:        1.8500 lwp_park(0xFFFFF5FFED6B99F0, 0)                 = 0
211238/7:        1.8501 write(31, "01", 1)                              = 1
211238/3:        1.8501 pollsys(0xFFFFF5FFEE1C59D0, 2, 0xFFFFF5FFEE1C5970, 0x00000000) = 1
211238/3:        1.8502 pollsys(0xFFFFF5FFEE1C59D0, 2, 0xFFFFF5FFEE1C5970, 0x00000000) = 1
211238/3:        1.8502 pollsys(0xFFFFF5FFEE1C59D0, 2, 0xFFFFF5FFEE1C5970, 0x00000000) = 1

.. this repeats rapidly until pollsys() returns 2

211238/3:        5.1829 pollsys(0xFFFFF5FFEE1C59D0, 2, 0xFFFFF5FFEE1C5970, 0x00000000) = 1
211238/3:        5.1830 pollsys(0xFFFFF5FFEE1C59D0, 2, 0xFFFFF5FFEE1C5970, 0x00000000) = 1
211238/3:        5.1830 pollsys(0xFFFFF5FFEE1C59D0, 2, 0xFFFFF5FFEE1C5970, 0x00000000) = 2
211238/3:        5.1830 read(30, "01", 1048576)                         = 1
211238/3:        5.1831 pollsys(0xFFFFF5FFEE1C5850, 1, 0xFFFFF5FFEE1C57E0, 0x00000000) = 1

# Client heartbeat

211238/3:        5.1831 recv(29, "\0\0\0\bFFFFFFFE\0\0\0\v", 1048576, 0) = 12
211238/3:        5.1832 lwp_unpark(6)                                   = 0
211238/6:        5.1832 lwp_park(0xFFFFF5FFEDECB910, 0)                 = 0
211238/3:        5.1832 getpid()                                        = 211238 [210808]
211238/3:        5.1832 lseek(5, 0, SEEK_CUR)                           = 13375
211238/3:        5.1833 write(5, 0x184F1910, 96)                        = 96
211238/3:          2 0 2 3 . 0 7 . 3 1   1 4 : 0 4 : 4 6 . 0 0 2 6 3 5   [   3   ]
211238/3:            { }   < T r a c e >   K e e p e r T C P H a n d l e r :   R e
211238/3:          c e i v e d   h e a r t b e a t   f o r   s e s s i o n   # 6\n
211238/6:        5.1833 write(23, 0x18F8F010, 27)                       = 27
211238/6:         C4\0\0 pA2 '97 q lE3 g q011306 204 D0410\005AE I n8804
211238/3:        5.1834 pollsys(0xFFFFF5FFEE1C57B0, 1, 0xFFFFF5FFEE1C5740, 0x00000000) = 1

# Server response to API version request

211238/3:        5.1835 send(29, 0x188F9220, 93, 0)                     = 93
211238/3:         \0\0\0 Y\0\0\001\0\0\0\0\0\0\0\n\0\0\0\0\0\0\001 1\0\0\0\0\0\0\0
211238/3:         \0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0
211238/3:         \0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0

[citrus-it]

I ran a dtrace script to watch what is happening around poll:

#!/usr/sbin/dtrace -Cs

pid$target::accept:entry
{
        self->fd = arg0;
}

pid$target::accept:return
{
        printf("accept(%x) = %x", self->fd, arg1);
}

pid$target::poll:entry
{
        self->p = arg0;
        printf("poll nfds=%x timeout=%x", arg1, arg2);
        p = (struct pollfd *)(copyin(arg0, sizeof (struct pollfd) * 2));
        print(*p);
        print(*(&p[1]));
}

pid$target::poll:return
{
        printf("Return: %x\n", arg1);
        p = (struct pollfd *)(copyin(self->p, sizeof (struct pollfd) * 2));
        print(*p);
        print(*(&p[1]));
}

and extracted the following pieces:

 55  60647                    accept:return accept(1c) = 1d

... there were pieces here around checking for writability and writing out the handshake reply etc. ...

103  60648                      poll:return Return: 1
struct pollfd {
    int fd = 0x1d
    short events = 0x1
    short revents = 0x1
}struct pollfd {
    int fd = 0x1e
    short events = 0x1
    short revents = 0
}

after a while, the second fd gets involved:

103  60638                       poll:entry poll nfds=2 timeout=2710struct pollfd {
    int fd = 0x1d
    short events = 0x1
    short revents = 0
}struct pollfd {
    int fd = 0x1e
    short events = 0x1
    short revents = 0xffff
}

103  60648                      poll:return Return: 1
struct pollfd {
    int fd = 0x1d
    short events = 0x1
    short revents = 0
}struct pollfd {
    int fd = 0x1e
    short events = 0x1
    short revents = 0x1
}

In this case, poll is returning having flagged the second FD in the array as ready for reading (POLLIN set), and the return value is 1 indicating that one of the array members has been updated.

However, note the following code in Clickhouse. This is in the poll() branch which is what is used on MacOS and illumos - Linux uses epoll().

            if (rc >= 1 && poll_buf[0].revents & POLLIN)
                socket_ready = true;
            if (rc >= 2 && poll_buf[1].revents & POLLIN)
                fd_ready = true;

This is obviously incorrect. The return value of 1 does not indicate that only the first array entry is valid.

[bnaecker]

Nice find. This seems to have changed recently. In the older code that I see locally, this section is:

            if (rc >= 1 && poll_buf[0].revents & POLLIN)
                socket_ready = true;
            if (rc >= 1 && poll_buf[1].revents & POLLIN)
                fd_ready = true;

It looks like the rc >= 2 was changed in 38873d726d22. That would prevent detecting readability on that descriptor until both are readable.

I'm pretty surprised, that commit was more than a year ago. There must not be much testing or widespread usage of clustered ClickHouse on non-Linux platforms.

[citrus-it]

This is ClickHouse/ClickHouse#52833 and I will publish a new clickhouse package that omicron can use once it finishes building.

[citrus-it]

New binary bundle at https://oxide-clickhouse-build.s3.us-west-2.amazonaws.com/clickhouse-v22.8.9.24-1.illumos.tar.gz
(Added -1 for the new version that contains this fix).

Requests to keeper return instantly now.

gimlet-sn06 # time bin/zkcli -s=127.0.0.1:9189 get /keeper/api_version
1

real    0m0.023s
user    0m0.009s
sys     0m0.017s

gimlet-sn06 # time bin/zkcli -s=127.0.0.1:9189 ls
[keeper]

real    0m0.024s
user    0m0.008s
sys     0m0.016s

However, I am getting a warning that the server was built in debug mode.