log: print unexpected version warning in validation log category

n-thumann commented at 4:38 pm on September 6, 2020: contributor

Fixes #19603: As suggested by practicalswift, instead of always printing <n> of the last 100 blocks have unexpected version as a warning appended to UpdateTip, it is now printed in the validation log category and therefore only visible with -debug=validation enabled.

Before: 2020-09-06T15:56:00Z UpdateTip: new best=00000000000000000001b2872e107a98b57913120e5c6c87ce2715a34c40adf8 height=646969 version=0x20400000 log2_work=92.261571 tx=565651941 date='2020-09-06T10:35:36Z' progress=0.999888 cache=32.2MiB(237417txo) warning='72 of last 100 blocks have unexpected version' After: 2020-09-06T16:31:26Z UpdateTip: new best=0000000000000000000b3bd786dc42745dd7be4a8c695500a04518cb9e2f4dc1 height=646971 version=0x20000000 log2_work=92.261607 tx=565655901 date='2020-09-06T10:57:19Z' progress=0.999883 cache=3.8MiB(27550txo) 2020-09-06T16:31:26Z 71 of last 100 blocks have unexpected version

Ran unit & functional tests, confirmed that the warning is now only printed when validation category is enabled.

n-thumann force-pushed on Sep 6, 2020

in src/validation.cpp:2477 in 0c02dcb854 outdated

2474       FormatISO8601DateTime(pindexNew->GetBlockTime()),
2475       GuessVerificationProgress(chainParams.TxData(), pindexNew), ::ChainstateActive().CoinsTip().DynamicMemoryUsage() * (1.0 / (1<<20)), ::ChainstateActive().CoinsTip().GetCacheSize(),
2476       !warning_messages.empty() ? strprintf(" warning='%s'", warning_messages.original) : "");
2477+
2478+    if (nUpgraded > 0)
2479+        LogPrint(BCLog::VALIDATION, "%d of last 100 blocks have unexpected version\n", nUpgraded);

hebasto commented at 4:55 pm on September 6, 2020:

Please follow code style for new code:

0    if (nUpgraded > 0) {
1        LogPrint(BCLog::VALIDATION, "%d of last 100 blocks have unexpected version\n", nUpgraded);
2    }

n-thumann commented at 5:38 pm on September 6, 2020:

thanks, done :)

hebasto commented at 4:58 pm on September 6, 2020: member

Concept ACK.

It seems out of scope of this PR, but I think the name nUpgraded is a bit misleading now.

n-thumann force-pushed on Sep 6, 2020

laanwj added the label Utils/log/libs on Sep 6, 2020

laanwj added the label Validation on Sep 6, 2020

pox commented at 7:10 pm on September 6, 2020: contributor

A blessed change!

Tested on Ubuntu by observing logs with default logging:

02020-09-06T19:01:17Z UpdateTip: new best=0000000000000000000c35da7da08dd7b1521a3ffcbe9efb5e8eedde53d7896b height=647000 version=0x20000000 log2_work=92.262139 tx=565693850 date='2020-09-06T13:53:09Z' progress=0.999892 cache=1.7MiB(12481txo)
12020-09-06T19:02:51Z UpdateTip: new best=0000000000000000000c5a85e128e2a1b6ef8df242c68e3284a5ac29ecaa159a height=647001 version=0x2000e000 log2_work=92.262157 tx=565694885 date='2020-09-06T13:53:38Z' progress=0.999892 cache=3.0MiB(22258txo)
22020-09-06T19:03:27Z UpdateTip: new best=00000000000000000008e73bdaca4a47cd3926d1dcc728238cb7de2bddd014c0 height=647002 version=0x20c00000 log2_work=92.262175 tx=565696981 date='2020-09-06T14:05:46Z' progress=0.999896 cache=4.3MiB(32499txo)
32020-09-06T19:03:57Z UpdateTip: new best=0000000000000000000d2b11cc472ca88e0e84fc9fdf210eff1378ab6f6191fd height=647003 version=0x37ffe000 log2_work=92.262194 tx=565699661 date='2020-09-06T14:22:45Z' progress=0.999901 cache=5.9MiB(43169txo)
42020-09-06T19:04:21Z UpdateTip: new best=0000000000000000000b39032cc59ffe754832bfb7b1bef4dee75a5bef0be502 height=647004 version=0x20000000 log2_work=92.262212 tx=565702102 date='2020-09-06T14:34:51Z' progress=0.999906 cache=7.2MiB(53849txo)

And with -debug=validation:

02020-09-06T19:08:55Z BlockChecked: block hash=0000000000000000000952b5504198cd2cb4d94041f09e3c81ae42ed3bb691c0 state=Valid
12020-09-06T19:08:55Z UpdateTip: new best=0000000000000000000952b5504198cd2cb4d94041f09e3c81ae42ed3bb691c0 height=647025 version=0x20400000 log2_work=92.262597 tx=565750210 date='2020-09-06T18:26:24Z' progress=0.999985 cache=26.4MiB(193591txo)
22020-09-06T19:08:55Z 63 of last 100 blocks have unexpected version
32020-09-06T19:08:55Z Enqueuing BlockConnected: block hash=0000000000000000000952b5504198cd2cb4d94041f09e3c81ae42ed3bb691c0 block height=647025
42020-09-06T19:08:55Z Enqueuing UpdatedBlockTip: new block hash=0000000000000000000952b5504198cd2cb4d94041f09e3c81ae42ed3bb691c0 fork block hash=0000000000000000000d235796b5fbc3df24499d78fcfa4e2ac77173d413de15 (in IBD=false)

practicalswift commented at 8:52 pm on September 6, 2020: contributor

Concept ACK

Thanks a lot for addressing this: this is causing a lot of unnecessary confusion for our users.

Our users are not helped by permanent warnings that are not actionable.

practicalswift commented at 7:35 pm on September 7, 2020: contributor

Tested ACK 7edc0689fad41cfee2830b89dc8331d19747eb5f

hebasto approved

hebasto commented at 10:12 am on September 8, 2020: member

ACK 7edc0689fad41cfee2830b89dc8331d19747eb5f, tested on Linux Mint 20 (x86_64) with and without -debug=validation command line option.

I think it is ok to do not translate log messages. bitcoinstrings.cpp will be updated automaGically.

laanwj commented at 10:45 am on September 8, 2020: member

Our users are not helped by permanent warnings that are not actionable.

I’ve tried to make this point about this log message, but from what I remember I got a lot of pushback last time. But I still agree. ACK 7edc0689fad41cfee2830b89dc8331d19747eb5f

I think it is ok to do not translate log messages. bitcoinstrings.cpp will be updated automaGically.

Yes, this was a pointless translation, good to see it go. It looks like the other one is translated because it can also end up in the GUI warnings, but this one couldn’t anyway.

in src/validation.cpp:2444 in 7edc0689fa outdated

2440@@ -2441,9 +2441,9 @@ static void UpdateTip(CTxMemPool& mempool, const CBlockIndex* pindexNew, const C
2441     }
2442 
2443     bilingual_str warning_messages;
2444+    int nUpgraded = 0;

MarcoFalke commented at 10:53 am on September 9, 2020:

When changing all places where this is used, might as well change the name to something more useful. This doesn’t count blocks (or miners) that are upgraded. It counts the number of blocks that have an unexpected version. E.g. a non-bip9 version or an unexpected bip9 deployment. Though, with asic boost, this might happen even if all nodes run the same version.

0    int num_unexpected_version = 0;

n-thumann commented at 6:57 pm on September 9, 2020:

good point, done

MarcoFalke commented at 11:24 am on September 9, 2020: member

ACK 7edc0689fad41cfee2830b89dc8331d19747eb5f

If a softfork is deployed without a BIP9 versionbits compatible warning, it is impossible to write code in advance to detect that scenario with full accuracy. A softfork deployment without a versionbits compatible warning (and especially one that would require most users to upgrade on a short notice) is reckless at best. Putting code into Bitcoin Core to encourage short notice “forced” upgrades seems counter-productive.

Also, the warning is disabled for users that sync up their nodes intermittently (e.g. once a day or once a week).

Finally, for the remaining well prepared users that:

Run a node 24/7
Have -debug or -debug=validation enabled
Read the debug.log I’d be surprised if this warning had any more impact on their decision to upgrade to a newer version or look out for new versions than the already existing release announcements and our well-known (?) EOL policy.

So I’d say to simply remove this warning.

log: print unexpected version warning in validation log category

Instead of printing "<n> of the last 100 blocks have unexpected version"
as a warning appended to UpdateTip, it is now printed in the validation
log category.

62dba9628d

n-thumann force-pushed on Sep 9, 2020

practicalswift commented at 7:20 pm on September 9, 2020: contributor

ACK 62dba9628d2532dca0c44934600f5aac3b21e275 – only change since last ACK is s/nUpgraded/num_unexpected_version/

MarcoFalke commented at 7:40 pm on September 9, 2020: member

re-ACK 62dba96

though I’d still prefer to remove the warning #19898#pullrequestreview-484888930

hebasto approved

hebasto commented at 8:44 am on September 10, 2020: member

re-ACK 62dba9628d2532dca0c44934600f5aac3b21e275, #19898#pullrequestreview-483158708 is resolved now.

theStack approved

theStack commented at 5:21 pm on September 12, 2020: member

ACK 62dba9628d2532dca0c44934600f5aac3b21e275

DrahtBot commented at 1:49 pm on September 19, 2020: member

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#15861 (Restore warning for individual unknown version bits, as well as unknown version schemas by luke-jr)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

practicalswift commented at 3:51 pm on September 26, 2020: contributor

Is this one ready for merge? :)

I’m counting 4 ACKs (practicalswift, MarcoFalke, hebasto, theStack) and one stale ACK (laanwj).

fanquake merged this on Sep 29, 2020

fanquake closed this on Sep 29, 2020

sidhujag referenced this in commit 85b5c6ccc8 on Sep 29, 2020

jonatack commented at 2:33 pm on October 6, 2020: member

Posthumous ACK 62dba9628d2532dca0c44934600f5aac3b21e275

bolatovumar commented at 7:19 pm on October 11, 2020: none

Thanks for this change! That message is really annoying.

iemwill commented at 1:44 pm on February 24, 2021: none

Line 2476 is a good one.

MarcoFalke locked this on Feb 24, 2021

log: print unexpected version warning in validation log category #19898

Conflicts