add log for parent spans finished before their children

LICENSE-3rdparty.csv

@@ -5,6 +5,7 @@ require,koalas,MIT,Copyright 2013-2017 Brian Woodward
 require,lodash.kebabcase,MIT,Copyright JS Foundation and other contributors
 require,lodash.memoize,MIT,Copyright JS Foundation and other contributors
 require,lodash.pick,MIT,Copyright JS Foundation and other contributors
+require,lodash.truncate,MIT,Copyright JS Foundation and other contributors
 require,lodash.uniq,MIT,Copyright JS Foundation and other contributors
 require,methods,MIT,Copyright 2013-2014 TJ Holowaychuk 2013-2014 TJ Holowaychuk
 require,msgpack-lite,MIT,Copyright 2015 Yusuke Kawasaki

package.json

@@ -39,6 +39,7 @@
     "lodash.kebabcase": "^4.1.1",
     "lodash.memoize": "^4.1.2",
     "lodash.pick": "^4.4.0",
+    "lodash.truncate": "^4.4.2",
     "lodash.uniq": "^4.5.0",
     "methods": "^1.1.2",
     "msgpack-lite": "^0.1.26",

src/opentracing/span.js

@@ -2,6 +2,7 @@
 
 const opentracing = require('opentracing')
 const Span = opentracing.Span
+const truncate = require('lodash.truncate')
 const SpanContext = require('./span_context')
 const platform = require('../platform')
 const log = require('../log')
@@ -29,10 +30,25 @@ class DatadogSpan extends Span {
     this._startTime = startTime
 
     this._spanContext = this._createContext(parent)
+    this._spanContext.name = operationName
     this._spanContext.tags = tags
     this._spanContext.metrics = metrics
   }
 
+  toString () {
+    const spanContext = this.context()
+    const json = JSON.stringify({
+      traceId: spanContext.traceId,
+      spanId: spanContext.spanId,
+      parentId: spanContext.parentId,
+      service: spanContext.tags['service.name'],
+      name: spanContext.name,
+      resource: truncate(spanContext.tags['resource.name'], { length: 100 })
+    })
+
+    return `Span${json}`
+  }
+
   _createContext (parent) {
     let spanContext
 
@@ -99,11 +115,18 @@ class DatadogSpan extends Span {
 
     this._duration = finishTime - this._startTime
     this._spanContext.trace.finished.push(this)
+    this._spanContext.isFinished = true
     this._prioritySampler.sample(this)
 
     if (this._spanContext.sampled) {
       this._recorder.record(this)
     }
+
+    this._spanContext.children
+      .filter(child => !child.isFinished)
+      .forEach(child => {
+        log.error(`Parent span ${this} was finished before child span ${child}.`)
+      })
   }
 }
 

src/opentracing/span_context.js

@@ -9,6 +9,9 @@ class DatadogSpanContext extends SpanContext {
     this.traceId = props.traceId
     this.spanId = props.spanId
     this.parentId = props.parentId || null
+    this.name = props.name
+    this.children = props.children || []
+    this.isFinished = props.isFinished || false
     this.tags = props.tags || {}
     this.metrics = props.metrics || {}
     this.sampled = props.sampled === undefined || props.sampled

src/opentracing/tracer.js

@@ -37,7 +37,10 @@ class DatadogTracer extends Tracer {
     }
   }
 
+  // TODO: move references handling to the Span class
   _startSpan (name, fields) {
+    const references = getReferences(fields.references)
+    const parent = getParent(references)
     const tags = {
       'resource.name': name
     }
@@ -48,12 +51,18 @@ class DatadogTracer extends Tracer {
       tags.env = this._env
     }
 
-    return new Span(this, this._recorder, this._sampler, this._prioritySampler, {
+    const span = new Span(this, this._recorder, this._sampler, this._prioritySampler, {
       operationName: fields.operationName || name,
-      parent: getParent(fields.references),
+      parent: parent && parent.referencedContext(),
       tags: Object.assign(tags, this._tags, fields.tags),
       startTime: fields.startTime
     })
+
+    if (parent && parent.type() === opentracing.REFERENCE_CHILD_OF) {
+      parent.referencedContext().children.push(span)
+    }
+
+    return span
   }
 
   _inject (spanContext, format, carrier) {
@@ -77,32 +86,38 @@ class DatadogTracer extends Tracer {
   }
 }
 
-function getParent (references) {
-  let parent = null
+function getReferences (references) {
+  if (!references) return []
 
-  if (references) {
-    for (let i = 0; i < references.length; i++) {
-      const ref = references[i]
+  return references.filter(ref => {
+    if (!(ref instanceof Reference)) {
+      log.error(() => `Expected ${ref} to be an instance of opentracing.Reference`)
+      return false
+    }
 
-      if (!(ref instanceof Reference)) {
-        log.error(() => `Expected ${ref} to be an instance of opentracing.Reference`)
-        break
-      }
+    const spanContext = ref.referencedContext()
 
-      const spanContext = ref.referencedContext()
+    if (!(spanContext instanceof SpanContext)) {
+      log.error(() => `Expected ${spanContext} to be an instance of SpanContext`)
+      return false
+    }
 
-      if (!(spanContext instanceof SpanContext)) {
-        log.error(() => `Expected ${spanContext} to be an instance of SpanContext`)
-        break
-      }
+    return true
+  })
+}
+
+function getParent (references) {
+  let parent = null
+
+  for (let i = 0; i < references.length; i++) {
+    const ref = references[i]
 
-      if (ref.type() === opentracing.REFERENCE_CHILD_OF) {
-        parent = ref.referencedContext()
-        break
-      } else if (ref.type() === opentracing.REFERENCE_FOLLOWS_FROM) {
-        if (!parent) {
-          parent = ref.referencedContext()
-        }
+    if (ref.type() === opentracing.REFERENCE_CHILD_OF) {
+      parent = ref
+      break
+    } else if (ref.type() === opentracing.REFERENCE_FOLLOWS_FROM) {
+      if (!parent) {
+        parent = ref
       }
     }
   }

test/opentracing/span_context.spec.js

@@ -12,6 +12,9 @@ describe('SpanContext', () => {
       traceId: '123',
       spanId: '456',
       parentId: '789',
+      name: 'test',
+      children: ['span'],
+      isFinished: true,
       tags: {},
       metrics: {},
       sampled: false,
@@ -32,6 +35,9 @@ describe('SpanContext', () => {
       traceId: '123',
       spanId: '456',
       parentId: null,
+      name: undefined,
+      children: [],
+      isFinished: false,
       tags: {},
       metrics: {},
       sampled: true,

test/opentracing/tracer.spec.js

@@ -142,17 +142,19 @@ describe('Tracer', () => {
     it('should start a span that is the child of a span', () => {
       const parent = new SpanContext()
 
+      parent.children = []
       fields.references = [
         new Reference(opentracing.REFERENCE_CHILD_OF, parent)
       ]
 
       tracer = new Tracer(config)
-      tracer.startSpan('name', fields)
+      const span = tracer.startSpan('name', fields)
 
       expect(Span).to.have.been.calledWithMatch(tracer, recorder, sampler, prioritySampler, {
         operationName: 'name',
         parent
       })
+      expect(parent.children).to.include(span)
     })
 
     it('should start a span that follows from a span', () => {