Disambiguate context loss from sampling when creating child spans (#416)

PR-URL: #416

src/trace-api.js

@@ -100,11 +100,8 @@ RootSpan.prototype.getTraceContext = function() {
   return this.serializedTraceContext_;
 };
 
-var nullSpan = {
-  addLabel: function(k, v) {},
-  endSpan: function() {},
-  getTraceContext: function() { return ''; }
-};
+// A sentinal stored in CLS to indicate that the current request was not sampled.
+var nullSpan = {};
 
 /**
  * The functional implementation of the Trace API
@@ -164,19 +161,20 @@ TraceApiImplementation.prototype.runInRootSpan = function(options, fn) {
  * @returns A new ChildSpan object, or null if there is no active root span.
  */
 TraceApiImplementation.prototype.createChildSpan = function(options) {
-  var rootSpan = getRootSpan_(this);
-  if (rootSpan) {
+  var rootSpan = cls.getRootContext();
+  if (!rootSpan) {
+    // Lost context
+    this.logger_.warn(this.pluginName_ + ': Attempted to create child span ' +
+      'without root');
+    return null;
+  } else if (rootSpan === nullSpan) {
+    // Chose not to sample
+    return null;
+  } else {
     options = options || {};
     var childContext = this.agent_.startSpan(options.name, {},
       options.skipFrames ? options.skipFrames + 2 : 2);
     return new ChildSpan(this.agent_, childContext);
-  } else {
-    // TODO: Elevate to warn if this results from a loss of context.
-    // We can't do this now because we don't have enough data here to tell the
-    // difference.
-    this.logger_.debug(this.pluginName_ + ': Attempted to create child span ' +
-      'without root');
-    return null;
   }
 };
 
@@ -221,8 +219,8 @@ TraceApiImplementation.prototype.labels = TraceLabels;
  */
 var phantomApiImpl = {
   enhancedDatabaseReportingEnabled: function() { return false; },
-  runInRootSpan: function(opts, fn) { return fn(nullSpan); },
-  createChildSpan: function(opts) { return nullSpan; },
+  runInRootSpan: function(opts, fn) { return fn(null); },
+  createChildSpan: function(opts) { return null; },
   wrap: function(fn) { return fn; },
   wrapEmitter: function(ee) {},
   constants: constants,
@@ -291,6 +289,7 @@ function createRootSpan_(api, options, skipFrames) {
   incomingTraceContext = incomingTraceContext || {};
   if (!api.agent_.shouldTrace(options.url || '',
         incomingTraceContext.options)) {
+    cls.setRootContext(nullSpan);
     return null;
   }
   var rootContext = api.agent_.createRootSpanData(options.name,
@@ -299,13 +298,3 @@ function createRootSpan_(api, options, skipFrames) {
     skipFrames + 1);
   return new RootSpan(api.agent_, rootContext);
 }
-
-function getRootSpan_(api) {
-  if (cls.getRootContext()) {
-    return new RootSpan(api.agent_, cls.getRootContext());
-  } else {
-    api.logger_.warn('Attempted to get root span when it doesn\'t' +
-      ' exist');
-    return null;
-  }
-}

test/plugins/common.js

@@ -55,8 +55,8 @@ function replaceFunction(target, prop, fn) {
   return old;
 }
 
-function replaceDebugLogger(agent, fn) {
-  return replaceFunction(agent.private_().logger, 'debug', fn);
+function replaceWarnLogger(agent, fn) {
+  return replaceFunction(agent.private_().logger, 'warn', fn);
 }
 
 function replaceTracingPolicy(agent, fn) {
@@ -260,7 +260,7 @@ module.exports = {
   getTraces: getTraces,
   runInTransaction: runInTransaction,
   getShouldTraceArgs: getShouldTraceArgs,
-  replaceDebugLogger: replaceDebugLogger,
+  replaceWarnLogger: replaceWarnLogger,
   replaceTracingPolicy: replaceTracingPolicy,
   createRootSpanData: createRootSpanData,
   clearNamespace: clearNamespace,

test/plugins/test-plugins-interop-mongo-express.js

@@ -29,14 +29,14 @@ var server;
 
 describe('mongodb + express', function() {
   var agent;
-  var oldDebug;
+  var oldWarn;
   var mongoose;
   var express;
   before(function() {
     agent = require('../..').start();
     express = require('./fixtures/express4');
     mongoose = require('./fixtures/mongoose4');
-    oldDebug = common.replaceDebugLogger(agent,
+    oldWarn = common.replaceWarnLogger(agent,
       function(error) {
         assert(error.indexOf('mongo') === -1, error);
     });
@@ -57,7 +57,7 @@ describe('mongodb + express', function() {
       http.get({port: common.serverPort}, function(res) {
         server.close();
         common.cleanTraces(agent);
-        common.replaceDebugLogger(agent, oldDebug);
+        common.replaceWarnLogger(agent, oldWarn);
         done();
       });
     });

test/test-grpc-context.js

@@ -52,16 +52,16 @@ Object.keys(versions).forEach(function(version) {
   var agent;
   var express;
   var grpc;
-  var httpDebugPrinted;
+  var httpLogCount;
   describe('express + ' + version, function() {
     before(function(done) {
       agent = require('..').start({ samplingRate: 0 });
       express = require('./plugins/fixtures/express4');
       grpc = require(versions[version]);
 
-      common.replaceDebugLogger(agent, function(msg) {
+      common.replaceWarnLogger(agent, function(msg) {
         if (msg.indexOf('http') !== -1) {
-          httpDebugPrinted = true;
+          httpLogCount++;
         }
       });
 
@@ -147,7 +147,7 @@ Object.keys(versions).forEach(function(version) {
     });
 
     beforeEach(function() {
-      httpDebugPrinted = false;
+      httpLogCount = 0;
     });
 
     after(function() {
@@ -156,7 +156,9 @@ Object.keys(versions).forEach(function(version) {
     });
 
     afterEach(function() {
-      assert.ok(httpDebugPrinted);
+      // We expect a single untraced http request for each test cooresponding to the
+      // top level request used to start the desired test.
+      assert.equal(httpLogCount, 1);
       common.cleanTraces(agent);
     });
 

test/test-no-self-tracing.js

@@ -18,7 +18,7 @@
 
 var assert = require('assert');
 var nock = require('nock');
-var newDebug = function(error) {
+var newWarn = function(error) {
   if (error.indexOf('http') !== -1) {
     assert(false, error);
   }
@@ -37,9 +37,9 @@ describe('test-no-self-tracing', function() {
                 .get('/computeMetadata/v1/project/project-id').reply(200);
     var agent = require('..').start({forceNewAgent_: true});
     require('http'); // Must require http to force patching of the module
-    var oldDebug = common.replaceDebugLogger(agent, newDebug);
+    var oldWarn = common.replaceWarnLogger(agent, newWarn);
     setTimeout(function() {
-      common.replaceDebugLogger(agent, oldDebug);
+      common.replaceWarnLogger(agent, oldWarn);
       scope.done();
       done();
     }, 200); // Need to wait for metadata access attempt
@@ -59,12 +59,12 @@ describe('test-no-self-tracing', function() {
     });
     common.avoidTraceWriterAuth(agent);
     require('http'); // Must require http to force patching of the module
-    var oldDebug = common.replaceDebugLogger(agent, newDebug);
+    var oldWarn = common.replaceWarnLogger(agent, newWarn);
     common.runInTransaction(agent, function(end) {
       end();
       setTimeout(function() {
         assert.equal(common.getTraces(agent).length, 0);
-        common.replaceDebugLogger(agent, oldDebug);
+        common.replaceWarnLogger(agent, oldWarn);
         metadataScope.done();
         apiScope.done();
         done();

test/test-plugins-sample-warning.js

@@ -26,25 +26,25 @@ var assert = require('assert');
 var http = require('http');
 
 describe('express + dbs', function() {
-  var debugCount = 0;
-  var oldDebug;
+  var untracedHttpSpanCount = 0;
+  var oldWarn;
   var agent;
 
   before(function() {
     agent = require('..').start({ samplingRate: 0 });
   });
 
   beforeEach(function() {
-    oldDebug = common.replaceDebugLogger(agent, function(msg) {
-      if (msg.indexOf('Attempted to create child span without root') !== -1) {
-        debugCount++;
+    oldWarn = common.replaceWarnLogger(agent, function(msg) {
+      if (msg.indexOf('http') !== -1) {
+        untracedHttpSpanCount++;
       }
     });
   });
 
   afterEach(function() {
-    common.replaceDebugLogger(agent, oldDebug);
-    debugCount = 0;
+    common.replaceWarnLogger(agent, oldWarn);
+    untracedHttpSpanCount = 0;
   });
 
   it('mongo should not warn', function(done) {
@@ -66,7 +66,7 @@ describe('express + dbs', function() {
         http.get({port: common.serverPort}, function(res) {
           server.close();
           common.cleanTraces(agent);
-          assert.equal(debugCount, 2);
+          assert.equal(untracedHttpSpanCount, 2);
           done();
         });
       });
@@ -89,7 +89,7 @@ describe('express + dbs', function() {
         http.get({port: common.serverPort + 1}, function(res) {
           server.close();
           common.cleanTraces(agent);
-          assert.equal(debugCount, 2);
+          assert.equal(untracedHttpSpanCount, 2);
           done();
         });
       });
@@ -110,7 +110,7 @@ describe('express + dbs', function() {
         http.get({port: common.serverPort + 2}, function(res) {
           server.close();
           common.cleanTraces(agent);
-          assert.equal(debugCount, 2);
+          assert.equal(untracedHttpSpanCount, 2);
           done();
         });
       });
@@ -137,7 +137,7 @@ describe('express + dbs', function() {
         http.get({port: common.serverPort + 3}, function(res) {
           server.close();
           common.cleanTraces(agent);
-          assert.equal(debugCount, 2);
+          assert.equal(untracedHttpSpanCount, 2);
           done();
         });
       });