CheckBlockIndex stalls for extremely long time #25897

1. 
   verdy-p commented at 9:24 pm on August 21, 2022: none

   Stale chain tips can block the RPC and all other responses from the peer for very long time (more than 15 minutes, sometimes hours, or undefinetely). During that time I can see that my local node no longer replies to ANY other peer (e.g. to bitnode.io core). And in process viewers, I can see that there’s a single thread blocking ALL other threads in a tight loop using 100% CPU in a tight loop.

   I’ve seen that this is occurs in any db indexer (notably the chainstate indexer during IBD, or the txindexer, or the coinstat db indexer), notably in some critical steps where new blocks are added to the chain (once every about 15 minutes). This seems to happen when a new block contains a transaction validating a better chain, and invalidating other blocks from dead branches. In that case, the ongoin indexer will fail with unchecked conditions in its internal iterator, apparently because it expect the next block to be present and locks it incorrectly, and is not able to release it and retry if that next valid block has been replaced by a better block in the chain.

    02022-08-21T19:44:15.875834Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70015, blocks=750474, peer=58, peeraddr=[2604:a880:cad:d0::d9e:f001]:8333 (block-relay-only)
    12022-08-21T19:44:45.012022Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 330879
    22022-08-21T19:45:16.005414Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 331746
    32022-08-21T19:45:47.003036Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 332578
    42022-08-21T19:46:18.039548Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 333378
    52022-08-21T19:46:49.007385Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 334219
    62022-08-21T19:47:20.013586Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 334916
    72022-08-21T19:47:51.022263Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 335794
    82022-08-21T19:48:22.007479Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 336769
    92022-08-21T19:48:53.009529Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 337743
   102022-08-21T19:49:24.039053Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 338611
   112022-08-21T19:49:55.041510Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 339322
   122022-08-21T19:50:26.010515Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 340016
   132022-08-21T19:50:57.016185Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 340630
   142022-08-21T19:51:28.055804Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 341499
   152022-08-21T19:52:08.460256Z [validation.cpp:2441] [UpdateTipLog] UpdateTip: new best=0000000000000000000758f0830f8c7cf41c06740b2004b4186e439b0b989062 height=750475 version=0x2281c000 log2_work=93.689008 tx=758464817 date='2022-08-21T19:50:59Z' progress=1.000000 cache=3.7MiB(27192txo)
   162022-08-21T19:52:10.247487Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 341803
   172022-08-21T19:52:30.568835Z [validation.cpp:2441] [UpdateTipLog] UpdateTip: new best=00000000000000000005d0b2bbb26ce7bb0eef932eed58853ebe6525ca71c85a height=750476 version=0x20000004 log2_work=93.689019 tx=758465224 date='2022-08-21T19:52:12Z' progress=1.000000 cache=3.9MiB(28964txo)
   182022-08-21T19:52:41.785630Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 341814
   192022-08-21T19:53:12.001085Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 342683
   202022-08-21T19:53:43.027307Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 343432
   212022-08-21T19:54:14.012871Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 344012
   222022-08-21T19:54:45.022063Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 344718
   232022-08-21T19:54:59.410934Z [validation.cpp:2441] [UpdateTipLog] UpdateTip: new best=000000000000000000098f79590f23c8bb78c3d4d22d1cd4bab3a0e94fc7e6be height=750477 version=0x2ab96000 log2_work=93.689030 tx=758465722 date='2022-08-21T19:54:36Z' progress=1.000000 cache=4.1MiB(30966txo)
   242022-08-21T19:55:16.033929Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 344913
   252022-08-21T19:56:00.985269Z [mapport.cpp:204] [ProcessUpnp] UPnP Port Mapping successful.
   262022-08-21T20:16:01.005268Z [mapport.cpp:204] [ProcessUpnp] UPnP Port Mapping successful.
   

   Finally later it may eventually detect that and detect the inconsistency, by eviting some peers.

    02022-08-21T20:26:10.234268Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 344915
    12022-08-21T20:26:10.236286Z [net_processing.cpp:4381] [CheckForStaleTipAndEvictPeers] Potential stale tip detected, will try using extra outbound peer (last tip update: 1871 seconds ago)
    22022-08-21T20:26:10.877268Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70016, blocks=750480, peer=194, peeraddr=78.108.108.38:8333 (outbound-full-relay)
    32022-08-21T20:26:18.436270Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70016, blocks=750480, peer=195, peeraddr=208.104.92.74:8333 (outbound-full-relay)
    42022-08-21T20:26:20.609320Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70016, blocks=750480, peer=196, peeraddr=[2a01:5200:6c:6162:6263:6173:6861:6263]:8333 (outbound-full-relay)
    52022-08-21T20:26:22.546436Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70016, blocks=750480, peer=198, peeraddr=141.95.45.187:30034 (outbound-full-relay)
    62022-08-21T20:27:18.146310Z [validation.cpp:2441] [UpdateTipLog] UpdateTip: new best=00000000000000000007cb8a63d4c0f24bf0e1c3e6bedbf0436ebab43a3ee690 height=750478 version=0x20800000 log2_work=93.689041 tx=758467003 date='2022-08-21T20:05:24Z' progress=0.999995 cache=5.5MiB(41861txo)
    72022-08-21T20:27:20.065326Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 344926
    82022-08-21T20:27:51.486742Z [validation.cpp:2441] [UpdateTipLog] UpdateTip: new best=00000000000000000006e1bb77ce90948b3050df8ee2143d1913fd583ce3c765 height=750479 version=0x20c00000 log2_work=93.689052 tx=758468307 date='2022-08-21T20:08:38Z' progress=0.999996 cache=6.6MiB(48588txo)
    92022-08-21T20:28:03.488188Z [validation.cpp:2441] [UpdateTipLog] UpdateTip: new best=0000000000000000000171f39891841e7128e85f45f386ddde82f65c12dd5773 height=750480 version=0x20400000 log2_work=93.689063 tx=758468706 date='2022-08-21T20:10:40Z' progress=0.999996 cache=6.8MiB(50180txo)
   102022-08-21T20:28:05.362170Z [index/base.cpp:169] [ThreadSync] Syncing coinstatsindex with block chain from height 344927
   112022-08-21T20:28:05.364170Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70015, blocks=750480, peer=205, peeraddr=116.203.112.73:8333 (outbound-full-relay)
   122022-08-21T20:28:05.718559Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70016, blocks=750480, peer=208, peeraddr=[2404:7a85:4161:2b00:49a1:427a:fac:3409]:8333 (outbound-full-relay)
   132022-08-21T20:28:08.302936Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70016, blocks=750480, peer=211, peeraddr=185.167.113.59:8333 (outbound-full-relay)
   142022-08-21T20:28:21.039390Z [net_processing.cpp:2797] [ProcessMessage] New outbound peer connected: version: 70016, blocks=750480, peer=213, peeraddr=[240b:252:9480:9d00:e65f:1ff:fe10:d767]:8333 (outbound-full-relay)
   

   And here again we see the deadlock occuring for long time in the coindb indexer (note the difference of time between the last too events). And in fact nothing else occured: no resposes to other peers, the coindb indexer was stalled, the RPC service stopped to respond even locally.

   It seems then that there are malicious nodes on the P2P network sending bad blocks that “partially pass” the basic security, but can cause BitCoin Core to be blocked and become unresponsive. It can no longer respond even to a basic RPC such as “bitcoin -getinfo”, or “bitcoin -netinfo”

   It will not even repond to a “bitcoin-cli stop”: some threads are stopped, but not all, and the indexer thread is still running in its tight loop; if you are in that situation, the only way to recover is to KILL the process entirely, and you’ll get the related index to become invalid as it was not committed, it will have to be reconstructed from zero.

   Most often, you have no way to recover (given that the RPC service is not responsive, and even the CTRL+C breaker, or a simple kill -hangup" will not work. You have to do an instant kill (kill -9 on Linux, or manual kill in the Process Viewer on Windows: nothing else will be synced to disk).

   If the index was the IBD index, the chainstate can only be recovered by check level 4 (works often, but not necessarily always, but never with check level 3). If it does not work, then you have to rebuild the chainstate entirely.

   But for any other index (such as the “txindex” or “coinstats” index, there’s NO check at all with recovery at startup, so the only way to recover is to entirely delete the content of that index directory and rebuild it from zero (and this will take many hours, and may fail again in the middle, due to bad blocks sent by malicious peers and that may have still not been replaced by valid blocks in the main chain).

   Apparently these bad blocks seem to come from unapproved forks (possibly implementing SegWit with too large block sizes?), which are not correctly detected and cause the indexer to fail or run into some infinite loops, or some bad signatures using unsupported/snon-standard bytecodes, taking extremely long time to validate or just discard rapidly as invalid.

   Such events with bad blocks coming from malicious peers tend to be frequent now. Unfortunately it’s not easy to track which nodes caused that bug as they may not even be connected since long: they have sent their garbage and have disconnected themselves as soon as done, just to crash specific versions of Bitcoin Core not detecting them.

   (Note: this is once again occuring with the current unmodified release v23.0 from your official site; it affects both Linux and Windows versions).

   Are there blocks that are extremely long to validate or index (taking much more than just about 1 minutes normally needed here to process every logged group of about 15 blocks, such as more than 30 minutes in the 1st break above, but still not completed after several hours at end of the logs above)? Isn’t it one of the reasons why SegWit was asked for, with blocks grouping many signatures, for example those generated by very large miner pools and needing tons of transactions to validate all their micropayments to many participants?

   ---

   See also Bug #25365 (may be related with the same race issue when there’s a new chaintip updated while the indexer is running and iterating from the older chain view)

   If this is the cause, the bug is manifested only when you run it on a machine with enough cores to allow more threads to run concurrently. The crashes/hangs I experiment are all runing with 8 cores activates; your test environment may just have 1 or 2 cores configured, most probably not enough to experiment the race issue between concurrent threads, and not experienced by people running it on cheap PC or notebooks, or in cheap/free VMs for Azure and Amazon (if you get just 1 or 2 non dedicated cores).

   Note also that synchronization issues in code may even more likely to cause bugs on CPUs running multiple threads per core, or using more complex parallelism (e.g. new Intel processors with power-efficient and performance CPUs, with more complex caching layers, or needing special kernel-initiated firmware mitigations like Retpoline against attacks based on latency response time on caches and with speculative execution models; those possibile attacks and firmware or OS mitigations exist on many processors, and their effect on execution latency may vary, depending on the number of active concurrent threads; if you have low I/O latency on disk storage, this will also increase the likelyhood of race issues caused by improper synchronization. But in all these cases this greatly impacts the leveldb indexers, not properly iterating over the main chain of blocks.)

   If you want to experiment it faster, you may want to test it on a machine with many more CPU cores, like newest AMD ThreadRipper (48 concurrent threads!). And then try running multiple indexers running in parallel (the chainstate indexer in IBD, the coinsdbindexer, the txindex, and the coinsdbindex: one of them will crash/hand, or report “data corruption”, but not caused by any hardware issue, but incorrect synchronization in Bitcoin Core’s code).

   As well it seems that all bugs like #25894 (reported quite often, but always diagnosed in replies" incorrectly as a “hardware issue”, just supposed but never really verified) are also related to the same synchronization issues between any indexer thread and the thread handling any changes of the tips on the chainstate (notably if there’s a change between concurrent forks for new blocks after establishing a consensus. They more likely occurs at end of a trading day, when more blocks are announced for compensating transactions made by major traders (it’s then more frequent to get new blocks emitted more rapidly than just once every 10 minutes during the rest of the day.

   ---

   Subsidiary question: Is there way to have a knonw list of trustable peers, and a blacklist for bad peers sending fake/corrupted data? Isn’t Bitcoin missing some additional checks of the structure of these blocks (not just the validation of the individual attempted transactions, but basically its assumed format, includnig for complex multipart signature schemes, or peers attempting to force the use of a hard fork with a disappoved BIP proposal, or attemping to use it too early before a valid date and proper nogociation, if they run some specific subchains)?

   One remote peer I remarked was always present when I saw crashes/hangs was this one:

   <-> type net mping ping send recv txn blk hb addrp addrl age id address version out full ipv6 27 27 4 1 0 1002 1 11 [2001:41d0:303:2b2b::]:8333 70015/Satoshi:0.14.2(bitcore-sl)/UASF-Segwit:1.0(BIP148)/

   I’ve seen it several times sending groups of 2 or 3 unconfirmed blocks with large transactions in a row. It is likely a non-upgraded miner node.

   (According to WHOIS, is is hosted by OVH in France, and likely on a fiber access; it uses the most antique version of Satoshi I seen for a “full node”, but with local patches trying to enforce BIP148 but with wrong version announcements).

   Do I need to list it in my banlist?

2. verdy-p added the label Bug on Aug 21, 2022
3. 
   maflcko commented at 6:32 am on August 22, 2022: member

   Can you reproduce the log with log contention logging enabled? My guess is just that cs_main is held by one thread, putting all others to sleep
4. 
   verdy-p commented at 10:25 am on August 22, 2022: none

   How do I enable logging “log contention”? I’ve not seen any option about it specifically. I just see an option for leveldb itself (debug=leveldb). Do you mean “lock contention” (debug=lock ?)

   Note also that there’s also UPNP, which currently does not uses the standard logs, but just uses “perror()”, i.e. logs on the standard error (notably messages about socket’s sendto(), when it cannot send the message as the target is unreachable) Allowing these logs to be redirected and assigning them a logging category would require patching some source files of its upstream library.

5. 
   jonatack commented at 10:30 am on August 22, 2022: member

   From the developer notes:

    0Defining `DEBUG_LOCKCONTENTION` adds a "lock" logging category to the logging
    1RPC that, when enabled, logs the location and duration of each lock contention
    2to the `debug.log` file.
    3
    4The `--enable-debug` configure option adds `-DDEBUG_LOCKCONTENTION` to the
    5compiler flags. You may also enable it manually for a non-debug build by running
    6configure with `-DDEBUG_LOCKCONTENTION` added to your CPPFLAGS,
    7i.e. `CPPFLAGS="-DDEBUG_LOCKCONTENTION"`, then build and run bitcoind.
    8
    9You can then use the `-debug=lock` configuration option at bitcoind startup or
   10`bitcoin-cli logging '["lock"]'` at runtime to turn on lock contention logging.
   11It can be toggled off again with `bitcoin-cli logging [] '["lock"]'`.
   

6. 
   verdy-p commented at 10:39 am on August 22, 2022: none

   OK so I need to use my compiled version and not the current releases that do not have it.

   I know already the syntax for the bitcoin-cli RPC “logging” command, I use it often.

   Note that this syntax depends on the shell used:

   • For Linux on bash: bitcoin-cli logging '["lock"]' '[]' (need single quotes to surround brackets around JSON arrays and double quotes for JSON strings in them)
   • For Windows CMD: bitcoin-cli logging [\"lock\"] [] (do not use single quotes around parameters, use a backslash before double quotes surrounding JSON string, not needed for brackets)

   That’s not ideal to use bitcoin-cli, which should support a non-RPC syntax like bitcoin-cli -log=lock to enable the category “lock” or bitcoin-cli -log=lock,leveldb if we want to enable more, and bitcoin-cli -nolog=lock to disable it (bitcoin-cli should translate it to the RPC JSON syntax itself…) or bitcoin-cli log=-lock: log category names should not contain commas, spaces, minus/plus signs, the JSON array syntax is ugly. We could even make it shorter as bitcoin-cli +lock for enabling and bitcoin-cli +-lock for disabling, using jut a + (no change needed for the syntax in bitcoin.conf files: debug=category or nodebug=category for individual categories or for special categories “0” or “none”, “1” or “all”, but eventually it could support comma-separated lists).

   Note that with these crashes/hangs, the UPNP thread is still running as I see its logs every few minutes (apparently it does not lock indexer threads, or RPC threads or validation threads; but it locks the connection handler thread that adds/removes new connections and manages the address list; but they are not affected: I can see on bitnode.io that my “hanged” nodes are connected but experiment either timeouts, or extremely long response times for more than 5 minutes to incoming requests from nodes already connected, and my firewall see them connecting with success, sending requests, but getting no reply to their RPC requests)

   Also I’ve tried both Windows (v11, Pro or Enterprise) and Linux (Debian Bullseye) on the same host (different VMs but same hypervisor, similar CPU/RAM/storage config, just a different filesystem NTFS vs. Ext4): the Windows version is MUCH faster by several factors (I bet Windows has a better I/O system, better caching strategies and a more responsive scheduler for multhreading and for handling mutexes). Debian in WSL (HyperV hypervisor on Windows) run with similar performances than native Windows but faster than native Debian (there may be tuning parameters for the Debian native kernel, but I did not invest time in it); i did not tune any guest or host OS specifically to run these tests, so did not use any root/administrator commands, except for installing required third party packages or system libraries and performing standard system updates with “sudo apt update/upgrade” on Debian, or Windows Update in Windows 11, and did not use any custom repositories for these packages).

   ---

   Note: I am currently rebuilding again after performing a git pull to the current main branch (23.99? targetting the next version 24.0). Should I pull instead from the 23.x archived branch?

7. 
   verdy-p commented at 11:27 am on August 22, 2022: none

   Also that that these hangs of the RPC service never occur if I use a RPC command immediately after startup to disable all communications (for exampIe have all the necessary blocks already downloaded, or just enough of them already there (thounsands from a backup e.g. from blocks2/* to blocks/*) so that I can run indexers (including several ones: chainstate, txindex, coinsdb,…). The bugs seems to occur when the chaintips are updated by incoming new blocks or undo blocks being added to blocks/blk*dat and blocks/rev*.dat, and apparently changing the total number of chaintips, and possibly changing the active one in the main branch. I frequently also use backups of chainstate/* to chainstate2/* or indexes/* to indexes2/*, by stopping bitcoind after about 30 minutes: if it exits properly (if not I need to “kill -9” bitcoind, then restart bitcoind to see which index is corrupted, bitcoind will exit after a few seconds and I will restore the failed index directory from the backup).

   Sometimes even if there’s no “corruption” detected and indexing restarts, it may hang very rapidly (depending on which peers are connected or not and if they submit new blocks to be downloaded) and bitcoind sometimes never runs withotu hanging for more than a couple of minutes (especially in the European trading evening around 17:00 UTC, if I’m not lucky), but never more than half an hour (even in late night with reduced transactions rate, so we only get smaller block updates once every ~10 minutes).

   Basically for now this is the only way I was able to complete the IBD (frequent need to restore the “chainstate” index), and then with exactly the same difficulties the other indexes (notably the coinsdb index which is very sensitive to incoming changes in the topology of the block chain with new concurrent branches created by miners, or “dead” branches caused by a new consensus). You can experiment these frequent problems with at least 8 CPU cores; they are much more exceptional with just 2 cores (the NUMA topology does not seem to play a major role, as well whether these are parallel threads in the same physical core or note; you can similate it using CPU affinity controls with system tools, or changing them in the hypervisor if you run bitcoind in a VM; as well the exact CPU model or CPU firmware updates in the BIOS or OS, or the CPU vendor like Intel or AMD does not play any role, these problems occur on all CPU configs I tested: some peers continue to upload blocks that they should have purged since long).

   Another note I made after I was forced to “kill -9” bitcoind, and restored the broken indexes after a 1st attmpt to restart, is that after the next successful restart, the “memory pool” lists thousands of “failed” transactions, when the mempool is reloaded. They are not “old”, more recent than the last 72 hours by default, all related to the most recent blocks announced and received from specific peers). But this also happens with specific historic blocks (when running the IBD for a new full node, where somewhere are records of a “late” switch to another branch spanning several blocks to be invalidated and discarded or partially merged to better blocks).

   However these hangs seem to be correlated to the activity of some miners or trading services, running specific versions of some Bitcoin engines (most probably sending broken blocks, or disobeying the rules of the standard protocol for these blocks or in specific types of transactions or signatures. This looks like BIP158 is incorrectly implemented by them, or they did not update their broken software: is there a way to detect them and ban them automatically so they won’t alter the chain with their bad announcements? Or is it a defect of the protocol itself? Or some stricter validation code missing in Bitcoin Core? Or a bug in the validation code made by Bitcoind Core, not correctly handling cases where some blocks or transactions are invalidated and marked to be discarded?).

8. 
   verdy-p commented at 9:15 pm on August 22, 2022: none

   Here is an example with the end of a debug.log (on Linux Debian Bullseye), containing LOCK CONTENTION (compiled with sources from current main branch in Git, so it is version 23.99).

   Logs include the microseconds in timestamps, as well as the [thread-id], before the [source file!line], and the [function name].

     02022-08-22T21:04:01.203118Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1504 transactions and 8030 inputs
     12022-08-22T21:04:01.203388Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=928341a43c02ee4202480c0f90f78133850490484b1c3e24ed435f42de495bdd wtxid=0737f4f8854b09fb5f6868f48bf4fd172aa41daef0013fd0005bae5182fba504
     22022-08-22T21:04:01.224386Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=51: accepted 928341a43c02ee4202480c0f90f78133850490484b1c3e24ed435f42de495bdd (poolsz 1504 txn, 4535 kB)
     32022-08-22T21:04:01.225317Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (1523 bytes) peer=8
     42022-08-22T21:04:01.225596Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 started
     52022-08-22T21:04:01.226283Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=83fbf108fe6e9f4b07bd739498ee9772795c5b1cd4e935e76a7b9362bc621602 wtxid=3f861c62c5f35d802f88cee35f00d72641da8e91c2eee1d1ac99bcbd4a7a1f84
     62022-08-22T21:04:01.226555Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1505 transactions and 8040 inputs
     72022-08-22T21:04:01.226761Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=83fbf108fe6e9f4b07bd739498ee9772795c5b1cd4e935e76a7b9362bc621602 wtxid=3f861c62c5f35d802f88cee35f00d72641da8e91c2eee1d1ac99bcbd4a7a1f84
     82022-08-22T21:04:01.246618Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=8: accepted 83fbf108fe6e9f4b07bd739498ee9772795c5b1cd4e935e76a7b9362bc621602 (poolsz 1505 txn, 4539 kB)
     92022-08-22T21:04:01.247285Z [msghand] [net.cpp:2744] [PushMessage] [net] sending inv (37 bytes) peer=8
    102022-08-22T21:04:01.247637Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (341 bytes) peer=260
    112022-08-22T21:04:01.247871Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 started
    122022-08-22T21:04:01.248049Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 completed (21839μs)
    132022-08-22T21:04:01.248232Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 completed (199μs)
    142022-08-22T21:04:01.256252Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 started
    152022-08-22T21:04:01.274457Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=cda2aef2c930240f4bd662ee34da420396baff401c27420287ded22b07e5a696 wtxid=e70e8bf21d4f1ecae20f4e52df91d3a8f8e4d7e6e361d18d52b90f84d240ef6f
    162022-08-22T21:04:01.274844Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1506 transactions and 8042 inputs
    172022-08-22T21:04:01.275190Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=cda2aef2c930240f4bd662ee34da420396baff401c27420287ded22b07e5a696 wtxid=e70e8bf21d4f1ecae20f4e52df91d3a8f8e4d7e6e361d18d52b90f84d240ef6f
    182022-08-22T21:04:01.295073Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=260: accepted cda2aef2c930240f4bd662ee34da420396baff401c27420287ded22b07e5a696 (poolsz 1506 txn, 4541 kB)
    192022-08-22T21:04:01.295860Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx fb123aed40da36ba4927120ad9e260ff793078fa9059d6c144fa39bd1dd76eab peer=260
    202022-08-22T21:04:01.296150Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 88c0414f7ad3b9e679e726eced8d8e6f5ff1ea5804a469873bf564b778214a52 peer=260
    212022-08-22T21:04:01.296382Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 23a28b42c93b6188a993218b025274466cc5f81fa41467f045d10533fcc4125b peer=260
    222022-08-22T21:04:01.296593Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 3861a0d55c107734a043cfdf1b3ab229c146350b548b34ff05984eaf41534272 peer=260
    232022-08-22T21:04:01.296800Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 4ddcba760e2a16843bdc5ddbfdd82a4e9ec19a0498c7c970ca0ba7d484bba62e peer=260
    242022-08-22T21:04:01.297005Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 3e80f0ce586eb96675071416ff447036468439909645b00b70064ef886a42189 peer=260
    252022-08-22T21:04:01.297427Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx c29609767edda3b96f4c6cbe75fafcb3d1a8e398decda939868ce5b9f578808c peer=260
    262022-08-22T21:04:01.297665Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 08e8f2b2b5a81782985f9af9d7c48d2e5170f2b4d2b03673cca83109d624672e peer=260
    272022-08-22T21:04:01.297856Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx b3c775ed1f650a3e785618788bb7543be1a2eb21ed98141979a9bd680775b7af peer=260
    282022-08-22T21:04:01.298049Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx a726049aa5e69e8f7b9512876a1ca18e993f2f82cc9b46d468e03485cc222af3 peer=260
    292022-08-22T21:04:01.298344Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx c8be41041e67bb7051b5c73c22d629804955514aac8fe91b9cdf5bc7f36362e6 peer=260
    302022-08-22T21:04:01.298706Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 7021fc322e3536bc54a1d8ba479e9283198f0d7265674d7fdef2206743d5d850 peer=260
    312022-08-22T21:04:01.298969Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 5a9b2fab7c6486d70b8c433b72b6d0bac2bbdab287df212f7509d32a901101dd peer=260
    322022-08-22T21:04:01.299201Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx c2020d4a816601f9837d68561fa2668ed7119f135bcab3ce0d5e045417505ec1 peer=260
    332022-08-22T21:04:01.299437Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 771eebebc63dc27538c7996d4d955e582ecb61670f2a0f6d2e51fd110d40e7ef peer=260
    342022-08-22T21:04:01.299653Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 98da58cb38b6c6242167b1e997b85d717d06762ca21861ba5f794c07a4295653 peer=260
    352022-08-22T21:04:01.299911Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 68e23871175261a0b918782d559178b07c004c8af0106b20679d46cfb0e0bd2d peer=260
    362022-08-22T21:04:01.300138Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx e8065dc1f8d6d270daa241656c13eee96cb4b3aa844506d33e01a71a7515b519 peer=260
    372022-08-22T21:04:01.300351Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 63fda95de082fae2e3fcc635307f65cc50d95734222c4e0bf38855353b89be9f peer=260
    382022-08-22T21:04:01.300554Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 7f4bc13e1b6fadc1c4c9408a5d4561605d36bec706cd5f5d0057a217c57ca637 peer=260
    392022-08-22T21:04:01.300756Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 606fd817fcef94c2f859c0c42b4b74682968c6d1d69ac9e3ba737161ef67f8bb peer=260
    402022-08-22T21:04:01.300955Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx d05c365f4d29d3efe8dcddc1751913b288b94971ec1fb806563ef66d913bfd7b peer=260
    412022-08-22T21:04:01.301164Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx d7ded45dd7875eb2b46b49503da80bd6bedc765ea42023fb0e6414f17ee48728 peer=260
    422022-08-22T21:04:01.301390Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx e3500cbf86e67c4b6aa8154099e4c6c6e36c3f91ba5a075d644bbcaeb799b6a8 peer=260
    432022-08-22T21:04:01.301601Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 896fd4ecc83b980bea3cd8755d9ffded61da44900736cbd2c60896ebb901a2a2 peer=260
    442022-08-22T21:04:01.301849Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 8a69cef8551a4f4046929295b35ddd42a558463fd78472c0836356f4bdee5e9b peer=260
    452022-08-22T21:04:01.302083Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx dc3262b25b3340ad6c832916acb461b50049d3a9f30a9b9ba2f54d4408a33a47 peer=260
    462022-08-22T21:04:01.302292Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 6f47818ba75973d580e68883004d1d54cf9d590f03acef467340d65921559a88 peer=260
    472022-08-22T21:04:01.302521Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 8ce9d91f3abd0463a64eac0a1bcf73b95f79c0b5f48204797a0802089b26f358 peer=260
    482022-08-22T21:04:01.302770Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx b5b2731afbd3dbf77e63251c8dc21dd710754b7b9be73967a0119fb4d993f5f8 peer=260
    492022-08-22T21:04:01.302994Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 28201bbc6e7288545d1e49b80a08a6f5677c774961377a00424b3396fae868fc peer=260
    502022-08-22T21:04:01.303308Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 33e3fd65ddc2704dafdfc643c7a2edbcb31219cccff89eb57306f77570dee77e peer=260
    512022-08-22T21:04:01.303573Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 6f4aa4838d5a7c5ddb5402695c5a9cd4ae387f87b735e0441b3b3edb0fa00b38 peer=260
    522022-08-22T21:04:01.303826Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx cbd6648da6c659981ccbd4e10649722283519b19bfd5fe7f28ffe6722919a49f peer=260
    532022-08-22T21:04:01.304051Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx ecac0b83f250fa8063abf94426db4da51aeacaa1300e991ce14a007dde17ffd2 peer=260
    542022-08-22T21:04:01.304283Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx fc2e44685232c1af2e2e7587d8457131296e4aa7561f37439b5522c5bee97dc6 peer=260
    552022-08-22T21:04:01.304523Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 88b18735f831e7fbd6ae6adea5a2890fa2e8503d9f99bba1c7ee866ac9371ba0 peer=260
    562022-08-22T21:04:01.304747Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 1551a7a57228e26c7518b851a3da94c914d22cb5cd70eac813063221bb215d03 peer=260
    572022-08-22T21:04:01.304963Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 662cfb48a7487d858df17eba7f83c8218166bbc511cf58b69c0e2dfa55540b02 peer=260
    582022-08-22T21:04:01.305171Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 0e551c169f74ef745a25c2b07d93098dc2fe075d8e8275c790bfb7df8694880f peer=260
    592022-08-22T21:04:01.305356Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 44651a8b255a368d7d23e45fca9c9ed5de570e41d21440911107ee1d6dab1ac6 peer=260
    602022-08-22T21:04:01.305870Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 826dfe764e3fdd5397d9c327bba745fd3f0c7a0013d454b7014c93de7fb242cd peer=260
    612022-08-22T21:04:01.306107Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 3527b45415519e3e377fac96d9b2cf0419ff0d4d51b852a10324ceb28425527a peer=260
    622022-08-22T21:04:01.306319Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 248017b1002f22d70f6ada6eea3a3b717786319565f46799abbb006c28d82870 peer=260
    632022-08-22T21:04:01.306530Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx f039350f3b7045d3ff17e8733d6253fd5aab04289bba1fd3a7cd5773c07ece4f peer=260
    642022-08-22T21:04:01.306747Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx a2d7086c7856fa7ac73f856e4c8d3077dd42bc390ff77bac01686e0060a1d1ec peer=260
    652022-08-22T21:04:01.306951Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx b4bdc263e6410bb524cf1db3921e22603084137cfc3f78b34f39c2945781e1c7 peer=260
    662022-08-22T21:04:01.307164Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx ad13bcd1de88137d7caf0d6e8a481fd5c443f6119979587ead867419cf90df71 peer=260
    672022-08-22T21:04:01.307369Z [msghand] [net_processing.cpp:5321] [SendMessages] [net] Requesting tx 6280d79bb02bb085075695bfd5fe378833dff9b8da78de34de8fb3f42f0d68c7 peer=260
    682022-08-22T21:04:01.307580Z [msghand] [net.cpp:2744] [PushMessage] [net] sending getdata (1765 bytes) peer=260
    692022-08-22T21:04:01.307992Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: inv (73 bytes) peer=86
    702022-08-22T21:04:01.308193Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:3225 started
    712022-08-22T21:04:01.308395Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 completed (51503μs)
    722022-08-22T21:04:01.308607Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:3225 completed (227μs)
    732022-08-22T21:04:01.308821Z [msghand] [net_processing.cpp:3264] [ProcessMessage] [net] got inv: wtx b298dfdf5155fd6e28dd813810dacb689a02ebb97785620a713f0b9187c1a8c4  new peer=86
    742022-08-22T21:04:01.309076Z [msghand] [net_processing.cpp:3264] [ProcessMessage] [net] got inv: wtx bbb71a547a41f50419e326104a5d816fd45f6a8f346700b0b75482ddf24b042c  new peer=86
    752022-08-22T21:04:01.309353Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (224 bytes) peer=6
    762022-08-22T21:04:01.317956Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=00a68162ef2b49d1b7f42190519af51c01c11a8b83b121d8814cda2b47848ead wtxid=234e2025b2ae9472d4cd22ef5658e761122c80fee8f8c5b879ddfff17bc6faa2
    772022-08-22T21:04:01.318334Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1507 transactions and 8043 inputs
    782022-08-22T21:04:01.318592Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=00a68162ef2b49d1b7f42190519af51c01c11a8b83b121d8814cda2b47848ead wtxid=234e2025b2ae9472d4cd22ef5658e761122c80fee8f8c5b879ddfff17bc6faa2
    792022-08-22T21:04:01.341320Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=6: accepted 00a68162ef2b49d1b7f42190519af51c01c11a8b83b121d8814cda2b47848ead (poolsz 1507 txn, 4542 kB)
    802022-08-22T21:04:01.342256Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (226 bytes) peer=204
    812022-08-22T21:04:01.342744Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=fc2e44685232c1af2e2e7587d8457131296e4aa7561f37439b5522c5bee97dc6 wtxid=182b3d50f47a0eaad8aa621e3e0a6a153f67eba6ad98985cad5eff62ff01b686
    822022-08-22T21:04:01.343061Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1508 transactions and 8044 inputs
    832022-08-22T21:04:01.343376Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=fc2e44685232c1af2e2e7587d8457131296e4aa7561f37439b5522c5bee97dc6 wtxid=182b3d50f47a0eaad8aa621e3e0a6a153f67eba6ad98985cad5eff62ff01b686
    842022-08-22T21:04:01.360066Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 started
    852022-08-22T21:04:01.363932Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=204: accepted fc2e44685232c1af2e2e7587d8457131296e4aa7561f37439b5522c5bee97dc6 (poolsz 1508 txn, 4543 kB)
    862022-08-22T21:04:01.364823Z [msghand] [net.cpp:2744] [PushMessage] [net] sending inv (73 bytes) peer=204
    872022-08-22T21:04:01.365266Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (222 bytes) peer=7
    882022-08-22T21:04:01.365528Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 started
    892022-08-22T21:04:01.365814Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 completed (4916μs)
    902022-08-22T21:04:01.366122Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 completed (332μs)
    912022-08-22T21:04:01.366430Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: inv (73 bytes) peer=86
    922022-08-22T21:04:01.366738Z [msghand] [net_processing.cpp:3264] [ProcessMessage] [net] got inv: wtx fee246cf80627d8de8cc33a478bcbd28deefb5df5374c742d615b2e3e19f2f00  new peer=86
    932022-08-22T21:04:01.367009Z [msghand] [net_processing.cpp:3264] [ProcessMessage] [net] got inv: wtx 95c96cd52682e5c4594580c36a85bebd0918b9072da4f599649dda5e698fb3c5  new peer=86
    942022-08-22T21:04:01.367275Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (191 bytes) peer=8
    952022-08-22T21:04:01.371055Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 started
    962022-08-22T21:04:01.376520Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=23a28b42c93b6188a993218b025274466cc5f81fa41467f045d10533fcc4125b wtxid=479dba19c8ee598f3d7367b957202f6b94de33d0c9a697690611e19924339ff8
    972022-08-22T21:04:01.376900Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1509 transactions and 8045 inputs
    982022-08-22T21:04:01.377893Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=23a28b42c93b6188a993218b025274466cc5f81fa41467f045d10533fcc4125b wtxid=479dba19c8ee598f3d7367b957202f6b94de33d0c9a697690611e19924339ff8
    992022-08-22T21:04:01.400799Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=8: accepted 23a28b42c93b6188a993218b025274466cc5f81fa41467f045d10533fcc4125b (poolsz 1509 txn, 4544 kB)
   1002022-08-22T21:04:01.401867Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (222 bytes) peer=1
   1012022-08-22T21:04:01.402126Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 started
   1022022-08-22T21:04:01.402386Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 completed (30498μs)
   1032022-08-22T21:04:01.402659Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 completed (316μs)
   1042022-08-22T21:04:01.403035Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=88c0414f7ad3b9e679e726eced8d8e6f5ff1ea5804a469873bf564b778214a52 wtxid=adfe2c38648144aeba6f255c56803b903c8e5be9592dcb1f85a5c6cfb6286bf2
   1052022-08-22T21:04:01.403335Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1510 transactions and 8046 inputs
   1062022-08-22T21:04:01.403573Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=88c0414f7ad3b9e679e726eced8d8e6f5ff1ea5804a469873bf564b778214a52 wtxid=adfe2c38648144aeba6f255c56803b903c8e5be9592dcb1f85a5c6cfb6286bf2
   1072022-08-22T21:04:01.424670Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 started
   1082022-08-22T21:04:01.426271Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=1: accepted 88c0414f7ad3b9e679e726eced8d8e6f5ff1ea5804a469873bf564b778214a52 (poolsz 1510 txn, 4545 kB)
   1092022-08-22T21:04:01.427362Z [msghand] [net.cpp:2744] [PushMessage] [net] sending inv (109 bytes) peer=1
   1102022-08-22T21:04:01.427827Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 started
   1112022-08-22T21:04:01.428094Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 completed (2862μs)
   1122022-08-22T21:04:01.428342Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 completed (272μs)
   1132022-08-22T21:04:01.428647Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (223 bytes) peer=16
   1142022-08-22T21:04:01.440188Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=c9b95c41e9abbfa4fdf55f7a6778c88679c66ece5068042c2ab0715a7dcbc415 wtxid=7f42cbb0f581273c186a756a838da31d8edee8611fb50062d2d1dbea1769bf2d
   1152022-08-22T21:04:01.440550Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1511 transactions and 8047 inputs
   1162022-08-22T21:04:01.440823Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=c9b95c41e9abbfa4fdf55f7a6778c88679c66ece5068042c2ab0715a7dcbc415 wtxid=7f42cbb0f581273c186a756a838da31d8edee8611fb50062d2d1dbea1769bf2d
   1172022-08-22T21:04:01.443428Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 started
   1182022-08-22T21:04:01.462594Z [net] [net.cpp:2726] [CNode] [net] Added connection to 94.237.44.67:16069 peer=263
   1192022-08-22T21:04:01.462876Z [net] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:1351 started
   1202022-08-22T21:04:01.464818Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=16: accepted c9b95c41e9abbfa4fdf55f7a6778c88679c66ece5068042c2ab0715a7dcbc415 (poolsz 1511 txn, 4546 kB)
   1212022-08-22T21:04:01.465651Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (223 bytes) peer=6
   1222022-08-22T21:04:01.465949Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 started
   1232022-08-22T21:04:01.466240Z [net] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:1351 completed (2538μs)
   1242022-08-22T21:04:01.466540Z [net] [net.cpp:1024] [CreateNodeFromAcceptedSocket] [net] connection from 94.237.44.67:16069 accepted
   1252022-08-22T21:04:01.466799Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 completed (22844μs)
   1262022-08-22T21:04:01.467094Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 completed (902μs)
   1272022-08-22T21:04:01.467610Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=ccd648051cbc82b15e98a1b2913a6890d0aafb1893fa089121407ed53213127c wtxid=7a5b693e454d00ad8b69035911e985b05230c9e33cdce92be4f052975cb55070
   1282022-08-22T21:04:01.467896Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1512 transactions and 8048 inputs
   1292022-08-22T21:04:01.468150Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=ccd648051cbc82b15e98a1b2913a6890d0aafb1893fa089121407ed53213127c wtxid=7a5b693e454d00ad8b69035911e985b05230c9e33cdce92be4f052975cb55070
   1302022-08-22T21:04:01.492445Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=6: accepted ccd648051cbc82b15e98a1b2913a6890d0aafb1893fa089121407ed53213127c (poolsz 1512 txn, 4548 kB)
   1312022-08-22T21:04:01.493490Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (223 bytes) peer=51
   1322022-08-22T21:04:01.506132Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 started
   1332022-08-22T21:04:01.508934Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=0228da62a4a2d54d859aa14f3a11722d93bf7cc886cb13cba999a466693f9706 wtxid=620944a61a9710f2faa3cb57178e0f433b710f6dd6de20456014a85c5a27eb86
   1342022-08-22T21:04:01.509285Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 1513 transactions and 8049 inputs
   1352022-08-22T21:04:01.509538Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=0228da62a4a2d54d859aa14f3a11722d93bf7cc886cb13cba999a466693f9706 wtxid=620944a61a9710f2faa3cb57178e0f433b710f6dd6de20456014a85c5a27eb86
   1362022-08-22T21:04:01.532533Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=51: accepted 0228da62a4a2d54d859aa14f3a11722d93bf7cc886cb13cba999a466693f9706 (poolsz 1513 txn, 4549 kB)
   1372022-08-22T21:04:01.533490Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: headers (162003 bytes) peer=262
   1382022-08-22T21:04:01.533779Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 completed (27073μs)
   1392022-08-22T21:04:01.534055Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, net_processing.cpp:2478 started
   1402022-08-22T21:04:01.534464Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, net_processing.cpp:2478 completed (5μs)
   1412022-08-22T21:04:01.547063Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 started
   1422022-08-22T21:04:08.431192Z [net] [net.cpp:2726] [CNode] [net] Added connection to [2a01:4f8:10a:37ee::2]:37890 peer=264
   1432022-08-22T21:04:08.431537Z [net] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:1351 started
   144sendto: Invalid argument
   145sendto: Invalid argument
   146sendto: Invalid argument
   147sendto: Invalid argument
   1482022-08-22T21:04:20.911610Z [mapport] [mapport.cpp:214] [ProcessUpnp] No valid UPnP IGDs found
   1492022-08-22T21:04:22.538769Z [scheduler] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:4625 started
   1502022-08-22T21:04:29.020805Z [addcon] [logging/timer.h:57] [Log] [lock] Enter: lock contention mut, threadinterrupt.cpp:33 started
   1512022-08-22T21:04:29.021186Z [addcon] [logging/timer.h:57] [Log] [lock] Enter: lock contention mut, threadinterrupt.cpp:33 completed (5μs)
   1522022-08-22T21:04:32.201709Z [opencon] [net.cpp:1828] [ThreadOpenConnections] [net] Making feeler connection to [2600:1700:170:fd0::29]:8333
   1532022-08-22T21:04:32.202102Z [opencon] [net.cpp:454] [ConnectNode] [net:debug] trying connection [2600:1700:170:fd0::29]:8333 lastseen=74.9hrs
   1542022-08-22T21:04:37.203130Z [opencon] [netbase.cpp:578] [ConnectSocketDirectly] [net] connection attempt to [2600:1700:170:fd0::29]:8333 timed out
   1552022-08-22T21:04:50.891510Z [opencon] [net.cpp:454] [ConnectNode] [net:debug] trying connection [2604:a880:400:d0::1bdb:4001]:8333 lastseen=13.0hrs
   1562022-08-22T21:04:50.984061Z [opencon] [net.cpp:2726] [CNode] [net] Added connection to [2604:a880:400:d0::1bdb:4001]:8333 peer=265
   1572022-08-22T21:04:50.984441Z [opencon] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:1351 started
   158sendto: Invalid argument
   159sendto: Invalid argument
   160sendto: Invalid argument
   161sendto: Invalid argument
   1622022-08-22T21:09:22.919756Z [mapport] [mapport.cpp:214] [ProcessUpnp] No valid UPnP IGDs found
   163sendto: Invalid argument
   164sendto: Invalid argument
   165sendto: Invalid argument
   166sendto: Invalid argument
   1672022-08-22T21:14:24.928378Z [mapport] [mapport.cpp:214] [ProcessUpnp] No valid UPnP IGDs found
   168sendto: Invalid argument
   169sendto: Invalid argument
   170sendto: Invalid argument
   171sendto: Invalid argument
   1722022-08-22T21:19:26.943932Z [mapport] [mapport.cpp:214] [ProcessUpnp] No valid UPnP IGDs found
   

   (note: the last few “sendto: Invalid argument” messages are actually captured on the console because I also run bitcoind with “-printtoconsole”; they are not in the log file; they are generated inside the MiniUPNP library on the standard error stream).

   This continues like this indefinitely, anll threads are blocked except upnp….

   If I press Ctrl-C in the console where bitcoind is running (because bitcoin-cli stop blocks, trying to connect to the daemon’s RPC service, and has no effect), I get instantly:

    0^C2022-08-22T21:24:45.664304Z [init] [httpserver.cpp:437] [InterruptHTTPServer] [http] Interrupting HTTP server
    12022-08-22T21:24:45.664670Z [init] [httprpc.cpp:314] [InterruptHTTPRPC] [rpc] Interrupting HTTP RPC server
    22022-08-22T21:24:45.665289Z [init] [rpc/server.cpp:301] [operator()] [rpc] Interrupting RPC
    32022-08-22T21:24:45.665896Z [init] [init.cpp:216] [Shutdown] Shutdown: In progress...
    42022-08-22T21:24:45.666120Z [shutoff] [httprpc.cpp:319] [StopHTTPRPC] [rpc] Stopping HTTP RPC server
    52022-08-22T21:24:45.666339Z [shutoff] [httpserver.cpp:689] [UnregisterHTTPHandler] [http] Unregistering HTTP handler for / (exactmatch 1)
    62022-08-22T21:24:45.666554Z [shutoff] [httpserver.cpp:689] [UnregisterHTTPHandler] [http] Unregistering HTTP handler for /wallet/ (exactmatch 0)
    72022-08-22T21:24:45.666770Z [shutoff] [rpc/server.cpp:313] [operator()] [rpc] Stopping RPC
    82022-08-22T21:24:45.666989Z [mapport] [util/thread.cpp:20] [TraceThread] mapport thread exit
    92022-08-22T21:24:45.667229Z [addcon] [util/thread.cpp:20] [TraceThread] addcon thread exit
   102022-08-22T21:24:45.667503Z [shutoff] [init.cpp:382] [OnRPCStopped] [rpc] RPC stopped.
   112022-08-22T21:24:45.667741Z [shutoff] [httpserver.cpp:449] [StopHTTPServer] [http] Stopping HTTP server
   122022-08-22T21:24:45.667966Z [shutoff] [httpserver.cpp:451] [StopHTTPServer] [http] Waiting for HTTP worker threads to exit
   132022-08-22T21:24:45.668282Z [shutoff] [httpserver.cpp:464] [StopHTTPServer] [http] Waiting for HTTP event thread to exit
   142022-08-22T21:24:45.668507Z [http] [httpserver.cpp:290] [ThreadHTTP] [http] Exited http event loop
   152022-08-22T21:24:45.668879Z [shutoff] [httpserver.cpp:476] [StopHTTPServer] [http] Stopped HTTP server
   

   But then the program freezes completely. Here is what I see in htop (which shows in blue color the distinctive name of all threads in the bitcoindp process): some threads exited correctly, others are not reacting, only the message handler thread is running in a tight loop.

   

   Need to use “kill -9” !

   Appaerntly it ia a dealock between two different mutexes: “cs_main” and “mut”. And the UPNP thread seems to acquire the cs_main mutex several times recursively; at the same time the timed scheduler attempts to open a new outgoing connection, which fails with timeout (no response from peer?), then it retries instantly another connection, but without first releasing the lock (it should release, then yield back to the scheduler to retry at another round.

9. 
   maflcko commented at 6:39 am on August 23, 2022: member

   only the message handler thread is running in a tight loop.

   The msghand thread shouldn’t be doing that for hours. It looks like it got stuck on

   2022-08-22T21:04:01.533490Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: headers (162003 bytes) peer=262

   This should be replied to with a getheaders …

   Can you attach gdb when this deadlock happens and let us know where exactly the msghand thread is stuck?

10. 
    verdy-p commented at 10:44 am on August 23, 2022: none

    Hmmm. I’ve tried to attach gdb, this did not work, got an error from gdb. Need to recompile with -g? (I only added -DDEBUG_LOCKCONTENTION as instructed). Anyway, the way multiple locks are acquired in the same thread, but not always in the same order depending on threads, can be a cause of deadlock between these threads. If you need a second lock and hold already one, you should release the 1st one, and then acquire both at the same time (and always in the same order). This may force you to rollback an ongoing atomic transaction, and restart it (and can also perform the second atomic operation needing the 2nd lock) once you got the two locks,

    I think this is a case of deadlock, where the message handler already owns one mutex and then repeatedly locks/unlocks the same second mutex, but never releases the 1st mutex that other concurrent threads need to be unfrozen and continue their operations.

11. 
    verdy-p commented at 11:01 am on August 23, 2022: none

    And again I see the same thing occuring this morning; these are the last logs before I saw that bitcoind was once again frozen, without any more activity (except UPNP updates; note that UPNP works, and IPV4 and IPv6 are enabled and used by incoming and ougoing connnections, but UPNP updates do not work from a VM; my router just has already a port forwarding rule to the host; but inside the VM, UPNP is anot permitted to change router settings on the physical network):

     02022-08-23T10:44:58.199152Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (222 bytes) peer=1
     12022-08-23T10:44:58.210323Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 started
     22022-08-23T10:44:58.213370Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=8d300d79cb2fcb9c5f8d3b25984ec734eefa82d0928707646ccc01ea6f78cd78 wtxid=965565b6d4e36f8c3ccef3a85e054c141c54ac785343ce0b854ca8ee35e286fb
     32022-08-23T10:44:58.213576Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 2720 transactions and 8349 inputs
     42022-08-23T10:44:58.213821Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=8d300d79cb2fcb9c5f8d3b25984ec734eefa82d0928707646ccc01ea6f78cd78 wtxid=965565b6d4e36f8c3ccef3a85e054c141c54ac785343ce0b854ca8ee35e286fb
     52022-08-23T10:44:58.235553Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=1: accepted 8d300d79cb2fcb9c5f8d3b25984ec734eefa82d0928707646ccc01ea6f78cd78 (poolsz 2720 txn, 5553 kB)
     62022-08-23T10:44:58.235984Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/coinstatsindex.cpp:125 completed (25439μs)
     72022-08-23T10:44:58.236306Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 started
     82022-08-23T10:44:58.236547Z [msghand] [logging/timer.h:57] [Log] [lock] Enter: lock contention ::cs_main, validation.cpp:5030 completed (4μs)
     92022-08-23T10:44:58.236877Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: tx (1265 bytes) peer=1
    102022-08-23T10:44:58.237667Z [msghand] [validationinterface.cpp:209] [TransactionAddedToMempool] [validation] Enqueuing TransactionAddedToMempool: txid=fe8702f042e4d03c032256b9acb218054a0b2750b6dcc52f469c5b4c04ab88b3 wtxid=fe8702f042e4d03c032256b9acb218054a0b2750b6dcc52f469c5b4c04ab88b3
    112022-08-23T10:44:58.237943Z [msghand] [txmempool.cpp:736] [check] [mempool] Checking mempool with 2721 transactions and 8356 inputs
    122022-08-23T10:44:58.238170Z [scheduler] [validationinterface.cpp:209] [operator()] [validation] TransactionAddedToMempool: txid=fe8702f042e4d03c032256b9acb218054a0b2750b6dcc52f469c5b4c04ab88b3 wtxid=fe8702f042e4d03c032256b9acb218054a0b2750b6dcc52f469c5b4c04ab88b3
    132022-08-23T10:44:58.259625Z [msghand] [net_processing.cpp:3605] [ProcessMessage] [mempool] AcceptToMemoryPool: peer=1: accepted fe8702f042e4d03c032256b9acb218054a0b2750b6dcc52f469c5b4c04ab88b3 (poolsz 2721 txn, 5556 kB)
    142022-08-23T10:44:58.260022Z [msghand] [net_processing.cpp:2790] [ProcessMessage] [net] received: headers (162003 bytes) peer=153
    152022-08-23T10:44:58.330193Z [coinstatsindex] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, index/base.cpp:166 started
    162022-08-23T10:45:01.954237Z [net] [net.cpp:1314] [SocketHandlerConnected] [net] socket closed for peer=147
    172022-08-23T10:45:01.954670Z [net] [net.cpp:563] [CloseSocketDisconnect] [net] disconnecting peer=147
    182022-08-23T10:45:15.893840Z [scheduler] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:4625 started
    19sendto: Invalid argument
    20sendto: Invalid argument
    21sendto: Invalid argument
    22sendto: Invalid argument
    232022-08-23T10:45:18.500189Z [mapport] [mapport.cpp:214] [ProcessUpnp] No valid UPnP IGDs found
    242022-08-23T10:45:25.303506Z [net] [net.cpp:1314] [SocketHandlerConnected] [net] socket closed for peer=46
    252022-08-23T10:45:25.303980Z [net] [net.cpp:563] [CloseSocketDisconnect] [net] disconnecting peer=46
    262022-08-23T10:45:45.838580Z [net] [net.cpp:2726] [CNode] [net] Added connection to [2001:470:88ff:2e::1]:42434 peer=154
    272022-08-23T10:45:45.839004Z [net] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:1351 started
    282022-08-23T10:46:43.723150Z [opencon] [net.cpp:454] [ConnectNode] [net:debug] trying connection [2a05:d01c:672:9200:b1c2:7680:3e94:27ad]:8333 lastseen=23.3hrs
    292022-08-23T10:46:43.744125Z [opencon] [net.cpp:2726] [CNode] [net] Added connection to [2a05:d01c:672:9200:b1c2:7680:3e94:27ad]:8333 peer=155
    302022-08-23T10:46:43.744480Z [opencon] [logging/timer.h:57] [Log] [lock] Enter: lock contention cs_main, net_processing.cpp:1351 started
    

    Here also “received: headers (162003 bytes)” not followed by getheaders (note: I’lm not in IBD, my node is already synchronized with all blocks). Isn’t that incoming request too large? How so we reply to such large request? Normally we should reply by jsut giving a reasonnable fragment and let the peer request other later (or from other peers than us). But it seems that such large request still attempts to lock a too large subset of our chain, more than needed, and apparently this is not possible because there’s an indexer (for coinsdb) running in the background (still locking blocks at a lower height, and progressing).

    As there’s no “usleep” between operations of the indexer before getting the mutex for the next block to index, and no “usleep” as well in the message handler for other concurrent threads giveing some free time for other threads, and because we have not defined priorities between threads a thread my release and hold the same mutex repeatedly, without giving a chance for other threads to get it. This is a case of “starvation” caused by a “selfish” thread making unsafe assumptions that it can always rnu as fast as he wish. Such cases are generally resovled by adding a small randomized usleep() (or yielding to other threads at least once every N operations, with N about 100 to 200, if you don’t want to use a random generator; in other multhreaded applications I generally use N=113 because it is a “good” prime generating enough variations), before or after atomic operations (but never inside the atomic operation when the mutex is hold).

    Note: I’ve not tested by diabling UPNP in bitcoin.conf to see if there’s such freezes again. UPNP is visible here because that is the only thread allowed to run without using any mutex, so it just witnesses that that thread is working. This could be replaced by any other thread sending dummy “I’m running” logs every few minutes, and doing nothing else with our mutexes.

12. 
    verdy-p commented at 6:41 pm on August 23, 2022: none

    Note that for using gdb and attaching it to a running program (with its process id to find with ps -ef or htop for example), this does not work, due to kernel restrictions (I get “ptrace: operation not permitted” reported by gdb; most probably because of kernel enforcement, not allowing to attach to a process running in another logon session or with a different controling terminal; I saw the tricks about chaging the kernel security model, but this requires installing another kernel, built ourself and using “tweak” parameter in the kernel security, and not their default).

    Note that I don’t use a kernel with SELinux, but the “yama” security model is enforced by default in Debian. I would not use a Linux kernel that does not apply a strong enough security model, with any application connected with the Internet (this includes bitcoind…).

    So the only thing I can do is to run bitcoind from within gdb, e.g.:

    0$ gdb --args bitcoind -printtoconsole
    1(gdb) run
    

    And then use another console/terminal to use htop or bitcoin-cli (because the current terminal is too busy to get used inside gdb, unless I pause the program from another console by sending it a signal that will break the program into gdb.

    When this break occurs, I can list threads (info threads), and look for the message handler thread (that thread that was the only one running and using more than 50% CPU, while all others are stuck). Here is what I get when I switch to that message handler thread:

     0(gdb) t 24
     1[Switching to thread 24 (Thread 0x7fff2fff0700 (LWP 21209))]
     2[#0](/bitcoin-bitcoin/0/)  0x00000000081e4cae in std::_Rb_tree<CBlockIndex*, std::pair<CBlockIndex* const, CBlockIndex*>, std::_Select1st<std::pair<CBlockIndex* const, CBlockIndex*> >, std::less<CBlockIndex*>, std::allocator<std::pair<CBlockIndex* const, CBlockIndex*> > >::_M_get_insert_equal_pos (this=0x7fff2ffebcb0, __k=@0x7fff24e717f0: 0xedcd108)
     3    at /usr/include/c++/10/bits/stl_tree.h:2132
     42132              __x = _M_impl._M_key_compare(__k, _S_key(__x)) ?
     5(gdb) i stack
     6[#0](/bitcoin-bitcoin/0/)  0x00000000081e4cae in std::_Rb_tree<CBlockIndex*, std::pair<CBlockIndex* const, CBlockIndex*>, std::_Select1st<std::pair<CBlockIndex* const, CBlockIndex*> >, std::less<CBlockIndex*>, std::allocator<std::pair<CBlockIndex* const, CBlockIndex*> > >::_M_get_insert_equal_pos (this=0x7fff2ffebcb0, __k=@0x7fff24e717f0: 0xedcd108)
     7    at /usr/include/c++/10/bits/stl_tree.h:2132
     8[#1](/bitcoin-bitcoin/1/)  0x000000000854ca46 in std::_Rb_tree<CBlockIndex*, std::pair<CBlockIndex* const, CBlockIndex*>, std::_Select1st<std::pair<CBlockIndex* const, CBlockIndex*> >, std::less<CBlockIndex*>, std::allocator<std::pair<CBlockIndex* const, CBlockIndex*> > >::_M_emplace_equal<CBlockIndex*&, CBlockIndex*> (this=0x7fff2ffebcb0)
     9    at /usr/include/c++/10/bits/stl_tree.h:2444
    10[#2](/bitcoin-bitcoin/2/)  0x0000000008542d05 in std::multimap<CBlockIndex*, CBlockIndex*, std::less<CBlockIndex*>, std::allocator<std::pair<CBlockIndex* const, CBlockIndex*> > >::emplace<CBlockIndex*&, CBlockIndex*> (this=0x7fff2ffebcb0) at /usr/include/c++/10/bits/stl_multimap.h:492
    11[#3](/bitcoin-bitcoin/3/)  0x00000000085270b2 in CChainState::CheckBlockIndex (this=0x9266350) at validation.cpp:4412
    12[#4](/bitcoin-bitcoin/4/)  0x0000000008520c70 in ChainstateManager::ProcessNewBlockHeaders (this=0x9263c50, headers=std::vector of length 17, capacity 17 = {...}, state=...,
    13    ppindex=0x7fff2ffebe78) at validation.cpp:3672
    14[#5](/bitcoin-bitcoin/5/)  0x0000000008136c01 in (anonymous namespace)::PeerManagerImpl::ProcessHeadersMessage (this=0x13b7a250, pfrom=..., peer=...,
    15    headers=std::vector of length 17, capacity 17 = {...}, via_compact_block=false) at net_processing.cpp:2503
    16[#6](/bitcoin-bitcoin/6/)  0x00000000081433e2 in (anonymous namespace)::PeerManagerImpl::ProcessMessage (this=0x13b7a250, pfrom=..., msg_type="headers", vRecv=..., time_received=...,
    17    interruptMsgProc=...) at net_processing.cpp:4048
    18[#7](/bitcoin-bitcoin/7/)  0x0000000008148843 in (anonymous namespace)::PeerManagerImpl::ProcessMessages (this=0x13b7a250, pfrom=0x7fff28001d40, interruptMsgProc=...)
    19    at net_processing.cpp:4447
    20[#8](/bitcoin-bitcoin/8/)  0x00000000080d2538 in CConnman::ThreadMessageHandler (this=0x925e880) at net.cpp:1985
    21[#9](/bitcoin-bitcoin/9/)  0x00000000080d5386 in operator() (__closure=0x7fff24000b60) at net.cpp:2333
    22[#10](/bitcoin-bitcoin/10/) 0x00000000080e4b9d in std::__invoke_impl<void, CConnman::Start(CScheduler&, const CConnman::Options&)::<lambda()>&>(std::__invoke_other, struct {...} &) (__f=...)
    23    at /usr/include/c++/10/bits/invoke.h:60
    24[#11](/bitcoin-bitcoin/11/) 0x00000000080e3fc7 in std::__invoke_r<void, CConnman::Start(CScheduler&, const CConnman::Options&)::<lambda()>&>(struct {...} &) (__fn=...)
    25    at /usr/include/c++/10/bits/invoke.h:110
    26[#12](/bitcoin-bitcoin/12/) 0x00000000080e3228 in std::_Function_handler<void(), CConnman::Start(CScheduler&, const CConnman::Options&)::<lambda()> >::_M_invoke(const std::_Any_data &) (
    27    __functor=...) at /usr/include/c++/10/bits/std_function.h:291
    28[#13](/bitcoin-bitcoin/13/) 0x000000000825c00b in std::function<void ()>::operator()() const (this=0x7fff2ffefb20) at /usr/include/c++/10/bits/std_function.h:622
    29[#14](/bitcoin-bitcoin/14/) 0x0000000008acd5a4 in util::TraceThread(char const*, std::function<void ()>) (thread_name=0x8c19699 "msghand", thread_func=...) at util/thread.cpp:19
    30[#15](/bitcoin-bitcoin/15/) 0x00000000080e1e81 in std::__invoke_impl<void, void (*)(char const*, std::function<void()>), char const*, CConnman::Start(CScheduler&, const CConnman::Options&)::<lambda()> >(std::__invoke_other, void (*&&)(const char *, std::function<void()>)) (__f=@0x138ce878: 0x8acd442 <util::TraceThread(char const*, std::function<void ()>)>)
    31    at /usr/include/c++/10/bits/invoke.h:60
    32[#16](/bitcoin-bitcoin/16/) 0x00000000080e156c in std::__invoke<void (*)(char const*, std::function<void()>), char const*, CConnman::Start(CScheduler&, const CConnman::Options&)::<lambda()> >(void (*&&)(const char *, std::function<void()>)) (__fn=@0x138ce878: 0x8acd442 <util::TraceThread(char const*, std::function<void ()>)>)
    33    at /usr/include/c++/10/bits/invoke.h:95
    34[#17](/bitcoin-bitcoin/17/) 0x00000000080e103c in std::thread::_Invoker<std::tuple<void (*)(char const*, std::function<void()>), char const*, CConnman::Start(CScheduler&, const CConnman::Options&)::<lambda()> > >::_M_invoke<0, 1, 2>(std::_Index_tuple<0, 1, 2>) (this=0x138ce868) at /usr/include/c++/10/thread:264
    35[#18](/bitcoin-bitcoin/18/) 0x00000000080e0e33 in std::thread::_Invoker<std::tuple<void (*)(char const*, std::function<void()>), char const*, CConnman::Start(CScheduler&, const CConnman::Options&)::<lambda()> > >::operator()(void) (this=0x138ce868) at /usr/include/c++/10/thread:271
    36[#19](/bitcoin-bitcoin/19/) 0x00000000080e0c9f in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(char const*, std::function<void()>), char const*, CConnman::Start(CScheduler&, const CConnman::Options&)::<lambda()> > > >::_M_run(void) (this=0x138ce860) at /usr/include/c++/10/thread:215
    37[#20](/bitcoin-bitcoin/20/) 0x00007fffff3eeed0 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
    38[#21](/bitcoin-bitcoin/21/) 0x00007fffff796ea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
    39[#22](/bitcoin-bitcoin/22/) 0x00007fffff0dddef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
    

    I can resume the execution from gdb, and see that the message handler continues its internal loop again and again, without terminating and releasing its locked mutex that block all other threads needing it. I can interrupt again the program, and I see that the message handler thread is still there, inside a call to ChainstateManager::ProcessNewBlockHeaders(…) which seems to never terminate. Apparently one of its iterator (on std::multimap<CBlockIndex*,CBlockIndex*,CBlockIndex*> at validation.cpp:4412) never finds an end when processing new block headers received (but probably still not in a valid state to be processed, or depending on other blocks that first need to be parsed and can’t if they are exclusively locked by some background thread indexing it, while that other indexing thread wants to lock a mutex owned by the message handler, that cannot return it). This is clearly a deadlock condition: the message handler can hold a lock for an infinite time, and is unable to fix a limit and abort to retry later: its iterators are imperative and must go from start to end of the new headers recieved. That iterator is then unsafe.

    Note: this is still a debug version compiled with the current master branch from git pull. Still running in Debian Bullseye (in a VM, where only a couple of bash sessions, one session for bitcoind and gdb, the second one to use htop, ps -ef…, or bitcoin-cli; the only other processes are in “init” for the kernel).

13. 
    maflcko commented at 7:06 pm on August 23, 2022: member

    Can you try with -checkblockindex=0 (disabled)
14. 
    verdy-p commented at 7:28 pm on August 23, 2022: none

    I have effectively “checkblockindex=1” and “checkmempool=1” in my bitcoin.conf… I also have “checkblock=6” (this is the default anyway) and “checklevel=4” (for the initial check that occurs at startup, but at least it allows repairing the chainstate after I had to “kill -9” after a hang; the default “chacklevel=3” is faster, but does not repair anything, and then we get a fatal corruption of the chainstate, not allowing to terminate the IBD on a full node).
15. 
    verdy-p commented at 7:43 pm on August 23, 2022: none

    See also #16998 already about the deadlock issue reported with “checkblockindex=1” (since september 2019).

    You asked to the reporter to submit a gdb stacktrace, but may be he did not know how to do it. Now you’ve got my stacktrace above.

16. 
    maflcko commented at 5:41 am on August 24, 2022: member

    Ok, so this can be closed as a duplicate of #https://github.com/bitcoin/bitcoin/issues/16998
17. maflcko renamed this:
    Bug "[net_processing.cpp:4381] [CheckForStaleTipAndEvictPeers] Potential stale tip detected" causing indexers to stall Bitcoin for extremely long time
    CheckBlockIndex stalls for extremely long time
    on Aug 24, 2022
18. 
    verdy-p commented at 9:34 am on August 24, 2022: none

    Except that #16998 had no reply since long, for the stacktrace that I proivided here. I can’t be sure that #16998 was a duplicate or is just stalled and shuold have been closed for lack of response, not even a question about how to do it if the reporter wondered how to use gdb (here I may explain how to do it if you can’t attach gdb to an already running process).

    At least here give the source of the bug at [validation.cpp:4412], which cannot work correctly with concurrent threads updating the chainstate (e.g. new block downloaded, or change of best changetip while validating ), because it attempts to parse the whole chain but seems to assume that the best chaintip and more generally its topology cannot change when there are concurrent branches for the last few blocks near the tips

    So the iterator will not terminate by reaching the correct tip: it should terminate when reaching any tip. It does not implement a full tree search and cannot rollback to lower heights to find alternate branches (in my opinion it should explore all branches: if there are several ones, it is beacuse they are concurrent and none of them are validated, so any one good be valid until one of them is validated, and this takes some time (about 10 minutes) to reach a consensus and being informed from the network. However there should be only one branch going from a block at a given height to a block of next height, if that target block is validated; other branches should be pruned according to the consensus rules.

    As well, as long as blocks are still not fully loaded and indexed in the chainstate (this takes hours, maybe several days during IBD for full nodes), we always have multiple tips (one old but validated snice long, and one or several near the end of the chain that we’ve still not indexed, and possibly still not downloaded, and creating more “active” tips).

    For now the code used in “check block index” does not seem to be valid, it is overly optimistic…. or there are some local operations occuring within the “chain” that do not use atomic operations protected by the same global mutex (actually the “chain” is a tree with short branches near the tips, with transactions to be validated and made in at most the last 2 days, i.e. roughly 288 blocks, but the protocol is designed so that concurrent branches should not survive for more then one day, and if the P2P network is correctly connected, those branches may not live for more than 1 hour, i.e. 6 blocks, and most of the time they do not persist for more than 10 minutes, within the last 2 block heights if the local node is fully synchronized).

    The current code for “check block index” cannot work if validators are running or if we have live connections with other peers and we download new blocks announced by them because we’ve requested a set of fresh headers. It may only be safely used when the node is restarting after a shutdown, and before even initiating its IBD phase. Or it could be used when the daemon is shut down, to perform offline analysis and reparation. Or when running the daemon when its “net” is offline and does not open or accept any connection with other peers, and as well it should stop all validators that may change the topology when selecting new tips. That could be initiated by a specific RPC call, that will temporarily suspend all network activity, flush everything as needed, perform check and necessary pruning and that could be also initiated automatically every hour (normally it does not take long, less than one second on my PC, we don’t necessarily need to close all connections, but our local node will stop esponding to other peers, adding some reasonnable delay that will most of the time get unnoticed by others, just seeing some temporary latency). This would avoid loosing data and the need to reindex everything after a crash, notably on full nodes. And we could as well implement a watchdog to “force” the termination of worker threads that take too long (e.g. running for more than 20 minutes), if we have a way to cleanup their memory allocated dynamically in the heap (and not on their stack where they are instantly garbage collected).

19. 
    Sjors commented at 12:55 pm on September 6, 2022: member

    Except that #16998 had no reply since long

    I just closed it.

20. 
    jsarenik commented at 1:19 pm on August 18, 2023: none

    @verdy-p Thank you for reporting this issue in such a detail! I experience it also for some time (running 25 or master). I do txindex and coinstatsindex, see be.anyone.eu.org
21. 
    jsarenik commented at 1:25 pm on August 18, 2023: none

    My workaround is to regularly do

    0pkill -9 -f b-shutoff
    

22. 
    mzumsande commented at 5:42 pm on August 18, 2023: contributor

    I experience it also for some time

    What do you experience? This issue is quite confusing.

    -checkblockindex is a diagnostic tool for the mandatory block index every node maintains. It is debug-only, not part of the bitcoind help and shouldn’t be used under normal circumstances. The checks it does are quite costly, especially when dealing with a long chain of >100k blocks, and especially during IBD because they are executed all the time during that. So they can slow down a node a lot during IBD.

    However, -checkblockindex has absolutely nothing to do with having additional optional indexes like txindex or coinstatsindex - the blockindex is very different from the other indexes (which share a common framework amongst themselves).

23. 
    jsarenik commented at 5:08 am on August 21, 2023: none

    I do not use -checkblockindex but found this issue most related to the symptom of hanging bitcoind process in shutoff phase (src/init.cpp).

    I use blocknotify shell script that runs bitcoin-cli. See I do not use -checkblockindex but found this issue most related to the symptom of hanging bitcoind process in shutoff phase (src/init.cpp).

    I use blocknotify shell script that runs bitcoin-cli. See jsarenik/cls/blocknotify.sh and I supposed a race condition so far (RPC conn of bitcoin-cli open but bitcoind shutting down hangs, not answering it)

24. 
    maflcko commented at 8:20 am on August 21, 2023: member

    @jsarenik Can you reproduce with logging (see #25897 (comment)) and gdb (see #25897 (comment))

    Generally it is best to open a new issue for unrelated issues.

25. 
    maflcko commented at 8:08 am on August 22, 2023: member

    Is this still an issue with a recent version of Bitcoin Core? If yes, what are the steps to reproduce, what does debug logging and what does gdb say?

    Closing for now, but this can be reopened, or a new issue can be filed for unrelated issues.

26. maflcko closed this on Aug 22, 2023

    ---

27. bitcoin locked this on Aug 21, 2024

Contributors
verdy-p maflcko jonatack Sjors jsarenik mzumsande

Labels
Bug