Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

traces of resource detectors being sent #2320

Open
david-luna opened this issue Jun 19, 2024 · 10 comments · Fixed by #2328
Open

traces of resource detectors being sent #2320

david-luna opened this issue Jun 19, 2024 · 10 comments · Fixed by #2328
Labels
bug Something isn't working priority:p2 Bugs and spec inconsistencies which cause telemetry to be incomplete or incorrect

Comments

@david-luna
Copy link
Contributor

david-luna commented Jun 19, 2024

What happened?

Steps to Reproduce

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: []
}
@david-luna david-luna added bug Something isn't working triage labels Jun 19, 2024
@pichlermarc 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
Copy link
Contributor Author

@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
Copy link
Contributor

trentm commented Jul 5, 2024

Should I move the issue there?

@david-luna I think, yes.

@hectorhdzg
Copy link
Member

@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
Copy link
Contributor Author

@hectorhdzg that's correct :)

@david-luna
Copy link
Contributor Author

@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
Copy link
Contributor Author

Reverting auto close done in #2328

@david-luna
Copy link
Contributor Author

Interestingly after update the example to @opentelemetry/[email protected] we do not get traces from the detectors but still get some from @opentelemetry/instrumentation-net

ExportTraceServiceRequest {
  resourceSpans: [
    ResourceSpans {
      scopeSpans: [
        ScopeSpans {
          spans: [
            Span {
              attributes: [
                KeyValue { key: 'net.transport', value: AnyValue { stringValue: 'ip_tcp' } },
                KeyValue { key: 'net.peer.name', value: AnyValue { stringValue: '169.254.169.254' } },
                KeyValue { key: 'net.peer.port', value: AnyValue { intValue: Long { low: 80, high: 0, unsigned: false } } }
              ],
              events: [],
              links: [],
              traceId: Buffer(16) [Uint8Array] [
                 63,  43,  97,  93,   4, 113,
                 13, 129, 150,  94, 191,  90,
                169,  79,  78, 118
              ],
              spanId: Buffer(8) [Uint8Array] [
                136,  21, 223,
                110, 210, 116,
                219, 230
              ],
              parentSpanId: Buffer(8) [Uint8Array] [
                106,  25, 212, 142,
                251, 167,  88, 173
              ],
              name: 'tcp.connect',
              kind: 1,
              startTimeUnixNano: Long { low: 1033071104, high: 402342101, unsigned: true },
              endTimeUnixNano: Long { low: 1036174854, high: 402342101, unsigned: true },
              droppedAttributesCount: 0,
              droppedEventsCount: 0,
              droppedLinksCount: 0,
              status: Status { message: 'connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.1.16:51771)', code: 2 }
            },
            Span {
              attributes: [
                KeyValue { key: 'net.transport', value: AnyValue { stringValue: 'ip_tcp' } },
                KeyValue { key: 'net.peer.name', value: AnyValue { stringValue: 'metadata.google.internal.' } },
                KeyValue { key: 'net.peer.port', value: AnyValue { intValue: Long { low: 80, high: 0, unsigned: false } } }
              ],
              events: [],
              links: [],
              traceId: Buffer(16) [Uint8Array] [
                 45, 248, 149,  61,   2, 143,
                159, 250,  15,  28, 242,  64,
                255, 149,  19, 228
              ],
              spanId: Buffer(8) [Uint8Array] [
                 11,  57, 155, 247,
                205, 119,  42, 115
              ],
              parentSpanId: Buffer(8) [Uint8Array] [
                 97, 84, 186, 118,
                210, 92, 224, 194
              ],
              name: 'tcp.connect',
              kind: 1,
              startTimeUnixNano: Long { low: 1034071104, high: 402342101, unsigned: true },
              endTimeUnixNano: Long { low: 1037742312, high: 402342101, unsigned: true },
              droppedAttributesCount: 0,
              droppedEventsCount: 0,
              droppedLinksCount: 0,
              status: Status { message: 'getaddrinfo ENOTFOUND metadata.google.internal.', code: 2 }
            }
          ],
          scope: InstrumentationScope { attributes: [], name: '@opentelemetry/instrumentation-net', version: '0.39.0' }
        },
        ScopeSpans {
          spans: [
            Span {
              attributes: [
                KeyValue { key: 'http.url', value: AnyValue { stringValue: 'http://169.254.169.254/computeMetadata/v1/instance' } },
                KeyValue { key: 'http.method', value: AnyValue { stringValue: 'GET' } },
                KeyValue { key: 'http.target', value: AnyValue { stringValue: '/computeMetadata/v1/instance' } },
                KeyValue { key: 'net.peer.name', value: AnyValue { stringValue: '169.254.169.254' } },
                KeyValue { key: 'http.host', value: AnyValue { stringValue: '169.254.169.254:80' } },
                KeyValue { key: 'http.error_name', value: AnyValue { stringValue: 'Error' } },
                KeyValue { key: 'http.error_message', value: AnyValue { stringValue: 'connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.1.16:51771)' } }
              ],
              events: [
                Event {
                  attributes: [
                    KeyValue { key: 'exception.type', value: AnyValue { stringValue: 'EHOSTDOWN' } },
                    KeyValue { key: 'exception.message', value: AnyValue { stringValue: 'connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.1.16:51771)' } },
                    KeyValue {
                      key: 'exception.stacktrace',
                      value: AnyValue {
                        stringValue: 'Error: connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.1.16:51771)\n' +
                          '    at internalConnect (node:net:1066:16)\n' +
                          '    at defaultTriggerAsyncIdScope (node:internal/async_hooks:464:18)\n' +
                          '    at node:net:1250:9\n' +
                          '    at process.processTicksAndRejections (node:internal/process/task_queues:77:11)'
                      }
                    }
                  ],
                  timeUnixNano: Long { low: 1036216937, high: 402342101, unsigned: true },
                  name: 'exception',
                  droppedAttributesCount: 0
                }
              ],
              links: [],
              traceId: Buffer(16) [Uint8Array] [
                 63,  43,  97,  93,   4, 113,
                 13, 129, 150,  94, 191,  90,
                169,  79,  78, 118
              ],
              spanId: Buffer(8) [Uint8Array] [
                106,  25, 212, 142,
                251, 167,  88, 173
              ],
              name: 'GET',
              kind: 3,
              startTimeUnixNano: Long { low: 1032071104, high: 402342101, unsigned: true },
              endTimeUnixNano: Long { low: 1036236354, high: 402342101, unsigned: true },
              droppedAttributesCount: 0,
              droppedEventsCount: 0,
              droppedLinksCount: 0,
              status: Status { message: 'connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.1.16:51771)', code: 2 }
            },
            Span {
              attributes: [
                KeyValue { key: 'http.url', value: AnyValue { stringValue: 'http://metadata.google.internal./computeMetadata/v1/instance' } },
                KeyValue { key: 'http.method', value: AnyValue { stringValue: 'GET' } },
                KeyValue { key: 'http.target', value: AnyValue { stringValue: '/computeMetadata/v1/instance' } },
                KeyValue { key: 'net.peer.name', value: AnyValue { stringValue: 'metadata.google.internal.' } },
                KeyValue { key: 'http.host', value: AnyValue { stringValue: 'metadata.google.internal.:80' } },
                KeyValue { key: 'http.error_name', value: AnyValue { stringValue: 'Error' } },
                KeyValue { key: 'http.error_message', value: AnyValue { stringValue: 'getaddrinfo ENOTFOUND metadata.google.internal.' } }
              ],
              events: [
                Event {
                  attributes: [
                    KeyValue { key: 'exception.type', value: AnyValue { stringValue: 'ENOTFOUND' } },
                    KeyValue { key: 'exception.message', value: AnyValue { stringValue: 'getaddrinfo ENOTFOUND metadata.google.internal.' } },
                    KeyValue {
                      key: 'exception.stacktrace',
                      value: AnyValue {
                        stringValue: '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)'
                      }
                    }
                  ],
                  timeUnixNano: Long { low: 1038196395, high: 402342101, unsigned: true },
                  name: 'exception',
                  droppedAttributesCount: 0
                }
              ],
              links: [],
              traceId: Buffer(16) [Uint8Array] [
                 45, 248, 149,  61,   2, 143,
                159, 250,  15,  28, 242,  64,
                255, 149,  19, 228
              ],
              spanId: Buffer(8) [Uint8Array] [
                 97, 84, 186, 118,
                210, 92, 224, 194
              ],
              name: 'GET',
              kind: 3,
              startTimeUnixNano: Long { low: 1034071104, high: 402342101, unsigned: true },
              endTimeUnixNano: Long { low: 1038199062, high: 402342101, unsigned: true },
              droppedAttributesCount: 0,
              droppedEventsCount: 0,
              droppedLinksCount: 0,
              status: Status { message: 'getaddrinfo ENOTFOUND metadata.google.internal.', code: 2 }
            }
          ],
          scope: InstrumentationScope { attributes: [], name: '@opentelemetry/instrumentation-http', version: '0.53.0' }
        }
      ],
      resource: Resource {
        attributes: [
          KeyValue { key: 'service.name', value: AnyValue { stringValue: 'unknown_service:node' } },
          KeyValue { key: 'telemetry.sdk.language', value: AnyValue { stringValue: 'nodejs' } },
          KeyValue { key: 'telemetry.sdk.name', value: AnyValue { stringValue: 'opentelemetry' } },
          KeyValue { key: 'telemetry.sdk.version', value: AnyValue { stringValue: '1.26.0' } },
          KeyValue { key: 'host.name', value: AnyValue { stringValue: 'moonlocal.local' } },
          KeyValue { key: 'host.arch', value: AnyValue { stringValue: 'arm64' } },
          KeyValue { key: 'os.type', value: AnyValue { stringValue: 'darwin' } },
          KeyValue { key: 'os.version', value: AnyValue { stringValue: '23.6.0' } },
          KeyValue { key: 'service.instance.id', value: AnyValue { stringValue: 'e2335740-7f88-424f-984b-96b0bb522776' } },
          KeyValue { key: 'process.pid', value: AnyValue { intValue: Long { low: 91666, high: 0, unsigned: false } } },
          KeyValue { key: 'process.executable.name', value: AnyValue { stringValue: 'node' } },
          KeyValue { key: 'process.executable.path', value: AnyValue { stringValue: '/Users/david/.nvm/versions/node/v18.16.0/bin/node' } },
          KeyValue {
            key: 'process.command_args',
            value: AnyValue {
              arrayValue: ArrayValue {
                values: [
                  AnyValue { stringValue: '/Users/david/.nvm/versions/node/v18.16.0/bin/node' },
                  AnyValue { stringValue: '--require' },
                  AnyValue { stringValue: '@opentelemetry/auto-instrumentations-node/register' },
                  AnyValue { stringValue: '/Users/david/Documents/repos/_temp/auto/server.js' }
                ]
              }
            }
          },
          KeyValue { key: 'process.runtime.version', value: AnyValue { stringValue: '18.16.0' } },
          KeyValue { key: 'process.runtime.name', value: AnyValue { stringValue: 'nodejs' } },
          KeyValue { key: 'process.runtime.description', value: AnyValue { stringValue: 'Node.js' } },
          KeyValue { key: 'process.command', value: AnyValue { stringValue: '/Users/david/Documents/repos/_temp/auto/server.js' } },
          KeyValue { key: 'process.owner', value: AnyValue { stringValue: 'david' } },
          KeyValue { key: 'host.id', value: AnyValue { stringValue: '7904601F-B9AB-5EB2-A389-E32C06D56851' } }
        ],
        droppedAttributesCount: 0
      }
    }
  ]
}
------ trace 3f2b61 (2 spans) ------
       span 6a19d4 "GET" (4.2ms, STATUS_CODE_ERROR, SPAN_KIND_CLIENT, GET http://169.254.169.254/computeMetadata/v1/instance)
  +1ms `- span 8815df "tcp.connect" (3.1ms, STATUS_CODE_ERROR, SPAN_KIND_INTERNAL)
------ trace 2df895 (2 spans) ------
       span 6154ba "GET" (4.1ms, STATUS_CODE_ERROR, SPAN_KIND_CLIENT, GET http://metadata.google.internal./computeMetadata/v1/instance)
  +0ms `- span 0b399b "tcp.connect" (3.7ms, STATUS_CODE_ERROR, SPAN_KIND_INTERNAL)

so this issue needs a bit more investigation and work

@david-luna
Copy link
Contributor Author

new version of GCP detector is not released yet. #2420

@trentm
Copy link
Contributor

trentm commented Oct 8, 2024

@david-luna The GCP detector is released node: @opentelemetry/[email protected]
However, I still get HTTP spans from it:

just-http-request.js

const http = require('http');
const url = 'http://www.google.com/';
const clientReq = http.request(url, function (cres) {
    console.log('client response: %s %s', cres.statusCode, cres.headers);
    const chunks = [];
    cres.on('data', function (chunk) {
        chunks.push(chunk);
    });
    cres.on('end', function () {
        const body = chunks.join('');
        console.log(
            'client response body (%d bytes): "%s..."',
            Buffer.byteLength(body),
            JSON.stringify(body.slice(0, 40)).slice(1, -1)
        );
    });
});
clientReq.end();

Running that:

% npm ls
[email protected] /Users/trentm/tmp/asdf.20241008T162508
└── @opentelemetry/[email protected]

% npm ls @opentelemetry/resource-detector-gcp
[email protected] /Users/trentm/tmp/asdf.20241008T162508
└─┬ @opentelemetry/[email protected]
  └── @opentelemetry/[email protected]

% node -r @opentelemetry/auto-instrumentations-node/register  just-http-request.js
OTEL_LOGS_EXPORTER is empty. Using default otlp exporter.
OTEL_TRACES_EXPORTER is empty. Using default otlp exporter.
OpenTelemetry automatic instrumentation started successfully
Accessing resource attributes before async attributes settled
Accessing resource attributes before async attributes settled
Accessing resource attributes before async attributes settled
client response: 200 {
  date: 'Tue, 08 Oct 2024 23:33:46 GMT',
  expires: '-1',
  'cache-control': 'private, max-age=0',
  'content-type': 'text/html; charset=ISO-8859-1',
  'content-security-policy-report-only': "object-src 'none';base-uri 'self';script-src 'nonce-_OWpeL8PQZceTT9VpI2nLA' 'strict-dynamic' 'report-sample' 'unsafe-eval' 'unsafe-inline' https: http:;report-uri https://csp.withgoogle.com/csp/gws/other-hp",
  p3p: 'CP="This is not a P3P policy! See g.co/p3phelp for more info."',
  server: 'gws',
  'x-xss-protection': '0',
  'x-frame-options': 'SAMEORIGIN',
  'set-cookie': [Array],
  'accept-ranges': 'none',
  vary: 'Accept-Encoding',
  connection: 'close',
  'transfer-encoding': 'chunked'
}
client response body (58848 bytes): "<!doctype html><html itemscope=\"\" itemty..."

Results in this telemetry (to mockoltpserver):

{
  "resourceSpans": [
    {
      "resource": {
        "attributes": {
          "service.name": "unknown_service:node",
          "telemetry.sdk.language": "nodejs",
          "telemetry.sdk.name": "opentelemetry",
          "telemetry.sdk.version": "1.26.0",
          "host.name": "peach.local",
          "host.arch": "arm64",
          "os.type": "darwin",
          "os.version": "23.6.0",
          "service.instance.id": "85d69681-7f04-4900-8a69-03a8283623e7",
          "process.pid": 55807,
          "process.executable.name": "node",
          "process.executable.path": "/Users/trentm/.nvm/versions/node/v18.20.4/bin/node",
          "process.command_args": [
            "/Users/trentm/.nvm/versions/node/v18.20.4/bin/node",
            "-r",
            "@opentelemetry/auto-instrumentations-node/register",
            "/Users/trentm/tmp/asdf.20241008T162508/just-http-request.js"
          ],
          "process.runtime.version": "18.20.4",
          "process.runtime.name": "nodejs",
          "process.runtime.description": "Node.js",
          "process.command": "/Users/trentm/tmp/asdf.20241008T162508/just-http-request.js",
          "process.owner": "trentm",
          "host.id": "REDACTED"
        },
        "droppedAttributesCount": 0
      },
      "scopeSpans": [
        {
          "scope": {
            "name": "@opentelemetry/instrumentation-http",
            "version": "0.53.0"
          },
          "spans": [
            {
              "traceId": "357313860fa68937f04c0b95e81e762f",
              "spanId": "57125359a17fcc03",
              "name": "GET",
              "kind": "SPAN_KIND_CLIENT",
              "startTimeUnixNano": "1728430426611000000",
              "endTimeUnixNano": "1728430426612594292",
              "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": "connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.7.248:58233)"
              },
              "droppedAttributesCount": 0,
              "events": [
                {
                  "timeUnixNano": "1728430426612556542",
                  "name": "exception",
                  "attributes": {
                    "exception.type": "EHOSTDOWN",
                    "exception.message": "connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.7.248:58233)",
                    "exception.stacktrace": "Error: connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.7.248:58233)\n    at internalConnect (node:net:1100:16)\n    at defaultTriggerAsyncIdScope (node:internal/async_hooks:462:18)\n    at node:net:1306:9\n    at process.processTicksAndRejections (node:internal/process/task_queues:77:11)"
                  },
                  "droppedAttributesCount": 0
                }
              ],
              "droppedEventsCount": 0,
              "droppedLinksCount": 0,
              "status": {
                "message": "connect EHOSTDOWN 169.254.169.254:80 - Local (192.168.7.248:58233)",
                "code": "STATUS_CODE_ERROR"
              }
            },
            {
              "traceId": "6e2a47149faf6007dd4dc0598f31119b",
              "spanId": "163f121cf22a9818",
              "name": "GET",
              "kind": "SPAN_KIND_CLIENT",
              "startTimeUnixNano": "1728430426612000000",
              "endTimeUnixNano": "1728430426614149625",
              "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."
              },
              "droppedAttributesCount": 0,
              "events": [
                {
                  "timeUnixNano": "1728430426614146541",
                  "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:128:17)"
                  },
                  "droppedAttributesCount": 0
                }
              ],
              "droppedEventsCount": 0,
              "droppedLinksCount": 0,
              "status": {
                "message": "getaddrinfo ENOTFOUND metadata.google.internal.",
                "code": "STATUS_CODE_ERROR"
              }
            },
            {
              "traceId": "5566d5202354b78f0c41bef4f79a65b1",
              "spanId": "74de796ab1a7c799",
              "name": "GET",
              "kind": "SPAN_KIND_CLIENT",
              "startTimeUnixNano": "1728430426606000000",
              "endTimeUnixNano": "1728430426724106084",
              "attributes": {
                "http.url": "http://www.google.com/",
                "http.method": "GET",
                "http.target": "/",
                "net.peer.name": "www.google.com",
                "http.host": "www.google.com:80",
                "net.peer.ip": "142.251.33.100",
                "net.peer.port": 80,
                "http.status_code": 200,
                "http.status_text": "OK",
                "http.flavor": "1.1",
                "net.transport": "ip_tcp"
              },
              "droppedAttributesCount": 0,
              "droppedEventsCount": 0,
              "droppedLinksCount": 0,
              "status": {
                "code": "STATUS_CODE_UNSET"
              }
            }
          ]
        }
      ]
    }
  ]
}
------ trace 357313 (1 span) ------
       span 571253 "GET" (1.6ms, STATUS_CODE_ERROR, SPAN_KIND_CLIENT, GET http://169.254.169.254/computeMetadata/v1/instance)
------ trace 6e2a47 (1 span) ------
       span 163f12 "GET" (2.1ms, STATUS_CODE_ERROR, SPAN_KIND_CLIENT, GET http://metadata.google.internal./computeMetadata/v1/instance)
------ trace 5566d5 (1 span) ------
       span 74de79 "GET" (118.1ms, SPAN_KIND_CLIENT, GET http://www.google.com/ -> 200)

Perhaps the gaxios call being made by the gcp-metadata dep is being invoked in a way that breaks the context tracking? I'm guessing.

@trentm
Copy link
Contributor

trentm commented Oct 9, 2024

Looking at GcpDetector, here is what I think is happening:

class GcpDetector implements DetectorSync {
  detect(_config?: ResourceDetectionConfig): IResource {
    const attributes = context.with(suppressTracing(context.active()), () =>
      this._getAttributes()
    );
    return new Resource({}, attributes);
  }

  private async _getAttributes(): Promise<ResourceAttributes> {
    if (!(await gcpMetadata.isAvailable())) {
      diag.debug('GcpDetector failed: GCP Metadata unavailable.');
      return {};
    }

    const [projectId, instanceId, zoneId, clusterName, hostname] =
      await Promise.all([
        this._getProjectId(),
        this._getInstanceId(),
        this._getZone(),
        this._getClusterName(),
        this._getHostname(),
      ]);
    // ...

When .detect() is called (early in the NodeSDK .start()) a ContextManager has not yet been registered. So when context.with(suppressTracing(context.active()), ... is called the context.with() is the implementation in the NoopContextManager ... which throws away the given context (with the suppress-tracing key on it).

The GcpDetector then goes into await gcpMetadata.isAvailable() where there is a long enough Promise chain before the actual HTTP request(s) that by this time: globals for tracing and context are registered. Something calls require('http') at this point -- I think it might be the gaxios library or its node-fetch dep itself -- which triggers the http instrumentation, and we start getting spans from those gaxios requests.

I don't have an idea for a fix yet.
(This is now the second reasons I've recently had for wanting to drop using the gcp-metadata module. The previous one was #2440 (comment))

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working priority:p2 Bugs and spec inconsistencies which cause telemetry to be incomplete or incorrect
Projects
None yet
4 participants