Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Prefix debug messages per node with peerID #378

Closed
Tracked by #2105
mkg20001 opened this issue Jul 14, 2019 · 3 comments
Closed
Tracked by #2105

Prefix debug messages per node with peerID #378

mkg20001 opened this issue Jul 14, 2019 · 3 comments
Labels
help wanted Seeking public contribution on this issue kind/discussion Topical discussion; usually not changes to codebase need/analysis Needs further analysis before proceeding

Comments

@mkg20001
Copy link
Member

  • Version: *
  • Platform: *
  • Subsystem: *

Type: feature

Severity: low

Description: Prefix debug messages per node with peerID

Let's take this log as an example:

  libp2p:switch:dialer create: 8 peer limit, 30000 dial timeout +0ms
  libp2p:connection-manager options: {"maxPeers":null,"minPeers":25,"maxData":null,"maxSentData":null,"maxReceivedData":null,"maxEventLoopDelay":null,"pollInterval":2000,"movingAverageInterval":60000,"defaultPeerValue":1,"maxPeersPerProtocol":{}} +0ms
  libp2p:switch:transport adding Circuit +0ms
  libp2p:switch:dialer create: 8 peer limit, 30000 dial timeout +13ms
  libp2p:connection-manager options: {"maxPeers":null,"minPeers":25,"maxData":null,"maxSentData":null,"maxReceivedData":null,"maxEventLoopDelay":null,"pollInterval":2000,"movingAverageInterval":60000,"defaultPeerValue":1,"maxPeersPerProtocol":{}} +10ms
  libp2p:switch:transport adding Circuit +9ms
  libp2p:switch:dialer create: 8 peer limit, 30000 dial timeout +14ms
  libp2p:connection-manager options: {"maxPeers":null,"minPeers":25,"maxData":null,"maxSentData":null,"maxReceivedData":null,"maxEventLoopDelay":null,"pollInterval":2000,"movingAverageInterval":60000,"defaultPeerValue":1,"maxPeersPerProtocol":{}} +14ms
  libp2p:switch:transport adding Circuit +14ms
  libp2p libp2p is starting +0ms
  libp2p:switch The switch is starting +0ms
  libp2p:switch The switch has started +4ms
  libp2p:switch:transport adding WebSockets +17ms
  libp2p libp2p has started +9ms
  libp2p libp2p is starting +1ms
  libp2p:switch The switch is starting +3ms
  libp2p:switch The switch has started +1ms
  libp2p:switch:transport adding WebSockets +3ms
  libp2p libp2p has started +2ms
  libp2p libp2p is starting +0ms
  libp2p:switch:transport adding WebSockets +2ms
  libp2p:switch The switch is starting +2ms
  libp2p:switch The switch has started +11ms
  libp2p libp2p has started +14ms
  libp2p:exchange:rendezvous:server server started +0ms
  libp2p:switch:dial starting dial queue to QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +0ms
  libp2p:connection-manager Qmf2uGBMP8VcLYAbh7katNyXyhiptYoUf1kLzbFd1jpRbf: connected to QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +39ms
  libp2p:connection-manager checking limit of maxPeers. current value: 1 of Infinity +0ms
  libp2p:connection-manager checking protocol limit. current value of ip4 is 1 +1ms
  libp2p:connection-manager checking protocol limit. current value of tcp is 1 +0ms
  libp2p:connection-manager checking protocol limit. current value of ws is 1 +0ms
  libp2p:connection-manager checking protocol limit. current value of ipfs is 1 +0ms
  libp2p:connection-manager checking protocol limit. current value of p2p-circuit is 1 +0ms
  libp2p:conn:out:Qmf2uGBM dialing QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +0ms
  libp2p:conn:out:Qmf2uGBM dialing transport WebSockets +1ms
  libp2p:switch:transport dialing WebSockets [ '/ip4/127.0.0.1/tcp/5394/ws/ipfs/QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x' ] +19ms
  libp2p:switch:dialer dialMany:start +44ms
  libp2p:switch:dialer dialSingle: QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x:/ip4/127.0.0.1/tcp/5394/ws/ipfs/QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +0ms
  libp2p:switch:dial starting dial queue to QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +8ms
  libp2p:connection-manager QmY6yfBGWghP7NcW3gFeJC9FgRQe2rbV8BkfyWAYfBAT3g: connected to QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +6ms
  libp2p:connection-manager checking limit of maxPeers. current value: 1 of Infinity +0ms
  libp2p:connection-manager checking protocol limit. current value of ip4 is 1 +0ms
  libp2p:connection-manager checking protocol limit. current value of tcp is 1 +0ms
  libp2p:connection-manager checking protocol limit. current value of ws is 1 +0ms
  libp2p:connection-manager checking protocol limit. current value of ipfs is 1 +0ms
  libp2p:connection-manager checking protocol limit. current value of p2p-circuit is 1 +0ms
  libp2p:conn:out:QmY6yfBG dialing QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +0ms
  libp2p:conn:out:QmY6yfBG dialing transport WebSockets +1ms
  libp2p:switch:transport dialing WebSockets [ '/ip4/127.0.0.1/tcp/5394/ws/ipfs/QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x' ] +6ms
  libp2p:switch:dialer dialMany:start +4ms
  libp2p:switch:dialer dialSingle: QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x:/ip4/127.0.0.1/tcp/5394/ws/ipfs/QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +0ms
  libp2p:switch:dialer:queue work:start +0ms
  libp2p:websockets:dialer dialing ws://127.0.0.1:5394/ipfs/QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +0ms
  libp2p:switch:dialer:queue work:start +8ms
  libp2p:websockets:dialer dialing ws://127.0.0.1:5394/ipfs/QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +8ms
  libp2p:switch:listener received incoming connection for transport WebSockets +0ms
  libp2p:conn:inc:QmW5gmNT encrypting connection via /secio/1.0.0 +0ms
  libp2p:switch:listener received incoming connection for transport WebSockets +6ms
  libp2p:conn:inc:QmW5gmNT encrypting connection via /secio/1.0.0 +0ms
  libp2p:switch:dialer:queue work:success +18ms
  libp2p:switch:dialer dialMany:success +27ms
  libp2p:conn:out:Qmf2uGBM successfully dialed QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +35ms
  libp2p:conn:out:Qmf2uGBM selecting crypto /secio/1.0.0 to QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +3ms
  libp2p:switch:dialer:queue work:success +5ms
  libp2p:switch:dialer dialMany:success +5ms
  libp2p:conn:out:QmY6yfBG successfully dialed QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +33ms
  libp2p:conn:out:QmY6yfBG selecting crypto /secio/1.0.0 to QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +1ms
  libp2p:secio 1. propose - start +0ms
  libp2p:secio 1. propose - writing proposal +0ms
  libp2p:secio 1. propose - start +3ms
  libp2p:secio 1. propose - writing proposal +0ms
  libp2p:secio 1. propose - start +2ms
  libp2p:secio 1. propose - writing proposal +0ms
  libp2p:secio 1. propose - reading proposal <Buffer 0a 10 e7 38 ff c4 35 6f 97 61 8d 7f 26 ce 1b 2d 64 07 12 ab 02 08 00 12 a6 02 30 82 01 22 30 0d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 01 0f 00 ... > +2ms
  libp2p:secio 1.1 identify +0ms
  libp2p:secio 1.1 identify - Qmf2uGBMP8VcLYAbh7katNyXyhiptYoUf1kLzbFd1jpRbf - identified remote peer as QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +17ms
  libp2p:secio 1.2 selection +0ms
  libp2p:secio 1. propose - finish +19ms
  libp2p:secio 2. exchange - start +0ms
  libp2p:secio 2. exchange - writing exchange +0ms
  libp2p:secio 1. propose - start +9ms
  libp2p:secio 1. propose - writing proposal +0ms
  libp2p:secio 1. propose - reading proposal <Buffer 0a 10 76 cd 78 3d 35 36 0d 8c 1b c0 d4 5d ff 71 38 f7 12 ab 02 08 00 12 a6 02 30 82 01 22 30 0d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 01 0f 00 ... > +2ms
  libp2p:secio 1.1 identify +13ms
  libp2p:secio 1.1 identify - QmY6yfBGWghP7NcW3gFeJC9FgRQe2rbV8BkfyWAYfBAT3g - identified remote peer as QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x +4ms
  libp2p:secio 1.2 selection +0ms
  libp2p:secio 1. propose - finish +5ms
  libp2p:secio 2. exchange - start +16ms
  libp2p:secio 2. exchange - writing exchange +0ms
  libp2p:secio 1. propose - reading proposal <Buffer 0a 10 89 74 95 18 f9 44 90 48 8f 1e 04 5a b3 73 d8 7e 12 ab 02 08 00 12 a6 02 30 82 01 22 30 0d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 01 0f 00 ... > +5ms
  libp2p:secio 1.1 identify +6ms
  libp2p:secio 1.1 identify - QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x - identified remote peer as Qmf2uGBMP8VcLYAbh7katNyXyhiptYoUf1kLzbFd1jpRbf +3ms
  libp2p:secio 1.2 selection +0ms
  libp2p:secio 1. propose - finish +4ms
  libp2p:secio 2. exchange - start +9ms
  libp2p:secio 2. exchange - writing exchange +0ms
  libp2p:secio 1. propose - reading proposal <Buffer 0a 10 56 f1 09 9e 31 f2 22 5e eb 75 c9 5b 98 a9 b1 14 12 ab 02 08 00 12 a6 02 30 82 01 22 30 0d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 01 0f 00 ... > +7ms
  libp2p:secio 1.1 identify +8ms
  libp2p:secio 1.1 identify - QmW5gmNTpGbFR48ieKVuYzcoz8jtrpmyCN3vB2jdoTDz5x - identified remote peer as QmY6yfBGWghP7NcW3gFeJC9FgRQe2rbV8BkfyWAYfBAT3g +6ms
  libp2p:secio 1.2 selection +0ms
  libp2p:secio 1. propose - finish +7ms
  libp2p:secio 2. exchange - start +14ms
  libp2p:secio 2. exchange - writing exchange +0ms
  libp2p:connection-manager checking limit of maxEventLoopDelay. current value: 1.444880666666658 of Infinity +2s
  libp2p:connection-manager checking limit of maxEventLoopDelay. current value: 1.8073759999999908 of Infinity +8ms
  libp2p:connection-manager checking limit of maxEventLoopDelay. current value: 0.8339546666666706 of Infinity +2ms
  libp2p:connection-manager checking limit of maxEventLoopDelay. current value: 0.9595879999999966 of Infinity +2s
  libp2p:connection-manager checking limit of maxEventLoopDelay. current value: 1.8623699999999985 of Infinity +8ms
  libp2p:connection-manager checking limit of maxEventLoopDelay. current value: 1.1791929999999837 of Infinity +3ms

This includes debug messages from 3 nodes running in the same process. It's very hard to attribute which logs message is from which node.

I know that it might possibly be very hard to implement (since this requires updatin debug('module') statements across all libp2p modules) but this could be very useful. Additionally the code changes required could also be automated.

Is this feature something the libp2p team considers a valuable addition?
@jacobheun
Copy link
Contributor

I think this could be helpful, but I think it would be ideal to look at creating a utility for this. Ideally I'd like to have all services and transports be created with the libp2p instance passed to them. We could potentially add a createLogger or similar method to handle prepending {id}:libp2p with a truncated id so that in the future we wouldn't need to change everything downstream.

@mkg20001
Copy link
Member Author

There would be a performance problem though: Certain modules, like secio, would only get access to the peer-id at actual usage time and not during construction of the swarm, thus requiring to create the logger every time for ex. the encrypt function is called

I'm unsure if this would be an actual bottleneck or not

@vasco-santos vasco-santos mentioned this issue Jan 22, 2021
Closed
@maschad maschad added help wanted Seeking public contribution on this issue kind/discussion Topical discussion; usually not changes to codebase need/analysis Needs further analysis before proceeding and removed kind/stale labels Oct 1, 2023
@maschad maschad mentioned this issue Oct 2, 2023
Closed
@maschad
Copy link
Member

maschad commented Nov 7, 2023

Closed by #2198

@maschad maschad closed this as completed Nov 7, 2023
@achingbrain achingbrain mentioned this issue Nov 26, 2023
Closed
3 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
help wanted Seeking public contribution on this issue kind/discussion Topical discussion; usually not changes to codebase need/analysis Needs further analysis before proceeding
Projects
js-libp2p
Archived in project
Milestone
No milestone
Development

No branches or pull requests
4 participants
@jacobheun @mkg20001 @maschad @p-shahi