Testnet Error Validating Block 872730 (v4, DEVELOPMENT)

[JasonCoombs]

Trying to debug this error condition on testnet (extra debug logging added) -- is this a known issue?

Does it look like the block organizer is failing on block 872,729 or is handle_accept being called on those three parallel threads (thread ids 0x700006a9c000, 0x700006996000, 0x700006913000) to process the three newly-received blocks (875420, 872743, 875370) and is the first attempt by header_organizer to handle_accept() which encounters error bitcoin:5 missing block parent causing the "store is now corrupt" condition? Adding thread id to each debug log message has been helping me trace program flow and figure out which thread is responsible, but I haven't added thread id here yet and wonder if there is any existing knowledge about this particular testnet error condition or block.

16:18:03.892302 INFO [node] Block #872729 (00) [0000000000000a17e01273a1399d3bcf53f1dbbe2a799b43d4a46538b8ae97a2] 000.000 00.00% 121
16:18:03.915318 INFO [node] Block #875420 (06) [000000005c3af6b0824371cd205372c256317474dbf91a1c4c71eb0bb7e912ba] 000.006 00.49% 121
16:18:03.948691 INFO [blockchain] Organized blocks [872729-872729]
16:18:04.066179 INFO [node] Block #872743 (00) [00000000ea2c44c2dc5eab6dbe0b998642766ed1292ae96ce51f28e7e24de279] 000.000 00.00% 120
16:18:04.560409 FATAL [blockchain] Failure in block organization, store is now corrupt: operation failed
16:18:04.560472 FATAL [blockchain] 0x700006a9c000 error header_organizer::handle_accept()  error_code = bitcoin:5 missing block parent
16:18:04.560840 INFO [node] Block #875370 (03) [000000000501702a60f618058d25bf22f6f1fac4d185b4b5cd862aebe24e718f] 000.000 00.00% 119
16:18:04.560946 FATAL [blockchain] 0x700006996000 error header_organizer::handle_accept()  error_code = bitcoin:5 missing block parent
16:18:04.641315 FATAL [blockchain] 0x700006913000 error header_organizer::handle_accept()  error_code = bitcoin:5 missing block parent
16:18:04.801483 ERROR [node] Internal failure generating block locator for [35.192.190.35:18333] object does not exist
16:18:04.804414 INFO [node] Block #875380 (03) [0000000030e7c4d94f0cc964730e71708a9de8f8101db0ab36687ce8584c200f] 000.000 00.00% 117
16:18:04.805649 INFO [node] Block #875389 (03) [000000001ddd92315e9207598b4b3449bb0064026c4f60e3a3eb4431a6664388] 000.021 00.10% 116
16:18:04.805857 INFO [node] Block #875398 (03) [0000000033cc256e719433a6f3292c4bda80a84b0cb4f87aaae8b3714b2481fc] 000.028 00.11% 115
16:18:04.805990 INFO [node] Block #875407 (03) [000000000fde7a6c22c119647583eadea4e43305d88f0a115c4b24600f8c8c1b] 000.035 00.12% 114
16:18:04.809475 ERROR [node] Internal failure generating block locator for [145.239.6.138:18333] object does not exist
16:18:04.815718 ERROR [node] Internal failure generating block locator for [58.35.77.155:18333] object does not exist
16:18:04.933441 INFO [node] Block #875416 (03) [0000000026488fc37fb963e3ece0f02d6d4f58e18cfc46d32f77ac0a64121b91] 000.000 00.00% 113
16:18:05.071772 INFO [node] Block #872758 (00) [000000008bd1c23a25d1e01c634764735eec76111ea4ba414533976197c7e023] 000.000 00.00% 113
16:18:06.099880 INFO [network] Connected outbound channel [68.168.122.2:18333] (1)
16:18:06.099981 ERROR [node] Internal failure generating block locator for [68.168.122.2:18333] object does not exist

[evoskuil]

If the parent is missing during validation it is not a known issue.

[JasonCoombs]

Started seeing "missing block parent" error on mainnet, and after adding additional debug logging, it is clear that the following header hash is not found:

00000000470b9e0dd4f6fb72c93e0c655f68069899a5b2a0b4e413ef8006469a

This is the umkoin genesis block.

http://blockexplorer.umkoin.org/en/blockexplorer.php?net=mainnet&block=0

What mechanism do we currently have in place to forcefully drop bad peers?

[JasonCoombs]

Also seeing Orphan header errors from the blocks supplied by the same peer, and of course they are the umkoin blockchain blocks. e.g.

http://blockexplorer.umkoin.org/en/blockexplorer.php?net=mainnet&block=0000000053d3d3b583afbe4751ca900a4facdfbe4c12f03c1a96d17889e84b3e

as an immediate work-around for my other debugging work I'm just going to blacklist the peer: 62.182.124.202

but we will need an improvement to bad peer handling. what do you recommend?

[JasonCoombs]

Here's another umkoin node, and note how we presume its blocks to be a potential chain fork:

19:40:36.400769 DEBUG [node] 0x70000efd3000 protocol_header_in::handle_store_header() Orphan header [0000000053d3d3b583afbe4751ca900a4facdfbe4c12f03c1a96d17889e84b3e] from [82.193.103.110:6333] missing block parent
19:40:36.400915 DEBUG [node] Ask [82.193.103.110:6333] for headers from [0000000000000421a264b2a6b2535d5cd0e628f16ddf86f27f5fb34eb3667a7e] through [0000000053d3d3b583afbe4751ca900a4facdfbe4c12f03c1a96d17889e84b3e]

[JasonCoombs]

Is this a different error at block height 872730 ?? Immediately after 872729 was organized, this:

23:04:18.738879 INFO [blockchain] 0x700004774000 Organized blocks [872729-872729]
23:04:18.739733 DEBUG [blockchain] 0x700004774000 Got next block #872730
23:04:18.744248 DEBUG [blockchain] Verify failed [872730] : invalid witness
 libconsensus : false
 forks        : 16382
 outpoint     : 1b9e1323923508ecc3d097f11aeaa66acbe6a6d3c4ea6b25d57d34ee9c8d660d:0
 script       : a914e5a679f81579cbf20bb2a4764be9e95e8b3e396787
 value        : 100000000
 inpoint      : 118c83b2c7aa4b500e0c0333dbfef990ca6c324004d68f68acb10ddada918474:0
 transaction  : 01000000020d668d9cee347dd5256beac4d3a6e6cb6aa6ea1af197d0c3ec08359223139e1b00000000171600143f0402fcb8beef28a89be7e94794ec66d469fdb6feffffff0d668d9cee347dd5256beac4d3a6e6cb6aa6ea1af197d0c3ec08359223139e1b010000006b483045022100eaceee00202693d7d54aa84bd8b216f62b1f041b16e08e0352eb1ed50f1ef10102201a90288f667f975cc8d524431d61bd8b15f5d189610d31a9bd12ee37c0674f06012103c4561ce27291b1730e5a429934f45fb4ff9b56e24b6e10e0d176f198fa029671feffffff02506c9800000000001976a9140af575373dad17150d91b6a191a371b59e09d87f88ac001c4e0e0000000017a91403572c975aec5228c0e2982ef8a03b6830e0554f8719510d00
23:04:19.687191 DEBUG [node] Maximal (1) not found.

[JasonCoombs]

This invalid witness error was probably the original cause of the error encountered three days ago.

#381 (comment)

That log excerpt was from the console output not from the debug log file.

We then had a bit of a tropical storm here and the power went out. Then I wiped the log files and started over, so didn't end up seeing the debug log file for this until now.

[JasonCoombs]

This looks relevant: https://bitcointalk.org/index.php?topic=2052851.0

Perhaps we aren't doing this decoding correctly, when a segwit and non-segwit input are redeemed?

By bip141 rules, when a segwit input and a non segwit input are redeemed in the same transaction, the non-segwit input will have an empty witness.  That is the single 0x00 byte that tells you "this is a witness stack of 0 items"

https://drive.google.com/file/d/0B7E799YMGCWTc3BUNFNndUVLS2c/view

[JasonCoombs]

https://testnet.blockchain.info/tx/118c83b2c7aa4b500e0c0333dbfef990ca6c324004d68f68acb10ddada918474

This is how bx 3.4.0 decodes the tx:

$ bx tx-decode 01000000020d668d9cee347dd5256beac4d3a6e6cb6aa6ea1af197d0c3ec08359223139e1b00000000171600143f0402fcb8beef28a89be7e94794ec66d469fdb6feffffff0d668d9cee347dd5256beac4d3a6e6cb6aa6ea1af197d0c3ec08359223139e1b010000006b483045022100eaceee00202693d7d54aa84bd8b216f62b1f041b16e08e0352eb1ed50f1ef10102201a90288f667f975cc8d524431d61bd8b15f5d189610d31a9bd12ee37c0674f06012103c4561ce27291b1730e5a429934f45fb4ff9b56e24b6e10e0d176f198fa029671feffffff02506c9800000000001976a9140af575373dad17150d91b6a191a371b59e09d87f88ac001c4e0e0000000017a91403572c975aec5228c0e2982ef8a03b6830e0554f8719510d00
transaction
{
    hash 118c83b2c7aa4b500e0c0333dbfef990ca6c324004d68f68acb10ddada918474
    inputs
    {
        input
        {
            address_hash e5a679f81579cbf20bb2a4764be9e95e8b3e3967
            previous_output
            {
                hash 1b9e1323923508ecc3d097f11aeaa66acbe6a6d3c4ea6b25d57d34ee9c8d660d
                index 0
            }
            script [00143f0402fcb8beef28a89be7e94794ec66d469fdb6]
            sequence 4294967294
        }
        input
        {
            address_hash e95f772e516a0bb68141e845483e23bc28acd29b
            previous_output
            {
                hash 1b9e1323923508ecc3d097f11aeaa66acbe6a6d3c4ea6b25d57d34ee9c8d660d
                index 1
            }
            script "[3045022100eaceee00202693d7d54aa84bd8b216f62b1f041b16e08e0352eb1ed50f1ef10102201a90288f667f975cc8d524431d61bd8b15f5d189610d31a9bd12ee37c0674f0601] [03c4561ce27291b1730e5a429934f45fb4ff9b56e24b6e10e0d176f198fa029671]"
            sequence 4294967294
        }
    }
    lock_time 872729
    outputs
    {
        output
        {
            address_hash 0af575373dad17150d91b6a191a371b59e09d87f
            script "dup hash160 [0af575373dad17150d91b6a191a371b59e09d87f] equalverify checksig"
            value 9989200
        }
        output
        {
            address_hash 03572c975aec5228c0e2982ef8a03b6830e0554f
            script "hash160 [03572c975aec5228c0e2982ef8a03b6830e0554f] equal"
            value 240000000
        }
    }
    version 1
}

[JasonCoombs]

The invalid_witness error appears to originate from this mistake of implementation of bip141:

https://github.com/libbitcoin/libbitcoin/blob/master/src/chain/witness.cpp#L444

As described here:

#381 (comment)

[evoskuil]

Please explain why you think the implementation is invalid.

[evoskuil]

A missing parent is not presumed to be a chain fork. It only implies we are missing one or more intervening blocks, on the strong chain or otherwise.

[evoskuil]

The mechanism to drop bad peers is to disconnect the channel. Determining whether a peer is bad is another question. Bad can only imply violation of protocol (objective) or resource overconsumption (subjective).

[evoskuil]

A missing parent during a header store is a logic error in our code, or a corrupt database. This is not at all the same as an orphan header received from a peer, which is normal and expected.

[JasonCoombs]

Did you read the bitcointalk discussion about this block and its transaction 44? Ordinarily there is at least one witness, but in this case it appears to be valid for witness length to be zero.

As a result of the invalid_witness error the correct block is never validated, which causes every subsequent block to produce a missing parent condition. This condition will never end, libbitcoin will never be able to validate another block, because we don't consider the correct block to be valid.

[JasonCoombs]

#381 (comment)

My point, above, about umkoin's errant nodes and the blocks being offered, accepted, and validated except for the missing parent error, is that in this case a missing parent should not be considered expected and normal. Do we really want libbitcoin to store the entire umkoin blockchain and every block of every other BTC fork that doesn't bother to differentiate its novel chain in some way? Accepting and storing umkoin blocks, waiting to some day receive their parents and do a chain reorg for BTC, should not be a thing.

http://www.umkoin.org/en/faq.php#who-created-umkoin