openraft: Example raft-kv-memstore hangs after printing change-membership

Nice catch, in Artix don’t happens probably because it uses a more modern version of OpenSSL. Will try to check as soon as I can get into the computer

This problem is caused by an issue of cargo that affects crate openssl.

1. In the example example/raft-key-value-memstore, it uses reqwest to send an RPC to raft service. And reqwest depends on native-tls, while native-tls depends on openssl.

2. When calling openssl::SslConnector::builder(): it will load certificate files if env variable SSL_CERT_FILE is set: https://github.com/sfackler/rust-openssl/blob/eaee383429d156bd91c4a188ba57cf1747c2e440/openssl/src/ssl/mod.rs#L889-L896

   strace shows the time spent on loading certificates:

   1670588693.413004 (+     0.000084) openat(AT_FDCWD, "/usr/lib/ssl/certs/ca-certificates.crt", O_RDONLY) = 3
   1670588693.413054 (+     0.000049) newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=190243, ...}, AT_EMPTY_PATH) = 0
   1670588693.413093 (+     0.000038) read(3, "-----BEGIN CERTIFICATE-----\nMIIH"..., 4096) = 4096
   1670588693.413790 (+     0.000697) read(3, "8B****************************vJw"..., 4096) = 4096
   ...
   1670588693.474642 (+     0.001588) read(3, "D\n*****************************T"..., 4096) = 4096
   1670588693.474848 (+     0.000205) brk(0x55e121d5d000) = 0x55e121d5d000
   1670588693.474888 (+     0.000039) brk(0x55e121d5c000) = 0x55e121d5c000
   1670588693.478875 (+     0.001058) read(3, "", 4096) = 0
   

3. And on Linux(at least on ubuntu), command cargo run pollutes environment variables: It leaks SSL_CERT_FILE and SSL_CERT_DIR to the testing sub progress it runs.

Finally, every time a reqwest::Client is created, it spends several dozen milliseconds on loading a bunch of certificates, which times out a raft RPC(50 ms).

I created a mini demo showing that on linux, cargo xxx will slow down openssl based program: https://github.com/drmingdrmer/test-native-tls-rs

On linux:

cargo run

SSL_CERT_DIR: /usr/lib/ssl/certs
SSL_CERT_FILE: /usr/lib/ssl/certs/ca-certificates.crt
...
=== : 66.382982ms

On my m1 mac:

cargo run

...
=== : 9.23432ms

Related issues:

• Works under cargo test, but not when harness is executed directly? https://github.com/sfackler/rust-openssl/issues/575

• Cargo appears to leak SSL_CERT_FILE and SSL_CERT_DIR to subprocesses https://github.com/rust-lang/cargo/issues/3676

• Cargo binaries are not run in pristine environment https://github.com/rust-lang/cargo/issues/2888

In all of my tests it happened if the hb was configured to any value lower than 101 milliseconds, it also only happened in Pop_OS! when I tried, unfortunately I didn’t find the time to try with other Ubuntu or Debían based distributions, it definitely wasn’t a problem in Artix

Third test environment:

• Artix Linux with Kernel 6.0.6 (zen flavor) and AMD 3950X CPU

No issues. Probably something with Ubuntu, will try to run on this last env with a live distro or VM if I find the time

Definitely is something wrong with the environment. I ran it in another environment with zero issues, this are my details:

Legend:

• Env1: Pop_OS! 22.04 LTS with Linux Kernel 6.0.6, AMD Ryzen 7 4800H CPU
• Env2: Artix Linux with Linux Kernel 5.15.26-lts, Intel i7-6700K CPU

I will try in another computer with also Artix Linux kernel 6.0.x and AMD 3950X CPU in a few minutes

I am experiencing the same issue, the test just hangs after showing the message of membership changing, there is 0ms of delay as I have no proxies or anything configured in this computer. The cluster_test.rs also hangs in the same point.

As @vishwaspai if I increase the heartebeat_timeout to some value higher than 100 it works (the test fails as the last read from node 3 returns an empty string instead of bar in the test but t works fine in the shell script). I have no clue what is going on but the 100 value barrier feels quite suspicious to me, will try to test in another environments.

Attached logs of the three nodes plus my Cargo.lock in case it can be of any help

raft-kv-memstore-logs-and-lock.tar.gz

Could not find much with additional debugging. With heartbeat of above 100ms things work fine. Below this, I see that the raft-append rpc timesout. I tried some tweaking (number of workers etc) on actix_web, but I do not much change in behavior.

For now, I ran with -w '\nConnect: %{time_connect}s\nXfer : %{time_starttransfer}s\nTotal : %{time_total}s\n' to curl (instead of time) and following is the result.

Based on the results I see that add-learner is taking time. Other curl requests fast. At least, I don’t see this as networking issue. Anyways, I’ll see if I can spend time on single stepping.

Initialize server 1 as a single-node cluster

--- rpc(:21001/init, {})  => 3ms
Connect: 0.000067s
Xfer   : 0.003601s
Total  : 0.003638s


Server 1 is a leader now
Get metrics from the leader

--- rpc(:21001/metrics, ) => 0.9ms
Connect: 0.000067s
Xfer   : 0.000851s
Total  : 0.000866s


Adding node 2 and node 3 as learners, to receive log from leader node 1

--- rpc(:21001/add-learner, [2, "127.0.0.1:21002"]) =>  157ms
Connect: 0.000203s
Xfer   : 0.157091s
Total  : 0.157123s


Node 2 added as learner

--- rpc(:21001/add-learner, [3, "127.0.0.1:21003"]) => 540ms
Xfer   : 0.539554s
Total  : 0.539581s


Node 3 added as learner
Get metrics from the leader, after adding 2 learners

--- rpc(:21001/metrics, ) => 0.7 ms
Connect: 0.000045s
Xfer   : 0.000678s
Total  : 0.000693s

Changing membership from [1] to 3 nodes cluster: [1, 2, 3]

--- rpc(:21001/change-membership, [1, 2, 3])
...

Added all the information in the attached tar.

raft-kv-memstore-logs-ac48309.tar.gz

I did not yet find what was going on from the log.

I updated the main branch to let examples output a more detailed log. May you rerun the test with the latest main branch ac4830923bb828288f8a33538991a2964658821a? And let’s see what’s going on.

And what’s your OS and the rust-toolchain?

And may you attach the examples/raft-kv-memstore/Cargo.lock that is built when running test-cluster.sh? So that I can check the dependency crate versions.

It looks just a simple timeout issue. Were you using a slow computer running this test?

No. I’m running on i7-12700H with 14 cores.

Attached logs

raft-kv-memstore-logs.tar.gz

The logs will be helpful. After running ./test-cluster.sh, there should be 3 logs in dir examples/raft-kv-memstore: n1.log n2.log n3.log.

Attach these logs, please and let me look at what’s happening.

Thanks for letting me know about this issue:D