Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix: mempool.update() frequent crashes in the main loop #25

Merged
merged 5 commits into from
Jul 28, 2023

Conversation

junderw
Copy link
Member

@junderw junderw commented Jul 26, 2023

After fixing one more bug with mempool syncing, @wiz Showed me the logs from the fix, and I noticed WARN - lookup txouts failed: missing outpoint OutPoint { txid: ee7ecd96379b6685d600f697eb6c3267a4f2d4ec4292000fafdabda1a1024500, vout: 0 } log (which was my missing Outpoint panic fix from a while back.

I looked into it further, and I thought of a way to make this error state handled much better.

  1. Old version (pre Outpoint error fix) = When updating the mempool, if we can't find the parent transactions of any of the transactions we are trying to add, we panicked. (really bad, since RBF etc. and other random reasons cause these kinds of issues all the time.
  2. Current version: Instead of panicking, it returns an error and skip the mempool update altogether.

This version changes two things:

  1. When creating the parent TxOut map, if a parent TxOut can't be found, it will just not be included in the txos HashMap.
  2. When trying to parse the transactions, if any of the parents are missing, continue; to the next loop, only skipping the current transaction, but parsing and caching the ones that succeed.

As an added bonus, this removes the need to return Result from a function that is used many places (and was most of the "error propagation work" that I had to do in my first fix.

@junderw junderw force-pushed the fix/outpoint-missing branch from ba7f655 to 96e4324 Compare July 26, 2023 03:21
Copy link
Contributor

@mononaut mononaut left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tested NACK @ [875057e]

DEBUG - 800301 headers were loaded, tip at 00000000000000000002ab45593d13585ae945c016fb8f12b4c791f9637ebdc2
TRACE - processing 800301 headers, tip at 00000000000000000002ab45593d13585ae945c016fb8f12b4c791f9637ebdc2
TRACE - 800301 chained headers (0 orphan blocks left)
DEBUG - applying 800301 new headers from height 0
DEBUG - downloading new block headers (800301 already indexed) from 00000000000000000002ab45593d13585ae945c016fb8f12b4c791f9637ebdc2
TRACE - downloaded 0 block headers
DEBUG - adding transactions from 0 blocks using Bitcoind
DEBUG - indexing history from 0 blocks using Bitcoind
DEBUG - flushing to disk
DEBUG - updating synced tip to 00000000000000000002ab45593d13585ae945c016fb8f12b4c791f9637ebdc2
DEBUG - Adding 276016 transactions to Mempool
thread 'main' panicked at 'missing mempool tx', src/new_index/mempool.rs:556:25
stack backtrace:
   0:        0x10112f188 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h66ccc15cfc206236
   1:        0x100f9d0cc - core::fmt::write::hb71584703c463b0e
   2:        0x10110f3f8 - std::io::Write::write_fmt::hbb6dd4b27eb1025e
   3:        0x1011325a0 - std::sys_common::backtrace::print::hc590e620d70c4e49
   4:        0x101132200 - std::panicking::default_hook::{{closure}}::h1d886a38230fba3e
   5:        0x1011330d0 - std::panicking::rust_panic_with_hook::h2edeaf2d175c23bd
   6:        0x101132c58 - std::panicking::begin_panic_handler::{{closure}}::h67a863b62de0d81c
   7:        0x101132bcc - std::sys_common::backtrace::__rust_end_short_backtrace::h8df7eeb5057dc923
   8:        0x101132ba8 - _rust_begin_unwind
   9:        0x101557204 - core::panicking::panic_fmt::hb14ca7af22664af2
  10:        0x100fa0c78 - core::panicking::panic_display::h7cd1b0defeaffc9b
  11:        0x100fa0c3c - core::panicking::panic_str::h9c41130935bf6216
  12:        0x101557304 - core::option::expect_failed::hb348e8ccdc51e14c
  13:        0x100fe2b20 - <core::iter::adapters::flatten::FlatMap<I,U,F> as core::iter::traits::iterator::Iterator>::next::h309752a8125c401e
  14:        0x100fe06b8 - electrs::new_index::mempool::Mempool::add::h88e4b9c9e9e0a637
  15:        0x101005784 - electrs::new_index::mempool::Mempool::update::h93205bf9de2ebb20
  16:        0x100f47588 - electrs::main::hebd44303b7c53292
  17:        0x100f3fe88 - std::sys_common::backtrace::__rust_begin_short_backtrace::h545cf82b10fb2d49
  18:        0x100f49bf4 - _main

@mononaut
Copy link
Contributor

or do I need to re-index first?

@junderw
Copy link
Member Author

junderw commented Jul 26, 2023

Ah, nope. That's a bug.

@junderw
Copy link
Member Author

junderw commented Jul 26, 2023

Should be fixed now.

No you don't need a re-index.

@mononaut
Copy link
Contributor

now electrs runs without crashing, but it returns [] for all /tx/:txid requests, which breaks the mempool backend

@junderw
Copy link
Member Author

junderw commented Jul 26, 2023

Any logs you can share (I added a bunch of them)?

@mononaut
Copy link
Contributor

mononaut commented Jul 26, 2023

nope, there aren't any warnings or debug traces, it just quietly returns 200 OK with an empty array instead of the transaction object:

curl -v http://localhost:3000/tx/2dae84fc866790229195eec8e13092a6a8a4318703bb7dbfe42c4e169a30e9e1
*   Trying 127.0.0.1:3000...
* Connected to localhost (127.0.0.1) port 3000 (#0)
> GET /tx/2dae84fc866790229195eec8e13092a6a8a4318703bb7dbfe42c4e169a30e9e1 HTTP/1.1
> Host: localhost:3000
> User-Agent: curl/7.88.1
> Accept: */*
> 
< HTTP/1.1 200 OK
< content-type: application/json
< cache-control: public, max-age=10
< x-powered-by: mempool-electrs 3.0.0-dev-c8a370d(dirty)
< access-control-allow-origin: *
< content-length: 2
< date: Wed, 26 Jul 2023 08:07:20 GMT
< 
* Connection #0 to host localhost left intact
[]
DEBUG - Adding 44 transactions to Mempool
TRACE - registering event source with poller: token=Token(83886084), interests=READABLE | WRITABLE
INFO - handle GET /tx/2dae84fc866790229195eec8e13092a6a8a4318703bb7dbfe42c4e169a30e9e1
TRACE - deregistering event source from poller
DEBUG - Adding 34 transactions to Mempool

This example is a mined transaction from block 800318, but it's the same for mempool transactions.

@junderw
Copy link
Member Author

junderw commented Jul 26, 2023

Fixed.

@junderw
Copy link
Member Author

junderw commented Jul 26, 2023

Electrs: "Finally, we have found the chosen one (tx)"

My code:
throw_simba

@junderw
Copy link
Member Author

junderw commented Jul 26, 2023

< x-powered-by: mempool-electrs 3.0.0-dev-c8a370d(dirty)

This is great for debugging.

Copy link
Contributor

@mononaut mononaut left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tested ACK @ [3188ddf]

@wiz wiz merged commit 34e29f4 into mempool Jul 28, 2023
@wiz wiz deleted the fix/outpoint-missing branch July 28, 2023 07:45
SatoKentaNayoro pushed a commit to boolnetwork/mempool-electrs that referenced this pull request Nov 29, 2024
Fix: mempool.update() frequent crashes in the main loop
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants