Devp2p, Client: Fix duplicated debug messages

[ScottyPoi]

Updates debug package to 4.3.3

Also fixes some logic devp2p code that caused multiple debug messages.

[codecov]

Codecov Report

Merging #1643 (18aa6a8) into master (56fbb0b) will decrease coverage by 0.13%.
The diff coverage is 84.61%.

Flag	Coverage Δ
block	85.01% <ø> (ø)
blockchain	83.28% <ø> (ø)
client	71.27% <ø> (ø)
common	93.89% <ø> (ø)
devp2p	82.63% <84.61%> (-0.20%)	⬇️
ethash	90.76% <ø> (ø)
rlp	?
trie	86.18% <ø> (ø)
tx	89.94% <ø> (ø)
util	92.62% <ø> (ø)
vm	81.27% <ø> (ø)

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

[acolytec3]

Great work @ScottyPoi and yay for the first PR!

I'm concerned about the IP based debug messages and would like others to weigh in. We need to decide how to handle them since we lose them with these changes (as far as I can tell based on testing it out) without adding an additional way to access those messages.

[acolytec3]

@holgerd77 Which messages did we want to dedup on this one? With this PR's changes, it looks like this:

And on current master, it looks like this.

Should we be removing the IP based messages? I believe with these changes we will lose the IP based messages entirely since I don't know if we'll ever encounter a situation where there is an IP based message debugger that doesn't also have a messageName debugger (which is a higher priority in the conditional logic here. Maybe we should change it to something like below so users could specify if they want to see log messages from a specific IP address:

if (ip && process.env.DEBUG === `devp2p:${ip}`) {
      this.msgDebuggers[ip](msg)
    } else if (disconnectReason && messageName === 'DISCONNECT') {
      if (this.msgDebuggers[disconnectReason]) {
        this.msgDebuggers[disconnectReason](msg)
      }...

It produces output that looks something like this:

We'd have to apply this same check everywhere we have the IP based messaging and then add some updates to the docs to reflect this usage but it seems to work well.

[holgerd77]

These devp2p:127.0.0.1 or devp2p:rlpx:peer:HELLO prefixes on the log messages are actually only the names of the loggers activated and not a "feature" to display the IP adress on some loggers. 😋

So on your usage this is the correct dedublication, the main point of this whole thing is the we do not have situations where the same message (in the screenshot from above e.g. "Received HELLO message...") is sent multiple times.

And even if only devp2p:rlpx:peer:HELLO is logged, the remote peer IP is visible in the debug message itself.

That said:

I also tested a local connection along these instructions with the following command:

cd ../devp2p && npm run build && cd ../client && DEBUG=devp2p:127.0.0.1 npm run client:start:dev2 -- --bootnodes=enode://90e0424dff457a1b677b45aa0bf861e71284c45514e944060f8fb3cca65ddc1b241e686e7a9fb8ac37e6090376a4faf379368cc8ad59ae29194ee3126c3e9c88@127.0.0.1:30303

And with the current conditional order the IP logger wouldn't display in this case.

I guess it's enough if we just switch the meesage logger and the IP logger order and keep the rest in place, so this would work for me locally:

const ip = this._socket.remoteAddress
if (disconnectReason && messageName === 'DISCONNECT') {
  if (this.msgDebuggers[disconnectReason]) {
    this.msgDebuggers[disconnectReason](msg)
  }
} else if (ip && this.msgDebuggers[ip]) {
  this.msgDebuggers[ip](msg)
} else if (this.msgDebuggers[messageName]) {
  this.msgDebuggers[messageName](msg)
} else {
  debug(msg)
}

Short nit for @ScottyPoi (actually all of this comment is mainly for Scotty of course 😛): it would be good if you also add brackets to one-liner code (so this simple debug(msg). We had some bugs lately caused by someone adding something below such a line and not noticing this is not executed in this conditional context. So this would be a bit more on the safe side.

Note: this order change from above would also need to be adjusted in the eth/index.ts file.

[holgerd77]

Thanks, great start 🎉, some comments. 🙂

[holgerd77]

These devp2p:127.0.0.1 or devp2p:rlpx:peer:HELLO prefixes on the log messages are actually only the names of the loggers activated and not a "feature" to display the IP adress on some loggers. 😋

So on your usage this is the correct dedublication, the main point of this whole thing is the we do not have situations where the same message (in the screenshot from above e.g. "Received HELLO message...") is sent multiple times.

And even if only devp2p:rlpx:peer:HELLO is logged, the remote peer IP is visible in the debug message itself.

That said:

I also tested a local connection along these instructions with the following command:

cd ../devp2p && npm run build && cd ../client && DEBUG=devp2p:127.0.0.1 npm run client:start:dev2 -- --bootnodes=enode://90e0424dff457a1b677b45aa0bf861e71284c45514e944060f8fb3cca65ddc1b241e686e7a9fb8ac37e6090376a4faf379368cc8ad59ae29194ee3126c3e9c88@127.0.0.1:30303

And with the current conditional order the IP logger wouldn't display in this case.

I guess it's enough if we just switch the meesage logger and the IP logger order and keep the rest in place, so this would work for me locally:

const ip = this._socket.remoteAddress
if (disconnectReason && messageName === 'DISCONNECT') {
  if (this.msgDebuggers[disconnectReason]) {
    this.msgDebuggers[disconnectReason](msg)
  }
} else if (ip && this.msgDebuggers[ip]) {
  this.msgDebuggers[ip](msg)
} else if (this.msgDebuggers[messageName]) {
  this.msgDebuggers[messageName](msg)
} else {
  debug(msg)
}

Short nit for @ScottyPoi (actually all of this comment is mainly for Scotty of course 😛): it would be good if you also add brackets to one-liner code (so this simple debug(msg). We had some bugs lately caused by someone adding something below such a line and not noticing this is not executed in this conditional context. So this would be a bit more on the safe side.

Note: this order change from above would also need to be adjusted in the eth/index.ts file.

[holgerd77]

What's this? 😀

[ScottyPoi]

This seemed entirely reduntant to debug messages coming from peer.ts. I left it here commented out in case I was mistaken

[holgerd77]

Hmm, I am not sure if we loose debug information here in the case we are not triggering the disconnect ourselves but the disconnect got triggered from the peer side.

Maybe double check and/or in doubt just leave, we can always remove this later along continued work since this is not so "core" for this PR to fulfill its purpose.

[holgerd77]

Ah, just realizing that this special FIRST_PEER logger (should take the first peer respectively its IP and then only log the messages from this peer) is also not working yet, also not with the code change I suggested.

I used:

cd ../devp2p && npm run build && cd ../client && DEBUG=devp2p:FIRST_PEER npm run client:start:dev2 -- --bootnodes=enode://90e0424dff457a1b677b45aa0bf861e71284c45514e944060f8fb3cca65ddc1b241e686e7a9fb8ac37e6090376a4faf379368cc8ad59ae29194ee3126c3e9c88@127.0.0.1:30303

Note that this might also not have been working before this PR, didn't test.

[ScottyPoi]

[ScottyPoi]

Changed to using the debug.extend() method to create the extended message names

[ScottyPoi]

[holgerd77]

Ah, you found the way how to actually properly do this, that's so great!!! 🙏 🙏 🙏

That's a lot better, thanks for digging deeper into this.

One comment on the disconnect debug removal, also please remove all commented out code, I guess otherwise this should be ready for merge.

Great work! 🙂

[holgerd77]

Hmm, I am not sure if we loose debug information here in the case we are not triggering the disconnect ourselves but the disconnect got triggered from the peer side.

Maybe double check and/or in doubt just leave, we can always remove this later along continued work since this is not so "core" for this PR to fulfill its purpose.

[holgerd77]

LGTM, thanks a lot Scotty! 🙂

Addressed.