WAL checksum validation failure

[RevengeComing]

Hello everyone,

We faced a problem which we dont know exactly what happened. We encountered an error as follows:

14:42:05.947 [error] Supervisor ra_log_wal_sup had child ra_log_wal started with ra_log_wal:start_link(#{compute_checksums => true,dir => "/var/lib/rabbitmq/mnesia/rabbit@rpc-rabbitmq-2/quorum/rabbi...",...}, [{max_batch_size,4096}]) at undefined exit with reason wal_checksum_validation_failure in context start_error
14:42:05.947 [error] Supervisor ra_log_sup had child ra_log_wal_sup started with ra_log_wal_sup:start_link(#{dir => "/var/lib/rabbitmq/mnesia/rabbit@rpc-rabbitmq-2/quorum/rabbit@rpc-rabbitmq-2"}) at undefined exit with reason {shutdown,{failed_to_start_child,ra_log_wal,wal_checksum_validation_failure}} in context start_error
14:42:05.947 [error] CRASH REPORT Process <0.271.0> with 0 neighbours exited with reason: wal_checksum_validation_failure in gen_batch_server:init_it/6 line 169
14:42:05.948 [error] Supervisor ra_system_sup had child ra_log_sup started with ra_log_sup:start_link("/var/lib/rabbitmq/mnesia/rabbit@rpc-rabbitmq-2/quorum/rabbit@rpc-rabbitmq-2") at undefined exit with reason {shutdown,{failed_to_start_child,ra_log_wal_sup,{shutdown,{failed_to_start_child,ra_log_wal,wal_checksum_validation_failure}}}} in context start_error
14:42:05.948 [error] Supervisor ra_sup had child ra_system_sup started with ra_system_sup:start_link() at undefined exit with reason {shutdown,{failed_to_start_child,ra_log_sup,{shutdown,{failed_to_start_child,ra_log_wal_sup,{shutdown,{failed_to_start_child,ra_log_wal,wal_checksum_validation_failure}}}}}} in context start_error
14:42:05.948 [error] CRASH REPORT Process <0.241.0> with 0 neighbours exited with reason: {{shutdown,{failed_to_start_child,ra_system_sup,{shutdown,{failed_to_start_child,ra_log_sup,{shutdown,{failed_to_start_child,ra_log_wal_sup,{shutdown,{failed_to_start_child,ra_log_wal,wal_checksum_validation_failure}}}}}}}},{ra_app,start,[normal,[]]}} in application_master:init/4 line 138
{"Kernel pid terminated",application_controller,"{application_start_failure,ra,{{shutdown,{failed_to_start_child,ra_system_sup,{shutdown,{failed_to_start_child,ra_log_sup,{shutdown,{failed_to_start_child,ra_log_wal_sup,{shutdown,{failed_to_start_child,ra_log_wal,wal_checksum_validation_failure}}}}}}}},{ra_app,start,[normal,[]]}}}"}
Kernel pid terminated (application_controller) ({application_start_failure,ra,{{shutdown,{failed_to_start_child,ra_system_sup,{shutdown,{failed_to_start_child,ra_log_sup,{shutdown,{failed_to_start_chi

Crash dump is being written to: erl_crash.dump...%                          

Rabbitmq version is 3.8.11 on the official docker on Kubernetes.

Also, we recently moved from 3.8.3 image to 3.8.11 because of disk leak which is reported to be solved on 3.8.10 and we deleted all quorum queues and recreated them.

Edit: erl_crash.dump included ( added .txt to end because github won't allow me to include .dump formatted file )
erl_crash.dump.txt

[michaelklishin]

I will convert this issue to a GitHub discussion. Currently GitHub will automatically close and lock the issue even though your question will be transferred and responded to elsewhere. This is to let you know that we do not intend to ignore this but this is how the current GitHub conversion mechanism makes it seem for the users :(

[michaelklishin]

The only known issue where WAL segment checksum would are rabbitmq/ra#138 and rabbitmq/ra#176. I'm not sure what "disk leak" issue you are referring to but if you hit rabbitmq/ra#176 then the node will fail to recover in a very similar way.

A runtime crash dump does not contain any relevant information. We need a complete quorum data directory from the moment when this can be reproduced, and information about the RabbitMQ version used then (not after the upgrade).

[RevengeComing]

By disk leak, I was referring to this discussion: rabbitmq/discussions#164

Unfortunately, I wanted the node back so I reset everything on that node and only picked up the crash dump and I have lost everything. But next time I'll back up the whole /var/lib/rabbitmq directory if happened again. Is it enough?

[kjnilsson]

The checksum is there to validate that no data corruption has occurred which could be the case here. If you don't mind sharing the .wal file us we can take a look and verify if that was the case. Alternatively if you just want to get back running again you can try just removing the .wal files on all nodes, start the system, delete all quorum queues, stop the system delete all wal files again, then start and re-create quorum queues.

[RevengeComing]

I have to mention that only one node of the cluster went into that state and 2 nodes were still running without any problem so I didn't reset the whole cluster. Unfortunately, I have deleted the PVC and restarted the node again since it was 2 nodes running at the time and it was a critical service and I can't recover the WAL file. And also I remember I tried to delete the WAL file and restart the node but it didn't work.

I'll include the WAL file next time if it happened again.

[michaelklishin]

OK, well, you know what to do if this happens again :)

[RevengeComing]

Hello again ... It happened again.

I want to upload the WAL file/mnesia folder but Github doesn't allow me ... how do you prefer to have it?

Edit: WAL file is 537.9 MB and the whole folder gziped is 352.4 MB
Edit2: WAL file Mnesia folder

[kjnilsson]

I understand that - I will try to take a look at your wal file as soon as I can. It is very unusual to see this however, what kind of disks are you using?

[RevengeComing]

We are using rabbitmq on kubernetes using RBD PVCs ... and if I'm not wrong our ceph cluster uses some kind of SSDs.

[michaelklishin]

This is not a common thing to see, and quorum queues have been around for well over a year now. My understanding is that Ceph RBD is a network-based block device. Ra is primarily tested and used on boring local block storage devices, primarily local SSDs.

We have recently seen a ZFS-specific issue with a RabbitMQ queue type that's not generally available but based on Ra as well. It turned out to be a problem with a specific filesystem/OS combination and it took days for a FreeBSD contributor to dig out and provide evidence. There also was an Erlang bug discovered in the process erlang/otp#4540.

So I'm afraid there is only so much we can tell with just a number of WAL segment files.

[michaelklishin]

One thing we can recommend using switching to ext4 or btrfs on a "local" volume for RabbitMQ pod volumes. At least some WAL segments shared fail to deserialize which already says that something was off with the filesystem writes.

Most recent Raft implementation issue around WAL storage we have seen are rabbitmq/ra#175 and rabbitmq/ra#165, at least about 10 months old.

[kjnilsson]

I've analysed your WAL and every single entry is corrupt. e.g:

            116,115,110,6,0,46,183,135,191,119,1,104,4,100,0,7,101,
            110,113,117,101,117,101,100,0,9,117,110,100,101,102,
            105,110,101,100,100,0,9,117,110,100,101,102,105,110,
            101,100,104,6,100,0,13,98,97,115,105,99,95,109,101,115,
            115,97,103,101,104,4,100,0,8,114,101,115,111,117,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,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,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,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,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,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,
            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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,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,0,0,0,0,0,
            0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0>>

This is a binary example that probably should not have that many 0s in it. The only explanation I can think of is that the disk somehow corrupts the data.