traces of resource detectors being sent #2320

david-luna · 2024-06-19T09:48:55Z

What happened?

Steps to Reproduce

Get the express example from https://github.com/open-telemetry/opentelemetry-js-contrib
instrument it with @opentelemetry/auto-instrumentations
enable all resource detectors

OTEL_TRACES_EXPORTER=console \
  OTEL_NODE_RESOURCE_DETECTORS=all \
  node --require '@opentelemetry/auto-instrumentations-node/register' index.js

Expected Result

Exported spans should belong only to application traces and not to any internal activity of the SDK or its components.

Actual Result

HTTP spans are exported for the requests done by GCP while it's doing its detection logic.

Additional Details

This is related to open-telemetry/opentelemetry-js#1989 since the instrumentations do the patching when constructor is called (before the detectors being used). IMO a user would expect to start collecting/exporting traces once the SDK has completely initialized and also to only export traces/logs/metrics activity related to the application. Self instrumentation would be a feature that could be activated or not.

Application Code

// index.js code no need for tracing.js 
// since is using --require '@opentelemetry/auto-instrumentations-node/register'

// Usage:
//  OTEL_NODE_RESOURCE_DETECTORS=all node --require '@opentelemetry/auto-instrumentations-node/register' index.js

// Require in rest of modules
const express = require('express');
const axios = require('axios');

// Setup express
const app = express();
const PORT = 8080;

const getCrudController = () => {
  const router = express.Router();
  const resources = [];
  router.get('/', (req, res) => res.send(resources));
  router.post('/', (req, res) => {
    resources.push(req.body);
    return res.status(201).send(req.body);
  });
  return router;
};

const authMiddleware = (req, res, next) => {
  const { authorization } = req.headers;
  if (authorization && authorization.includes('secret_token')) {
    next();
  } else {
    res.sendStatus(401);
  }
};

app.use(express.json());
app.get('/health', (req, res) => res.status(200).send("HEALTHY")); // endpoint that is called by framework/cluster
app.get('/run_test', async (req, res) => {
  // Calls another endpoint of the same API, somewhat mimicking an external API call
  const createdCat = await axios.post(`http://localhost:${PORT}/cats`, {
    name: 'Tom',
    friends: [
      'Jerry',
    ],
  }, {
    headers: {
      Authorization: 'secret_token',
    },
  });

  return res.status(201).send(createdCat.data);
});
app.use('/cats', authMiddleware, getCrudController());

app.listen(PORT, () => {
  console.log(`Listening on http://localhost:${PORT}`);
});

package.json

{
  "name": "test",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "scripts": {
    "test": "echo \"Error: no test specified\" && exit 1"
  },
  "author": "",
  "license": "ISC",
  "dependencies": {
    "@opentelemetry/api": "^1.9.0",
    "@opentelemetry/auto-instrumentations-node": "^0.47.0",
    "axios": "^1.7.2",
    "express": "^4.19.2"
  }
}

Relevant log output

{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '1.25.0',
      'host.name': 'moonlocal.local',
      'host.arch': 'arm64',
      'os.type': 'darwin',
      'os.version': '23.5.0',
      'service.instance.id': 'a76f5efb-7885-43ed-8fb4-9dc8e3398cf6',
      'process.pid': 42300,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/david/.nvm/versions/node/v18.16.0/bin/node',
      'process.command_args': [
        '/Users/david/.nvm/versions/node/v18.16.0/bin/node',
        '--require',
        '@opentelemetry/auto-instrumentations-node/register',
        '/Users/david/Documents/repos/_temp/auto/index.js'
      ],
      'process.runtime.version': '18.16.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/david/Documents/repos/_temp/auto/index.js',
      'process.owner': 'david',
      'host.id': '7904601F-B9AB-5EB2-A389-E32C06D56851'
    }
  },
  traceId: 'b8ef69198ae03da2ffae839bcdc5e371',
  parentId: undefined,
  traceState: undefined,
  name: 'GET',
  id: 'd714a445e304e8b9',
  kind: 2,
  timestamp: 1718788125997000,
  duration: 4792.5,
  attributes: {
    'http.url': 'http://metadata.google.internal./computeMetadata/v1/instance',
    'http.method': 'GET',
    'http.target': '/computeMetadata/v1/instance',
    'net.peer.name': 'metadata.google.internal.',
    'http.host': 'metadata.google.internal.:80',
    'http.error_name': 'Error',
    'http.error_message': 'getaddrinfo ENOTFOUND metadata.google.internal.'
  },
  status: {
    code: 2,
    message: 'getaddrinfo ENOTFOUND metadata.google.internal.'
  },
  events: [
    {
      name: 'exception',
      attributes: {
        'exception.type': 'ENOTFOUND',
        'exception.message': 'getaddrinfo ENOTFOUND metadata.google.internal.',
        'exception.stacktrace': 'Error: getaddrinfo ENOTFOUND metadata.google.internal.\n' +
          '    at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:107:26)\n' +
          '    at GetAddrInfoReqWrap.callbackTrampoline (node:internal/async_hooks:130:17)'
      },
      time: [ 1718788126, 1774625 ],
      droppedAttributesCount: 0
    }
  ],
  links: []
}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '1.25.0',
      'host.name': 'moonlocal.local',
      'host.arch': 'arm64',
      'os.type': 'darwin',
      'os.version': '23.5.0',
      'service.instance.id': 'a76f5efb-7885-43ed-8fb4-9dc8e3398cf6',
      'process.pid': 42300,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/david/.nvm/versions/node/v18.16.0/bin/node',
      'process.command_args': [
        '/Users/david/.nvm/versions/node/v18.16.0/bin/node',
        '--require',
        '@opentelemetry/auto-instrumentations-node/register',
        '/Users/david/Documents/repos/_temp/auto/index.js'
      ],
      'process.runtime.version': '18.16.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/david/Documents/repos/_temp/auto/index.js',
      'process.owner': 'david',
      'host.id': '7904601F-B9AB-5EB2-A389-E32C06D56851'
    }
  },
  traceId: 'ece99000315c980e2b9ec5ec8598093e',
  parentId: '36483355dad25343',
  traceState: undefined,
  name: 'tcp.connect',
  id: '9d341c6668a04ee0',
  kind: 0,
  timestamp: 1718788125996000,
  duration: 3008817.375,
  attributes: {
    'net.transport': 'ip_tcp',
    'net.peer.name': '169.254.169.254',
    'net.peer.port': 80
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: {
    attributes: {
      'service.name': 'unknown_service:node',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '1.25.0',
      'host.name': 'moonlocal.local',
      'host.arch': 'arm64',
      'os.type': 'darwin',
      'os.version': '23.5.0',
      'service.instance.id': 'a76f5efb-7885-43ed-8fb4-9dc8e3398cf6',
      'process.pid': 42300,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/david/.nvm/versions/node/v18.16.0/bin/node',
      'process.command_args': [
        '/Users/david/.nvm/versions/node/v18.16.0/bin/node',
        '--require',
        '@opentelemetry/auto-instrumentations-node/register',
        '/Users/david/Documents/repos/_temp/auto/index.js'
      ],
      'process.runtime.version': '18.16.0',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/david/Documents/repos/_temp/auto/index.js',
      'process.owner': 'david',
      'host.id': '7904601F-B9AB-5EB2-A389-E32C06D56851'
    }
  },
  traceId: 'ece99000315c980e2b9ec5ec8598093e',
  parentId: undefined,
  traceState: undefined,
  name: 'GET',
  id: '36483355dad25343',
  kind: 2,
  timestamp: 1718788125995000,
  duration: 3011271.333,
  attributes: {
    'http.url': 'http://169.254.169.254/computeMetadata/v1/instance',
    'http.method': 'GET',
    'http.target': '/computeMetadata/v1/instance',
    'net.peer.name': '169.254.169.254',
    'http.host': '169.254.169.254:80',
    'http.error_name': 'Error',
    'http.error_message': 'socket hang up'
  },
  status: { code: 2, message: 'socket hang up' },
  events: [
    {
      name: 'exception',
      attributes: {
        'exception.type': 'ECONNRESET',
        'exception.message': 'socket hang up',
        'exception.stacktrace': 'Error: socket hang up\n' +
          '    at connResetException (node:internal/errors:717:14)\n' +
          '    at Socket.socketCloseListener (node:_http_client:475:25)\n' +
          '    at Socket.emit (node:events:525:35)\n' +
          '    at TCP.<anonymous> (node:net:322:12)\n' +
          '    at TCP.callbackTrampoline (node:internal/async_hooks:130:17)'
      },
      time: [ 1718788129, 6248458 ],
      droppedAttributesCount: 0
    }
  ],
  links: []
}

The text was updated successfully, but these errors were encountered:

david-luna · 2024-07-05T17:59:14Z

@pichlermarc since we agreed on suppress tracing in the implicated detectors and these are placed in opentelemetry-js-contrib repo. Should I move the issue there?

trentm · 2024-07-05T21:54:35Z

Should I move the issue there?

@david-luna I think, yes.

hectorhdzg · 2024-07-12T18:35:31Z

@david-luna I can see Azure VM detector trace there as well, are you refactoring all detectors to use latest interface and then fixing the issue suppressing the trace in the resources package? sorry if you already clarified this but is easy to get lost with all the referenced issues and PRs here.

david-luna · 2024-07-12T19:50:31Z

@hectorhdzg that's correct :)

david-luna · 2024-08-02T08:06:10Z

@hectorhdzg that's correct :)

Clarification on that. Azure detectors are already implementing DetectorSync interface so I'm going to start the PR to suppress tracing for them :)

david-luna · 2024-08-05T17:59:21Z

Reverting auto close done in #2328

david-luna added bug Something isn't working triage labels Jun 19, 2024

david-luna mentioned this issue Jun 19, 2024

InstrumentationBase calls init on partly initialized Instrumentations open-telemetry/opentelemetry-js#1989

Open

pichlermarc added priority:p2 Bugs and spec inconsistencies which cause telemetry to be incomplete or incorrect and removed triage labels Jun 19, 2024

david-luna transferred this issue from open-telemetry/opentelemetry-js Jul 8, 2024

david-luna closed this as completed in #2328 Aug 2, 2024

david-luna reopened this Aug 5, 2024

david-luna mentioned this issue Aug 6, 2024

fix(detector-azure): suppress tracing for AzureVmDetector #2371

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

traces of resource detectors being sent #2320

traces of resource detectors being sent #2320

david-luna commented Jun 19, 2024 •

edited

Loading

david-luna commented Jul 5, 2024

trentm commented Jul 5, 2024

hectorhdzg commented Jul 12, 2024

david-luna commented Jul 12, 2024

david-luna commented Aug 2, 2024

david-luna commented Aug 5, 2024

traces of resource detectors being sent #2320

traces of resource detectors being sent #2320

Comments

david-luna commented Jun 19, 2024 • edited Loading

What happened?

Steps to Reproduce

Expected Result

Actual Result

Additional Details

Application Code

package.json

Relevant log output

david-luna commented Jul 5, 2024

trentm commented Jul 5, 2024

hectorhdzg commented Jul 12, 2024

david-luna commented Jul 12, 2024

david-luna commented Aug 2, 2024

david-luna commented Aug 5, 2024

david-luna commented Jun 19, 2024 •

edited

Loading