diff --git a/CHANGELOG.md b/CHANGELOG.md index e31a35c648..6f4e1382e4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -31,6 +31,7 @@ For experimental package changes, see the [experimental CHANGELOG](experimental/ * `telemetry.sdk.name` * `telemetry.sdk.language` * `telemetry.sdk.version` +* fix(sdk-trace): make spans resilient to clock drift [#3434](https://github.com/open-telemetry/opentelemetry-js/pull/3434) @dyladan * fix(selenium-tests): updated webpack version for selenium test issue [#3456](https://github.com/open-telemetry/opentelemetry-js/issues/3456) @SaumyaBhushan * fix(sdk-metrics): fix duplicated registration of metrics for collectors [#3488](https://github.com/open-telemetry/opentelemetry-js/pull/3488) @legendecas * fix(core): fix precision loss in numberToHrtime [#3480](https://github.com/open-telemetry/opentelemetry-js/pull/3480) @legendecas diff --git a/experimental/CHANGELOG.md b/experimental/CHANGELOG.md index a76aa1842b..9416823ca2 100644 --- a/experimental/CHANGELOG.md +++ b/experimental/CHANGELOG.md @@ -33,6 +33,8 @@ All notable changes to experimental packages in this project will be documented * fix(prometheus-sanitization): replace repeated `_` with a single `_` [3470](https://github.com/open-telemetry/opentelemetry-js/pull/3470) @samimusallam * fix(prometheus-serializer): correct string used for NaN [#3477](https://github.com/open-telemetry/opentelemetry-js/pull/3477) @JacksonWeber * fix(instrumentation-http): close server span when response finishes [#3407](https://github.com/open-telemetry/opentelemetry-js/pull/3407) @legendecas +* fix(instrumentation-fetch): make spans resilient to clock drift by using Date.now [#3434](https://github.com/open-telemetry/opentelemetry-js/pull/3434) @dyladan +* fix(instrumentation-xml-http-request): make spans resilient to clock drift by using Date.now [#3434](https://github.com/open-telemetry/opentelemetry-js/pull/3434) @dyladan * fix(sdk-node): fix exporter to be read only OTEL_TRACES_EXPORTER is set to a valid exporter [3492] @svetlanabrennan ### :house: (Internal) diff --git a/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts b/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts index 14862a8e81..75aa38c921 100644 --- a/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts +++ b/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts @@ -276,12 +276,13 @@ export class FetchInstrumentation extends InstrumentationBase< spanData: SpanData, response: FetchResponse ) { - const endTime = core.hrTime(); + const endTime = core.millisToHrTime(Date.now()); + const performanceEndTime = core.hrTime(); this._addFinalSpanAttributes(span, response); setTimeout(() => { spanData.observer?.disconnect(); - this._findResourceAndAddNetworkEvents(span, spanData, endTime); + this._findResourceAndAddNetworkEvents(span, spanData, performanceEndTime); this._tasksCount--; this._clearResources(); span.end(endTime); diff --git a/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts b/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts index 621dc73f89..238119f09d 100644 --- a/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts +++ b/experimental/packages/opentelemetry-instrumentation-xml-http-request/src/xhr.ts @@ -389,7 +389,8 @@ export class XMLHttpRequestInstrumentation extends InstrumentationBase { - endSpanTimeout(eventName, xhrMem, endTime); + endSpanTimeout(eventName, xhrMem, performanceEndTime, endTime); }, OBSERVER_WAIT_TIME_MS); } diff --git a/packages/opentelemetry-core/src/common/time.ts b/packages/opentelemetry-core/src/common/time.ts index aa94aefec9..8dd650a992 100644 --- a/packages/opentelemetry-core/src/common/time.ts +++ b/packages/opentelemetry-core/src/common/time.ts @@ -27,7 +27,7 @@ const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS); * Converts a number of milliseconds from epoch to HrTime([seconds, remainder in nanoseconds]). * @param epochMillis */ -function numberToHrtime(epochMillis: number): api.HrTime { +export function millisToHrTime(epochMillis: number): api.HrTime { const epochSeconds = epochMillis / 1000; // Decimals only. const seconds = Math.trunc(epochSeconds); @@ -36,7 +36,7 @@ function numberToHrtime(epochMillis: number): api.HrTime { return [seconds, nanos]; } -function getTimeOrigin(): number { +export function getTimeOrigin(): number { let timeOrigin = performance.timeOrigin; if (typeof timeOrigin !== 'number') { const perf: TimeOriginLegacy = performance as unknown as TimeOriginLegacy; @@ -50,21 +50,12 @@ function getTimeOrigin(): number { * @param performanceNow */ export function hrTime(performanceNow?: number): api.HrTime { - const timeOrigin = numberToHrtime(getTimeOrigin()); - const now = numberToHrtime( + const timeOrigin = millisToHrTime(getTimeOrigin()); + const now = millisToHrTime( typeof performanceNow === 'number' ? performanceNow : performance.now() ); - let seconds = timeOrigin[0] + now[0]; - let nanos = timeOrigin[1] + now[1]; - - // Nanoseconds - if (nanos > SECOND_TO_NANOSECONDS) { - nanos -= SECOND_TO_NANOSECONDS; - seconds += 1; - } - - return [seconds, nanos]; + return addHrTimes(timeOrigin, now); } /** @@ -82,10 +73,10 @@ export function timeInputToHrTime(time: api.TimeInput): api.HrTime { return hrTime(time); } else { // epoch milliseconds or performance.timeOrigin - return numberToHrtime(time); + return millisToHrTime(time); } } else if (time instanceof Date) { - return numberToHrtime(time.getTime()); + return millisToHrTime(time.getTime()); } else { throw TypeError('Invalid input type'); } @@ -175,3 +166,18 @@ export function isTimeInput( value instanceof Date ); } + +/** + * Given 2 HrTime formatted times, return their sum as an HrTime. + */ +export function addHrTimes(time1: api.HrTime, time2: api.HrTime): api.HrTime { + const out = [time1[0] + time2[0], time1[1] + time2[1]] as api.HrTime; + + // Nanoseconds + if (out[1] >= SECOND_TO_NANOSECONDS) { + out[1] -= SECOND_TO_NANOSECONDS; + out[0] += 1; + } + + return out; +} diff --git a/packages/opentelemetry-core/test/common/time.test.ts b/packages/opentelemetry-core/test/common/time.test.ts index d0b933e7a1..bf691c7071 100644 --- a/packages/opentelemetry-core/test/common/time.test.ts +++ b/packages/opentelemetry-core/test/common/time.test.ts @@ -27,6 +27,7 @@ import { hrTimeToMicroseconds, hrTimeToTimeStamp, isTimeInput, + addHrTimes, } from '../../src/common/time'; describe('time', () => { @@ -224,4 +225,34 @@ describe('time', () => { assert.strictEqual(isTimeInput(undefined), false); }); }); + + describe('#addHrTimes', () => { + const NANOSECOND_DIGITS = 9; + const SECOND_TO_NANOSECONDS = Math.pow(10, NANOSECOND_DIGITS); + + it('should add two positive times', () => { + const output = addHrTimes([10, 20], [30, 40]); + assert.deepStrictEqual(output, [40, 60]); + }); + it('should add two negative times', () => { + const output = addHrTimes([-10, 20], [-30, 40]); + assert.deepStrictEqual(output, [-40, 60]); + }); + it('should add a positive and negative time (result positive)', () => { + const output = addHrTimes([-10, 20], [30, 40]); + assert.deepStrictEqual(output, [20, 60]); + }); + it('should add a positive and negative time (result negative)', () => { + const output = addHrTimes([10, 20], [-30, 40]); + assert.deepStrictEqual(output, [-20, 60]); + }); + it('should overflow nanoseconds to seconds', () => { + const output = addHrTimes([10, SECOND_TO_NANOSECONDS - 10], [10, 20]); + assert.deepStrictEqual(output, [21, 10]); + }); + it('should overflow nanoseconds to seconds (negative)', () => { + const output = addHrTimes([-10, SECOND_TO_NANOSECONDS - 10], [-10, 20]); + assert.deepStrictEqual(output, [-19, 10]); + }); + }); }); diff --git a/packages/opentelemetry-sdk-trace-base/src/Span.ts b/packages/opentelemetry-sdk-trace-base/src/Span.ts index 87ee47e28a..7677e6f5ce 100644 --- a/packages/opentelemetry-sdk-trace-base/src/Span.ts +++ b/packages/opentelemetry-sdk-trace-base/src/Span.ts @@ -14,17 +14,33 @@ * limitations under the License. */ -import * as api from '@opentelemetry/api'; -import { Context, HrTime, SpanAttributeValue } from '@opentelemetry/api'; import { - Clock, + Context, + diag, + Exception, + HrTime, + Link, + Span as APISpan, + SpanAttributes, + SpanAttributeValue, + SpanContext, + SpanKind, + SpanStatus, + SpanStatusCode, + TimeInput, +} from '@opentelemetry/api'; +import { + addHrTimes, + millisToHrTime, + getTimeOrigin, + hrTime, hrTimeDuration, InstrumentationLibrary, isAttributeValue, isTimeInput, + isTimeInputHrTime, otperformance, sanitizeAttributes, - timeInputToHrTime, } from '@opentelemetry/core'; import { Resource } from '@opentelemetry/resources'; import { SemanticAttributes } from '@opentelemetry/semantic-conventions'; @@ -38,29 +54,32 @@ import { SpanLimits } from './types'; /** * This class represents a span. */ -export class Span implements api.Span, ReadableSpan { +export class Span implements APISpan, ReadableSpan { // Below properties are included to implement ReadableSpan for export // purposes but are not intended to be written-to directly. - private readonly _spanContext: api.SpanContext; - readonly kind: api.SpanKind; + private readonly _spanContext: SpanContext; + readonly kind: SpanKind; readonly parentSpanId?: string; - readonly attributes: api.SpanAttributes = {}; - readonly links: api.Link[] = []; + readonly attributes: SpanAttributes = {}; + readonly links: Link[] = []; readonly events: TimedEvent[] = []; - readonly startTime: api.HrTime; + readonly startTime: HrTime; readonly resource: Resource; readonly instrumentationLibrary: InstrumentationLibrary; name: string; - status: api.SpanStatus = { - code: api.SpanStatusCode.UNSET, + status: SpanStatus = { + code: SpanStatusCode.UNSET, }; - endTime: api.HrTime = [0, 0]; + endTime: HrTime = [0, 0]; private _ended = false; - private _duration: api.HrTime = [-1, -1]; + private _duration: HrTime = [-1, -1]; private readonly _spanProcessor: SpanProcessor; private readonly _spanLimits: SpanLimits; private readonly _attributeValueLengthLimit: number; - private readonly _clock: Clock; + + private readonly _performanceStartTime: number; + private readonly _performanceOffset: number; + private readonly _startTimeProvided: boolean; /** * Constructs a new Span instance. @@ -71,20 +90,27 @@ export class Span implements api.Span, ReadableSpan { parentTracer: Tracer, context: Context, spanName: string, - spanContext: api.SpanContext, - kind: api.SpanKind, + spanContext: SpanContext, + kind: SpanKind, parentSpanId?: string, - links: api.Link[] = [], - startTime?: api.TimeInput, - clock: Clock = otperformance + links: Link[] = [], + startTime?: TimeInput, + _deprecatedClock?: unknown // keeping this argument even though it is unused to ensure backwards compatibility ) { - this._clock = clock; this.name = spanName; this._spanContext = spanContext; this.parentSpanId = parentSpanId; this.kind = kind; this.links = links; - this.startTime = timeInputToHrTime(startTime ?? clock.now()); + + const now = Date.now(); + this._performanceStartTime = otperformance.now(); + this._performanceOffset = + now - (this._performanceStartTime + getTimeOrigin()); + this._startTimeProvided = startTime != null; + + this.startTime = this._getTime(startTime ?? now); + this.resource = parentTracer.resource; this.instrumentationLibrary = parentTracer.instrumentationLibrary; this._spanLimits = parentTracer.getSpanLimits(); @@ -94,7 +120,7 @@ export class Span implements api.Span, ReadableSpan { this._spanLimits.attributeValueLengthLimit || 0; } - spanContext(): api.SpanContext { + spanContext(): SpanContext { return this._spanContext; } @@ -102,11 +128,11 @@ export class Span implements api.Span, ReadableSpan { setAttribute(key: string, value: unknown): this { if (value == null || this._isSpanEnded()) return this; if (key.length === 0) { - api.diag.warn(`Invalid attribute key: ${key}`); + diag.warn(`Invalid attribute key: ${key}`); return this; } if (!isAttributeValue(value)) { - api.diag.warn(`Invalid attribute value set for key: ${key}`); + diag.warn(`Invalid attribute value set for key: ${key}`); return this; } @@ -121,7 +147,7 @@ export class Span implements api.Span, ReadableSpan { return this; } - setAttributes(attributes: api.SpanAttributes): this { + setAttributes(attributes: SpanAttributes): this { for (const [k, v] of Object.entries(attributes)) { this.setAttribute(k, v); } @@ -133,42 +159,40 @@ export class Span implements api.Span, ReadableSpan { * @param name Span Name * @param [attributesOrStartTime] Span attributes or start time * if type is {@type TimeInput} and 3rd param is undefined - * @param [startTime] Specified start time for the event + * @param [timeStamp] Specified time stamp for the event */ addEvent( name: string, - attributesOrStartTime?: api.SpanAttributes | api.TimeInput, - startTime?: api.TimeInput + attributesOrStartTime?: SpanAttributes | TimeInput, + timeStamp?: TimeInput ): this { if (this._isSpanEnded()) return this; if (this._spanLimits.eventCountLimit === 0) { - api.diag.warn('No events allowed.'); + diag.warn('No events allowed.'); return this; } if (this.events.length >= this._spanLimits.eventCountLimit!) { - api.diag.warn('Dropping extra events.'); + diag.warn('Dropping extra events.'); this.events.shift(); } + if (isTimeInput(attributesOrStartTime)) { - if (typeof startTime === 'undefined') { - startTime = attributesOrStartTime as api.TimeInput; + if (!isTimeInput(timeStamp)) { + timeStamp = attributesOrStartTime; } attributesOrStartTime = undefined; } - if (typeof startTime === 'undefined') { - startTime = this._clock.now(); - } const attributes = sanitizeAttributes(attributesOrStartTime); this.events.push({ name, attributes, - time: timeInputToHrTime(startTime), + time: this._getTime(timeStamp), }); return this; } - setStatus(status: api.SpanStatus): this { + setStatus(status: SpanStatus): this { if (this._isSpanEnded()) return this; this.status = status; return this; @@ -180,18 +204,18 @@ export class Span implements api.Span, ReadableSpan { return this; } - end(endTime?: api.TimeInput): void { + end(endTime?: TimeInput): void { if (this._isSpanEnded()) { - api.diag.error('You can only call end() on a span once.'); + diag.error('You can only call end() on a span once.'); return; } this._ended = true; - this.endTime = timeInputToHrTime(endTime ?? this._clock.now()); + this.endTime = this._getTime(endTime); this._duration = hrTimeDuration(this.startTime, this.endTime); if (this._duration[0] < 0) { - api.diag.warn( + diag.warn( 'Inconsistent start and end time, startTime > endTime. Setting span duration to 0ms.', this.startTime, this.endTime @@ -203,15 +227,41 @@ export class Span implements api.Span, ReadableSpan { this._spanProcessor.onEnd(this); } + private _getTime(inp?: TimeInput): HrTime { + if (typeof inp === 'number' && inp < otperformance.now()) { + // must be a performance timestamp + // apply correction and convert to hrtime + return hrTime(inp + this._performanceOffset); + } + + if (typeof inp === 'number') { + return millisToHrTime(inp); + } + + if (inp instanceof Date) { + return millisToHrTime(inp.getTime()); + } + + if (isTimeInputHrTime(inp)) { + return inp; + } + + if (this._startTimeProvided) { + // if user provided a time for the start manually + // we can't use duration to calculate event/end times + return millisToHrTime(Date.now()); + } + + const msDuration = otperformance.now() - this._performanceStartTime; + return addHrTimes(this.startTime, millisToHrTime(msDuration)); + } + isRecording(): boolean { return this._ended === false; } - recordException( - exception: api.Exception, - time: api.TimeInput = this._clock.now() - ): void { - const attributes: api.SpanAttributes = {}; + recordException(exception: Exception, time?: TimeInput): void { + const attributes: SpanAttributes = {}; if (typeof exception === 'string') { attributes[SemanticAttributes.EXCEPTION_MESSAGE] = exception; } else if (exception) { @@ -236,11 +286,11 @@ export class Span implements api.Span, ReadableSpan { ) { this.addEvent(ExceptionEventName, attributes, time); } else { - api.diag.warn(`Failed to record an exception ${exception}`); + diag.warn(`Failed to record an exception ${exception}`); } } - get duration(): api.HrTime { + get duration(): HrTime { return this._duration; } @@ -250,7 +300,7 @@ export class Span implements api.Span, ReadableSpan { private _isSpanEnded(): boolean { if (this._ended) { - api.diag.warn( + diag.warn( `Can not execute the operation on ended Span {traceId: ${this._spanContext.traceId}, spanId: ${this._spanContext.spanId}}` ); } @@ -284,7 +334,7 @@ export class Span implements api.Span, ReadableSpan { // Check limit if (limit <= 0) { // Negative values are invalid, so do not truncate - api.diag.warn(`Attribute value limit must be positive, got ${limit}`); + diag.warn(`Attribute value limit must be positive, got ${limit}`); return value; } diff --git a/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts b/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts index df19ace156..dac8728138 100644 --- a/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts +++ b/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts @@ -137,6 +137,8 @@ describe('Span', () => { spanContext, SpanKind.SERVER ); + // @ts-expect-error writing readonly property. performance time origin is mocked to return ms value of [1,1] + span['_performanceOffset'] = 0; span.end(hrTimeToMilliseconds(span.startTime) - 1); assert.ok(hrTimeToNanoseconds(span.duration) >= 0); }); @@ -157,6 +159,7 @@ describe('Span', () => { }); it('should have an entered time for event', () => { + const startTime = Date.now(); const span = new Span( tracer, ROOT_CONTEXT, @@ -165,11 +168,11 @@ describe('Span', () => { SpanKind.SERVER, undefined, [], - 0 + startTime ); - const timeMS = 123; + const eventTimeMS = 123; const spanStartTime = hrTimeToMilliseconds(span.startTime); - const eventTime = spanStartTime + timeMS; + const eventTime = spanStartTime + eventTimeMS; span.addEvent('my-event', undefined, eventTime); @@ -179,6 +182,7 @@ describe('Span', () => { describe('when 2nd param is "TimeInput" type', () => { it('should have an entered time for event - ', () => { + const startTime = Date.now(); const span = new Span( tracer, ROOT_CONTEXT, @@ -187,11 +191,11 @@ describe('Span', () => { SpanKind.SERVER, undefined, [], - 0 + startTime ); - const timeMS = 123; + const eventTimeMS = 123; const spanStartTime = hrTimeToMilliseconds(span.startTime); - const eventTime = spanStartTime + timeMS; + const eventTime = spanStartTime + eventTimeMS; span.addEvent('my-event', eventTime); @@ -1172,6 +1176,8 @@ describe('Span', () => { spanContext, SpanKind.CLIENT ); + // @ts-expect-error writing readonly property. performance time origin is mocked to return ms value of [1,1] + span['_performanceOffset'] = 0; assert.strictEqual(span.events.length, 0); span.recordException('boom', [0, 123]); const event = span.events[0]; diff --git a/packages/opentelemetry-shim-opentracing/test/Shim.test.ts b/packages/opentelemetry-shim-opentracing/test/Shim.test.ts index c2ff3c8e1a..cd3749a681 100644 --- a/packages/opentelemetry-shim-opentracing/test/Shim.test.ts +++ b/packages/opentelemetry-shim-opentracing/test/Shim.test.ts @@ -22,7 +22,7 @@ import { CompositePropagator, W3CBaggagePropagator, W3CTraceContextPropagator, - timeInputToHrTime, + hrTimeToMilliseconds, } from '@opentelemetry/core'; import { defaultTextMapGetter, @@ -256,8 +256,13 @@ describe('OpenTracing Shim', () => { const otSpan = (span as SpanShim).getSpan() as Span; + const adjustment = otSpan['_performanceOffset']; + assert.strictEqual(otSpan.links.length, 1); - assert.deepStrictEqual(otSpan.startTime, timeInputToHrTime(now)); + assert.deepStrictEqual( + hrTimeToMilliseconds(otSpan.startTime), + Math.round(now + adjustment + performance.timeOrigin) + ); assert.deepStrictEqual(otSpan.attributes, opentracingOptions.tags); }); }); @@ -487,7 +492,11 @@ describe('OpenTracing Shim', () => { it('sets explicit end timestamp', () => { const now = performance.now(); span.finish(now); - assert.deepStrictEqual(otSpan.endTime, timeInputToHrTime(now)); + const adjustment = otSpan['_performanceOffset']; + assert.deepStrictEqual( + hrTimeToMilliseconds(otSpan.endTime), + Math.round(now + adjustment + performance.timeOrigin) + ); }); it('can set and retrieve baggage', () => {