Plugin unable to find currentRootSpan and "currentRootSpan != root on notifyEnd"

[pelzerim]

What version of OpenCensus are you using?

0.0.18

What version of Node are you using?

v10.15.3

What did you do?

I was trying to fix the mongodb plugin. This is a poc of the issue (in vanilla js):

index.js

const ocTracing = require('@opencensus/nodejs')
const ocagent = require('@opencensus/exporter-ocagent')
const propagation = require('@opencensus/propagation-jaeger')

const config = {
  enabled: true,
  port: 55678,
  host: 'ocagent',
  bufferTimeout: 500,
  debug: true
}

// Setup tracing
const jaeger = new propagation.JaegerFormat()
const exporter = new ocagent.OCAgentExporter(config)

const { tracer } = ocTracing.start({
  'exporter': exporter,
  'propagation': jaeger,
  'logLevel': 4,
  'plugins': {
    'mongodb': require.resolve('./mongodb-tracing')
  }
})

// Setup mongo
const mongoose = require('mongoose')

const mongoConnectionString =
  `mongodb://mongodb:27010/test`
const options = {
  useFindAndModify: false,
  useNewUrlParser: true
}
mongoose.connect(mongoConnectionString, options)

const TestSchema = new mongoose.Schema({ userId: String })
const Test = mongoose.model('Test', TestSchema)

// Express
var express = require('express')

var app = express()

app.get('/', async(req, res) => {
  await Test.findOneAndUpdate({ userId: 'test' }, { userId: Math.random() }, { upsert: true })
  await Test.findOneAndUpdate({ userId: 'test' }, { userId: Math.random() }, { upsert: true })
  res.send({})
})

var server = app.listen(3000, function() {
  console.log('app running on port.', server.address().port)
})

mongodb-tracing/index.js

/* eslint-disable no-prototype-builtins */
/* eslint-disable no-underscore-dangle */
function __export(m) {
  for (var p in m) if (!exports.hasOwnProperty(p)) exports[p] = m[p]
}
Object.defineProperty(exports, '__esModule', { value: true })
__export(require('./mongodb'))
//# sourceMappingURL=index.js.map

mongodb-tracing/mongodb.js

/* eslint-disable camelcase */
/* eslint-disable prefer-rest-params */

Object.defineProperty(exports, '__esModule', { value: true })
const core_1 = require('@opencensus/core')
const shimmer = require('shimmer')

/** MongoDB instrumentation plugin for Opencensus */
class MongoDBPlugin extends core_1.BasePlugin {
  /** Constructs a new MongoDBPlugin instance. */
  constructor(moduleName) {
    super(moduleName)
    this.CURSOR_FNS_FIRST = ['next', '_next']
  }
  /**
   * Patches MongoDB operations.
   */
  applyPatch() {
    this.logger.debug('Patched MongoDB')
    this.logger.debug('patching mongodb-core.Server.prototype.command')
    shimmer.wrap(this.moduleExports.Server.prototype, 'command', this.getPatchCommand())
    return this.moduleExports
  }
  /** Unpatches all MongoDB patched functions. */
  applyUnpatch() {
    shimmer.massUnwrap(this.moduleExports.Cursor.prototype, this.CURSOR_FNS_FIRST)
  }
  getPatchCommand() {
    const plugin = this
    return (original) => function(
      ns,
      // tslint:disable-next-line:no-any
      command, options, callback
    ) {
      const resultHandler = typeof options === 'function' ? options : callback
      plugin.logger.debug('plugin.tracer.currentRootSpan', plugin.tracer.currentRootSpan != undefined)
      if (plugin.tracer.currentRootSpan &&
        arguments.length > 0 &&
                    typeof resultHandler === 'function') {
        let type
        let database
        if (command.createIndexes) {
          type = 'createIndexes'
        } else if (command.findandmodify) {
          type = 'findAndModify'
        } else if (command.findAndModify) {
          type = 'findAndModify'
          database = `.${command.findAndModify}`
        } else if (command.ismaster) {
          type = 'isMaster'
        } else if (command.count) {
          type = 'count'
        } else {
          type = 'command'
        }

        const span = plugin.tracer.startChildSpan({
          name: `${ns}${database}.${type}`,
          kind: core_1.SpanKind.SERVER
        })

        if (typeof options === 'function') {
          return original.call(this, ns, command, plugin.patchEnd(span, options))
        }

        return original.call(this, ns, command, options, plugin.patchEnd(span, callback))
      }
      plugin.logger.debug('**** Did not find root span')
      return original.apply(this, arguments)
    }
  }
  patchEnd(span, resultHandler) {
    // tslint:disable-next-line:no-any
    return function patchedEnd() {
      span.end()
      return resultHandler.apply(this, arguments)
    }
  }
}
exports.MongoDBPlugin = MongoDBPlugin
const plugin = new MongoDBPlugin('mongodb')
exports.plugin = plugin

What did you expect to see?

When doing GET localhost:3000 I expect the following to happen:

• http creates a root span
• the two calls to mongo inside the express route create child spans on that root span

What did you see instead?

The first mongo function call is unable to find a plugin.tracer.currentRpptSpan, but the second mongo call can find one.
Additionally, the debugger returns 'currentRootSpan != root on notifyEnd. Need more investigation.'

Additional context

After doing a deep dive into the code I found that trace/model/tracer.js's setCurrentRootSpan indeed gets called with the root span. But in internal/cls-ah.js somehow the current is replaced with one where rootspan == null before its retrieved from there.

I was unable to debug further and would be glad for some guidance on this.

There seem to be multiple Issues on this topic but the only current issue I was able to find, which might be related is this one #580