Inconsistent endTime when ending Spans. EndTime may be > than startTime with Typescript

[SergioTijerino]

What happened?

Steps to Reproduce

• Set up a WebVitalsInstrumentation class that extends from InstrumentationBase
• Using a custom constructor, call the super function and assign a started time this._started = new Date()
• Initialize the class with an init method, that gets WebVitals traces (CLS, FID, FCP, ...)
• Inside the initialization of these Traces, we will use traces that comes from IntrumentationBase and start creating Spans with startSpan
• Send the required parameters to it
• Finally, end the span with span.end() function without any endTime send as argument (this should in theory, set the endTime as later than this._started

Expected Result

We see the Spans with StartTime <= EndTime

Actual Result

The EndTime value is inconsistent. In some cases is behaving as expected, and in some others we see the date being up to 12 hours before the _started date.

Additional Details

Screenshot of the Ingested Traces

OpenTelemetry Setup Code

instrumentation.js

import * as otelApi from '@opentelemetry/api'
import {
  InstrumentationBase,
  InstrumentationConfig
} from "@opentelemetry/instrumentation"

import * as WebVitals from 'web-vitals'

const VERSION = "0.1.0"

export class WebVitalsInstrumentation extends InstrumentationBase {
  private _isRecording = false
  private readonly _started: Date
  private _isInitialized = false

  constructor(config: InstrumentationConfig = {}) {
    super("@company/instrumentation-web-vitals", VERSION, config)
    this._started = new Date()
  }

  protected init(): void {
    if (this._isInitialized) {
      return
    }

    this._isInitialized = true
    console.log("WebVitalsInstrumentation.initialized")
    WebVitals.getCLS(m => this._record("web-vitals-cls", m)) // |  Good   <100ms  |  Okay   <250ms   |  Bad   >250ms   |
    WebVitals.getFID(m => this._record("web-vitals-fid", m)) // |  Good   <100ms  |  Okay   <300ms   |  Bad   >300ms   |
    WebVitals.getLCP(m => this._record("web-vitals-lcp", m)) // |  Good   <2.5s   |  Okay   <4.0s    |  Bad   >4.0s    |
    WebVitals.getFCP(m => this._record("web-vitals-fcp", m))
    WebVitals.getTTFB(m => this._record("web-vitals-ttfb", m))
  }

  private _record(name: string, metric: WebVitals.Metric): void {
    if (!this._isRecording) {
      return
    }

    console.log("WebVitalsInstrumentation._record", name, metric)
    const span = this.tracer.startSpan(name, {
      startTime: this._started,
      attributes: { value: metric.value },
      kind: otelApi.SpanKind.INTERNAL
    })
    span.end()
  }

  public enable(): void {
    this._isRecording = true
    this.init()
    console.log("WebVitalsInstrumentation.enabled")
  }

  public disable(): void {
    this._isRecording = false
    console.log("WebVitalsInstrumentation.disabled")
  }
}

loader.js

// OpenTelemetry
import * as otelCore from "@opentelemetry/core"
import * as otelApi from "@opentelemetry/api"

// Otel Setup (Trace Provider, Processor, Exporter, ...)
import { WebTracerProvider } from '@opentelemetry/sdk-trace-web'
import { BatchSpanProcessor } from '@opentelemetry/sdk-trace-base'
import { CollectorTraceExporter } from '@opentelemetry/exporter-collector'
import { registerInstrumentations } from '@opentelemetry/instrumentation'
import { ZoneContextManager } from "@opentelemetry/context-zone"

// Plugins
import { Resource } from '@opentelemetry/resources'
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions'
import { DocumentLoadInstrumentation } from '@opentelemetry/instrumentation-document-load'
import { WebVitalsInstrumentation } from './instrumentation/web-vitals-instrumentation'
import { B3Propagator, B3InjectEncoding } from "@opentelemetry/propagator-b3";

export function initOpenTelemetry() {
  // setup Propagator
  const propagator = new otelCore.CompositePropagator({
    propagators: [
      new B3Propagator(),
      new B3Propagator({ injectEncoding: B3InjectEncoding.MULTI_HEADER }),
      // new otelCore.HttpBaggagePropagator()
    ]
  })

  otelApi.propagation.setGlobalPropagator(propagator)

  // setup Collector
  const collectorOptions = {
    url: "https://our-collector.com/",
    headers: {
      "content-type": "application/json"
    }
  }

  // setup Span Resource
  const resource = new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: "mock_name",
    [SemanticResourceAttributes.SERVICE_NAMESPACE]: "mock_namespace",
    [SemanticResourceAttributes.SERVICE_INSTANCE_ID]: "web",
    [SemanticResourceAttributes.SERVICE_VERSION]: process.env.VERSION || "0.0.0"  })

  // init provider and exporter
  const provider = new WebTracerProvider({ resource })
  const exporter = new CollectorTraceExporter( collectorOptions )

  // Add Span Processor to provider
  provider.addSpanProcessor(new BatchSpanProcessor(exporter, {
    // The maximum queue size. After the size is reached spans are dropped.
    maxQueueSize: 100,
    // The maximum batch size of every export. It must be smaller or equal to maxQueueSize.
    maxExportBatchSize: 50,
    // The interval between two consecutive exports
    scheduledDelayMillis: 500,
    // How long the export can run before it is cancelled
    exportTimeoutMillis: 30000,
  }))
  
  // Instrumentation
  registerInstrumentations({
    instrumentations: [
      new DocumentLoadInstrumentation(),
      new WebVitalsInstrumentation(),
    ],
    tracerProvider: provider,
  })
  
  provider.register({
    contextManager: new ZoneContextManager().enable() as otelApi.ContextManager,
    propagator
  })

  // Baggage Init
  const baggage =
    otelApi.propagation.getBaggage(otelApi.context.active()) ||
    otelApi.propagation.createBaggage()

  baggage.setEntry("sessionId", { value: "session-id-value" })
  otelApi.propagation.setBaggage(otelApi.context.active(), baggage)
}

package.json

No response

Relevant log output

No response

[dyladan]

I think this is a duplicate of #3279 can you confirm and move conversation there if you can?

[SergioTijerino]

Indeed, after reading the other conversation, looks like were are addressing the same type of errors with Traces and Spans. I'll keep an eye on the other bug 👍