Add log output during initial header sync

[jonasschnelli]

The non debug log output is completely quiet during the header sync. I see two main reasons to add infos about the state of the initial header sync...

• users may think the node did fail to start sync
• it's a little complicate to check if your getting throttled during header sync (repeatedly calling getchaintips or similar)

[promag]

Tested ACK 4e74875. Sample output with -testnet:

2019-03-17T23:49:45Z Synchronizing blockheaders, height: 1153998 (~92.96%)
2019-03-17T23:49:45Z more getheaders (1153998) to end to peer=0 (startheight:1485065)
2019-03-17T23:49:45Z sending getheaders (1061 bytes) peer=0
2019-03-17T23:49:45Z received: headers (162003 bytes) peer=0
2019-03-17T23:49:45Z Synchronizing blockheaders, height: 1155998 (~93.13%)
2019-03-17T23:49:45Z more getheaders (1155998) to end to peer=0 (startheight:1485065)
2019-03-17T23:49:45Z sending getheaders (1061 bytes) peer=0
2019-03-17T23:49:46Z received: headers (162003 bytes) peer=0
2019-03-17T23:49:46Z Synchronizing blockheaders, height: 1157998 (~93.23%)
2019-03-17T23:49:46Z more getheaders (1157998) to end to peer=0 (startheight:1485065)
2019-03-17T23:49:46Z sending getheaders (1061 bytes) peer=0
2019-03-17T23:49:46Z received: headers (162003 bytes) peer=0
2019-03-17T23:49:46Z Synchronizing blockheaders, height: 1159998 (~93.25%)
2019-03-17T23:49:46Z more getheaders (1159998) to end to peer=0 (startheight:1485065)
2019-03-17T23:49:46Z sending getheaders (1061 bytes) peer=0
2019-03-17T23:49:46Z received: headers (162003 bytes) peer=0
2019-03-17T23:49:46Z Synchronizing blockheaders, height: 1161998 (~93.26%)
2019-03-17T23:49:46Z more getheaders (1161998) to end to peer=0 (startheight:1485065)
2019-03-17T23:49:46Z sending getheaders (1061 bytes) peer=0
2019-03-17T23:49:46Z received: headers (162003 bytes) peer=0
2019-03-17T23:49:46Z Synchronizing blockheaders, height: 1163998 (~93.27%)
2019-03-17T23:49:46Z more getheaders (1163998) to end to peer=0 (startheight:1485065)

[practicalswift]

Can we find a way to make it so that the non-debug output is non-quiet but not spammy?

I'm afraid the total number of logged lines would be substantial if merged as is. This in turn would educe the signal-to-noise ratio and reduce the value of the log.

Logging too much to the non-debug log is almost as bad as logging too little :-)

[jonasschnelli]

Can we find a way to make it so that the non-debug output is non-quiet but not spammy?

I don't think its spammy... At current height, it logs around 284 lines for the header sync... seems acceptable compared to >567000 lines from UpdateTip during IBD.

[practicalswift]

@jonasschnelli I'm not very fond of the UpdateTip logging during IBD either :-)

Can you think of a smart way to reduce the number of logged lines while achieving the stated goals?

Let's not forget that this is the logging meeting a first-time bitcoind user: let's give a nice first usability impression :-)

[sipa]

Let's not forget that this is the logging meeting a first-time bitcoind user: let's give a nice first usability impression

It's called a debug log. I don't think the criterion to optimize for is usability, but a tradeoff between disk usage and ability to diagnose problems (by an expert user or developer).

[practicalswift]

@sipa Clarification: When talking about usability I was referring the "write to standard output for immediate consumption" aspect of LogPrintf(…) and not the "write to debug.log on disk for later consumption" aspect.

Generally I think we print too much debug information to standard output resulting in a low signal-to-noise ratio for the end-user invoking bitcoind.

Perhaps this could be solved by having two different log levels for LogPrintf where both log levels get written to debug.log but only the higher log level gets written to standard output.

[laanwj]

Concept ACK, I think it's better to log something. Could add logic to log only every so many %, but this is a good start.

It does fail to build here, might need rebase for recent changes:

/.../bitcoin/src/validation.cpp: In function ‘bool ProcessNewBlockHeaders(const std::vector<CBlockHeader>&, CValidationState&, const CChainParams&, const CBlockIndex**, CBlockHeader*)’:
/.../bitcoin/src/validation.cpp:3332:13: error: ‘IsInitialBlockDownload’ was not declared in this scope
         if (IsInitialBlockDownload() && ppindex && *ppindex) {
             ^~~~~~~~~~~~~~~~~~~~~~

[jonasschnelli]

Thanks @laanwj!
Fixed.

[fanquake]

Concept ACK d75e704

Agree with @sipa:

It's called a debug log. I don't think the criterion to optimize for is usability, but a tradeoff between disk usage and ability to diagnose problems (by an expert user or developer).

Tested on top of master (7524376) using -testnet -debug=net:

143:2019-06-14T07:28:12Z Synchronizing blockheaders, height: 2000 (~0.54%)
159:2019-06-14T07:28:13Z Synchronizing blockheaders, height: 4000 (~1.07%)
167:2019-06-14T07:28:14Z Synchronizing blockheaders, height: 6000 (~1.59%)
194:2019-06-14T07:28:15Z Synchronizing blockheaders, height: 8000 (~2.11%)
201:2019-06-14T07:28:15Z Synchronizing blockheaders, height: 10000 (~2.63%)
206:2019-06-14T07:28:16Z Synchronizing blockheaders, height: 12000 (~3.14%)
213:2019-06-14T07:28:16Z Synchronizing blockheaders, height: 14000 (~3.64%)
231:2019-06-14T07:28:17Z Synchronizing blockheaders, height: 16000 (~4.17%)
248:2019-06-14T07:28:17Z Synchronizing blockheaders, height: 18000 (~4.75%)
273:2019-06-14T07:28:18Z Synchronizing blockheaders, height: 20000 (~5.27%)
......
1239:2019-06-14T07:28:55Z Synchronizing blockheaders, height: 268000 (~50.83%)
1243:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 254000 (~48.93%)
1247:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 260000 (~49.57%)
1251:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 258000 (~49.34%)
1255:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 270000 (~51.15%)
1259:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 270000 (~51.15%)
1263:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 258000 (~49.34%)
1267:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 256000 (~49.13%)
1271:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 258000 (~49.34%)
1275:2019-06-14T07:28:56Z Synchronizing blockheaders, height: 272000 (~51.57%)
......
350831:2019-06-14T07:34:51Z Synchronizing blockheaders, height: 1532000 (~99.94%)
352022:2019-06-14T07:34:51Z Synchronizing blockheaders, height: 1534000 (~99.94%)
353240:2019-06-14T07:34:52Z Synchronizing blockheaders, height: 1536000 (~99.94%)
354471:2019-06-14T07:34:53Z Synchronizing blockheaders, height: 1538000 (~99.94%)
355709:2019-06-14T07:34:53Z Synchronizing blockheaders, height: 1540000 (~99.95%)
357365:2019-06-14T07:34:54Z Synchronizing blockheaders, height: 1542000 (~99.97%)
358206:2019-06-14T07:34:55Z Synchronizing blockheaders, height: 1543389 (~100.00%)
609974:2019-06-14T07:37:43Z Synchronizing blockheaders, height: 1543389 (~100.00%)

The full debug.log grep for Synchronizing blockheaders is available here.

[practicalswift]

@fanquake

Again: the problem is not what we're writing to disk. The problem is that this will also be written to standard output.

I'm afraid such verbose logging will flood the console and effectively hide any important non- blockheaders issues.

I'm not convinced this will be a net win if merged as is: sure, we'll have plenty of information about any blockheaders issue at the cost of very low signal-to-noise for all other issues.

I agree that it is problematic that we're completely quiet during the header sync, but I'm not at all convinced that the only sane alternative to the status quo is the other extreme: to flood everything we know about it :-)

[jonasschnelli]

@practicalswift:
We are speaking around 280 lines mainly happening once before the initial IBD (later probably due to falling out of sync, but much less lines). I don't think this is noise rather it's a great help to figure out what's going on in general and if you are slowed down during a single-peer header sync.

[practicalswift]

@jonasschnelli Sorry: my last comment was written under the incorrect assumption that the number of lines that would be printed was ~5000 judging from @fanquake's posted gist. I read the output as 5000 lines written at a speed of 10 lines/second during the first ten minutes of operation. I now understand that this is incorrect :-)

I guess 280 lines is a bit more than I'd like personally but it is way better than the 5000 lines I thought. Anyways I understand that the consensus opinion is to go with current version, so I won't argue further. Let's go with this and tweak later if necessary :-)

utACK d75e704

[laanwj]

Tested ACK d75e704