search

input-output-hk / mithril

Stake-based threshold multi-signatures protocol
https://mithril.network
Apache License 2.0
123 stars 39 forks source link

`testing-sanchonet` does not sign Cardano transactions #1845

Closed jpraynaud closed 2 months ago

jpraynaud commented 2 months ago

Why

We have noticed that the signature of the Cardano transactions is not working properly on the testing-sanchonet network.

The error message received is: 

{"msg":"register_signatures::error","v":0,"name":"slog-rs","level":40,"time":"2024-07-18T14:52:07.727575235Z","hostname":"c96c01796931","pid":1,"error":"Multi Signer can not verify single signature for message 'ProtocolMessage { message_parts: {CardanoTransactionsMerkleRoot: \"081b67779cf128e9ca9928213ed97bd4de54d31f8cdbabeb36348046c82b4fe8\", NextAggregateVerificationKey: \"7b226d745f636f6d6d69746d656e74223a7b22726f6f74223a5b35302c3232312c31332c3136372c3230372c33372c3136362c38312c3138332c3235302c3139302c36342c3133392c35352c39382c38302c3231352c38382c3235332c3138372c3230362c3133372c3132322c3139372c39342c38332c3131382c3139382c3235302c3136392c31392c39395d2c226e725f6c6561766573223a312c22686173686572223a6e756c6c7d2c22746f74616c5f7374616b65223a3239363739353339373831397d\", LatestBlockNumber: \"10589099\"} }'\n\nCaused by:\n    0: Invalid signature for party: 'pool1re8cmjt895tpx8dx2veg0cew5yqtxnt82sll03e433a4ugnh9w7'\n    1: A provided signature is invalid\n\nStack backtrace:\n   0: mithril_common::protocol::multi_signer::MultiSigner::verify_single_signature\n   1: <mithril_aggregator::multi_signer::MultiSignerImpl as mithril_aggregator::multi_signer::MultiSigner>::verify_single_signature::{{closure}}\n   2: <mithril_aggregator::services::certifier::MithrilCertifierService as mithril_aggregator::services::certifier::CertifierService>::register_single_signature::{{closure}}\n   3: <warp::filter::and_then::AndThenFuture<T,F> as core::future::future::Future>::poll\n   4: <warp::filter::or::EitherFuture<T,U> as core::future::future::Future>::poll\n   5: <warp::filter::or::EitherFuture<T,U> as core::future::future::Future>::poll\n   6: <warp::filters::cors::internal::WrappedFuture<F> as core::future::future::Future>::poll\n   7: <warp::filter::and::AndFuture<T,U> as core::future::future::Future>::poll\n   8: <warp::filter::recover::RecoverFuture<T,F> as core::future::future::Future>::poll\n   9: <warp::filter::and::AndFuture<T,U> as core::future::future::Future>::poll\n  10: scoped_tls::ScopedKey<T>::set\n  11: hyper::proto::h1::dispatch::Dispatcher<D,Bs,I,T>::poll_catch\n  12: <hyper::server::conn::upgrades::UpgradeableConnection<I,S,E> as core::future::future::Future>::poll\n  13: <hyper::server::server::new_svc::NewSvcTask<I,N,S,E,W> as core::future::future::Future>::poll\n  14: tokio::runtime::task::core::Core<T,S>::poll\n  15: tokio::runtime::task::harness::Harness<T,S>::poll\n  16: tokio::runtime::scheduler::multi_thread::worker::Context::run_task\n  17: tokio::runtime::scheduler::multi_thread::worker::Context::run\n  18: tokio::runtime::context::set_scheduler\n  19: tokio::runtime::context::runtime::enter_runtime\n  20: tokio::runtime::scheduler::multi_thread::worker::run\n  21: tokio::runtime::task::core::Core<T,S>::poll\n  22: tokio::runtime::task::harness::Harness<T,S>::poll\n  23: tokio::runtime::blocking::pool::Inner::run\n  24: std::sys_common::backtrace::__rust_begin_short_backtrace\n  25: core::ops::function::FnOnce::call_once{{vtable.shim}}\n  26: std::sys::pal::unix::thread::Thread::new::thread_start\n  27: start_thread\n  28: clone"}
{"msg":"================================================================================","v":0,"name":"slog-rs","level":30,"time":"2024-07-18T14:52:21.867714884Z","hostname":"c96c01796931","pid":1}

After investigation, it appears that the signer node does not always sign the same state than the aggregator (which leads to having the signature rejected by the aggregator).

After resetting the Cardano transactions databases of the signer and the aggregator on the testing-sanchonet we have noticed that the transaction importer was stuck and kept trying to import the same blocks:

{"msg":"Running Transactions importer between block '13020' and '14520'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:43.750702547Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter will retrieve Cardano transactions between block_number '13020' and '14520'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:43.751113705Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:43.753753867Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer received a RollBackward(260894)","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:43.753833148Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"RUNNER: update_era_checker","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:43.83492258Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"Current Era is thales (Epoch 400).","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:43.864407954Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"MetricsService: incrementing 'runtime_cycle_success_since_startup' counter","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:43.86448447Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"… Cycle finished, Sleeping for 120000 ms","v":0,"name":"slog-rs","level":30,"time":"2024-07-19T13:15:43.864642539Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:44.424102277Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter - computing Block Range Roots","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:44.425215054Z","hostname":"b6b6dcdb2f8f","pid":1,"end_block":14520,"start_block":13035}
{"msg":"Transaction Import finished - Pruning transactions included in block range roots","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:44.429032173Z","hostname":"b6b6dcdb2f8f","pid":1,"number_of_blocks_to_keep":2160}
{"msg":"Transaction Import finished - Vacuuming database to reclaim disk space","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:44.429211464Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"Running Transactions importer between block '14520' and '16020'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:44.464015379Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter will retrieve Cardano transactions between block_number '13026' and '16020'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:44.464243574Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:44.465191818Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer received a RollBackward(261084)","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:44.465629092Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:45.51125501Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter - computing Block Range Roots","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:45.511916769Z","hostname":"b6b6dcdb2f8f","pid":1,"end_block":16020,"start_block":13035}
{"msg":"Transaction Import finished - Pruning transactions included in block range roots","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:45.519211695Z","hostname":"b6b6dcdb2f8f","pid":1,"number_of_blocks_to_keep":2160}
{"msg":"Transaction Import finished - Vacuuming database to reclaim disk space","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:45.51928679Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"Running Transactions importer between block '16020' and '17520'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:45.602144962Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter will retrieve Cardano transactions between block_number '13026' and '17520'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:45.602280169Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:45.603359574Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer received a RollBackward(261084)","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:45.603755676Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:47.28669406Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter - computing Block Range Roots","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:47.287277776Z","hostname":"b6b6dcdb2f8f","pid":1,"end_block":17520,"start_block":13035}
{"msg":"Transaction Import finished - Pruning transactions included in block range roots","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:47.297542362Z","hostname":"b6b6dcdb2f8f","pid":1,"number_of_blocks_to_keep":2160}
{"msg":"Transaction Import finished - Vacuuming database to reclaim disk space","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:47.298696583Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"Running Transactions importer between block '17520' and '19020'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:47.34432532Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter will retrieve Cardano transactions between block_number '13026' and '19020'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:47.344569248Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:47.345778998Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer received a RollBackward(261084)","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:47.346195606Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:49.422553212Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter - computing Block Range Roots","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:49.42340299Z","hostname":"b6b6dcdb2f8f","pid":1,"end_block":19020,"start_block":13035}
{"msg":"Transaction Import finished - Pruning transactions included in block range roots","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:49.437930772Z","hostname":"b6b6dcdb2f8f","pid":1,"number_of_blocks_to_keep":2160}
{"msg":"Transaction Import finished - Vacuuming database to reclaim disk space","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:49.438299454Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"Running Transactions importer between block '19020' and '20520'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:49.462005551Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"TransactionsImporter will retrieve Cardano transactions between block_number '13026' and '20520'","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:49.462234658Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer polls next","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:49.463838717Z","hostname":"b6b6dcdb2f8f","pid":1}
{"msg":"ChainReaderBlockStreamer received a RollBackward(261084)","v":0,"name":"slog-rs","level":20,"time":"2024-07-19T13:15:49.464418462Z","hostname":"b6b6dcdb2f8f","pid":1}

After each round of the importer, the cardano_tx table is left unchanged:

+------------------------------------------------------------------+--------------+-------------+------------------------------------------------------------------+
|                         transaction_hash                         | block_number | slot_number |                            block_hash                            |
+------------------------------------------------------------------+--------------+-------------+------------------------------------------------------------------+
| 6110df4d59fdac4eb4cde5b6c037a849ef4acca3978f166d3bce2cebc7889f4b | 13026        | 261084      | 61cbb4d1b11036eaceeade18722113923cabd4e3d4aee9b7b4d26c9f66992870 |
| 91082aaeddbf1576200c1a03e460e4895b5b79e31944c3010821605541ec35fd | 13026        | 261084      | 61cbb4d1b11036eaceeade18722113923cabd4e3d4aee9b7b4d26c9f66992870 |
| cb05719257d3089c9c37aea9cc1c1bf88a0bfdc3d4751421639b4c6ffd9131e7 | 13026        | 261084      | 61cbb4d1b11036eaceeade18722113923cabd4e3d4aee9b7b4d26c9f66992870 |
| 3e9692afcac33cfde4079626cac45b3097b991bdc93bdad021cd779254407a38 | 13026        | 261084      | 61cbb4d1b11036eaceeade18722113923cabd4e3d4aee9b7b4d26c9f66992870 |
| 2be76aa53b3d0f6b08d4e0ef8ac3997120f426893e24c7fb96e25be759d3105f | 13026        | 261084      | 61cbb4d1b11036eaceeade18722113923cabd4e3d4aee9b7b4d26c9f66992870 |
| e373a5212e3739d3fd4dc22c8a1d40b8612ef7854e9320a79221726421678487 | 13026        | 261084      | 61cbb4d1b11036eaceeade18722113923cabd4e3d4aee9b7b4d26c9f66992870 |
| fb26e7fbf49758135e02ad0be20df1d95adfec8a770a358b76dd8bdd81290086 | 13025        | 260989      | 008a536e24492cee2a4a9bcb8a83b505484832d2c3aefbaecbbe8abad591d4b0 |
| 5b474a3392f3269dfa82741f49e55c25ed243a88dfcc3351a29baba1d3d550e7 | 13025        | 260989      | 008a536e24492cee2a4a9bcb8a83b505484832d2c3aefbaecbbe8abad591d4b0 |
| bfefe6799da472177d74479ac87cf59038da0999c4ad9a9d1127e66296d417a5 | 13025        | 260989      | 008a536e24492cee2a4a9bcb8a83b505484832d2c3aefbaecbbe8abad591d4b0 |
| c401e1f9f1704e2894f5e77b250acc8d78f725998e6318149b209d065b63dafe | 13025        | 260989      | 008a536e24492cee2a4a9bcb8a83b505484832d2c3aefbaecbbe8abad591d4b0 |
+------------------------------------------------------------------+--------------+-------------+------------------------------------------------------------------+

Also, we have noticed that a test SPO (which is not run by the core team) with the same version of the signer 0.2.167 is able to sign properly the transactions.

What

Investigate and fix the problem(s) which prevent the signature of the Cardano transactions.

How

dlachaume commented 2 months ago

After investigation, we were able to understand and reproduce the problem:

It's caused by the chunk import system with a sequence of blocks containing no transactions. The chunk import divides the total number of blocks to be imported by 1500. In each iteration, the lower bound (starting block) remains the same, but the range of blocks to be imported grows larger. This behavior is only reproducible on a network like Sanchonet, which contains very few transactions.

For comparison:

On testing-preview, the import time is about 45 minutes with 4,793,471 transactions (included in 1,234,225 blocks in a range of 2,313,659 blocks). On testing-sanchonet, the import time is about 25-30 hours with 8,932 transactions (included 4,897 blocks in a range of 1,742,609 blocks)