Cluster is flacky, sometimes nodes are getting in a corrupted state

[kerkmann]

Describe the bug

I've setup a cluster with 3 nodes, what I did was stopping, waiting and starting nodes. There was always at least one node online. Restarting some nodes is corrupting the database/state of one node. It's now not able to start the entire database is corrupted on that node.

To Reproduce

1. Setup a cluster with 3 nodes.
2. Stop Node 2
3. Wait a few seconds
4. Stop node 3
5. Wait a few seconds
6. Node 1 was Running. Start Node 3
7. Stop Node 3
8. Wait a few seconds
9. Start Node 2
10. Wait a few seconds
11. Start Node 3
12. Then the Node 3 was corrupted

Expected behavior

A cluster should be more bullet proof in regards to clean restarts.

Additional context

After restarting the leader node, everything worked as intended.

rauthy  |
rauthy  |
rauthy  |                                                   88
rauthy  |                                             ,d    88
rauthy  |                                             88    88
rauthy  |         8b,dPPYba, ,adPPYYba, 88       88 MM88MMM 88,dPPYba,  8b       d8
rauthy  |         88P'   "Y8 ""     `Y8 88       88   88    88P'    "8a `8b     d8'
rauthy  |         88         ,adPPPPP88 88       88   88    88       88  `8b   d8'
rauthy  |         88         88,    ,88 "8a,   ,a88   88,   88       88   `8b,d8'
rauthy  |         88         `"8bbdP"Y8  `"YbbdP'Y8   "Y888 88       88     Y88'
rauthy  |                                                                   d8'
rauthy  |                                                                  d8'
rauthy  |
rauthy  | 2025-09-22T10:47:00.068382Z  INFO rauthy: Starting Rauthy v0.32.3-20250915 (2025-09-15 08:10:42 UTC)
rauthy  | 2025-09-22T10:47:00.068415Z  INFO rauthy: Log Level set to 'INFO'
rauthy  | 2025-09-22T10:47:00.068422Z  INFO rauthy_data::rauthy_config: Public URL: auth.ihate.tech
rauthy  | 2025-09-22T10:47:00.068427Z  INFO rauthy_data::rauthy_config: Issuer: https://auth.ihate.tech/auth/v1
rauthy  | 2025-09-22T10:47:00.068574Z  WARN hiqlite_wal::log_store: LockFile data/logs exists already - this is not a clean start!
rauthy  | 2025-09-22T10:47:00.068989Z  INFO check_integrity:check_repair_data_integrity: hiqlite_wal::wal: Starting detailed WalFile integrity check for data/logs/0000000000000001.wal
rauthy  | 2025-09-22T10:47:00.069171Z  INFO check_integrity:check_repair_data_integrity: hiqlite_wal::wal: No unexpected additional data found in data/logs/0000000000000001.wal
rauthy  | 2025-09-22T10:47:00.069340Z  INFO hiqlite::store::state_machine::sqlite::state_machine: db_exists in state_machine::new(): true
rauthy  | 2025-09-22T10:47:00.069501Z  WARN hiqlite::store::state_machine::sqlite::state_machine: Lock file already exists: data/state_machine/lock
rauthy  | Node did not shut down gracefully - auto-rebuilding State Machine
rauthy  | 2025-09-22T10:47:00.150448Z  INFO hiqlite::store::state_machine::sqlite::writer: Starting snapshot restore from data/state_machine/snapshots/019970fb-9b48-7952-ac10-bc05fcb07e74
rauthy  | Database restore remaining: 50
rauthy  | Database restore remaining: 0
rauthy  | 2025-09-22T10:47:00.154905Z  INFO hiqlite::store::state_machine::sqlite::writer: Snapshot restore finished after 4 ms
rauthy  | 2025-09-22T10:47:00.155753Z  INFO hiqlite::store::state_machine::sqlite::state_machine: applied_state: StateMachineData { last_applied_log_id: Some(LogId { leader_id: LeaderId { term: 1, node_id: 1 }, index: 11 }), last_membership: StoredMembership { log_id: Some(LogId { leader_id: LeaderId { term: 0, node_id: 0 }, index: 0 }), membership: Membership { configs: [{1}], nodes: {1: Node { id: 1, addr_raft: "192.168.1.12:8100", addr_api: "192.168.1.12:8200" }} } }, last_snapshot_id: Some("019970fb-9b48-7952-ac10-bc05fcb07e74") }
rauthy  | 2025-09-22T10:47:00.155810Z  INFO openraft::storage::helper: get_initial_state vote=T4-N3:committed last_purged_log_id=None last_applied=T1-N1-11 committed=None last_log_id=T4-N3-241
rauthy  | 2025-09-22T10:47:00.156070Z  INFO hiqlite::store::state_machine::sqlite::state_machine: applied_state: StateMachineData { last_applied_log_id: Some(LogId { leader_id: LeaderId { term: 1, node_id: 1 }, index: 11 }), last_membership: StoredMembership { log_id: Some(LogId { leader_id: LeaderId { term: 0, node_id: 0 }, index: 0 }), membership: Membership { configs: [{1}], nodes: {1: Node { id: 1, addr_raft: "192.168.1.12:8100", addr_api: "192.168.1.12:8200" }} } }, last_snapshot_id: Some("019970fb-9b48-7952-ac10-bc05fcb07e74") }
rauthy  | 2025-09-22T10:47:00.156104Z  INFO openraft::storage::helper: load membership from log: [12..242)
rauthy  | 2025-09-22T10:47:00.156576Z  INFO openraft::storage::helper: load key log ids from (None,T4-N3-241]
rauthy  | 2025-09-22T10:47:00.156681Z ERROR hiqlite_wal::reader: Error reading logs: Generic("`id_from` is below threshold - id_from: 0 / self.id_from: 12")
rauthy  | 2025-09-22T10:47:00.156721Z  INFO openraft::core::tick: Timer shutdown signal sent: Ok(())
rauthy  |
rauthy  |
rauthy  | thread 'main' panicked at /usr/local/cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hiqlite-0.10.1/src/store/mod.rs:92:6:
rauthy  | Raft create failed: StorageError(Defensive { source: DefensiveError { subject: LogIndex(0), violation: LogIndexNotFound { want: 0, got: None }, backtrace: None } })
rauthy  | note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
rauthy  | 2025-09-22T10:47:00.157246Z  INFO openraft::core::tick: TickLoop received cancel signal, quit

[kerkmann]

today I did a graceful shutdown with just one server, now I get this error:

Sep 23 01:36:10 media systemd-rauthy[6632]:
Sep 23 01:36:10 media systemd-rauthy[6632]:                                                   88
Sep 23 01:36:10 media systemd-rauthy[6632]:                                             ,d    88
Sep 23 01:36:10 media systemd-rauthy[6632]:                                             88    88
Sep 23 01:36:10 media systemd-rauthy[6632]:         8b,dPPYba, ,adPPYYba, 88       88 MM88MMM 88,dPPYba,  8b       d8
Sep 23 01:36:10 media systemd-rauthy[6632]:         88P'   "Y8 ""     `Y8 88       88   88    88P'    "8a `8b     d8'
Sep 23 01:36:10 media systemd-rauthy[6632]:         88         ,adPPPPP88 88       88   88    88       88  `8b   d8'
Sep 23 01:36:10 media systemd-rauthy[6632]:         88         88,    ,88 "8a,   ,a88   88,   88       88   `8b,d8'
Sep 23 01:36:10 media systemd-rauthy[6632]:         88         `"8bbdP"Y8  `"YbbdP'Y8   "Y888 88       88     Y88'
Sep 23 01:36:10 media systemd-rauthy[6632]:                                                                   d8'
Sep 23 01:36:10 media systemd-rauthy[6632]:                                                                  d8'
Sep 23 01:36:10 media systemd-rauthy[6632]:
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.741663Z  INFO rauthy: Starting Rauthy v0.32.3-20250915 (2025-09-15 08:10:42 UTC)
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.741680Z  INFO rauthy: Log Level set to 'INFO'
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.741682Z  INFO rauthy_data::rauthy_config: Public URL: auth.ihate.tech
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.741685Z  INFO rauthy_data::rauthy_config: Issuer: https://auth.ihate.tech/auth/v1
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.741747Z  WARN hiqlite_wal::log_store: LockFile data/logs exists already - this is not a clean start!
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.742052Z  INFO check_integrity:check_repair_data_integrity: hiqlite_wal::wal: Starting detailed WalFile integrity check for data/logs/0000000000000001.wal
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.743430Z  INFO check_integrity:check_repair_data_integrity: hiqlite_wal::wal: No unexpected additional data found in data/logs/0000000000000001.wal
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.743550Z  INFO hiqlite::store::state_machine::sqlite::state_machine: db_exists in state_machine::new(): true
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.743687Z  WARN hiqlite::store::state_machine::sqlite::state_machine: Lock file already exists: data/state_machine/lock
Sep 23 01:36:10 media systemd-rauthy[6632]: Node did not shut down gracefully - auto-rebuilding State Machine
Sep 23 01:36:10 media rauthy[6613]: c821ea4ffbe41b234e3f24b318b03da5c119a2c39f9ed3d74930e666b4536527
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.785047Z  INFO hiqlite::store::state_machine::sqlite::writer: Starting snapshot restore from data/state_machine/snapshots/019970fb-9b48-7952-ac10-bc05fcb07e74
Sep 23 01:36:10 media systemd-rauthy[6632]: Database restore remaining: 50
Sep 23 01:36:10 media systemd-rauthy[6632]: Database restore remaining: 0
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.788325Z  INFO hiqlite::store::state_machine::sqlite::writer: Snapshot restore finished after 3 ms
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.788672Z  INFO hiqlite::store::state_machine::sqlite::state_machine: applied_state: StateMachineData { last_applied_log_id: Some(LogId { leader_id: LeaderId { term: 1, node_id: 1 }, index: 11 }), last_membership: StoredMembership { log_id: Some(LogId { leader_id: LeaderId { term: 0, node_id: 0 }, index: 0 }), membership: Membership { configs: [{1}], nodes: {1: Node { id: 1, addr_raft: "192.168.1.12:8100", addr_api: "192.168.1.12:8200" }} } }, last_snapshot_id: Some("019970fb-9b48-7952-ac10-bc05fcb07e74") }
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.788712Z  INFO openraft::storage::helper: get_initial_state vote=T24-N1:committed last_purged_log_id=None last_applied=T1-N1-11 committed=None last_log_id=T24-N1-9597
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.788736Z  INFO hiqlite::store::state_machine::sqlite::state_machine: applied_state: StateMachineData { last_applied_log_id: Some(LogId { leader_id: LeaderId { term: 1, node_id: 1 }, index: 11 }), last_membership: StoredMembership { log_id: Some(LogId { leader_id: LeaderId { term: 0, node_id: 0 }, index: 0 }), membership: Membership { configs: [{1}], nodes: {1: Node { id: 1, addr_raft: "192.168.1.12:8100", addr_api: "192.168.1.12:8200" }} } }, last_snapshot_id: Some("019970fb-9b48-7952-ac10-bc05fcb07e74") }
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.788794Z  INFO openraft::storage::helper: load membership from log: [12..9598)
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.835576Z  INFO openraft::storage::helper: load key log ids from (None,T24-N1-9597]
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.835597Z ERROR hiqlite_wal::reader: Error reading logs: Generic("`id_from` is below threshold - id_from: 0 / self.id_from: 12")
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.835621Z  INFO openraft::core::tick: Timer shutdown signal sent: Ok(())
Sep 23 01:36:10 media systemd-rauthy[6632]: 2025-09-22T23:36:10.835644Z  INFO openraft::core::tick: TickLoop received cancel signal, quit
Sep 23 01:36:10 media systemd-rauthy[6632]:
Sep 23 01:36:10 media systemd-rauthy[6632]: thread 'main' panicked at /usr/local/cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hiqlite-0.10.1/src/store/mod.rs:92:6:
Sep 23 01:36:10 media systemd-rauthy[6632]: Raft create failed: StorageError(Defensive { source: DefensiveError { subject: LogIndex(0), violation: LogIndexNotFound { want: 0, got: None }, backtrace: None } })
Sep 23 01:36:10 media systemd-rauthy[6632]: note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Sep 23 01:36:11 media systemd-coredump[6663]: [🡕] Process 6635 (rauthy) of user 1018 dumped core.

The only solution is to delete the data folder... :(

[sebadob]

I am pretty sick right now and completely unable to do any work. Will answer when I'm better. But for now: I did over 10.000 node restarts and all different kinds of configurations and everything was smooth and stable.

However, there are some situations you can force, which can deadlock a cluster. All manangement operations like join a cluster or vote a new leader, are at least 2 step operations. This means, if you kill are restarting node right in the middle of an election, and there are not enough other nodes online, yes it can deadlock your cluster. That's just how Raft works and by design, and there is no way to change that.

After a very first look, you have a weird setup there. E.g. I see the node did not shut down cleanly and you have a DB restore from backup. But, you cannot do this to just a single node, this only works on the full cluster. And it has many warnings and logs and so on in different places that explain how it works. If you need to restore a single node but don't want to touch the other nodes of the cluster, deleting the data volume is what you want. It will then be rebuilt.

You can always restore the membership by shutting down the whole cluster and do a fresh cold start. What you described in your first post is something you should never do though. I mean, it will work (tested this many times), but you never want to shut down more than 1 node at a time, because it will leave your cluster in a read only mode and bring an interruption in service. Restart one node at a time and make sure it joined the cluster successfully (this is a 2 step process again, mostly), before you shut down the next one. Especially by force-killing, yes you can of course lock the cluster.

Edit:

Another way to screw it up is a too fast restart. When you restart the node before the rest of the cluster even noticed it was gone, and then maybe even delete the data volume, you will screw up the memberhsip as well, because the leader expects a different state on the just restarted node.

[kerkmann]

@sebadob Don't worry, take your time and get well soon! ❤️

One thing I'd mention is, maybe podman is restarting way too fast. The Backup was one problem but my second post showed the error logs after one system rebooted (using the reboot command), no multiple reboots at the same time, just one host. :)

[sebadob]

So what I can see from your logs, is that you first did not do a clean shutdown / restart. I have seen issues with podman or quadlets, that Rauthy was force-killed way too quickly (like after 10 seconds), which could be your issue here. Hiqlite has mechanisms in place too smooth out these rolling restarts. It adds some artificial delays in different places and an actual clean shutdown of a Rauthy (or actually Hiqlite, this is not a Rauthy issue) node in a HA cluster will end up somewhere in the range of 10 - 15 seconds, depending on the configured Raft cluster timings and some other variables.
The Cache Raft layer will also actually leave the current cluster, if it's set to ephemeral. This gets rid of some log warnings while the node is down, and makes the next start quicker, but it also initiates a management change, which is again a 2-step cluster operation. While this operation is unfinished, the whole cluster is basically on pause, which is how Raft works by design.

I don't use podman, but if you simply reboot, you should check if it actually shuts down the containers (and waits for them instead of force-killing).

today I did a graceful shutdown with just one server, now I get this error:

No, you did not. It was not a graceful shutdown, as you can see in the logs:

WARN hiqlite_wal::log_store: LockFile data/logs exists already - this is not a clean start!

ERROR hiqlite_wal::reader: Error reading logs: Generic("id_from is below threshold - id_from: 0 / self.id_from: 12")

Since you are below 10.000 log id, and your logs start from 12, I guess you restored from a backup and did not create a snapshot at 12 logs yourself, right? This procedure is even integration tested, but then I at least have a hint where I can take a look at.

---

Btw, this is a Hiqlite issues, not a Rauthy one. I am not fully recovered yet, only wanted to fix the login group prefix issue quickly. Will take a look at this later.

[cocoon]

@sebadob sorry to ready you're sick, get well soon and take timevto recover!

I am also using podman and had to configure a higher Stop timout in the compose file with:

stop_grace_period

more things good to know regarding sigs when stopping etc:

https://docs.docker.com/compose/support-and-feedback/faq/

https://cloud.theodo.com/en/blog/docker-processes-container

moby/moby#36955

[sebadob]

@kerkmann were you able to solve your issue with proper shutdown / readiness probe settings? Because after a lot of testing, when set up porperly, I would not find current issues.

[sebadob]

Closing this issue now because of lack of an answer, and I am not aware of any cluster issues, as long as you use a proper config / setup. May be re-opened if any new information comes up or issues still persist.

[sebadob]

I did some more testing and yes, it is possible to get the cluster into a bad state. Not sure yet how exactly I managed to do it, but I will have a look into that.

I just created the following error:

thread 'main' (1) panicked at /usr/local/cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hiqlite-0.11.1/src/store/mod.rs:92:6:
Raft create failed: StorageError(Defensive { source: DefensiveError { subject: LogIndex(0), violation: LogIndexNotFound { want: 0, got: None }, backtrace: None } })
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

The good thing, at least for this one, is that it seems to be just a logic error, because log entry 0 is effectivley None and I just need to check that state better. But I also created a hiccup during a rolling release restart of containers. Again, not sure yet how exactly I got into it, but there is something. I just need to find a way to reproduce it.

Edit:

After more testing, I think it is something related to container runtimes, somehow, even though I have no idea why right now.

I did a lot of local testing and even to a point where I force-killed a leader, followed by immediate rm -rf of all its data and directly restarting it before the other followers even noticed it was down, because I made it happen in between 2 heartbeats. The the result: Everything was perfectly fine. The old leader detected that it has lost its volume while the other nodes thought it was still the leader, it cleaned itself up and then re-joined the already running cluster cleanly.

So my next idea is to add a more specialiced /ready endpoint that only returns ready when "this" node is a voting cluster member of all running Rafts. In combination with K8s publishNotReadyAddresses: true on the headless service, this will probably smooth things out a bit more, even though this was probably not the original issue.

So, if anyone finds a way how to reproduce cluster issues, please let me know.

Edit 2:

I found out that this error can happen after a restore from snapshot, but only if you had enough Raft logs in the past, that you at least had the WAL files rolled over and cleaned up so far, that you don't have the log with id 0 anymore. This is most probably an issue with the snapshot restore, that it does not read the "last applied log id" properly.

This means I do have a trace now. Let's see where it leads me. I was able to copy a data set which produces this issue during startup.

Edit 3:

Found the reason why it could get into that state. Can only happen during truncation of Raft logs, which again can only happen during cluster modifications and when something unexpected happened. The fix itself it pretty easy (most probably, cannot really reproduce it easily, since it needs a race condition), but I will try to implement something to try to "repair" currently broken versions, even though they could get rebuilt pretty easily. This is also something that will never happen to a single node instance, only in an HA cluster.