From 5c759990a5c4e2499f12c8314829a72344235046 Mon Sep 17 00:00:00 2001 From: Ben Ripkens Date: Wed, 25 Apr 2018 15:11:54 +0200 Subject: [PATCH] fix(leak): HTTP agents with maxSockets: Infinity result in a large memory leak This memory leak cannot be truly fixed, as Node.js itself is keeping these sockets alive. cls-hooked context objects will therefore continue to exist as long as the socket hasn't been closed. We can only reduce the impact this has on a monitored system and the likeliness that this turns into a problem, by removing (potentially) large span objects from the CLS context objects. --- CHANGELOG.md | 1 + package-lock.json | 12 +- package.json | 3 +- src/tracing/cls.js | 99 ++-- src/tracing/clsHooked/context-legacy.js | 432 +++++++++++++++++ src/tracing/clsHooked/context.js | 486 +++++++++++++++++++ src/tracing/clsHooked/index.js | 40 ++ src/tracing/cls_test.js | 15 + src/tracing/instrumentation/elasticsearch.js | 5 +- src/tracing/instrumentation/httpClient.js | 7 +- src/tracing/instrumentation/httpServer.js | 6 +- src/tracing/instrumentation/ioredis.js | 7 +- src/tracing/instrumentation/kafka.js | 5 +- src/tracing/instrumentation/mongodb.js | 26 +- src/tracing/instrumentation/mysql.js | 7 +- src/tracing/instrumentation/redis.js | 5 +- 16 files changed, 1079 insertions(+), 77 deletions(-) create mode 100644 src/tracing/clsHooked/context-legacy.js create mode 100644 src/tracing/clsHooked/context.js create mode 100644 src/tracing/clsHooked/index.js diff --git a/CHANGELOG.md b/CHANGELOG.md index 53a6402c4b..3e8c20feed 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,7 @@ ## Unreleased - Prepare support for 128bit trace IDs. + - Reduce memory footprint when using HTTP agents with `maxSockets: Infinity`. ## 1.37.2 - MongoDB: Properly initialize and assure operationId is generated diff --git a/package-lock.json b/package-lock.json index 4b83338b45..90de4e3848 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,6 +1,6 @@ { "name": "instana-nodejs-sensor", - "version": "1.37.0", + "version": "1.37.2", "lockfileVersion": 1, "requires": true, "dependencies": { @@ -952,16 +952,6 @@ "shimmer": "1.1.0" } }, - "cls-hooked": { - "version": "4.2.2", - "resolved": "https://registry.npmjs.org/cls-hooked/-/cls-hooked-4.2.2.tgz", - "integrity": "sha512-J4Xj5f5wq/4jAvcdgoGsL3G103BtWpZrMo8NEinRltN+xpTZdI+M38pyQqhuFU/P792xkMFvnKSf+Lm81U1bxw==", - "requires": { - "async-hook-jl": "1.7.6", - "emitter-listener": "1.1.1", - "semver": "5.4.1" - } - }, "cluster-key-slot": { "version": "1.0.8", "resolved": "https://registry.npmjs.org/cluster-key-slot/-/cluster-key-slot-1.0.8.tgz", diff --git a/package.json b/package.json index 3ea5e77dd1..df5cbc2222 100644 --- a/package.json +++ b/package.json @@ -39,9 +39,10 @@ }, "homepage": "https://github.com/instana/nodejs-sensor#readme", "dependencies": { + "async-hook-jl": "^1.7.6", "bunyan": "^1.5.1", "cls-bluebird": "^2.1.0", - "cls-hooked": "4.2.2", + "emitter-listener": "^1.1.1", "event-loop-lag": "^1.3.0", "opentracing": "^0.14.1", "redis-commands": "^1.3.1", diff --git a/src/tracing/cls.js b/src/tracing/cls.js index 25f40002b2..6180dbd379 100644 --- a/src/tracing/cls.js +++ b/src/tracing/cls.js @@ -1,10 +1,12 @@ 'use strict'; +var transmission = require('./transmission'); var tracingUtil = require('./tracingUtil'); -var hooked = require('cls-hooked'); +var hooked = require('./clsHooked'); -var currentRootSpanKey = 'com.instana.rootSpan'; -var currentSpanKey = 'com.instana.span'; +var currentRootSpanKey = exports.currentRootSpanKey = 'com.instana.rootSpan'; +var currentSpanKey = exports.currentSpanKey = 'com.instana.span'; +var tracingLevelKey = exports.tracingLevelKey = 'com.instana.tl'; var exitSpans = ['node.http.client', 'elasticsearch', 'mongo', 'mysql', 'redis']; var entrySpans = ['node.http.server']; @@ -18,30 +20,15 @@ var entrySpans = ['node.http.server']; * cls.ns.run(function() {}); * */ -var instanaNamespace = 'instana.sensor'; -Object.defineProperty(exports, 'ns', { - get: function() { - return hooked.getNamespace(instanaNamespace) || hooked.createNamespace(instanaNamespace); - } -}); +exports.ns = hooked.createNamespace('instana.sensor'); /* * Start a new span and set it as the current span * */ -exports.startSpan = function startSpan(spanName, traceId, spanId) { - var span = { - f: tracingUtil.getFrom(), - async: false, - error: false, - ec: 0, - ts: Date.now(), - d: 0, - n: spanName, - stack: [], - data: null - }; - +exports.startSpan = function startSpan(spanName, traceId, spanId, modifyAsyncContext) { + modifyAsyncContext = modifyAsyncContext !== false; + var span = new InstanaSpan(spanName); var parentSpan = exports.ns.get(currentSpanKey); // If specified, use params @@ -61,14 +48,19 @@ exports.startSpan = function startSpan(spanName, traceId, spanId) { // Set span direction type (1=entry, 2=exit, 3=local/intermediate) if (entrySpans.indexOf(span.n) > -1) { span.k = 1; - exports.ns.set(currentRootSpanKey, span); + + if (!span.p && modifyAsyncContext) { + span.addCleanup(exports.ns.set(currentRootSpanKey, span)); + } } else if (exitSpans.indexOf(span.n) > -1) { span.k = 2; } else { span.k = 3; } - exports.ns.set(currentSpanKey, span); + if (modifyAsyncContext) { + span.addCleanup(exports.ns.set(currentSpanKey, span)); + } return span; }; @@ -85,7 +77,8 @@ exports.getCurrentRootSpan = function getCurrentRootSpan() { * */ exports.setCurrentSpan = function setCurrentSpan(span) { - return exports.ns.set(currentSpanKey, span); + exports.ns.set(currentSpanKey, span); + return span; }; /* @@ -107,9 +100,9 @@ exports.isTracing = function isTracing() { /* * Set the tracing level */ -var tracingLevelKey = 'tlKey'; exports.setTracingLevel = function setTracingLevel(level) { - return exports.ns.set(tracingLevelKey, level); + exports.ns.set(tracingLevelKey, level); + return level; }; /* @@ -154,3 +147,55 @@ exports.isExitSpan = function isExitSpan(span) { exports.isLocalSpan = function isLocalSpan(span) { return span.k === 3 ? true : false; }; + +/* + * Instead of creating a span object via {}, we use new InstanaSpan(). + * This will support better debugging, especially in cases where we need + * to analyse heap dumps. + * + * Furthermore, it allows us to add CLS cleanup logic to the span and to + * manipulate JSON serialization logic. + */ +function InstanaSpan(name) { + // properties that part of our span model + this.t = undefined; + this.s = undefined; + this.p = undefined; + this.k = undefined; + this.n = name; + this.f = tracingUtil.getFrom(); + this.async = false; + this.error = false; + this.ec = 0; + this.ts = Date.now(); + this.d = 0; + this.stack = []; + this.data = undefined; + + // properties used within the sensor that should not be transmitted to the agent/backend + // NOTE: If you add a new property, make sure that it is not enumerable, as it may otherwise be transmitted + // to the backend! + Object.defineProperty(this, 'cleanupFunctions', { + value: [], + writable: false, + enumerable: false + }); +} + +InstanaSpan.prototype.addCleanup = function addCleanup(fn) { + this.cleanupFunctions.push(fn); +}; + +InstanaSpan.prototype.transmit = function transmit() { + transmission.addSpan(this); + this.cleanup(); +}; + +InstanaSpan.prototype.cleanup = function cleanup() { + this.cleanupFunctions.forEach(call); + this.cleanupFunctions.length = 0; +}; + +function call(fn) { + fn(); +} diff --git a/src/tracing/clsHooked/context-legacy.js b/src/tracing/clsHooked/context-legacy.js new file mode 100644 index 0000000000..13db9f531d --- /dev/null +++ b/src/tracing/clsHooked/context-legacy.js @@ -0,0 +1,432 @@ +/* eslint-env es6 */ +/* eslint-disable */ + +// Copy of +// Jeff-Lewis, feat(compat): v4.2 for node v4.7-v8 (0ebfb9b on Jul 21, 2017) +// https://github.com/Jeff-Lewis/cls-hooked/blob/066c6c4027a7924b06997cc6b175b1841342abdc/context-legacy.js + +'use strict'; + +const util = require('util'); +const assert = require('assert'); +const wrapEmitter = require('emitter-listener'); +const asyncHook = require('async-hook-jl'); + +const CONTEXTS_SYMBOL = 'instanaClsHooked@contexts'; +const ERROR_SYMBOL = 'instanaClsHookedError@context'; + +//const trace = []; + +const invertedProviders = []; +for (let key in asyncHook.providers) { + invertedProviders[asyncHook.providers[key]] = key; +} + +const DEBUG_CLS_HOOKED = process.env.DEBUG_CLS_HOOKED; + +let currentUid = -1; + +module.exports = { + getNamespace: getNamespace, + createNamespace: createNamespace, + destroyNamespace: destroyNamespace, + reset: reset, + //trace: trace, + ERROR_SYMBOL: ERROR_SYMBOL +}; + +function Namespace(name) { + this.name = name; + // changed in 2.7: no default context + this.active = null; + this._set = []; + this.id = null; + this._contexts = new Map(); +} + +Namespace.prototype.set = function set(key, value) { + if (!this.active) { + throw new Error('No context available. ns.run() or ns.bind() must be called first.'); + } + + if (DEBUG_CLS_HOOKED) { + debug2(' SETTING KEY:' + key + '=' + value + ' in ns:' + this.name + ' uid:' + currentUid + ' active:' + + util.inspect(this.active, true)); + } + var context = this.active; + context[key] = value; + return function unset() { + if (context[key] === value) { + delete context[key]; + } + }; +}; + +Namespace.prototype.get = function get(key) { + if (!this.active) { + if (DEBUG_CLS_HOOKED) { + debug2(' GETTING KEY:' + key + '=undefined' + ' ' + this.name + ' uid:' + currentUid + ' active:' + + util.inspect(this.active, true)); + } + return undefined; + } + if (DEBUG_CLS_HOOKED) { + debug2(' GETTING KEY:' + key + '=' + this.active[key] + ' ' + this.name + ' uid:' + currentUid + ' active:' + + util.inspect(this.active, true)); + } + return this.active[key]; +}; + +Namespace.prototype.createContext = function createContext() { + if (DEBUG_CLS_HOOKED) { + debug2(' CREATING Context: ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' ' + ' active:' + + util.inspect(this.active, true, 2, true)); + } + + let context = Object.create(this.active ? this.active : Object.prototype); + context._ns_name = this.name; + context.id = currentUid; + + if (DEBUG_CLS_HOOKED) { + debug2(' CREATED Context: ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' ' + ' context:' + + util.inspect(context, true, 2, true)); + } + + return context; +}; + +Namespace.prototype.run = function run(fn) { + let context = this.createContext(); + this.enter(context); + try { + if (DEBUG_CLS_HOOKED) { + debug2(' BEFORE RUN: ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' ' + + util.inspect(context)); + } + fn(context); + return context; + } + catch (exception) { + if (exception) { + exception[ERROR_SYMBOL] = context; + } + throw exception; + } + finally { + if (DEBUG_CLS_HOOKED) { + debug2(' AFTER RUN: ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' ' + + util.inspect(context)); + } + this.exit(context); + } +}; + +Namespace.prototype.runAndReturn = function runAndReturn(fn) { + var value; + this.run(function (context) { + value = fn(context); + }); + return value; +}; + +/** + * Uses global Promise and assumes Promise is cls friendly or wrapped already. + * @param {function} fn + * @returns {*} + */ +Namespace.prototype.runPromise = function runPromise(fn) { + let context = this.createContext(); + this.enter(context); + + let promise = fn(context); + if (!promise || !promise.then || !promise.catch) { + throw new Error('fn must return a promise.'); + } + + if (DEBUG_CLS_HOOKED) { + debug2(' BEFORE runPromise: ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' ' + + util.inspect(context)); + } + + return promise + .then(result => { + if (DEBUG_CLS_HOOKED) { + debug2(' AFTER runPromise: ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' ' + + util.inspect(context)); + } + this.exit(context); + return result; + }) + .catch(err => { + err[ERROR_SYMBOL] = context; + if (DEBUG_CLS_HOOKED) { + debug2(' AFTER runPromise: ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' ' + + util.inspect(context)); + } + this.exit(context); + throw err; + }); +}; + +Namespace.prototype.bind = function bindFactory(fn, context) { + if (!context) { + if (!this.active) { + context = this.createContext(); + } + else { + context = this.active; + } + } + + let self = this; + return function clsBind() { + self.enter(context); + try { + return fn.apply(this, arguments); + } + catch (exception) { + if (exception) { + exception[ERROR_SYMBOL] = context; + } + throw exception; + } + finally { + self.exit(context); + } + }; +}; + +Namespace.prototype.enter = function enter(context) { + assert.ok(context, 'context must be provided for entering'); + if (DEBUG_CLS_HOOKED) { + debug2(' ENTER ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' context: ' + + util.inspect(context)); + } + + this._set.push(this.active); + this.active = context; +}; + +Namespace.prototype.exit = function exit(context) { + assert.ok(context, 'context must be provided for exiting'); + if (DEBUG_CLS_HOOKED) { + debug2(' EXIT ' + this.name + ' uid:' + currentUid + ' len:' + this._set.length + ' context: ' + + util.inspect(context)); + } + + // Fast path for most exits that are at the top of the stack + if (this.active === context) { + assert.ok(this._set.length, 'can\'t remove top context'); + this.active = this._set.pop(); + return; + } + + // Fast search in the stack using lastIndexOf + let index = this._set.lastIndexOf(context); + + if (index < 0) { + if (DEBUG_CLS_HOOKED) { + debug2('??ERROR?? context exiting but not entered - ignoring: ' + util.inspect(context)); + } + assert.ok(index >= 0, 'context not currently entered; can\'t exit. \n' + util.inspect(this) + '\n' + + util.inspect(context)); + } else { + assert.ok(index, 'can\'t remove top context'); + this._set.splice(index, 1); + } +}; + +Namespace.prototype.bindEmitter = function bindEmitter(emitter) { + assert.ok(emitter.on && emitter.addListener && emitter.emit, 'can only bind real EEs'); + + let namespace = this; + let thisSymbol = 'context@' + this.name; + + // Capture the context active at the time the emitter is bound. + function attach(listener) { + if (!listener) { + return; + } + if (!listener[CONTEXTS_SYMBOL]) { + listener[CONTEXTS_SYMBOL] = Object.create(null); + } + + listener[CONTEXTS_SYMBOL][thisSymbol] = { + namespace: namespace, + context: namespace.active + }; + } + + // At emit time, bind the listener within the correct context. + function bind(unwrapped) { + if (!(unwrapped && unwrapped[CONTEXTS_SYMBOL])) { + return unwrapped; + } + + let wrapped = unwrapped; + let unwrappedContexts = unwrapped[CONTEXTS_SYMBOL]; + Object.keys(unwrappedContexts).forEach(function (name) { + let thunk = unwrappedContexts[name]; + wrapped = thunk.namespace.bind(wrapped, thunk.context); + }); + return wrapped; + } + + wrapEmitter(emitter, attach, bind); +}; + +/** + * If an error comes out of a namespace, it will have a context attached to it. + * This function knows how to find it. + * + * @param {Error} exception Possibly annotated error. + */ +Namespace.prototype.fromException = function fromException(exception) { + return exception[ERROR_SYMBOL]; +}; + +function getNamespace(name) { + return process.namespaces[name]; +} + +function createNamespace(name) { + assert.ok(name, 'namespace must be given a name.'); + + if (DEBUG_CLS_HOOKED) { + debug2('CREATING NAMESPACE ' + name); + } + let namespace = new Namespace(name); + namespace.id = currentUid; + + asyncHook.addHooks({ + init(uid, handle, provider, parentUid, parentHandle) { + //parentUid = parentUid || currentUid; // Suggested usage but appears to work better for tracing modules. + currentUid = uid; + + //CHAIN Parent's Context onto child if none exists. This is needed to pass net-events.spec + if (parentUid) { + namespace._contexts.set(uid, namespace._contexts.get(parentUid)); + if (DEBUG_CLS_HOOKED) { + debug2('PARENTID: ' + name + ' uid:' + uid + ' parent:' + parentUid + ' provider:' + provider); + } + } else { + namespace._contexts.set(currentUid, namespace.active); + } + + if (DEBUG_CLS_HOOKED) { + debug2('INIT ' + name + ' uid:' + uid + ' parent:' + parentUid + ' provider:' + invertedProviders[provider] + + ' active:' + util.inspect(namespace.active, true)); + } + + }, + pre(uid, handle) { + currentUid = uid; + let context = namespace._contexts.get(uid); + if (context) { + if (DEBUG_CLS_HOOKED) { + debug2(' PRE ' + name + ' uid:' + uid + ' handle:' + getFunctionName(handle) + ' context:' + + util.inspect(context)); + } + + namespace.enter(context); + } else { + if (DEBUG_CLS_HOOKED) { + debug2(' PRE MISSING CONTEXT ' + name + ' uid:' + uid + ' handle:' + getFunctionName(handle)); + } + } + }, + post(uid, handle) { + currentUid = uid; + let context = namespace._contexts.get(uid); + if (context) { + if (DEBUG_CLS_HOOKED) { + debug2(' POST ' + name + ' uid:' + uid + ' handle:' + getFunctionName(handle) + ' context:' + + util.inspect(context)); + } + + namespace.exit(context); + } else { + if (DEBUG_CLS_HOOKED) { + debug2(' POST MISSING CONTEXT ' + name + ' uid:' + uid + ' handle:' + getFunctionName(handle)); + } + } + }, + destroy(uid) { + currentUid = uid; + + if (DEBUG_CLS_HOOKED) { + debug2('DESTROY ' + name + ' uid:' + uid + ' context:' + util.inspect(namespace._contexts.get(currentUid)) + + ' active:' + util.inspect(namespace.active, true)); + } + + namespace._contexts.delete(uid); + } + }); + + process.namespaces[name] = namespace; + return namespace; +} + +function destroyNamespace(name) { + let namespace = getNamespace(name); + + assert.ok(namespace, 'can\'t delete nonexistent namespace! "' + name + '"'); + assert.ok(namespace.id, 'don\'t assign to process.namespaces directly! ' + util.inspect(namespace)); + + process.namespaces[name] = null; +} + +function reset() { + // must unregister async listeners + if (process.namespaces) { + Object.keys(process.namespaces).forEach(function (name) { + destroyNamespace(name); + }); + } + process.namespaces = Object.create(null); +} + +process.namespaces = {}; + +if (asyncHook._state && !asyncHook._state.enabled) { + asyncHook.enable(); +} + +function debug2(msg) { + if (process.env.DEBUG) { + process._rawDebug(msg); + } +} + + +/*function debug(from, ns) { + process._rawDebug('DEBUG: ' + util.inspect({ + from: from, + currentUid: currentUid, + context: ns ? ns._contexts.get(currentUid) : 'no ns' + }, true, 2, true)); + }*/ + + +function getFunctionName(fn) { + if (!fn) { + return fn; + } + if (typeof fn === 'function') { + if (fn.name) { + return fn.name; + } + return (fn.toString().trim().match(/^function\s*([^\s(]+)/) || [])[1]; + } else if (fn.constructor && fn.constructor.name) { + return fn.constructor.name; + } +} + + +// Add back to callstack +if (DEBUG_CLS_HOOKED) { + var stackChain = require('stack-chain'); + for (var modifier in stackChain.filter._modifiers) { + stackChain.filter.deattach(modifier); + } +} diff --git a/src/tracing/clsHooked/context.js b/src/tracing/clsHooked/context.js new file mode 100644 index 0000000000..7fb17cbe94 --- /dev/null +++ b/src/tracing/clsHooked/context.js @@ -0,0 +1,486 @@ +/* eslint-env es6 */ +/* eslint-disable */ + +// Copy of +// Jeff-Lewis, fix(destroy): destroy based on asyncId only (3cf7539 on Jul 25, 2017) +// https://github.com/Jeff-Lewis/cls-hooked/blob/066c6c4027a7924b06997cc6b175b1841342abdc/context.js + +'use strict'; + +const util = require('util'); +const assert = require('assert'); +const wrapEmitter = require('emitter-listener'); +const async_hooks = require('async_hooks'); + +const CONTEXTS_SYMBOL = 'instanaClsHooked@contexts'; +const ERROR_SYMBOL = 'instanaClsHookedError@context'; + +const DEBUG_CLS_HOOKED = process.env.DEBUG_CLS_HOOKED; + +let currentUid = -1; + +module.exports = { + getNamespace: getNamespace, + createNamespace: createNamespace, + destroyNamespace: destroyNamespace, + reset: reset, + ERROR_SYMBOL: ERROR_SYMBOL +}; + +function Namespace(name) { + this.name = name; + // changed in 2.7: no default context + this.active = null; + this._set = []; + this.id = null; + this._contexts = new Map(); + this._indent = 0; +} + +Namespace.prototype.set = function set(key, value) { + if (!this.active) { + throw new Error('No context available. ns.run() or ns.bind() must be called first.'); + } + + var context = this.active; + context[key] = value; + + if (DEBUG_CLS_HOOKED) { + const indentStr = ' '.repeat(this._indent < 0 ? 0 : this._indent); + debug2(indentStr + 'CONTEXT-SET KEY:' + key + '=' + value + ' in ns:' + this.name + ' currentUid:' + currentUid + ' active:' + util.inspect(this.active, {showHidden:true, depth:2, colors:true})); + } + + return function unset() { + if (context[key] === value) { + delete context[key]; + } + }; +}; + +Namespace.prototype.get = function get(key) { + if (!this.active) { + if (DEBUG_CLS_HOOKED) { + const asyncHooksCurrentId = async_hooks.currentId(); + const triggerId = async_hooks.triggerAsyncId(); + const indentStr = ' '.repeat(this._indent < 0 ? 0 : this._indent); + //debug2(indentStr + 'CONTEXT-GETTING KEY NO ACTIVE NS:' + key + '=undefined' + ' (' + this.name + ') currentUid:' + currentUid + ' active:' + util.inspect(this.active, {showHidden:true, depth:2, colors:true})); + debug2(`${indentStr}CONTEXT-GETTING KEY NO ACTIVE NS: (${this.name}) ${key}=undefined currentUid:${currentUid} asyncHooksCurrentId:${asyncHooksCurrentId} triggerId:${triggerId} len:${this._set.length}`); + } + return undefined; + } + if (DEBUG_CLS_HOOKED) { + const asyncHooksCurrentId = async_hooks.executionAsyncId(); + const triggerId = async_hooks.triggerAsyncId(); + const indentStr = ' '.repeat(this._indent < 0 ? 0 : this._indent); + debug2(indentStr + 'CONTEXT-GETTING KEY:' + key + '=' + this.active[key] + ' (' + this.name + ') currentUid:' + currentUid + ' active:' + util.inspect(this.active, {showHidden:true, depth:2, colors:true})); + debug2(`${indentStr}CONTEXT-GETTING KEY: (${this.name}) ${key}=${this.active[key]} currentUid:${currentUid} asyncHooksCurrentId:${asyncHooksCurrentId} triggerId:${triggerId} len:${this._set.length} active:${util.inspect(this.active)}`); + } + return this.active[key]; +}; + +Namespace.prototype.createContext = function createContext() { + // Prototype inherit existing context if created a new child context within existing context. + let context = Object.create(this.active ? this.active : Object.prototype); + context._ns_name = this.name; + context.id = currentUid; + + if (DEBUG_CLS_HOOKED) { + const asyncHooksCurrentId = async_hooks.executionAsyncId(); + const triggerId = async_hooks.triggerAsyncId(); + const indentStr = ' '.repeat(this._indent < 0 ? 0 : this._indent); + debug2(`${indentStr}CONTEXT-CREATED Context: (${this.name}) currentUid:${currentUid} asyncHooksCurrentId:${asyncHooksCurrentId} triggerId:${triggerId} len:${this._set.length} context:${util.inspect(context, {showHidden:true, depth:2, colors:true})}`); + } + + return context; +}; + +Namespace.prototype.run = function run(fn) { + let context = this.createContext(); + this.enter(context); + + try { + if (DEBUG_CLS_HOOKED) { + const triggerId = async_hooks.triggerAsyncId(); + const asyncHooksCurrentId = async_hooks.executionAsyncId(); + const indentStr = ' '.repeat(this._indent < 0 ? 0 : this._indent); + debug2(`${indentStr}CONTEXT-RUN BEGIN: (${this.name}) currentUid:${currentUid} triggerId:${triggerId} asyncHooksCurrentId:${asyncHooksCurrentId} len:${this._set.length} context:${util.inspect(context)}`); + } + fn(context); + return context; + } catch (exception) { + if (exception) { + exception[ERROR_SYMBOL] = context; + } + throw exception; + } finally { + if (DEBUG_CLS_HOOKED) { + const triggerId = async_hooks.triggerAsyncId(); + const asyncHooksCurrentId = async_hooks.executionAsyncId(); + const indentStr = ' '.repeat(this._indent < 0 ? 0 : this._indent); + debug2(`${indentStr}CONTEXT-RUN END: (${this.name}) currentUid:${currentUid} triggerId:${triggerId} asyncHooksCurrentId:${asyncHooksCurrentId} len:${this._set.length} ${util.inspect(context)}`); + } + this.exit(context); + } +}; + +Namespace.prototype.runAndReturn = function runAndReturn(fn) { + let value; + this.run(function (context) { + value = fn(context); + }); + return value; +}; + +/** + * Uses global Promise and assumes Promise is cls friendly or wrapped already. + * @param {function} fn + * @returns {*} + */ +Namespace.prototype.runPromise = function runPromise(fn) { + let context = this.createContext(); + this.enter(context); + + let promise = fn(context); + if (!promise || !promise.then || !promise.catch) { + throw new Error('fn must return a promise.'); + } + + if (DEBUG_CLS_HOOKED) { + debug2('CONTEXT-runPromise BEFORE: (' + this.name + ') currentUid:' + currentUid + ' len:' + this._set.length + ' ' + util.inspect(context)); + } + + return promise + .then(result => { + if (DEBUG_CLS_HOOKED) { + debug2('CONTEXT-runPromise AFTER then: (' + this.name + ') currentUid:' + currentUid + ' len:' + this._set.length + ' ' + util.inspect(context)); + } + this.exit(context); + return result; + }) + .catch(err => { + err[ERROR_SYMBOL] = context; + if (DEBUG_CLS_HOOKED) { + debug2('CONTEXT-runPromise AFTER catch: (' + this.name + ') currentUid:' + currentUid + ' len:' + this._set.length + ' ' + util.inspect(context)); + } + this.exit(context); + throw err; + }); +}; + +Namespace.prototype.bind = function bindFactory(fn, context) { + if (!context) { + if (!this.active) { + context = this.createContext(); + } else { + context = this.active; + } + } + + let self = this; + return function clsBind() { + self.enter(context); + try { + return fn.apply(this, arguments); + } catch (exception) { + if (exception) { + exception[ERROR_SYMBOL] = context; + } + throw exception; + } finally { + self.exit(context); + } + }; +}; + +Namespace.prototype.enter = function enter(context) { + assert.ok(context, 'context must be provided for entering'); + if (DEBUG_CLS_HOOKED) { + const asyncHooksCurrentId = async_hooks.executionAsyncId(); + const triggerId = async_hooks.triggerAsyncId(); + const indentStr = ' '.repeat(this._indent < 0 ? 0 : this._indent); + debug2(`${indentStr}CONTEXT-ENTER: (${this.name}) currentUid:${currentUid} triggerId:${triggerId} asyncHooksCurrentId:${asyncHooksCurrentId} len:${this._set.length} ${util.inspect(context)}`); + } + + this._set.push(this.active); + this.active = context; +}; + +Namespace.prototype.exit = function exit(context) { + assert.ok(context, 'context must be provided for exiting'); + if (DEBUG_CLS_HOOKED) { + const asyncHooksCurrentId = async_hooks.executionAsyncId(); + const triggerId = async_hooks.triggerAsyncId(); + const indentStr = ' '.repeat(this._indent < 0 ? 0 : this._indent); + debug2(`${indentStr}CONTEXT-EXIT: (${this.name}) currentUid:${currentUid} triggerId:${triggerId} asyncHooksCurrentId:${asyncHooksCurrentId} len:${this._set.length} ${util.inspect(context)}`); + } + + // Fast path for most exits that are at the top of the stack + if (this.active === context) { + assert.ok(this._set.length, 'can\'t remove top context'); + this.active = this._set.pop(); + return; + } + + // Fast search in the stack using lastIndexOf + let index = this._set.lastIndexOf(context); + + if (index < 0) { + if (DEBUG_CLS_HOOKED) { + debug2('??ERROR?? context exiting but not entered - ignoring: ' + util.inspect(context)); + } + assert.ok(index >= 0, 'context not currently entered; can\'t exit. \n' + util.inspect(this) + '\n' + util.inspect(context)); + } else { + assert.ok(index, 'can\'t remove top context'); + this._set.splice(index, 1); + } +}; + +Namespace.prototype.bindEmitter = function bindEmitter(emitter) { + assert.ok(emitter.on && emitter.addListener && emitter.emit, 'can only bind real EEs'); + + let namespace = this; + let thisSymbol = 'context@' + this.name; + + // Capture the context active at the time the emitter is bound. + function attach(listener) { + if (!listener) { + return; + } + if (!listener[CONTEXTS_SYMBOL]) { + listener[CONTEXTS_SYMBOL] = Object.create(null); + } + + listener[CONTEXTS_SYMBOL][thisSymbol] = { + namespace: namespace, + context: namespace.active + }; + } + + // At emit time, bind the listener within the correct context. + function bind(unwrapped) { + if (!(unwrapped && unwrapped[CONTEXTS_SYMBOL])) { + return unwrapped; + } + + let wrapped = unwrapped; + let unwrappedContexts = unwrapped[CONTEXTS_SYMBOL]; + Object.keys(unwrappedContexts).forEach(function (name) { + let thunk = unwrappedContexts[name]; + wrapped = thunk.namespace.bind(wrapped, thunk.context); + }); + return wrapped; + } + + wrapEmitter(emitter, attach, bind); +}; + +/** + * If an error comes out of a namespace, it will have a context attached to it. + * This function knows how to find it. + * + * @param {Error} exception Possibly annotated error. + */ +Namespace.prototype.fromException = function fromException(exception) { + return exception[ERROR_SYMBOL]; +}; + +function getNamespace(name) { + return process.namespaces[name]; +} + +function createNamespace(name) { + assert.ok(name, 'namespace must be given a name.'); + + if (DEBUG_CLS_HOOKED) { + debug2(`NS-CREATING NAMESPACE (${name})`); + } + let namespace = new Namespace(name); + namespace.id = currentUid; + + const hook = async_hooks.createHook({ + init(asyncId, type, triggerId, resource) { + currentUid = async_hooks.executionAsyncId(); + + //CHAIN Parent's Context onto child if none exists. This is needed to pass net-events.spec + // let initContext = namespace.active; + // if(!initContext && triggerId) { + // let parentContext = namespace._contexts.get(triggerId); + // if (parentContext) { + // namespace.active = parentContext; + // namespace._contexts.set(currentUid, parentContext); + // if (DEBUG_CLS_HOOKED) { + // const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + // debug2(`${indentStr}INIT [${type}] (${name}) WITH PARENT CONTEXT asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, true)} resource:${resource}`); + // } + // } else if (DEBUG_CLS_HOOKED) { + // const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + // debug2(`${indentStr}INIT [${type}] (${name}) MISSING CONTEXT asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, true)} resource:${resource}`); + // } + // }else { + // namespace._contexts.set(currentUid, namespace.active); + // if (DEBUG_CLS_HOOKED) { + // const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + // debug2(`${indentStr}INIT [${type}] (${name}) asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, true)} resource:${resource}`); + // } + // } + if(namespace.active) { + namespace._contexts.set(asyncId, namespace.active); + + if (DEBUG_CLS_HOOKED) { + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}INIT [${type}] (${name}) asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, {showHidden:true, depth:2, colors:true})} resource:${resource}`); + } + }else if(currentUid === 0){ + // CurrentId will be 0 when triggered from C++. Promise events + // https://github.com/nodejs/node/blob/master/doc/api/async_hooks.md#triggerid + const triggerId = async_hooks.triggerAsyncId(); + const triggerIdContext = namespace._contexts.get(triggerId); + if (triggerIdContext) { + namespace._contexts.set(asyncId, triggerIdContext); + if (DEBUG_CLS_HOOKED) { + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}INIT USING CONTEXT FROM TRIGGERID [${type}] (${name}) asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, { showHidden: true, depth: 2, colors: true })} resource:${resource}`); + } + } else if (DEBUG_CLS_HOOKED) { + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}INIT MISSING CONTEXT [${type}] (${name}) asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, { showHidden: true, depth: 2, colors: true })} resource:${resource}`); + } + } + + + if(DEBUG_CLS_HOOKED && type === 'PROMISE'){ + debug2(util.inspect(resource, {showHidden: true})); + const parentId = resource.parentId; + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}INIT RESOURCE-PROMISE [${type}] (${name}) parentId:${parentId} asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, {showHidden:true, depth:2, colors:true})} resource:${resource}`); + } + + }, + before(asyncId) { + currentUid = async_hooks.executionAsyncId(); + let context; + + /* + if(currentUid === 0){ + // CurrentId will be 0 when triggered from C++. Promise events + // https://github.com/nodejs/node/blob/master/doc/api/async_hooks.md#triggerid + //const triggerId = async_hooks.triggerAsyncId(); + context = namespace._contexts.get(asyncId); // || namespace._contexts.get(triggerId); + }else{ + context = namespace._contexts.get(currentUid); + } + */ + + //HACK to work with promises until they are fixed in node > 8.1.1 + context = namespace._contexts.get(asyncId) || namespace._contexts.get(currentUid); + + if (context) { + if (DEBUG_CLS_HOOKED) { + const triggerId = async_hooks.triggerAsyncId(); + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}BEFORE (${name}) asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, {showHidden:true, depth:2, colors:true})} context:${util.inspect(context)}`); + namespace._indent += 2; + } + + namespace.enter(context); + + } else if (DEBUG_CLS_HOOKED) { + const triggerId = async_hooks.triggerAsyncId(); + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}BEFORE MISSING CONTEXT (${name}) asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, {showHidden:true, depth:2, colors:true})} namespace._contexts:${util.inspect(namespace._contexts, {showHidden:true, depth:2, colors:true})}`); + namespace._indent += 2; + } + }, + after(asyncId) { + currentUid = async_hooks.executionAsyncId(); + let context; // = namespace._contexts.get(currentUid); + /* + if(currentUid === 0){ + // CurrentId will be 0 when triggered from C++. Promise events + // https://github.com/nodejs/node/blob/master/doc/api/async_hooks.md#triggerid + //const triggerId = async_hooks.triggerAsyncId(); + context = namespace._contexts.get(asyncId); // || namespace._contexts.get(triggerId); + }else{ + context = namespace._contexts.get(currentUid); + } + */ + //HACK to work with promises until they are fixed in node > 8.1.1 + context = namespace._contexts.get(asyncId) || namespace._contexts.get(currentUid); + + if (context) { + if (DEBUG_CLS_HOOKED) { + const triggerId = async_hooks.triggerAsyncId(); + namespace._indent -= 2; + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}AFTER (${name}) asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, {showHidden:true, depth:2, colors:true})} context:${util.inspect(context)}`); + } + + namespace.exit(context); + + } else if (DEBUG_CLS_HOOKED) { + const triggerId = async_hooks.triggerAsyncId(); + namespace._indent -= 2; + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}AFTER MISSING CONTEXT (${name}) asyncId:${asyncId} currentUid:${currentUid} triggerId:${triggerId} active:${util.inspect(namespace.active, {showHidden:true, depth:2, colors:true})} context:${util.inspect(context)}`); + } + }, + destroy(asyncId) { + currentUid = async_hooks.executionAsyncId(); + if (DEBUG_CLS_HOOKED) { + const triggerId = async_hooks.triggerAsyncId(); + const indentStr = ' '.repeat(namespace._indent < 0 ? 0 : namespace._indent); + debug2(`${indentStr}DESTROY (${name}) currentUid:${currentUid} asyncId:${asyncId} triggerId:${triggerId} active:${util.inspect(namespace.active, {showHidden:true, depth:2, colors:true})} context:${util.inspect(namespace._contexts.get(currentUid))}`); + } + + namespace._contexts.delete(asyncId); + } + }); + + hook.enable(); + + process.namespaces[name] = namespace; + return namespace; +} + +function destroyNamespace(name) { + let namespace = getNamespace(name); + + assert.ok(namespace, 'can\'t delete nonexistent namespace! "' + name + '"'); + assert.ok(namespace.id, 'don\'t assign to process.namespaces directly! ' + util.inspect(namespace)); + + process.namespaces[name] = null; +} + +function reset() { + // must unregister async listeners + if (process.namespaces) { + Object.keys(process.namespaces).forEach(function (name) { + destroyNamespace(name); + }); + } + process.namespaces = Object.create(null); +} + +process.namespaces = {}; + +//const fs = require('fs'); +function debug2(...args) { + if (DEBUG_CLS_HOOKED) { + //fs.writeSync(1, `${util.format(...args)}\n`); + process._rawDebug(`${util.format(...args)}`); + } +} + +/*function getFunctionName(fn) { + if (!fn) { + return fn; + } + if (typeof fn === 'function') { + if (fn.name) { + return fn.name; + } + return (fn.toString().trim().match(/^function\s*([^\s(]+)/) || [])[1]; + } else if (fn.constructor && fn.constructor.name) { + return fn.constructor.name; + } +}*/ diff --git a/src/tracing/clsHooked/index.js b/src/tracing/clsHooked/index.js new file mode 100644 index 0000000000..a313e592ad --- /dev/null +++ b/src/tracing/clsHooked/index.js @@ -0,0 +1,40 @@ +/* eslint-env es6 */ +/* eslint-disable */ + +// This is a copy of cls-hooked + +// We are using a variation of cls-hooked, because we need to add additional cleanup logic. +// cls-hooked in its published version does not permit removal of values added to contexts. +// This is problematic for us in cases where sockets are long lived, e.g. http agents with +// maxSockets: Infinity. In such cases, the addition of the Node.js sensor and the values it +// adds to async contexts (which are kept alive due to the living sockets), can tip a Node.js +// process over the edge. +// +// See also: +// https://github.com/Jeff-Lewis/cls-hooked/issues/21 +// https://github.com/Jeff-Lewis/cls-hooked/issues/11 + +// Changes: +// - rename the symbols to avoid name clashes +// - have Namespace.prototype.set return a function which can be used to unset the value from the context +// on which it was originally set. + +// Copy of +// Jeff-Lewis, feat(compat): v4.2 for node v4.7-v8 (0ebfb9b on Jul 21, 2017) +// https://github.com/Jeff-Lewis/cls-hooked/blob/066c6c4027a7924b06997cc6b175b1841342abdc/index.js + +'use strict'; + +const semver = require('semver'); + +/** + * In order to increase node version support, this loads the version of context + * that is appropriate for the version of on nodejs that is running. + * Node < v8 - uses AsyncWrap and async-hooks-jl + * Node >= v8 - uses native async-hooks + */ +if(process && semver.gte(process.versions.node, '8.0.0')){ + module.exports = require('./context'); +}else{ + module.exports = require('./context-legacy'); +} diff --git a/src/tracing/cls_test.js b/src/tracing/cls_test.js index 3eac57a9d9..0543d951a9 100644 --- a/src/tracing/cls_test.js +++ b/src/tracing/cls_test.js @@ -123,4 +123,19 @@ describe('tracing/cls', function() { expect(cls.isExitSpan(localSpan)).to.equal(false); expect(cls.isLocalSpan(localSpan)).to.equal(true); }); + + it('must clean up span data from contexts once the span is transmitted', function() { + cls.ns.run(function(context) { + expect(context[cls.currentRootSpanKey]).to.equal(undefined); + expect(context[cls.currentSpanKey]).to.equal(undefined); + + var span = cls.startSpan('node.http.server'); + expect(context[cls.currentRootSpanKey]).to.equal(span); + expect(context[cls.currentSpanKey]).to.equal(span); + + span.cleanup(); + expect(context[cls.currentRootSpanKey]).to.equal(undefined); + expect(context[cls.currentSpanKey]).to.equal(undefined); + }); + }); }); diff --git a/src/tracing/instrumentation/elasticsearch.js b/src/tracing/instrumentation/elasticsearch.js index a8418ba7cc..aed1ed270d 100644 --- a/src/tracing/instrumentation/elasticsearch.js +++ b/src/tracing/instrumentation/elasticsearch.js @@ -1,7 +1,6 @@ 'use strict'; var requireHook = require('../../util/requireHook'); -var transmission = require('../transmission'); var tracingUtil = require('../tracingUtil'); var cls = require('../cls'); @@ -92,7 +91,7 @@ function instrumentApi(client, action, info) { } span.d = Date.now() - span.ts; span.error = false; - transmission.addSpan(span); + span.transmit(); return response; } @@ -101,7 +100,7 @@ function instrumentApi(client, action, info) { span.error = true; span.ec = 1; span.data.elasticsearch.error = tracingUtil.getErrorDetails(error); - transmission.addSpan(span); + span.transmit(); } }; } diff --git a/src/tracing/instrumentation/httpClient.js b/src/tracing/instrumentation/httpClient.js index 5ac3ba44b0..a4dfc69087 100644 --- a/src/tracing/instrumentation/httpClient.js +++ b/src/tracing/instrumentation/httpClient.js @@ -4,7 +4,6 @@ var coreHttpModule = require('http'); var discardUrlParameters = require('../../util/url').discardUrlParameters; var tracingConstants = require('../constants'); -var transmission = require('../transmission'); var tracingUtil = require('../tracingUtil'); var cls = require('../cls'); @@ -57,7 +56,7 @@ exports.init = function() { span.d = Date.now() - span.ts; span.error = res.statusCode >= 500; span.ec = span.error ? 1 : 0; - transmission.addSpan(span); + span.transmit(); if (givenResponseListener) { givenResponseListener(res); @@ -88,7 +87,7 @@ exports.init = function() { span.d = Date.now() - span.ts; span.error = true; span.ec = 1; - transmission.addSpan(span); + span.transmit(); }); clientRequest.on('error', function(err) { @@ -102,7 +101,7 @@ exports.init = function() { span.d = Date.now() - span.ts; span.error = true; span.ec = 1; - transmission.addSpan(span); + span.transmit(); }); }); return clientRequest; diff --git a/src/tracing/instrumentation/httpServer.js b/src/tracing/instrumentation/httpServer.js index f0cfeb89e8..8ca60d9016 100644 --- a/src/tracing/instrumentation/httpServer.js +++ b/src/tracing/instrumentation/httpServer.js @@ -5,7 +5,6 @@ var coreHttpModule = require('http'); var discardUrlParameters = require('../../util/url').discardUrlParameters; var tracingConstants = require('../constants'); -var transmission = require('../transmission'); var shimmer = require('shimmer'); var cls = require('../cls'); @@ -35,8 +34,7 @@ function shimEmit(realEmit) { var incomingTraceId = getExistingTraceId(req); var incomingSpanId = getExistingSpanId(req); - // expose the span for the express instrumentation - var span = req.__instanaHttpSpan = cls.startSpan(exports.spanName, incomingTraceId, incomingSpanId); + var span = cls.startSpan(exports.spanName, incomingTraceId, incomingSpanId); // Grab the URL before application code gets access to the incoming message. // We are doing this because libs like express are manipulating req.url when @@ -79,7 +77,7 @@ function shimEmit(realEmit) { span.error = res.statusCode >= 500; span.ec = span.error ? 1 : 0; span.d = Date.now() - span.ts; - transmission.addSpan(span); + span.transmit(); }); cls.ns.bindEmitter(req); diff --git a/src/tracing/instrumentation/ioredis.js b/src/tracing/instrumentation/ioredis.js index 1f95ff8dec..79fed7c370 100644 --- a/src/tracing/instrumentation/ioredis.js +++ b/src/tracing/instrumentation/ioredis.js @@ -3,7 +3,6 @@ var shimmer = require('shimmer'); var requireHook = require('../../util/requireHook'); -var transmission = require('../transmission'); var tracingUtil = require('../tracingUtil'); var cls = require('../cls'); @@ -97,7 +96,7 @@ function instrumentSendCommand(original) { span.data.redis.error = error.message; } - transmission.addSpan(span); + span.transmit(); } }; } @@ -125,7 +124,7 @@ function getMultiCommandEndCall(span) { span.data.redis.error = error.message; } - transmission.addSpan(span); + span.transmit(); }; } @@ -211,5 +210,5 @@ function pipelineCommandEndCallback(span, error, results) { } } - transmission.addSpan(span); + span.transmit(); } diff --git a/src/tracing/instrumentation/kafka.js b/src/tracing/instrumentation/kafka.js index 07b134f8be..3b7eaebbef 100644 --- a/src/tracing/instrumentation/kafka.js +++ b/src/tracing/instrumentation/kafka.js @@ -3,7 +3,6 @@ var shimmer = require('shimmer'); var requireHook = require('../../util/requireHook'); -var transmission = require('../transmission'); var tracingUtil = require('../tracingUtil'); var cls = require('../cls'); @@ -64,7 +63,7 @@ function instrumentedSend(ctx, originalSend, produceRequests, cb) { } span.d = Date.now() - span.ts; - transmission.addSpan(span); + span.transmit(); if (cb) { return cb.apply(this, arguments); @@ -97,7 +96,7 @@ function shimEmit(original) { return original.apply(originalThis, originalArgs); } finally { span.d = Date.now() - span.ts; - transmission.addSpan(span); + span.transmit(); } }); }; diff --git a/src/tracing/instrumentation/mongodb.js b/src/tracing/instrumentation/mongodb.js index c90ebb094e..5fcba1ff5b 100644 --- a/src/tracing/instrumentation/mongodb.js +++ b/src/tracing/instrumentation/mongodb.js @@ -2,7 +2,6 @@ var logger = require('../../logger').getLogger('tracing/mongodb'); var requireHook = require('../../util/requireHook'); -var transmission = require('../transmission'); var tracingUtil = require('../tracingUtil'); var cls = require('../cls'); @@ -56,23 +55,24 @@ function instrument(mongodb) { function onStarted(event) { - if (!isActive || !cls.isTracing()) { + if (!isActive) { return; } + var traceId = event.operationId.traceId; + var parentSpanId = event.operationId.parentSpanId; var parentSpan = cls.getCurrentSpan(); - var span = null; - - if (event.operationId == null) { - event.operationId = {}; + if (parentSpan && (traceId == null || parentSpanId == null)) { + traceId = parentSpan.t; + parentSpanId = parentSpan.s; } - if (event.operationId.traceId && event.operationId.parentSpanId) { - span = cls.startSpan('mongo', event.operationId.traceId, event.operationId.parentSpanId); - } else { - span = cls.startSpan('mongo'); + if (traceId == null || parentSpanId == null) { + // no parent found. We don't want to keep track of isolated mongodb spans + return; } - cls.setCurrentSpan(parentSpan); + + var span = cls.startSpan('mongo', traceId, parentSpanId, false); var host = event.connectionId.host; var port = event.connectionId.port; @@ -127,7 +127,7 @@ function onSucceeded(event) { spanData.span.d = Date.now() - spanData.span.ts; spanData.span.error = false; - transmission.addSpan(spanData.span); + spanData.span.transmit(); cleanup(event); } @@ -147,7 +147,7 @@ function onFailed(event) { spanData.span.d = Date.now() - spanData.span.ts; spanData.span.error = true; spanData.span.ec = 1; - transmission.addSpan(spanData.span); + spanData.span.transmit(); cleanup(event); } diff --git a/src/tracing/instrumentation/mysql.js b/src/tracing/instrumentation/mysql.js index 6b84c4abd2..8e547efc02 100644 --- a/src/tracing/instrumentation/mysql.js +++ b/src/tracing/instrumentation/mysql.js @@ -3,7 +3,6 @@ var shimmer = require('shimmer'); var requireHook = require('../../util/requireHook'); -var transmission = require('../transmission'); var tracingUtil = require('../tracingUtil'); var cls = require('../cls'); @@ -122,7 +121,7 @@ function instrumentedQuery(ctx, originalQuery, statementOrOpts, valuesOrCallback resultPromise.then(function(result) { span.d = Date.now() - span.ts; - transmission.addSpan(span); + span.transmit(); return result; }).catch(function(error) { span.ec = 1; @@ -130,7 +129,7 @@ function instrumentedQuery(ctx, originalQuery, statementOrOpts, valuesOrCallback span.data.mysql.error = tracingUtil.getErrorDetails(error); span.d = Date.now() - span.ts; - transmission.addSpan(span); + span.transmit(); return error; }); return resultPromise; @@ -145,7 +144,7 @@ function instrumentedQuery(ctx, originalQuery, statementOrOpts, valuesOrCallback } span.d = Date.now() - span.ts; - transmission.addSpan(span); + span.transmit(); if (originalCallback) { return originalCallback.apply(this, arguments); diff --git a/src/tracing/instrumentation/redis.js b/src/tracing/instrumentation/redis.js index 775948822c..d87466dac0 100644 --- a/src/tracing/instrumentation/redis.js +++ b/src/tracing/instrumentation/redis.js @@ -4,7 +4,6 @@ var commands = require('redis-commands'); var shimmer = require('shimmer'); var requireHook = require('../../util/requireHook'); -var transmission = require('../transmission'); var tracingUtil = require('../tracingUtil'); var cls = require('../cls'); @@ -96,7 +95,7 @@ function instrumentCommand(command, original) { span.data.redis.error = tracingUtil.getErrorDetails(error); } - transmission.addSpan(span); + span.transmit(); if (typeof userProvidedCallback === 'function') { return userProvidedCallback.apply(this, arguments); @@ -168,7 +167,7 @@ function instrumentMultiExec(isAtomic, original) { span.ec = span.data.redis.subCommands.length; } - transmission.addSpan(span); + span.transmit(); if (typeof userProvidedCallback === 'function') { return userProvidedCallback.apply(this, arguments);