feat(sdk-trace-base): log resource attributes in ConsoleSpanExporter

[pichlermarc]

Which problem is this PR solving?

It's currently impossible to troubleshoot resource setup without explicitly logging the resource before setting up the SDK.
This PR adds the span's resource to the output that's logged to the console to aid troubleshooting.

Type of change

• New feature (non-breaking change which adds functionality)

[codecov]

Codecov Report

Merging #4605 (6513763) into main (c046867) will not change coverage.
The diff coverage is n/a.

Additional details and impacted files

@@           Coverage Diff           @@
##             main    #4605   +/-   ##
=======================================
  Coverage   92.83%   92.83%           
=======================================
  Files         329      329           
  Lines        9528     9528           
  Branches     2053     2053           
=======================================
  Hits         8845     8845           
  Misses        683      683           

Files	Coverage Δ
...y-sdk-trace-base/src/export/ConsoleSpanExporter.ts	82.35% <ø> (ø)

[Flarna]

Not sure if adding immutable Resource to each and every printed span is really helpful in general.
What about a log once or some opt-in?

[pichlermarc]

Not sure if adding immutable Resource to each and every printed span is really helpful in general.

Yes it's not optimal, I think that was the original reason why this way not added.

What about a log once or some opt-in?

We rejected logging once at some point in the past as we'd have to build a map to organize the data as an equivalent to ResourceSpans. It's a very code and resource intensive operation for what is intended as a quick debugging tool.

I'd also like to avoid increasing the API surface for this if at all possible.

Opting-in for this kind of situation would require users to pass an extra option to NodeSDK, instead of just being able to set OTEL_TRACES_EXPORTER=console which is an option there. This can be cumbersome when troubleshooting containerized apps where resources are added dynamically (such as via environment variables or a container detector). In situations like this the person troubleshooting also may not have the ability to quickly change the code they're running, but they may be able to modify environment variables.

I think that the extra verbosity is the best compromise until we can change the exporter-interface to require pre-organized data in SDK 2.0.

[Flarna]

config could happen via env similar to other exporters which, e.g. OTEL_EXPORTER_OTLP_TRACES_ENDPOINT.

But well, that likely needs spec work first so out of scope here.

[trentm]

We rejected logging once at some point in the past as we'd have to build a map to organize the data as an equivalent to ResourceSpans.

I was playing with this a little bit... but then I noticed that given OTEL_TRACES_EXPORTER=console, the NodeSDK will wrap the ConsoleSpanExporter in SimpleSpanProcessor rather than BatchSpanProcessor, so ConsoleSpanExporter will only ever get one span at a time. In other words, quick code I'd done in ConsoleSpanExporter to group into resourceSpans groups never grouped anything.

Perhaps that's expected for debugging -- don't want possible issues/confusion from batching to get in the way?

Experiment A

1. hack sdk-node to use batching for ConsoleSpanExporter:

--- a/experimental/packages/opentelemetry-sdk-node/src/TracerProviderWithEnvExporter.ts
+++ b/experimental/packages/opentelemetry-sdk-node/src/TracerProviderWithEnvExporter.ts
@@ -168,7 +168,7 @@ export class TracerProviderWithEnvExporters extends NodeTracerProvider {
     exporters: SpanExporter[]
   ): (BatchSpanProcessor | SimpleSpanProcessor)[] {
     return exporters.map(exporter => {
-      if (exporter instanceof ConsoleSpanExporter) {
+      if (false && exporter instanceof ConsoleSpanExporter) {
         return new SimpleSpanProcessor(exporter);
       } else {
         return new BatchSpanProcessor(exporter);

2. Do the resourceSpans grouping in COnsoleSpanExporter:

diff --git a/packages/opentelemetry-sdk-trace-base/src/export/ConsoleSpanExporter.ts b/packages/opentelemetry-sdk-trace-base/src/export/ConsoleSpanExporter.ts
index 596b3cef..afe0c51a 100644
--- a/packages/opentelemetry-sdk-trace-base/src/export/ConsoleSpanExporter.ts
+++ b/packages/opentelemetry-sdk-trace-base/src/export/ConsoleSpanExporter.ts
@@ -86,8 +86,26 @@ export class ConsoleSpanExporter implements SpanExporter {
     spans: ReadableSpan[],
     done?: (result: ExportResult) => void
   ): void {
+    const resourceSpanss = [];
     for (const span of spans) {
-      console.dir(this._exportInfo(span), { depth: 3 });
+      const lastResourceSpans = resourceSpanss[resourceSpanss.length - 1];
+      if (!lastResourceSpans || span.resource !== lastResourceSpans.resource) {
+        resourceSpanss.push({
+          resource: span.resource,
+          spans: [span],
+        });
+      } else {
+        lastResourceSpans.spans.push(span);
+      }
+    }
+    for (const resourceSpans of resourceSpanss) {
+      const repr = {
+        resource: {
+          attributes: resourceSpans.resource.attributes,
+        },
+        spans: resourceSpans.spans.map(this._exportInfo),
+      };
+      console.dir(repr, { depth: 3 });
     }
     if (done) {
       return done({ code: ExportResultCode.SUCCESS });

Running that with an example script that generates a number of spans manually looks like this:

% OTEL_TRACES_EXPORTER=console node --require ./start-otel-sdk.js  two-spans-same-ms.js
{
  resource: {
    attributes: {
      'service.name': 'two-spans-same-ms',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '1.23.0',
      'process.pid': 18222,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/trentm/.nvm/versions/node/v16.20.2/bin/node',
      'process.command_args': [
        '/Users/trentm/.nvm/versions/node/v16.20.2/bin/node',
        '--require',
        './start-otel-sdk.js',
        '/Users/trentm/el/elastic-otel-node/examples/two-spans-same-ms.js'
      ],
      'process.runtime.version': '16.20.2',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/trentm/el/elastic-otel-node/examples/two-spans-same-ms.js',
      'process.owner': 'trentm',
      'host.name': 'pink.local',
      'host.arch': 'amd64'
    }
  },
  spans: [
    {
      traceId: '5e90c21c4dbb77f9016d5c24ee9fe544',
      parentId: 'bf275154efa723ea',
      traceState: undefined,
      name: 's0',
      id: 'ebac52081dca7031',
      kind: 0,
      timestamp: 1712278050712000,
      duration: 179.639,
      attributes: {},
      status: { code: 0 },
      events: [],
      links: []
    },
    {
      traceId: '5e90c21c4dbb77f9016d5c24ee9fe544',
      parentId: 'bf275154efa723ea',
      traceState: undefined,
      name: 's1',
      id: '6ba38d3bcda92f77',
      kind: 0,
      timestamp: 1712278050713000,
      duration: 61.716,
      attributes: {},
      status: { code: 0 },
      events: [],
      links: []
    },
    {
      traceId: '5e90c21c4dbb77f9016d5c24ee9fe544',
      parentId: 'bf275154efa723ea',
      traceState: undefined,
      name: 's2',
      id: '1ddbb777d28fa605',
      kind: 0,
      timestamp: 1712278050713000,
      duration: 53.049,
      attributes: {},
      status: { code: 0 },
      events: [],
      links: []
    },
...

Thoughts?

[trentm]

Experiment B

1. Don't change that ConsoleSpanExporter does not get batching.
2. Change ConsoleSpanExporter._sendSpans() to replace span.resource with Symbol.for('ibid') (https://en.wikipedia.org/wiki/Ibid.) if it is the same resource as the last emitted span.

    _sendSpans(spans, done) {
        for (const span of spans) {
            const repr = this._exportInfo(span);
            if (span.resource === this._lastResource) {
                repr.resource = Symbol.for('ibid');
            } else {
                repr.resource = { attributes: span.resource.attributes };
                this._lastResource = span.resource;
            }
            console.dir(repr, { depth: 3 });
        }
        // ...

It looks like this:

% OTEL_TRACES_EXPORTER=console node --require ./start-otel-sdk.js  two-spans-same-ms.js
{
  resource: {
    attributes: {
      'service.name': 'two-spans-same-ms',
      'telemetry.sdk.language': 'nodejs',
      'telemetry.sdk.name': 'opentelemetry',
      'telemetry.sdk.version': '1.23.0',
      'process.pid': 30713,
      'process.executable.name': 'node',
      'process.executable.path': '/Users/trentm/.nvm/versions/node/v16.20.2/bin/node',
      'process.command_args': [
        '/Users/trentm/.nvm/versions/node/v16.20.2/bin/node',
        '--require',
        './start-otel-sdk.js',
        '/Users/trentm/el/elastic-otel-node/examples/two-spans-same-ms.js'
      ],
      'process.runtime.version': '16.20.2',
      'process.runtime.name': 'nodejs',
      'process.runtime.description': 'Node.js',
      'process.command': '/Users/trentm/el/elastic-otel-node/examples/two-spans-same-ms.js',
      'process.owner': 'trentm',
      'host.name': 'pink.local',
      'host.arch': 'amd64'
    }
  },
  traceId: '515e02e858d899fd3722b67d77367831',
  parentId: 'd22952cbf74f4b3d',
  traceState: undefined,
  name: 's0',
  id: '7dd6be7bee63edc9',
  kind: 0,
  timestamp: 1712278578230000,
  duration: 129.955,
  attributes: {},
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: Symbol(ibid),
  traceId: '515e02e858d899fd3722b67d77367831',
  parentId: 'd22952cbf74f4b3d',
  traceState: undefined,
  name: 's1',
  id: '727b4dc3bd7ff842',
  kind: 0,
  timestamp: 1712278578231000,
  duration: 59.35,
  attributes: {},
  status: { code: 0 },
  events: [],
  links: []
}
{
  resource: Symbol(ibid),
  traceId: '515e02e858d899fd3722b67d77367831',
  parentId: 'd22952cbf74f4b3d',
  traceState: undefined,
  name: 's2',
  id: '35cc27f5ba998464',
  kind: 0,
  timestamp: 1712278578231000,
  duration: 38.666,
  attributes: {},
  status: { code: 0 },
  events: [],
  links: []
}
...

Thoughts?

[Flarna]

I wonder why exporter gets more spans in B if SimpleSpanProcessor is used. Isn't the main idea of SimpleSpanProcessor to forward a span sync in onEnd?

In my opinion ConsoleSpanExporter is a debugging tool and delayed output via BatchSpanProcessor is usually not what I want. There is also no network overhead/connection limit/... to consider.

If ConsoleSpanExporter is really just used for debugging the number of spans logged should be not that high so adding resource everywhere should be not that a problem.

If someone has a need for an optimized console exporter because of a special setup it's not that hard to create a custom variant.

By the way, does anyone know what other techs do with resource in console exporter?

[pichlermarc]

I wonder why exporter gets more spans in B if SimpleSpanProcessor is used. Isn't the main idea of SimpleSpanProcessor to forward a span sync in onEnd?

That's also my understanding. @trentm Is is possible that this was using the BatchSpanProcessor? 🤔

In my opinion ConsoleSpanExporter is a debugging tool and delayed output via BatchSpanProcessor is usually not what I want.

Yes, SimpleSpanProcessor is also how I usually use it for debugging. There are some cases where I have used a BatchSpanProcessor to investigate SDK shutdown behavior, but in these cases I'm not too interested in the data that's being exported, but rather I'm interested if something is exported at all given I'm using that processor.

If someone has a need for an optimized console exporter because of a special setup it's not that hard to create a custom variant.

Agree.

By the way, does anyone know what other techs do with resource in console exporter?

• Python just logs it for each span (as suggested in this PR):
  • Exporter
  • ReadableSpan#to_json()
• Ruby also logs it for each span (I'm always having trouble reading ruby code so please correct me if I'm wrong)
  • The Exporter just pretty prints every span, including resource
• C++ also just logs it for each span
  • Exporter
• Java leaves it out (as we do now):
  • Exporter
• The collector likely sorts it to be a ResourceSpans-like structure:
  • I don't have a link to the code, but you can see an output here
  • I've heard people say that it's hard to see which resource/scope is attached to which span, and I agree that it's hard to see sometimes.

Haha, I wonder if anyone will ever again think about this as hard as we do now. 😄

[trentm]

I wonder why exporter gets more spans in B if SimpleSpanProcessor is used. Isn't the main idea of SimpleSpanProcessor to forward a span sync in onEnd?

That's also my understanding. @trentm Is is possible that this was using the BatchSpanProcessor? 🤔

Pretty sure it was with SimpleSpanProcessor. That ibid handling was working across separate calls to ConsoleSpanExporter.export() -- each call was exporting a single span.

[trentm]

I'm fine with this -- though I kinda like the ibid thing. ;)

[pichlermarc]

I'm fine with this -- though I kinda like the ibid thing. ;)

Let's go with the change from this PR first. We can then iterate on it if users find that logging the resource every time is too verbose for debugging purposes.