CORS Preflight Requests not accounted for

mariomc commented 2 weeks ago

What happened?

Currently XHR and Fetch instrumentation are treating CORS with the assumption that there's 2 entries (one for the actual request, another for the preflight) on the performance entry. This is not the case.

Steps to Reproduce

Launch the web-opentelemetry-example
Instrument a client with either XHR or fetch instrumentation

Expected Result

CORS preflight requests are created as child spans of the main request

Actual Result

No child spans are created

Additional Details

I believe this behaviour happens because according to Resource Timing Level 2:

For fetches composed of multiple requests (e.g. preflights, authentication challenge-response, redirects, and so on), the reported responseStart value is that of the last request.

Which means there's no duplicate entry performance entry in case of preflights.

OpenTelemetry Setup Code

const { context, trace } = require( '@opentelemetry/api');
const { ConsoleSpanExporter, SimpleSpanProcessor } = require( '@opentelemetry/sdk-trace-base');
const { OTLPTraceExporter } = require( '@opentelemetry/exporter-trace-otlp-http');
const { WebTracerProvider } = require( '@opentelemetry/sdk-trace-web');
const { FetchInstrumentation } = require( '@opentelemetry/instrumentation-fetch');
const { ZoneContextManager } = require( '@opentelemetry/context-zone');
const { B3Propagator } = require( '@opentelemetry/propagator-b3');
const { registerInstrumentations } = require( '@opentelemetry/instrumentation');
const { Resource } = require('@opentelemetry/resources');
const { SEMRESATTRS_SERVICE_NAME } = require('@opentelemetry/semantic-conventions');

const provider = new WebTracerProvider({
  resource: new Resource({
    [SEMRESATTRS_SERVICE_NAME]: 'fetch-web-service'
  })
});

// Note: For production consider using the "BatchSpanProcessor" to reduce the number of requests
// to your exporter. Using the SimpleSpanProcessor here as it sends the spans immediately to the
// exporter without delay
provider.addSpanProcessor(new SimpleSpanProcessor(new ConsoleSpanExporter()));
provider.addSpanProcessor(new SimpleSpanProcessor(new OTLPTraceExporter()));
provider.register({
  contextManager: new ZoneContextManager(),
  propagator: new B3Propagator(),
});

registerInstrumentations({
  instrumentations: [
    new FetchInstrumentation({
      ignoreUrls: [/localhost:8090\/sockjs-node/],
      propagateTraceHeaderCorsUrls: [
        'https://cors-test.appspot.com/test',
        'https://httpbin.org/get',
      ],
      clearTimingResources: true,
    }),
  ],
});

const webTracerWithZone = provider.getTracer('example-tracer-web');

const getData = (url) => fetch(url, {
  method: 'GET',
  headers: {
    Accept: 'application/json',
    'Content-Type': 'application/json',
  },
});

// example of keeping track of context between async operations
const prepareClickEvent = () => {
  const url = 'https://httpbin.org/get';

  const element = document.getElementById('button1');

  const onClick = () => {
    const singleSpan = webTracerWithZone.startSpan('files-series-info');
    context.with(trace.setSpan(context.active(), singleSpan), () => {
      getData(url).then((_data) => {
        trace.getSpan(context.active()).addEvent('fetching-single-span-completed');
        singleSpan.end();
      });
    });
    for (let i = 0, j = 5; i < j; i += 1) {
      const span = webTracerWithZone.startSpan(`files-series-info-${i}`);
      context.with(trace.setSpan(context.active(), span), () => {
        getData(url).then((_data) => {
          trace.getSpan(context.active()).addEvent(`fetching-span-${i}-completed`);
          span.end();
        });
      });
    }
  };
  element.addEventListener('click', onClick);
};

window.addEventListener('load', prepareClickEvent);

package.json

{
  "name": "web-opentelemetry-example",
  "private": true,
  "version": "0.53.0",
  "description": "Example of using @opentelemetry/sdk-trace-web and @opentelemetry/sdk-metrics in browser",
  "main": "index.js",
  "scripts": {
    "start": "webpack serve --progress --color --port 8090 --config webpack.dev.config.js --hot --host 0.0.0.0 --compress",
    "start-nc": "webpack serve --progress --color --port 8090 --config webpack.dev.config.js --hot --host 0.0.0.0 --no-compress",
    "start-prod": "webpack serve --progress --color --port 8090 --config webpack.prod.config.js --hot --host 0.0.0.0 --compress",
    "start-prodnc": "webpack serve --progress --color --port 8090 --config webpack.prod.config.js --hot --host 0.0.0.0 --no-compress",
    "docker:start": "cd ./docker && docker-compose down && docker-compose up",
    "docker:startd": "cd ./docker && docker-compose down && docker-compose up -d",
    "docker:stop": "cd ./docker && docker-compose down",
    "align-api-deps": "node ../../scripts/align-api-deps.js"
  },
  "repository": {
    "type": "git",
    "url": "git+ssh://git@github.com/open-telemetry/opentelemetry-js.git"
  },
  "keywords": [
    "opentelemetry",
    "tracing",
    "metrics",
    "web"
  ],
  "engines": {
    "node": ">=14"
  },
  "author": "OpenTelemetry Authors",
  "license": "Apache-2.0",
  "bugs": {
    "url": "https://github.com/open-telemetry/opentelemetry-js/issues"
  },
  "devDependencies": {
    "@babel/core": "^7.23.6",
    "@babel/preset-env": "^7.22.20",
    "babel-loader": "^8.0.6",
    "ts-loader": "^9.2.6",
    "typescript": "^4.5.2",
    "webpack": "^5.89.0",
    "webpack-cli": "^5.1.4",
    "webpack-dev-server": "^4.5.0",
    "webpack-merge": "^5.10.0"
  },
  "dependencies": {
    "@opentelemetry/api": "^1.3.0",
    "@opentelemetry/context-zone": "1.26.0",
    "@opentelemetry/core": "1.26.0",
    "@opentelemetry/exporter-metrics-otlp-http": "0.53.0",
    "@opentelemetry/exporter-trace-otlp-http": "0.53.0",
    "@opentelemetry/exporter-trace-otlp-proto": "0.53.0",
    "@opentelemetry/exporter-zipkin": "1.26.0",
    "@opentelemetry/instrumentation": "0.53.0",
    "@opentelemetry/instrumentation-fetch": "0.53.0",
    "@opentelemetry/instrumentation-xml-http-request": "0.53.0",
    "@opentelemetry/propagator-b3": "1.26.0",
    "@opentelemetry/sdk-metrics": "1.26.0",
    "@opentelemetry/sdk-trace-base": "1.26.0",
    "@opentelemetry/sdk-trace-web": "1.26.0",
    "@opentelemetry/semantic-conventions": "1.27.0"
  },
  "homepage": "https://github.com/open-telemetry/opentelemetry-js/tree/main/examples/tracer-web"
}

Relevant log output

No response

dyladan commented 2 days ago

It's not really clear what you mean here. In the issue you say "CORS preflight requests are created as child spans of the main request" but in the PR you introduced it looks like you're actually removing this behavior? Are you saying the behavior doesn't work and should be removed for that reason? Or are you saying we shouldn't be creating these spans at all?

mariomc commented 2 days ago

Are you saying the behavior doesn't work and should be removed for that reason?

Thank you for the reply. Exactly.

The current code was built upon what seems a false assumption: that there's two Performance entries per each cross-origin request (one for the preflight/OPTIONS/CORS, another for the actual request). There isn't. (Maybe this was the case in some early implementations of the Resource Timing spec?)

At least as per Resource Timing level 2, request preconditions (authentication, redirects, CORS) are accounted for as a part of the entry of the originator request. There is no way of, with the PerformanceResourceTiming, extracting (or inferring) data for the CORS preflight request specifically. Which means that we could drop this code entirely: needing to find the duplicate (there will never be one) and if there's one, using it to create a nested span.

open-telemetry / opentelemetry-js