Mnesia -> Khepri fails when changes are made during the migration

[markusgust]

Hello!,

We've been doing some Khepri migration testing, and came across an issue which we thought be best to report. We kept getting crashes during large migrations (many exchanges/bindings, time consuming) and realised that root cause seems to be when a user (or any other object potentially) is deleted/created/updated during the migration. The crash also put the cluster in a broken state, and only recovers when we reset the cluster.

Is the migration not expected to handle changes to tables during migration?

To reproduce:

• install 3.13.0-rc.1 (Erlang version; 26.0) on a single-node cluster.
• create some data, for example exchanges/bindings, something like:

curl -i -u $USER:$PASS -H "content-type:application/json" -XPUT -d '{"durable":true}' http://localhost:15672/api/queues/$USER/one_queue

for i in {1..150}
do
        curl -u $USER:$PASS  -H "content-type:application/json" -XPUT -d '{"type":"direct","durable":true}' http://localhost:15672/api/exchanges/$USER/exchange.$i
        for j in {1..10}
        do
                curl -u $USER:$PASS  -H "content-type:application/json" -XPOST -d'{"routing_key":"RK = '${j}'","arguments":{}}' http://localhost:15672/api/bindings/$USER/e/exchange.$i/q/one_queue
        done
done

• run rabbitmqctl enable_feature_flag khepri_db
• during migration, in a different terminal, delete or add a user (eg. rabbitmqctl delete_user guest)
• keep an eye, eventually you should see a crash complaining about inconsistent db's (below).

log excerpt:

2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>     reason: {badarg,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>              [{erlang,apply,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                [{rabbit_db_m2k_converter,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                  [{rabbit_vhost,rabbit_db_vhost_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_user,rabbit_db_user_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_user_permission,rabbit_db_user_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_topic_permission,rabbit_db_user_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_runtime_parameters,rabbit_db_rtparams_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_queue,rabbit_db_queue_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_exchange,rabbit_db_exchange_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_exchange_serial,rabbit_db_exchange_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_route,rabbit_db_binding_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_node_maintenance_states,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                    rabbit_db_maintenance_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {mirrored_sup_childspec,rabbit_db_msup_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   rabbit_durable_queue,rabbit_durable_exchange,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   rabbit_durable_route,rabbit_semi_durable_route,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   rabbit_reverse_route,rabbit_index_route,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rabbit_exchange_type_consistent_hash_ring_state,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                    rabbit_db_ch_exchange_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {x_jms_topic_table,rabbit_db_jms_exchange_m2k_converter},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                   {rh_exchange_table,rabbit_db_rh_exchange_m2k_converter}]},
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                 delete_from_khepri,
2023-10-25 22:27:55.820400+00:00 [error] <0.10177.0>                 [rabbit_user,<<"guest">>,

Thanks,

[michaelklishin]

@markus812498 migration cannot and will not "double check" if there were any changes during its run but it probably can avoid exceptions. For example, logging a warning should be enough.

A similar scenario with collections ("modified during iteration") in many programming languages would result in an exception by design but it would be much more practical for RabbitMQ to continue migrating.

[dumbbell]

khepri_mnesia_migration migration doesn't double-check but it subscribes to Mnesia changes. Therefore, it won't miss changes happening in parallel to the initial copy.

This exception is a bug: in some place we apparently forget to "unpack" the {Module, Arguments} tuple before calling Module:delete_from_khepri().

[michaelklishin]

Here are some docs about the migration process steps

[michaelklishin]

3.13.0-alpha.251 includes a change that should make Mnesia => Khepri migrations handle these change events better.

@markus812498 please give it a shot.

[markusgust]

Thanks @michaelklishin , tried with the latest alpha 3.13.0~alpha.256-1. Same test as above, and now successful!
Took about 20~ minutes, I suspect it's not unexpected given 15k direct exchanges/bindings.

Cheers!

2023-10-31 20:24:17.489072+00:00 [notice] <0.63831.0> Feature flags: `khepri_db`: starting migration of 20 tables from Mnesia to Khepri; expect decrease in performance and increase in memory footprint
2023-10-31 20:24:17.489191+00:00 [info] <0.63831.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2023-10-31 20:24:17.489415+00:00 [info] <0.63831.0> Successfully synced tables from a peer
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0> Mnesia->Khepri data copy: starting migration "rabbitmq_metadata" from Mnesia to Khepri; tables: [rabbit_vhost,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_user,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_user_permission,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_topic_permission,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_runtime_parameters,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_queue,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_exchange,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_exchange_serial,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_route,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_node_maintenance_states,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  mirrored_sup_childspec,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_durable_queue,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_durable_exchange,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_durable_route,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_semi_durable_route,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_reverse_route,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_index_route,
2023-10-31 20:24:17.489663+00:00 [info] <0.63842.0>                                                                                                  rabbit_exchange_type_consistent_hash_ring_state]
2023-10-31 20:24:25.431725+00:00 [info] <0.63880.0> Created user 'test_user'
2023-10-31 20:24:30.483373+00:00 [info] <0.63897.0> Created user 'test_user123123'
~
2023-10-31 20:41:06.068007+00:00 [warning] <0.65551.0> AUGMENT QUEUES is_enabled false stats detailed
2023-10-31 20:41:26.415423+00:00 [info] <0.65607.0> Deleted user 'guest'
2023-10-31 20:41:26.420908+00:00 [info] <0.65609.0> Closing all connections from user 'guest' because it's being deleted
2023-10-31 20:41:31.283641+00:00 [info] <0.65646.0> Successfully set permissions for user 'admin' in virtual host 'rrrkmisv' to '^$', '^$', '^$'
~
2023-10-31 20:48:00.267165+00:00 [info] <0.63842.0> Mnesia->Khepri data copy: migration "rabbitmq_metadata" from Mnesia to Khepri finished
2023-10-31 20:48:00.269234+00:00 [notice] <0.63831.0> Feature flags: `khepri_db`: migration from Mnesia to Khepri finished
2023-10-31 20:48:00.705158+00:00 [notice] <0.44.0> Application mnesia exited with reason: stopped
2023-10-31 20:48:00.706801+00:00 [notice] <0.341.0> Feature flags: `khepri_db` enabled

[mkuratczyk]

@markus812498 can you share the definitions file for this test? We have a bunch here https://github.com/rabbitmq/sample-configs/tree/main but on my machine, for example q0-with-100k-topic-bindings.json (1 queue with 100k topic bindings) takes ~10 minutes to migrate, so 20 minutes for 15k bindings seems slow. Perhaps it's related to the number of exchanges or something else. Either way, worth taking a look if there's something we could improve. Thanks

[markusgust]

Sure thing!
q-with-15k-direct-exchange-15k-bindings.json
Took over an hour this time (on a smaller instance) and at most used 6GB of data in the coordinations folder. @mkuratczyk

ubuntu@test-rmq-01:~$ time sudo rabbitmqctl enable_feature_flag khepri_db
Enabling feature flag "khepri_db" ...

real    66m2.777s
user    0m0.013s
sys     0m0.000s

Had a crash while testing because disk space ran out during the migration. Suspect that's not very unexpected, but thought I'd share it. A way to replicate is to import attached definitions and run migration on a disk smaller than 5gb.

2023-11-02 22:13:15.888163+00:00 [error] <0.97889.0> Failed to copy Mnesia->Khepri data: {error,{khepri_mnesia_migration,converter_mod_error,#{error => {error,{'EXIT',{error,{error,{"Tab copier iteration failed",badarg}}}}},converter_mod => {rabbit_db_m2k_converter,[{rabbit_vhost,rabbit_db_vhost_m2k_converter},{rabbit_user,rabbit_db_user_m2k_converter},{rabbit_user_permission,rabbit_db_user_m2k_converter},{rabbit_topic_permission,rabbit_db_user_m2k_converter},{rabbit_runtime_parameters,rabbit_db_rtparams_m2k_converter},{rabbit_queue,rabbit_db_queue_m2k_converter},{rabbit_exchange,rabbit_db_exchange_m2k_converter},{rabbit_exchange_serial,rabbit_db_exchange_m2k_converter},{rabbit_route,rabbit_db_binding_m2k_converter},{rabbit_node_maintenance_states,rabbit_db_maintenance_m2k_converter},{mirrored_sup_childspec,rabbit_db_msup_m2k_converter},rabbit_durable_queue,rabbit_durable_exchange,rabbit_durable_route,rabbit_semi_durable_route,rabbit_reverse_route,rabbit_index_route,{rabbit_exchange_type_consistent_hash_ring_state,rabbit_db_ch_exchange_m2k_converter},{x_jms_topic_table,rabbit_db_jms_exchange_m2k_converter},{rh_exchange_table,rabbit_db_rh_exchange_m2k_converter}]}}}}
2023-11-02 22:13:15.888163+00:00 [error] <0.97889.0> [{m2k_table_copy,handle_migration_records,1,
2023-11-02 22:13:15.888163+00:00 [error] <0.97889.0>                  [{file,"src/m2k_table_copy.erl"},{line,520}]},
2023-11-02 22:13:15.888163+00:00 [error] <0.97889.0>  {m2k_table_copy,do_copy_data,1,[{file,"src/m2k_table_copy.erl"},{line,370}]},
2023-11-02 22:13:15.888163+00:00 [error] <0.97889.0>  {m2k_table_copy,handle_call,3,[{file,"src/m2k_table_copy.erl"},{line,267}]},
2023-11-02 22:13:15.888163+00:00 [error] <0.97889.0>  {gen_server,try_handle_call,4,[{file,"gen_server.erl"},{line,1113}]},
2023-11-02 22:13:15.888163+00:00 [error] <0.97889.0>  {gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1142}]},
2023-11-02 22:13:15.888163+00:00 [error] <0.97889.0>  {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]
2023-11-02 22:13:15.895081+00:00 [warning] <0.97888.0> Mnesia->Khepri data copy: failed to unsubscribe to changes to Mnesia table `rabbit_exchange_type_consistent_hash_ring_state`: {error,

Thanks!

[markusgust]

For completion I also imported your q1-with-100k-topic-bindings.json definitions and migrated with result:

ubuntu@test-rmq-01:~$ time sudo rabbitmqctl enable_feature_flag khepri_db
Enabling feature flag "khepri_db" ...

real    13m24.937s
user    0m0.006s
sys     0m0.008s

[the-mikedavis]

Thanks for the reproduction case! We have some optimizations coming down the pike for the mnesia->khepri migration with #9646. On my laptop with the definitions file you provided, on master I see 293 seconds to migrate and with the optimizations I see 8.3 seconds. The speed-up should be more noticeable for slower disk sync speeds, so I think you will see much better than 66 min to migrate in your case after we get those changes in.