search

braidpool / bitcoin

Bitcoin Core integration/staging tree
https://bitcoincore.org/en/download
MIT License
1 stars 0 forks source link

WARNING submitblock returned inconclusive #1

Open mcelrath opened 2 months ago

mcelrath commented 2 months ago

Is there an existing issue for this?

Current behaviour

Sometimes submitted blocks are not accepted by bitcoin core, logging "inconclusive". The header seems to be accepted by bitcoin but not connected as a block tip. This message is generated in src/bitcoin-chainstate.cpp and seems to indicate that block.GetHash() does not match the passed in parameter to submitblock_StateCatcher. This is very very odd because at the point it's called, it's called with just submitblock_StateCatcher(block.GetHash()) which is compared directly against block.GetHash().

I've seen this twice, and increased logging verbosity to try to find the error.

Restarting bitcoind caused it to connect this block as a block tip without resubmitting it.

Expected behaviour

.

Steps to reproduce

.

Relevant log output

contrib/cpunet/miner output:

2024-08-22 09:32:11 WARNING submitblock returned inconclusive for height 400 hash                 00000000937214fdfb13ccd45f4e3170db7e441182efcaffc964e68aef70170c
2024-08-22 09:32:11 INFO Mined a block solution at height 400 with hash:                          00000000937214fdfb13ccd45f4e3170db7e441182efcaffc964e68aef70170c
2024-08-22 09:32:11 INFO Mining Block: CBlock(nVersion=536870912                                  hashPrevBlock=000000002845d58dd229549bd64ac99e862e36052133de5da1f9e4afa0c0dcc6                    hashMerkleRoot=93979a6fe58fe2baed50f01e8faa8f3281a6d6072d456cfd9410297f80ea5678 nTime=Thu Aug 22  09:32:11 2024 nBits=1d00ffff nNonce=00000000 vtx=[CTransaction(version=2                          vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=029101 nSequence=4294967294)] vout=[CTxOut(nValue=50.00000000            scriptPubKey=0014314b346296a361d3e349edf0d0879be8095a68d5)] wit=CTxWitness() nLockTime=0)])

debug.log output:

2024-08-22T13:32:11Z Saw new header                                                               hash=00000000937214fdfb13ccd45f4e3170db7e441182efcaffc964e68aef70170c height=400

How did you obtain Bitcoin Core

Compiled from source

What version of Bitcoin Core are you using?

Bitcoin Core version v27.99.0-e8b157f687eb-dirty from cpunet branch

Operating system and version

Arch Linux 6.10.5-zen1-1-zen #1 ZEN SMP PREEMPT_DYNAMIC

Machine specifications

8 core AMD Ryzen

mcelrath commented 2 months ago

This "inconclusive" means it's an orphan. It looks like Bitcoin is not sending the UpdateTip ZMQ message. In the log below the miner starts mining at 9:40:05 local time and a new block comes in at 9:44:55 local time (13:44:55Z) and then the grind command finishes (successfully) at 9:45:34 local time. Since the miner script DOES process the ZMQ ConnectTip message, ("sequence C"), this indicates that bitcoind did not send us the ZMQ message, which, had we received it, the miner script would have stopped the existing mining process and started a new one with the new tip.

Bitcoin's log shows

2024-09-05T13:44:55Z Saw new header hash=0000000036968631c19291d914141e99d1cf0312481ee8394d8e65314
c268d51 height=984
2024-09-05T13:44:55Z UpdateTip: new best=0000000036968631c19291d914141e99d1cf0312481ee8394d8e65314
c268d51 height=984 version=0x20000000 log2_work=41.944002 tx=985 date='2024-09-05T13:40:05Z' progr
ess=1.000000 cache=0.3MiB(72txo)
2024-09-05T13:45:34Z Saw new header hash=00000000aa32745da6f8d44c7fccd597060ed51ac0d33c5caf7bcca06

while the miner log shows:

2024-09-05 09:40:05 DEBUG Calling grind command: 'src/bitcoin-util -cpunet -ntasks=8 grind 0000002
0fad74eae053b0eb367c270b6c1ff169b1451feeec3a501ed2129d096000000009405e820ed0e1cd37eff4427b17dc3347
60ebe13e180a0400ad53d68f69fd78bb5b4d966ffff001d00000000'
2024-09-05 09:45:34 DEBUG Calling bitcoin-cli: 'src/bitcoin-cli -cpunet -stdin submitblock'
2024-09-05 09:45:34 DEBUG     with input=b'00000020fad74eae053b0eb367c270b6c1ff169b1451feeec3a501e
d2129d096000000009405e820ed0e1cd37eff4427b17dc334760ebe13e180a0400ad53d68f69fd78bb5b4d966ffff001df
97c77db0102000000010000000000000000000000000000000000000000000000000000000000000000ffffffff0302d80
3feffffff0100f2052a0100000016001478749cbc210732b480fa9dfa981bc41c56d0422e00000000'
2024-09-05 09:45:34 DEBUG     result = b'inconclusive\n'
mcelrath commented 2 months ago

Running now with some more debug output on ZMQ messages to see if it was sent but we didn't decode it properly. Next step is to see if there's a race condition in bitcoind that might cause the UpdateTip ZMQ message to not be sent for some reason.

mcelrath commented 1 month ago

Saw another one. Bitcoin's log shows:

2024-09-06T15:51:35Z Saw new header hash=0000000003a0ad6b58bf45a5346aec558242c0b20577b5efdeaddd6a655a7026 height=1063
2024-09-06T15:51:35Z Saw new cmpctblock header hash=0000000003a0ad6b58bf45a5346aec558242c0b20577b5efdeaddd6a655a7026 peer=0
2024-09-06T15:51:35Z UpdateTip: new best=0000000003a0ad6b58bf45a5346aec558242c0b20577b5efdeaddd6a655a7026 height=1063 version=0x20000000 log2_work=42.055304 tx=1064 date='2024-09-06T15:48:12Z' progress=1.000000 cache=0.3MiB(25txo)
2024-09-06T15:54:31Z Saw new header hash=00000000c7d7e2c6d524d8b02472dc94144b3113f7ccf8b6d5baf405c47b1b2c height=1063

while miner.log shows:

2024-09-06 11:48:12 DEBUG Calling grind command: 'src/bitcoin-util -cpunet -ntasks=8 grind 0000002
007bf0812a1d78e8a34f03a50365aeeea71ba7f74ea6073a31fc0c9d00000000065e75ba787cde4720fe866b1708af8196
24ee53fba87e8c001704866bf5b8ef83c24db66ffff001d00000000'
2024-09-06 11:54:31 DEBUG Calling bitcoin-cli: 'src/bitcoin-cli -cpunet -stdin submitblock'
2024-09-06 11:54:31 DEBUG     with input=b'0000002007bf0812a1d78e8a34f03a50365aeeea71ba7f74ea6073a
31fc0c9d00000000065e75ba787cde4720fe866b1708af819624ee53fba87e8c001704866bf5b8ef83c24db66ffff001dd
d1aa4f80102000000010000000000000000000000000000000000000000000000000000000000000000ffffffff0302270
4feffffff0100f2052a010000001600146b885d00449707d1da384fba80745f3ef61335cf00000000'
2024-09-06 11:54:31 DEBUG     result = b'inconclusive\n'
2024-09-06 11:54:31 DEBUG     stdout = b'inconclusive\n'
2024-09-06 11:54:31 DEBUG     stderr = b''
2024-09-06 11:54:31 DEBUG Submitting block: 0000002007bf0812a1d78e8a34f03a50365aeeea71ba7f74ea6073
a31fc0c9d00000000065e75ba787cde4720fe866b1708af819624ee53fba87e8c001704866bf5b8ef83c24db66ffff001d
dd1aa4f80102000000010000000000000000000000000000000000000000000000000000000000000000ffffffff030227
04feffffff0100f2052a010000001600146b885d00449707d1da384fba80745f3ef61335cf00000000
2024-09-06 11:54:31 WARNING submitblock returned inconclusive for height 1063 hash 00000000c7d7e2c
6d524d8b02472dc94144b3113f7ccf8b6d5baf405c47b1b2c

I had subscribed to the hashblock and rawblock messages and added logging for them as well as for if an unexpected sequence message was received. It seems bitcoind emitted none of these at 11:51:35 local time when the new block was received from an external source. 3 minutes later at 11:54:31 local time the local miner generated a stale block. :-/

Not sure what is causing this. At this point it looks like a bug in bitcoind's ZMQ implementation...

I wonder if the ZMQ socket got closed? I'll investigate that next.

mcelrath commented 1 month ago

Seen again.

The ZMQ socket is not closed when the "inconclusive" message is received.

mcelrath commented 1 month ago

Well saw it again, reopening.

Bitcoin's log:

2024-09-10T13:09:32Z UpdateTip: new best=000000006a9759d25bf63fac080d56004e77ba872732da25a5985fca2
1a21acf height=1200 version=0x20000000 log2_work=42.230042 tx=1201 date='2024-09-10T11:48:15Z' pro
gress=1.000000 cache=0.3MiB(122txo)
2024-09-10T13:09:32Z New outbound-full-relay v2 peer connected: version: 70016, blocks=1200, peer=
37
2024-09-10T13:09:58Z Saw new header hash=00000000ce8f148b78bde71112a8795c01fce216a1ea58f862ef444e0
f34aae3 height=1200

Miner log:

2024-09-10 09:09:32 INFO Connected new block tip 000000006a9759d25bf63fac080d56004e77ba872732da25a
5985fca21a21acf
2024-09-10 09:09:32 DEBUG     result = b'{\n  "capabilities": [\n    "proposal"\n  ],\n  "version"
: 536870912,\n  "rules": [\n    "csv",\n    "!segwit",\n    "taproot"\n  ],\n  "vbavailable": {\n 
 },\n  "vbrequired": 0,\n  "previousblockhash": "00000000f5b91658bab675da8d994065ac8f0ef17ba11251e
f2d474534e93de6",\n  "transactions": [\n  ],\n  "coinbaseaux": {\n  },\n  "coinbasevalue": 5000000
000,\n  "longpollid": "00000000f5b91658bab675da8d994065ac8f0ef17ba11251ef2d474534e93de6128",\n  "t
arget": "00000000ffff0000000000000000000000000000000000000000000000000000",\n  "mintime": 17259185
11,\n  "mutable": [\n    "time",\n    "transactions",\n    "prevblock"\n  ],\n  "noncerange": "000
00000ffffffff",\n  "sigoplimit": 80000,\n  "sizelimit": 4000000,\n  "weightlimit": 4000000,\n  "cu
rtime": 1725973772,\n  "bits": "1d00ffff",\n  "height": 1200,\n  "default_witness_commitment": "6a
24aa21a9ede2f61c3f71d1defd3fa999dfa36953755c690689799962b48bebd836974e8cf9"\n}\n'
2024-09-10 09:09:32 DEBUG     stdout = b'{\n  "capabilities": [\n    "proposal"\n  ],\n  "version"
: 536870912,\n  "rules": [\n    "csv",\n    "!segwit",\n    "taproot"\n  ],\n  "vbavailable": {\n 
 },\n  "vbrequired": 0,\n  "previousblockhash": "00000000f5b91658bab675da8d994065ac8f0ef17ba11251e
f2d474534e93de6",\n  "transactions": [\n  ],\n  "coinbaseaux": {\n  },\n  "coinbasevalue": 5000000
000,\n  "longpollid": "00000000f5b91658bab675da8d994065ac8f0ef17ba11251ef2d474534e93de6128",\n  "target": "00000000ffff0000000000000000000000000000000000000000000000000000",\n  "mintime": 1725918511,\n  "mutable": [\n    "time",\n    "transactions",\n    "prevblock"\n  ],\n  "noncerange": "00000000ffffffff",\n  "sigoplimit": 80000,\n  "sizelimit": 4000000,\n  "weightlimit": 4000000,\n  "curtime": 1725973772,\n  "bits": "1d00ffff",\n  "height": 1200,\n  "default_witness_commitment": "6a24aa21a9ede2f61c3f71d1defd3fa999dfa36953755c690689799962b48bebd836974e8cf9"\n}\n'
2024-09-10 09:09:32 DEBUG     stderr = b''
2024-09-10 09:09:32 DEBUG GBT template: {'capabilities': ['proposal'], 'version': 536870912, 'rules': ['csv', '!segwit', 'taproot'], 'vbavailable': {}, 'vbrequired': 0, 'previousblockhash': '00000000f5b91658bab675da8d994065ac8f0ef17ba11251ef2d474534e93de6', 'transactions': [], 'coinbaseaux': {}, 'coinbasevalue': 5000000000, 'longpollid': '00000000f5b91658bab675da8d994065ac8f0ef17ba11251ef2d474534e93de6128', 'target': '00000000ffff0000000000000000000000000000000000000000000000000000', 'mintime': 1725918511, 'mutable': ['time', 'transactions', 'prevblock'], 'noncerange': '00000000ffffffff', 'sigoplimit': 80000, 'sizelimit': 4000000, 'weightlimit': 4000000, 'curtime': 1725973772, 'bits': '1d00ffff', 'height': 1200, 'default_witness_commitment': '6a24aa21a9ede2f61c3f71d1defd3fa999dfa36953755c690689799962b48bebd836974e8cf9'}
2024-09-10 09:09:32 INFO Mining Block: CBlock(nVersion=536870912 hashPrevBlock=00000000f5b91658bab675da8d994065ac8f0ef17ba11251ef2d474534e93de6 hashMerkleRoot=fa9bb457513b1bdb012d73f1f0112be95e0f624bd7e35a7a8b0ed09cedf2e161 nTime=Tue Sep 10 09:09:32 2024 nBits=1d00ffff nNonce=00000000 vtx=[CTransaction(version=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=02b004 nSequence=4294967294)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=0014545cb26ee5771cf33af26d18c84694b8e6c24b5c)] wit=CTxWitness() nLockTime=0)])
2024-09-10 09:09:32 DEBUG Calling grind command: 'src/bitcoin-util -cpunet -ntasks=8 grind 00000020e63de93445472def5112a17bf10e8fac6540998dda75b6ba5816b9f50000000061e1f2ed9cd00e8b7a5ae3d74b620f5ee92b11f0f1732d01db1b3b5157b49bfa0c45e066ffff001d00000000'
2024-09-10 09:09:58 DEBUG Calling bitcoin-cli: 'src/bitcoin-cli -cpunet -stdin submitblock'
2024-09-10 09:09:58 DEBUG     with input=b'00000020e63de93445472def5112a17bf10e8fac6540998dda75b6ba5816b9f50000000061e1f2ed9cd00e8b7a5ae3d74b620f5ee92b11f0f1732d01db1b3b5157b49bfa0c45e066ffff001d5140ca100102000000010000000000000000000000000000000000000000000000000000000000000000ffffffff0302b004feffffff0100f2052a01000000160014545cb26ee5771cf33af26d18c84694b8e6c24b5c00000000'
2024-09-10 09:09:58 DEBUG     result = b'inconclusive\n'
2024-09-10 09:09:58 DEBUG     stdout = b'inconclusive\n'
2024-09-10 09:09:58 DEBUG     stderr = b''
2024-09-10 09:09:58 DEBUG Submitting block: 00000020e63de93445472def5112a17bf10e8fac6540998dda75b6ba5816b9f50000000061e1f2ed9cd00e8b7a5ae3d74b620f5ee92b11f0f1732d01db1b3b5157b49bfa0c45e066ffff001d5140ca100102000000010000000000000000000000000000000000000000000000000000000000000000ffffffff0302b004feffffff0100f2052a01000000160014545cb26ee5771cf33af26d18c84694b8e6c24b5c00000000
2024-09-10 09:09:58 WARNING submitblock returned inconclusive for height 1200 hash 00000000ce8f148b78bde71112a8795c01fce216a1ea58f862ef444e0f34aae3
2024-09-10 09:09:58 INFO Mined a block solution at height 1200 with hash: 00000000ce8f148b78bde71112a8795c01fce216a1ea58f862ef444e0f34aae3
2024-09-10 09:09:58 DEBUG Block hash 00000000ce8f148b78bde71112a8795c01fce216a1ea58f862ef444e0f34aae3 payout to tc1q23wtymh9wuw0xwhjd5vvs355hrnvyj6u8hs7ey
2024-09-10 09:09:58 DEBUG Solved block is CBlock(nVersion=536870912 hashPrevBlock=00000000f5b91658bab675da8d994065ac8f0ef17ba11251ef2d474534e93de6 hashMerkleRoot=fa9bb457513b1bdb012d73f1f0112be95e0f624bd7e35a7a8b0ed09cedf2e161 nTime=Tue Sep 10 09:09:32 2024 nBits=1d00ffff nNonce=10ca4051 vtx=[CTransaction(version=2 vin=[CTxIn(prevout=COutPoint(hash=0000000000000000000000000000000000000000000000000000000000000000 n=4294967295) scriptSig=02b004 nSequence=4294967294)] vout=[CTxOut(nValue=50.00000000 scriptPubKey=0014545cb26ee5771cf33af26d18c84694b8e6c24b5c)] wit=CTxWitness() nLockTime=0)])

At :32:09 we were notified over ZMQ of connection of a new block tip, and correctly restarted the mining process. We then immediately call getblocktemplate and we get a block with 00000000f5b91658bab675da8d994065ac8f0ef17ba11251e as the previous block hash, instead of the newly-seen (height 1200) block 000000006a9759d25bf63fac080d56004e77ba872732da25a.

Therefore this is a race condition in Bitcoin between the ZMQ notification and getblocktemplate returning a result with the updated information.

mcelrath commented 1 month ago

Why is there a new peer connection in the middle of that? The miner script does not make peer connections nor spin up/down bitcoind peer nodes.