From 6ea733de908eb1e61195eeab04a125ec19db65eb Mon Sep 17 00:00:00 2001 From: Ayan Khan Date: Mon, 10 Jun 2024 15:53:58 -0400 Subject: [PATCH] Khanayan123/implement span events (#4386) * implement span events and record exception api --- packages/dd-trace/src/format.js | 23 +++++- packages/dd-trace/src/opentelemetry/span.js | 40 ++++++++-- packages/dd-trace/src/opentracing/span.js | 38 ++++++++++ packages/dd-trace/src/tagger.js | 11 ++- packages/dd-trace/test/encode/0.4.spec.js | 15 ++++ packages/dd-trace/test/encode/0.5.spec.js | 21 ++++++ packages/dd-trace/test/format.spec.js | 40 +++++++++- .../dd-trace/test/opentelemetry/span.spec.js | 73 ++++++++++++++++++- .../dd-trace/test/opentracing/span.spec.js | 37 ++++++++++ packages/dd-trace/test/tagger.spec.js | 29 ++++++++ 10 files changed, 315 insertions(+), 12 deletions(-) diff --git a/packages/dd-trace/src/format.js b/packages/dd-trace/src/format.js index 6d7c85ce039..fcb2a07d01d 100644 --- a/packages/dd-trace/src/format.js +++ b/packages/dd-trace/src/format.js @@ -34,6 +34,7 @@ function format (span) { const formatted = formatSpan(span) extractSpanLinks(formatted, span) + extractSpanEvents(formatted, span) extractRootTags(formatted, span) extractChunkTags(formatted, span) extractTags(formatted, span) @@ -88,6 +89,22 @@ function extractSpanLinks (trace, span) { if (links.length > 0) { trace.meta['_dd.span_links'] = JSON.stringify(links) } } +function extractSpanEvents (trace, span) { + const events = [] + if (span._events) { + for (const event of span._events) { + const formattedEvent = { + name: event.name, + time_unix_nano: Math.round(event.startTime * 1e6), + attributes: event.attributes && Object.keys(event.attributes).length > 0 ? event.attributes : undefined + } + + events.push(formattedEvent) + } + } + if (events.length > 0) { trace.meta.events = JSON.stringify(events) } +} + function extractTags (trace, span) { const context = span.context() const origin = context._trace.origin @@ -134,7 +151,10 @@ function extractTags (trace, span) { case ERROR_STACK: // HACK: remove when implemented in the backend if (context._name !== 'fs.operation') { - trace.error = 1 + // HACK: to ensure otel.recordException does not influence trace.error + if (tags.setTraceError) { + trace.error = 1 + } } else { break } @@ -142,7 +162,6 @@ function extractTags (trace, span) { addTag(trace.meta, trace.metrics, tag, tags[tag]) } } - setSingleSpanIngestionTags(trace, context._spanSampling) addTag(trace.meta, trace.metrics, 'language', 'javascript') diff --git a/packages/dd-trace/src/opentelemetry/span.js b/packages/dd-trace/src/opentelemetry/span.js index 5c1be3f1e60..5a8fb29c693 100644 --- a/packages/dd-trace/src/opentelemetry/span.js +++ b/packages/dd-trace/src/opentelemetry/span.js @@ -20,6 +20,20 @@ function hrTimeToMilliseconds (time) { return time[0] * 1e3 + time[1] / 1e6 } +function isTimeInput (startTime) { + if (typeof startTime === 'number') { + return true + } + if (startTime instanceof Date) { + return true + } + if (Array.isArray(startTime) && startTime.length === 2 && + typeof startTime[0] === 'number' && typeof startTime[1] === 'number') { + return true + } + return false +} + const spanKindNames = { [api.SpanKind.INTERNAL]: kinds.INTERNAL, [api.SpanKind.SERVER]: kinds.SERVER, @@ -196,11 +210,6 @@ class Span { return this } - addEvent (name, attributesOrStartTime, startTime) { - api.diag.warn('Events not supported') - return this - } - addLink (context, attributes) { // extract dd context const ddSpanContext = context._ddContext @@ -244,12 +253,29 @@ class Span { return this.ended === false } - recordException (exception) { + addEvent (name, attributesOrStartTime, startTime) { + startTime = attributesOrStartTime && isTimeInput(attributesOrStartTime) ? attributesOrStartTime : startTime + const hrStartTime = timeInputToHrTime(startTime || (performance.now() + timeOrigin)) + startTime = hrTimeToMilliseconds(hrStartTime) + + this._ddSpan.addEvent(name, attributesOrStartTime, startTime) + return this + } + + recordException (exception, timeInput) { + // HACK: identifier is added so that trace.error remains unchanged after a call to otel.recordException this._ddSpan.addTags({ [ERROR_TYPE]: exception.name, [ERROR_MESSAGE]: exception.message, - [ERROR_STACK]: exception.stack + [ERROR_STACK]: exception.stack, + doNotSetTraceError: true }) + const attributes = {} + if (exception.message) attributes['exception.message'] = exception.message + if (exception.type) attributes['exception.type'] = exception.type + if (exception.escaped) attributes['exception.escaped'] = exception.escaped + if (exception.stack) attributes['exception.stacktrace'] = exception.stack + this.addEvent(exception.name, attributes, timeInput) } get duration () { diff --git a/packages/dd-trace/src/opentracing/span.js b/packages/dd-trace/src/opentracing/span.js index 6cb9cb77b1b..f71cf329c02 100644 --- a/packages/dd-trace/src/opentracing/span.js +++ b/packages/dd-trace/src/opentracing/span.js @@ -67,6 +67,8 @@ class DatadogSpan { this._store = storage.getStore() this._duration = undefined + this._events = [] + // For internal use only. You probably want `context()._name`. // This name property is not updated when the span name changes. // This is necessary for span count metrics. @@ -163,6 +165,19 @@ class DatadogSpan { }) } + addEvent (name, attributesOrStartTime, startTime) { + const event = { name } + if (attributesOrStartTime) { + if (typeof attributesOrStartTime === 'object') { + event.attributes = this._sanitizeEventAttributes(attributesOrStartTime) + } else { + startTime = attributesOrStartTime + } + } + event.startTime = startTime || this._getTime() + this._events.push(event) + } + finish (finishTime) { if (this._duration !== undefined) { return @@ -221,7 +236,30 @@ class DatadogSpan { const [key, value] = entry addArrayOrScalarAttributes(key, value) }) + return sanitizedAttributes + } + + _sanitizeEventAttributes (attributes = {}) { + const sanitizedAttributes = {} + for (const key in attributes) { + const value = attributes[key] + if (Array.isArray(value)) { + const newArray = [] + for (const subkey in value) { + if (ALLOWED.includes(typeof value[subkey])) { + newArray.push(value[subkey]) + } else { + log.warn('Dropping span event attribute. It is not of an allowed type') + } + } + sanitizedAttributes[key] = newArray + } else if (ALLOWED.includes(typeof value)) { + sanitizedAttributes[key] = value + } else { + log.warn('Dropping span event attribute. It is not of an allowed type') + } + } return sanitizedAttributes } diff --git a/packages/dd-trace/src/tagger.js b/packages/dd-trace/src/tagger.js index aa3dd8efea4..41c8616a086 100644 --- a/packages/dd-trace/src/tagger.js +++ b/packages/dd-trace/src/tagger.js @@ -1,6 +1,10 @@ 'use strict' +const constants = require('./constants') const log = require('./log') +const ERROR_MESSAGE = constants.ERROR_MESSAGE +const ERROR_STACK = constants.ERROR_STACK +const ERROR_TYPE = constants.ERROR_TYPE const otelTagMap = { 'deployment.environment': 'env', @@ -14,7 +18,6 @@ function add (carrier, keyValuePairs, parseOtelTags = false) { if (Array.isArray(keyValuePairs)) { return keyValuePairs.forEach(tags => add(carrier, tags)) } - try { if (typeof keyValuePairs === 'string') { const segments = keyValuePairs.split(',') @@ -32,6 +35,12 @@ function add (carrier, keyValuePairs, parseOtelTags = false) { carrier[key.trim()] = value.trim() } } else { + // HACK: to ensure otel.recordException does not influence trace.error + if (ERROR_MESSAGE in keyValuePairs || ERROR_STACK in keyValuePairs || ERROR_TYPE in keyValuePairs) { + if (!('doNotSetTraceError' in keyValuePairs)) { + carrier.setTraceError = true + } + } Object.assign(carrier, keyValuePairs) } } catch (e) { diff --git a/packages/dd-trace/test/encode/0.4.spec.js b/packages/dd-trace/test/encode/0.4.spec.js index 13d20250109..564daf8e92e 100644 --- a/packages/dd-trace/test/encode/0.4.spec.js +++ b/packages/dd-trace/test/encode/0.4.spec.js @@ -185,6 +185,21 @@ describe('encode', () => { }) }) + it('should encode span events', () => { + const encodedLink = '[{"name":"Something went so wrong","time_unix_nano":1000000},' + + '{"name":"I can sing!!! acbdefggnmdfsdv k 2e2ev;!|=xxx","time_unix_nano":1633023102000000,' + + '"attributes":{"emotion":"happy","rating":9.8,"other":[1,9.5,1],"idol":false}}]' + + data[0].meta.events = encodedLink + + encoder.encode(data) + + const buffer = encoder.makePayload() + const decoded = msgpack.decode(buffer, { codec }) + const trace = decoded[0] + expect(trace[0].meta.events).to.deep.equal(encodedLink) + }) + it('should encode spanLinks', () => { const traceIdHigh = id('10') const traceId = id('1234abcd1234abcd') diff --git a/packages/dd-trace/test/encode/0.5.spec.js b/packages/dd-trace/test/encode/0.5.spec.js index 2ef925c60c3..ec7b36af08b 100644 --- a/packages/dd-trace/test/encode/0.5.spec.js +++ b/packages/dd-trace/test/encode/0.5.spec.js @@ -65,6 +65,27 @@ describe('encode 0.5', () => { expect(stringMap[trace[0][11]]).to.equal('') // unset }) + it('should encode span events', () => { + const encodedLink = '[{"name":"Something went so wrong","time_unix_nano":1000000},' + + '{"name":"I can sing!!! acbdefggnmdfsdv k 2e2ev;!|=xxx","time_unix_nano":1633023102000000,' + + '"attributes":{"emotion":"happy","rating":9.8,"other":[1,9.5,1],"idol":false}}]' + + data[0].meta.events = encodedLink + + encoder.encode(data) + + const buffer = encoder.makePayload() + const decoded = msgpack.decode(buffer, { codec }) + const stringMap = decoded[0] + const trace = decoded[1][0] + expect(stringMap).to.include('events') + expect(stringMap).to.include(encodedLink) + expect(trace[0][9]).to.include({ + [stringMap.indexOf('bar')]: stringMap.indexOf('baz'), + [stringMap.indexOf('events')]: stringMap.indexOf(encodedLink) + }) + }) + it('should encode span links', () => { const traceIdHigh = id('10') const traceId = id('1234abcd1234abcd') diff --git a/packages/dd-trace/test/format.spec.js b/packages/dd-trace/test/format.spec.js index b75c73d99a7..65cf8a4aa3e 100644 --- a/packages/dd-trace/test/format.spec.js +++ b/packages/dd-trace/test/format.spec.js @@ -87,6 +87,27 @@ describe('format', () => { }) describe('format', () => { + it('should format span events', () => { + span._events = [ + { name: 'Something went so wrong', startTime: 1 }, + { + name: 'I can sing!!! acbdefggnmdfsdv k 2e2ev;!|=xxx', + attributes: { emotion: 'happy', rating: 9.8, other: [1, 9.5, 1], idol: false }, + startTime: 1633023102 + } + ] + + trace = format(span) + const spanEvents = JSON.parse(trace.meta.events) + expect(spanEvents).to.deep.equal([{ + name: 'Something went so wrong', + time_unix_nano: 1000000 + }, { + name: 'I can sing!!! acbdefggnmdfsdv k 2e2ev;!|=xxx', + time_unix_nano: 1633023102000000, + attributes: { emotion: 'happy', rating: 9.8, other: [1, 9.5, 1], idol: false } + }]) + }) it('should convert a span to the correct trace format', () => { trace = format(span) @@ -403,14 +424,31 @@ describe('format', () => { }) }) - it('should set the error flag when there is an error-related tag', () => { + it('should not set the error flag when there is an error-related tag without a set trace tag', () => { + spanContext._tags[ERROR_TYPE] = 'Error' + spanContext._tags[ERROR_MESSAGE] = 'boom' + spanContext._tags[ERROR_STACK] = '' + + trace = format(span) + + expect(trace.error).to.equal(0) + }) + + it('should set the error flag when there is an error-related tag with should setTrace', () => { spanContext._tags[ERROR_TYPE] = 'Error' spanContext._tags[ERROR_MESSAGE] = 'boom' spanContext._tags[ERROR_STACK] = '' + spanContext._tags.setTraceError = 1 trace = format(span) expect(trace.error).to.equal(1) + + spanContext._tags[ERROR_TYPE] = 'foo' + spanContext._tags[ERROR_MESSAGE] = 'foo' + spanContext._tags[ERROR_STACK] = 'foo' + + expect(trace.error).to.equal(1) }) it('should not set the error flag for internal spans with error tags', () => { diff --git a/packages/dd-trace/test/opentelemetry/span.spec.js b/packages/dd-trace/test/opentelemetry/span.spec.js index 378067ae541..ecdea99a1fa 100644 --- a/packages/dd-trace/test/opentelemetry/span.spec.js +++ b/packages/dd-trace/test/opentelemetry/span.spec.js @@ -2,8 +2,12 @@ require('../setup/tap') -const { expect } = require('chai') +const sinon = require('sinon') +const { performance } = require('perf_hooks') +const { timeOrigin } = performance +const { timeInputToHrTime } = require('@opentelemetry/core') +const { expect } = require('chai') const tracer = require('../../').init() const api = require('@opentelemetry/api') @@ -347,6 +351,40 @@ describe('OTel Span', () => { } } + const error = new TestError() + const datenow = Date.now() + span.recordException(error, datenow) + + const { _tags } = span._ddSpan.context() + expect(_tags).to.have.property(ERROR_TYPE, error.name) + expect(_tags).to.have.property(ERROR_MESSAGE, error.message) + expect(_tags).to.have.property(ERROR_STACK, error.stack) + + const events = span._ddSpan._events + expect(events).to.have.lengthOf(1) + expect(events).to.deep.equal([{ + name: error.name, + attributes: { + 'exception.message': error.message, + 'exception.stacktrace': error.stack + }, + startTime: datenow + }]) + }) + + it('should record exception without passing in time', () => { + const stub = sinon.stub(performance, 'now').returns(60000) + const span = makeSpan('name') + + class TestError extends Error { + constructor () { + super('test message') + } + } + + const time = timeInputToHrTime(60000 + timeOrigin) + const timeInMilliseconds = time[0] * 1e3 + time[1] / 1e6 + const error = new TestError() span.recordException(error) @@ -354,6 +392,18 @@ describe('OTel Span', () => { expect(_tags).to.have.property(ERROR_TYPE, error.name) expect(_tags).to.have.property(ERROR_MESSAGE, error.message) expect(_tags).to.have.property(ERROR_STACK, error.stack) + + const events = span._ddSpan._events + expect(events).to.have.lengthOf(1) + expect(events).to.deep.equal([{ + name: error.name, + attributes: { + 'exception.message': error.message, + 'exception.stacktrace': error.stack + }, + startTime: timeInMilliseconds + }]) + stub.restore() }) it('should not set status on already ended spans', () => { @@ -402,4 +452,25 @@ describe('OTel Span', () => { expect(processor.onStart).to.have.been.calledWith(span, span._context) expect(processor.onEnd).to.have.been.calledWith(span) }) + it('should add span events', () => { + const span1 = makeSpan('span1') + const span2 = makeSpan('span2') + const datenow = Date.now() + span1.addEvent('Web page unresponsive', + { 'error.code': '403', 'unknown values': [1, ['h', 'a', [false]]] }, datenow) + span2.addEvent('Web page loaded') + span2.addEvent('Button changed color', { colors: [112, 215, 70], 'response.time': 134.3, success: true }) + const events1 = span1._ddSpan._events + const events2 = span2._ddSpan._events + expect(events1).to.have.lengthOf(1) + expect(events1).to.deep.equal([{ + name: 'Web page unresponsive', + startTime: datenow, + attributes: { + 'error.code': '403', + 'unknown values': [1] + } + }]) + expect(events2).to.have.lengthOf(2) + }) }) diff --git a/packages/dd-trace/test/opentracing/span.spec.js b/packages/dd-trace/test/opentracing/span.spec.js index 754d0a67f37..326796cae26 100644 --- a/packages/dd-trace/test/opentracing/span.spec.js +++ b/packages/dd-trace/test/opentracing/span.spec.js @@ -279,6 +279,43 @@ describe('Span', () => { }) }) + describe('events', () => { + it('should add span events', () => { + span = new Span(tracer, processor, prioritySampler, { operationName: 'operation' }) + + span.addEvent('Web page unresponsive', + { 'error.code': '403', 'unknown values': [1, ['h', 'a', [false]]] }, 1714536311886) + span.addEvent('Web page loaded') + span.addEvent('Button changed color', { colors: [112, 215, 70], 'response.time': 134.3, success: true }) + + const events = span._events + const expectedEvents = [ + { + name: 'Web page unresponsive', + startTime: 1714536311886, + attributes: { + 'error.code': '403', + 'unknown values': [1] + } + }, + { + name: 'Web page loaded', + startTime: 1500000000000 + }, + { + name: 'Button changed color', + attributes: { + colors: [112, 215, 70], + 'response.time': 134.3, + success: true + }, + startTime: 1500000000000 + } + ] + expect(events).to.deep.equal(expectedEvents) + }) + }) + describe('getBaggageItem', () => { it('should get a baggage item', () => { span = new Span(tracer, processor, prioritySampler, { operationName: 'operation' }) diff --git a/packages/dd-trace/test/tagger.spec.js b/packages/dd-trace/test/tagger.spec.js index 4f0426ea179..161136819d2 100644 --- a/packages/dd-trace/test/tagger.spec.js +++ b/packages/dd-trace/test/tagger.spec.js @@ -1,6 +1,10 @@ 'use strict' +const constants = require('../src/constants') require('./setup/tap') +const ERROR_MESSAGE = constants.ERROR_MESSAGE +const ERROR_STACK = constants.ERROR_STACK +const ERROR_TYPE = constants.ERROR_TYPE describe('tagger', () => { let carrier @@ -45,4 +49,29 @@ describe('tagger', () => { it('should handle missing carrier', () => { expect(() => tagger.add()).not.to.throw() }) + + it('should set trace error', () => { + tagger.add(carrier, { + [ERROR_TYPE]: 'foo', + [ERROR_MESSAGE]: 'foo', + [ERROR_STACK]: 'foo', + doNotSetTraceError: true + }) + + expect(carrier).to.have.property(ERROR_TYPE, 'foo') + expect(carrier).to.have.property(ERROR_MESSAGE, 'foo') + expect(carrier).to.have.property(ERROR_STACK, 'foo') + expect(carrier).to.not.have.property('setTraceError') + + tagger.add(carrier, { + [ERROR_TYPE]: 'foo', + [ERROR_MESSAGE]: 'foo', + [ERROR_STACK]: 'foo' + }) + + expect(carrier).to.have.property(ERROR_TYPE, 'foo') + expect(carrier).to.have.property(ERROR_MESSAGE, 'foo') + expect(carrier).to.have.property(ERROR_STACK, 'foo') + expect(carrier).to.have.property('setTraceError', true) + }) })