jaeger: opentracing not being set in client error handlers

esatterwhite commented 7 years ago

It looks like the caller doesn't have the opentracing object set on this in the error event handlers

Description

[2017-10-24T13:14:43.335Z] FATAL (hemera-xavier-4d2a6987498e4aada870449d20fbe8a1/1353 on xavier): Fatal error
    FatalError: Fatal error
        at Hemera._sendRequestHandler (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats-hemera/lib/index.js:1052:29)
        at self._sid.self._transport.sendRequest.resp (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats-hemera/lib/index.js:1252:22)
        at Object.callback (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats/lib/nats.js:1274:5)
        at Client.processMsg (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats/lib/nats.js:1003:11)
        at Client.processInbound (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats/lib/nats.js:931:14)
        at Socket.<anonymous> (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats/lib/nats.js:470:12)
        at emitOne (events.js:115:13)
        at Socket.emit (events.js:210:7)
        at addChunk (_stream_readable.js:264:12)
        at readableAddChunk (_stream_readable.js:251:11)
    Cause: TypeError: Cannot read property 'finish' of undefined
        at Hemera.<anonymous> (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/hemera-jaeger/index.js:139:21)
        at emitOne (events.js:115:13)
        at Hemera.emit (events.js:210:7)
        at onClientPostRequest (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats-hemera/lib/extensions.js:126:11)
        at Hemera.(anonymous function).push (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats-hemera/lib/extension.js:55:15)
        at makeCall (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/fastseries/series.js:113:10)
        at ResultsHolder.release (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/fastseries/series.js:96:9)
        at Hemera.series [as _series] (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/fastseries/series.js:39:14)
        at Hemera._sendRequestHandler (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats-hemera/lib/index.js:1047:12)
        at self._sid.self._transport.sendRequest.resp (/home/esatterwhite/dev/js/node-allstar/allstar-auth/node_modules/nats-hemera/lib/index.js:1252:22)

Steps to Reproduce

Example:

Start NATS
Use plugin hemera-jeager
Send message
client handler (async function) throws error

the handler looks like this

hemera.add({
  topic: 'user'
, cmd: 'create'
, version: 'v1'
, auth$: {
    permissions: 'auth:user:create'
  }
}, async function getUser(req) {
  const opts = req
  await _validateRoles(opts.roles) // <---- This function MAY throw
  opts.roles = opts.roles || []
  if (opts.password != null) {
    this.log.debug('generating initial password for user', opts.email)
    const salt = await bcrypt.salt()
    opts.password = await bcrypt.encode(opts.password, salt)
  }
  opts.superuser = undefined
  opts.permissions = undefined
  const u = await new User(opts).save()
  const permissions = await u.getAllPermissions()
  this.log.info('new user created', u.email)

  return Object.assign({}, u, {
    password: undefined
  , permissions: permissions
  })
})

with out the jaeger pluging, it works just fine, the error is propagated back the caller. This also works fine with the jaeger plugin and there is no error.

Expected Result

error is logged and sent to jaeger

Actual Result

error is throw and process crashes

Context

[x] nats-hemera (core)
[ ] hemera-zipkin
[ ] hemera-store
[x] hemera-stats
[ ] hemera-rabbitmq
[ ] hemera-nsq
[ ] hemera-arango-store
[ ] hemera-sql-store
[ ] hemera-elasticsearch
[ ] hemera-couchbase-store
[ ] hemera-mongo-store
[ ] hemera-joi
[ ] hemera-parambulator
[ ] hemera-msgpack
[ ] hemera-avro
[ ] hemera-redis-cache
[ ] hemera-jwt-auth

Your Environment

NATS: 0.7.20
Hemera:2.2.0
NodeJs: 8.7.0
Environment name and version: ??
Operating System and version: Majaro (Arch) linux v17

StarpTech commented 7 years ago

Hi, thanks for reporting I will investigate.

StarpTech commented 7 years ago

@esatterwhite I can't reproduce it. I tried:

  hemera.add(
    {
      topic: 'profile',
      cmd: 'get'
    },
    async function(req) {
      throw new Error('test')
    }
  )

with this example https://github.com/hemerajs/hemera/blob/master/examples/monitoring/jaeger.js but the error is returned correctly. Please have in mind that errors that are thrown asynchronously are not able to catch.

esatterwhite commented 7 years ago

ah, sorry I mis-spoke. The function doesn't throw, it calls the reject function from a promise. so more like

  hemera.add(
    {
      topic: 'profile',
      cmd: 'get'
    },
    async function(req) {
      await someOp()
    }
  )

function someOp() {
  return new Promise((resolve, reject) => {
    const error = new Error('broke')
    setImmediate(reject, err)
  })
}

The problem isn't that the error isn't being handled. It is getting to this line and this.opentracing is undefined

StarpTech commented 7 years ago

I can't reproduce it the error is logged and the process survived. Could you provide a full example?

const Hemera = require('hemera')
const nats = require('nats').connect()
const hemeraJaeger = require('hemera-jaeger')

const hemera = new Hemera(nats, {
  logLevel: 'debug',
  childLogger: true,
  tag: 'math'
})

hemera.use(hemeraJaeger, {
  serviceName: 'math'
})
hemera.ready(() => {
  hemera.add(
    {
      topic: 'math',
      cmd: 'add'
    },
    async function(req) {
      await someOp()
    }
  )

  function someOp() {
    return new Promise((resolve, reject) => {
      const error = new Error('broke')
      setImmediate(reject, error)
    })
  }

  hemera.act({
    topic: 'math',
    cmd: 'add'
  }, function() {

  })
})

StarpTech commented 7 years ago

Please also update to hemera 2.3.1

esatterwhite commented 7 years ago

Ah, I found it!. I was running a script and calling hemera.act with out wrapping it in the ready callback. I think that fixes my problem.

user error 🥇

esatterwhite commented 7 years ago

will the ready callback be executed immediately if hemera is ready ? basically is it ok to call hemera.ready more than once or if the ready event has already been triggered.

or do you only have 1 shot?

silly example, but this:


hemera.ready(() => {
  hemera.ready(() => {
     // will I ever get here?
  })
})

StarpTech commented 7 years ago

Yes, the event is called once when nats and all plugins were initialized.

StarpTech commented 7 years ago

You can't listen to the ready event multiple times.

StarpTech commented 7 years ago

Can be closed ?

esatterwhite commented 7 years ago

Yep. Thanks for your help

hemerajs / hemera