Client: Added Fetcher debug logger

[holgerd77]

Another debug thing, I was finally fed up that we do not get the Fetcher under control and control flow is so hard to debug and trace there.

I first tried to take Andrews @acolytec3 concerns on having two different loggers in the client into account and added new debug messages as classic this.config.logger.debug() messages, but this turned out to be impractical because things become too verbose especially when debugging on something so process-heavy as the Fetcher, and at the same time the other debug output is highly distracting and this would only get worse over time if we add on classic debug logging. So at some point I switched over and used the debug package.

Good thing is: this is really making things hyper-clear 😀, I guess once you see the output you will "feel" this yourself. I guess this will dramatically help us to get the control flow under control from this angle, I actually directly was drawn to fix things on 2-3 ends because things become so obvious.

Here is some sample output on running DEBUG=client:fetcher npm run client:start:

Have opened this up for review, but eventually I will also do some additional work here.

[codecov]

Codecov Report

Merging #1544 (e85f765) into master (f15f28b) will increase coverage by 0.03%.
The diff coverage is 63.26%.

Flag	Coverage Δ
block	84.81% <ø> (ø)
blockchain	82.53% <ø> (+0.06%)	⬆️
client	77.68% <63.26%> (+0.24%)	⬆️
common	94.08% <ø> (ø)
devp2p	82.62% <ø> (-0.24%)	⬇️
ethash	90.76% <ø> (ø)
tx	88.76% <ø> (ø)

Flags with carried forward coverage won't be shown. Click here to find out more.

[ryanio]

very cool 👍 running this now to see if I can get any more insights

[ryanio]

One idea here might be that if we receive an empty BlockBodies result of [] txs and [] uncles but the header has a non-empty value then we can reject the results.

Will try with something like this:

      if (
        (!headers[i].transactionsTrie.equals(KECCAK256_RLP) && txsData.length === 0) ||
        (!headers[i].uncleHash.equals(KECCAK256_RLP_ARRAY) && unclesData.length === 0)
      ) {
        this.debug(
          `Requested block=${headers[i].number}} from peer ${peerInfo} missing non-empty txs or uncles`
        )
        return []
      }

edit: ok so far so good, this seems to be catching some of the occurrences and preventing sync interruptions, will push a commit

[holgerd77]

Thanks, great 🙂, yes, that's a great check and might already help, will also continue a bit on this this morning, maybe it's additionally possible to also get closer to some root cause.

Have restarted client sync on the server, and that works fine for now though 👍 for roughly half an hour now.