search

libp2p / js-libp2p

The JavaScript Implementation of libp2p networking stack.
https://libp2p.github.io/js-libp2p/
Other
2.33k stars 446 forks source link

improve error logging #785

Closed mh-cbon closed 4 years ago

mh-cbon commented 4 years ago

Type: Bug

Severity: Medium

Description: Errors generated by event handlers attached to a node created with libp2p.create are not printed on stderr.

Steps to reproduce the error:

Using this script

const Libp2p = require('libp2p')
const MulticastDNS = require('libp2p-mdns')
const KadDHT = require('libp2p-kad-dht')
const Bootstrap = require('libp2p-bootstrap')
const TCP = require('libp2p-tcp')
const Mplex = require('libp2p-mplex')
const { NOISE } = require('libp2p-noise')

const CID = require('cids')
const all = require('it-all')
const delay = require('delay')
const { EventEmitter } = require('events')

const bootstrapers = [
  '/ip4/104.131.131.82/tcp/4001/p2p/QmaCpDMGvV2BGHeYERUEnRQAwe3N8SzbUtfsmvsqQLuvuJ',
  '/ip4/104.236.176.52/tcp/4001/p2p/QmSoLnSGccFuZQJzRadHn95W2CrSFmZuTdDWP8HXaHca9z',
  '/ip4/104.236.179.241/tcp/4001/p2p/QmSoLPppuBtQSGwKDZT2M73ULpjvfd3aZ6ha4oFGL1KrGM',
  '/ip4/162.243.248.213/tcp/4001/p2p/QmSoLueR4xBeUbY9WZ9xGUUxunbKWcrNFTDAadQJmocnWm',
  '/ip4/128.199.219.111/tcp/4001/p2p/QmSoLSafTMBsPKadTEgaXctDQVcqN88CNLHXMkTNwMKPnu',
  '/ip4/104.236.76.40/tcp/4001/p2p/QmSoLV4Bbm51jM9C4gDYZQ9Cy3U6aXMJDAbzgu2fzaDs64',
  '/ip4/178.62.158.247/tcp/4001/p2p/QmSoLer265NRgSp2LA3dPaeykiS1J6DifTC88f5uVQKNAd',
  '/ip4/178.62.61.185/tcp/4001/p2p/QmSoLMeWqB7YGVLJN3pNLQpmmEk35v6wYtsMGLzSr5QBU3',
  '/ip4/104.236.151.122/tcp/4001/p2p/QmSoLju6m7xTh3DuokvT3886QRYqxAzb1kShaanJgW36yx'
]

const createNode = () => {
  return Libp2p.create({
    addresses: {
      listen: ['/ip4/0.0.0.0/tcp/0']
    },
    modules: {
      transport: [ TCP ],
      streamMuxer: [ Mplex ],
      connEncryption: [ NOISE ],
      peerDiscovery: [ MulticastDNS ],
      dht: KadDHT,
    },
    config: {
      peerDiscovery: {
        autoDial: true,
        [MulticastDNS.tag]: {
          broadcast: true,
          interval: 1000,
          enabled: true
        },
        [Bootstrap.tag]: {
          interval: 1000,
          enabled: true,
          list: bootstrapers
        },
      },
      dht: {
        enabled: true
      }
    }
  })
}

( async () => {

  const [node1, node2] = await Promise.all([
    createNode(),
    createNode()
  ])

  node1.on('peer:discovery', (peerID) => {
    throw "YO"
    console.log(node1.peerId.toB58String(), "discovered:", peerID.toB58String())
  })
  node2.on('peer:discovery', (peerID) => {
    console.log(node2.peerId.toB58String(), "discovered:", peerID.toB58String())
  })

  await Promise.all([
    node1.start(),
    node2.start()
  ])
})()

Running node index.js, the output is empty. Using $ DEBUG=*err* node index.js the ouput does not contain the "YO" error.

example output

$ DEBUG=*err* node index.js
QmfHQdZ737fhQ8exhrcnWmGjqV4dEg2nc9eUb3ftoGg3sM discovered: Qmekcj3NdtxRqoZ82TNjVUcHDMTEKFiQh91CQuoxuhjm6a
(node:8740) ExperimentalWarning: Readable[Symbol.asyncIterator] is an experimental feature. This feature could change at any time
  libp2p:upgrader:error Failed to upgrade outbound connection { Error: The operation was aborted
    at nextAbortHandler (/home/mh-cbon/projects/libp2p/node_modules/abortable-iterator/index.js:37:20)
    at AbortSignal.abortHandler (/home/mh-cbon/projects/libp2p/node_modules/abortable-iterator/index.js:16:29)
    at AbortSignal.dispatchEvent (/home/mh-cbon/projects/libp2p/node_modules/event-target-shim/dist/event-target-shim.js:818:35)
    at abortSignal (/home/mh-cbon/projects/libp2p/node_modules/abort-controller/dist/abort-controller.js:52:12)
    at AbortController.abort (/home/mh-cbon/projects/libp2p/node_modules/abort-controller/dist/abort-controller.js:91:9)
    at AbortSignal.onAbort (/home/mh-cbon/projects/libp2p/node_modules/any-signal/index.js:13:16)
    at AbortSignal.dispatchEvent (/home/mh-cbon/projects/libp2p/node_modules/event-target-shim/dist/event-target-shim.js:818:35)
    at abortSignal (/home/mh-cbon/projects/libp2p/node_modules/abort-controller/dist/abort-controller.js:52:12)
    at AbortController.abort (/home/mh-cbon/projects/libp2p/node_modules/abort-controller/dist/abort-controller.js:91:9)
    at dialAbortControllers.map.c (/home/mh-cbon/projects/libp2p/node_modules/libp2p/src/dialer/dial-request.js:74:39) type: 'aborted', code: 'ERR_MUXER_UNAVAILABLE' } +0ms
  libp2p:upgrader:error Failed to upgrade outbound connection { Error: The operation was aborted
    at nextAbortHandler (/home/mh-cbon/projects/libp2p/node_modules/abortable-iterator/index.js:37:20)
    at AbortSignal.abortHandler (/home/mh-cbon/projects/libp2p/node_modules/abortable-iterator/index.js:16:29)
    at AbortSignal.dispatchEvent (/home/mh-cbon/projects/libp2p/node_modules/event-target-shim/dist/event-target-shim.js:818:35)
    at abortSignal (/home/mh-cbon/projects/libp2p/node_modules/abort-controller/dist/abort-controller.js:52:12)
    at AbortController.abort (/home/mh-cbon/projects/libp2p/node_modules/abort-controller/dist/abort-controller.js:91:9)
    at AbortSignal.onAbort (/home/mh-cbon/projects/libp2p/node_modules/any-signal/index.js:13:16)
    at AbortSignal.dispatchEvent (/home/mh-cbon/projects/libp2p/node_modules/event-target-shim/dist/event-target-shim.js:818:35)
    at abortSignal (/home/mh-cbon/projects/libp2p/node_modules/abort-controller/dist/abort-controller.js:52:12)
    at AbortController.abort (/home/mh-cbon/projects/libp2p/node_modules/abort-controller/dist/abort-controller.js:91:9)
    at dialAbortControllers.map.c (/home/mh-cbon/projects/libp2p/node_modules/libp2p/src/dialer/dial-request.js:74:39) type: 'aborted', code: 'ERR_MUXER_UNAVAILABLE' } +4ms
  libp2p:upgrader:error could not create new stream { Error: read ECONNRESET
    at TCP.onread (net.js:656:25) errno: 'ECONNRESET', code: 'ECONNRESET', syscall: 'read' } +13ms
  libp2p:identify:error Error: read ECONNRESET
  libp2p:identify:error     at TCP.onread (net.js:656:25) +0ms
  libp2p:upgrader:error could not create new stream { Error: read ECONNRESET
    at TCP.onread (net.js:656:25) errno: 'ECONNRESET', code: 'ECONNRESET', syscall: 'read' } +1ms
  libp2p:identify:error Error: read ECONNRESET
  libp2p:identify:error     at TCP.onread (net.js:656:25) +0ms

You can try adding node1.on("error", console.error);, the output does not contain the error.

Solution

The problem is located in libp2p.emit method. When it emits over super, it does not catch errors, they are lost. Using below patch

  emit (eventName, ...args) {
    if (eventName === 'error' && !this._events.error) {
      log.error(...args)
    } else {
      // super.emit(eventName, ...args)
      try{
        super.emit(eventName, ...args)
      }catch(ex){
        this.emit("error", ex)
      }
    }
  }

when emit fails with an exception, the error is re sent over this.emit to possibly be redirected to the logger (there is risk of circular call...) or over super.

I can run $ DEBUG=*err* node index.js and get:

$ DEBUG=*err* node index.js
QmWUqo3Yd4hzZnfH2M7psEFK1Du8DwCWKk1N1V9JxXBkP6 discovered: QmWa2Df6cPANNrATs1E5juNd66cqeVpeE1eqsXLueLZKrt
  libp2p:error YO +0ms

If i add an event listener to node.error, i get

$ DEBUG=*err* node index.js
QmVhdYZaiDpMnHMhB6ZXTsmCPH5MUjpqxNF1cFVMR9vrAq discovered: QmfV2F1Gpbj9TxXTFv5TsR9YPrsKUgZtiQR4e6Zqny5kV9
YO
(node:9121) ExperimentalWarning: Readable[Symbol.asyncIterator] is an experimental feature. This feature could change at any time
  libp2p:upgrader:error Failed to upgrade outbound connection { Error: The operation was aborted
    at nextAbortHandler (/home/mh-cbon/projects/libp2p/node_modules/abortable-iterator/index.js:37:20)
    at AbortSignal.abortHandler (/home/mh-cbon/projects/libp2p/node_modules/abortable-iterator/index.js:16:29)
    at AbortSignal.dispatchEve...

But also $ node index.js and get:

$ node index.js
QmRCHQ6eVGCTfC6a2cXyACDAcBQWYVvCh3preCB9RtzCd6 discovered: QmbZgTiWQixYwRMN2xAfUNaZAbnVDkG6xbpZNZ83bFmzG6
YO
(node:9203) ExperimentalWarning: Readable[Symbol.asyncIterator] is an experimental feature. This feature could change at any time
^C

Finally, i would like to get your attention to the special event EventEmitter.errorMonitor as described in https://nodejs.org/api/events.html#events_error_events. I believe the constructor should install such listener to forward all errors to the logger. In such case i guess the libp2p.emit method wont need the logic to redirect errors on the logger and that the catch block should not re emit over this, but directly over super.

mh-cbon commented 4 years ago

related to #762 when it says There were several libp2p users having trouble with "silent" errors

jacobheun commented 4 years ago

Closing this as a duplicate of https://github.com/libp2p/js-libp2p/issues/751