Span Status not being set as ERROR for HTTP Client spans even if the HTTP status code is 4xx.

[biswajit-nanda]

What happened?

I have a very simple node.js application that receives a HTTP request and then makes a HTTP get call to http://httpstat.us:80/410 which returns a 410 status code.

Please see the attached reproduction.zip/app.js.

The instrumentation is done using attached reproduction.zip/tracing.js.

The application gets instrumented successfully, but the Span Status of the Client Span making the HTTP call to http://httpstat.us:80/410 is returned as UNSET even if the HTTP Status Code is coming as 410.

Please see the below SPAN snippet in my Otel Collector logs attached: reproduction.zip//otelcol.log.

As per OpenTelemetry Specs (https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/trace/semantic_conventions/http.md#status), for HTTP status codes in the 4xx range span status MUST be left unset in case of SpanKind.SERVER and MUST be set to Error in case of SpanKind.CLIENT.

Steps to Reproduce:

a. Make sure that you have node.js installed on your machine. b. Make sure that you have an OpenTelemetry Collector running on your machine receiving traces over HTTP at http://localhost:4318/v1/traces. It is preferable to configure a logging exporter with loglevel set to debug and add that service->pipelines->traces->exporters c. Download the attached reproduction.zip and unzip it. b. Open a commandline from the unzipped directory and run the app as: node -r ./tracing.js app.js

Expected Result:

Span #1 Trace ID : 317adf38045b52a99bcde15d01fa5b3c Parent ID : cca2305261e20ef6 ID : 785733c484f7ddfa Name : HTTP GET Kind : SPAN_KIND_CLIENT Start time : 2023-01-24 19:56:31.086000128 +0000 UTC End time : 2023-01-24 19:56:31.393211392 +0000 UTC Status code : STATUS_CODE_ERROR Status message : Attributes: -> http.url: STRING(http://httpstat.us/410) -> http.method: STRING(GET) -> http.target: STRING(/410) -> net.peer.name: STRING(httpstat.us) -> http.host: STRING(httpstat.us:80) -> net.peer.ip: STRING(20.40.202.3) -> net.peer.port: INT(80) -> http.response_content_length_uncompressed: INT(8) -> http.status_code: INT(410) -> http.status_text: STRING(GONE) -> http.flavor: STRING(1.1) -> net.transport: STRING(ip_tcp)

Actual Result

Span #1 Trace ID : 317adf38045b52a99bcde15d01fa5b3c Parent ID : cca2305261e20ef6 ID : 785733c484f7ddfa Name : HTTP GET Kind : SPAN_KIND_CLIENT Start time : 2023-01-24 19:56:31.086000128 +0000 UTC End time : 2023-01-24 19:56:31.393211392 +0000 UTC Status code : STATUS_CODE_UNSET Status message : Attributes: -> http.url: STRING(http://httpstat.us/410) -> http.method: STRING(GET) -> http.target: STRING(/410) -> net.peer.name: STRING(httpstat.us) -> http.host: STRING(httpstat.us:80) -> net.peer.ip: STRING(20.40.202.3) -> net.peer.port: INT(80) -> http.response_content_length_uncompressed: INT(8) -> http.status_code: INT(410) -> http.status_text: STRING(GONE) -> http.flavor: STRING(1.1) -> net.transport: STRING(ip_tcp)

Additional Details

reproduction.zip

OpenTelemetry Setup Code

//tracing.js

"use strict";

const process = require("process")
const defaultOtlpEndpoint = 'http://localhost:4318/v1/traces';
const opentelemetry = require("@opentelemetry/sdk-node");
const { getNodeAutoInstrumentations } = require("@opentelemetry/auto-instrumentations-node");
const { ConsoleSpanExporter } = require("@opentelemetry/sdk-trace-base");
const { OTLPTraceExporter } = require("@opentelemetry/exporter-trace-otlp-http");
const { Resource } = require("@opentelemetry/resources");
const { SemanticResourceAttributes } = require("@opentelemetry/semantic-conventions");
// const consoleTraceExporter = new ConsoleSpanExporter();

//Exporter
if ("OTLP_HTTP_ENDPOINT" in process.env) {
  var otlpUrl = process.env.OTLP_HTTP_ENDPOINT;
  console.log ("Value of Environment variable OTLP_HTTP_ENDPOINT set to: " + otlpUrl);
} 
else {
  var otlpUrl = defaultOtlpEndpoint;
  console.log ("Value of Environment variable OTLP_HTTP_ENDPOINT not set, Using: " + otlpUrl);
}

const otlpTraceExporter = new OTLPTraceExporter({
    url: otlpUrl
  })

const sdk = new opentelemetry.NodeSDK({
  resource: new Resource({
      [SemanticResourceAttributes.SERVICE_NAME]: 'nodejs-web',
    }),
  //consoleTraceExporter,
  otlpTraceExporter,
  instrumentations: [getNodeAutoInstrumentations()]
});

sdk.start()
  .then(() => console.log ('Tracing Initialized'))
  .catch((error) => console.log ('Error Initializing Tracing', error))

process.on('SIGTERM', () => {
  sdk.shutdown()
  .then(() => console.log('Tracing Terminated'))
  .catch((error) => console.log('Error Terminating Tracing', error))
  .finally(() => process.exit(0))
  process.exit(0);
});

package.json

{
  "name": "app",
  "version": "1.0.0",
  "main": "app.js",
  "scripts": {
    "start": "node -r tracing.js app.js"
  },
  "dependencies": {
    "@opentelemetry/api": "^1.4.0",
    "@opentelemetry/auto-instrumentations-node": "^0.36.0",
    "@opentelemetry/exporter-trace-otlp-http": "^0.35.0",
    "@opentelemetry/instrumentation": "^0.35.0",
    "@opentelemetry/instrumentation-http": "^0.35.0",
    "@opentelemetry/resources": "^1.9.0",
    "@opentelemetry/sdk-node": "^0.35.0",
    "@opentelemetry/sdk-trace-base": "^1.9.0",
    "@opentelemetry/sdk-trace-node": "^1.9.0",
    "nodejslogger": "^1.2.3"
  }
}

Relevant log output

2023-01-24T13:56:37.180-0600    INFO    loggingexporter/logging_exporter.go:43  TracesExporter  {"#spans": 2}
2023-01-24T13:56:37.180-0600    DEBUG   loggingexporter/logging_exporter.go:52  ResourceSpans #0
Resource SchemaURL: 
Resource labels:
     -> service.name: STRING(nodejs-web)
     -> telemetry.sdk.language: STRING(nodejs)
     -> telemetry.sdk.name: STRING(opentelemetry)
     -> telemetry.sdk.version: STRING(1.9.0)
     -> process.pid: INT(17453)
     -> process.executable.name: STRING(node)
     -> process.command: STRING(/Users/bisnanda/Desktop/reproduction/app.js)
     -> process.command_line: STRING(/usr/local/Cellar/node/18.11.0/bin/node /Users/bisnanda/Desktop/reproduction/app.js)
     -> process.runtime.version: STRING(18.11.0)
     -> process.runtime.name: STRING(nodejs)
     -> process.runtime.description: STRING(Node.js)
ScopeSpans #0
ScopeSpans SchemaURL: 
InstrumentationScope @opentelemetry/instrumentation-http 0.34.0
Span #0
    Trace ID       : 317adf38045b52a99bcde15d01fa5b3c
    Parent ID      : 
    ID             : cca2305261e20ef6
    Name           : HTTP GET
    Kind           : SPAN_KIND_SERVER
    Start time     : 2023-01-24 19:56:31.081999872 +0000 UTC
    End time       : 2023-01-24 19:56:31.390118656 +0000 UTC
    Status code    : STATUS_CODE_UNSET
    Status message : 
Attributes:
     -> http.url: STRING(http://localhost:8080/nodejs/unresolved/hello)
     -> http.host: STRING(localhost:8080)
     -> net.host.name: STRING(localhost)
     -> http.method: STRING(GET)
     -> http.scheme: STRING(http)
     -> http.target: STRING(/nodejs/unresolved/hello)
     -> http.user_agent: STRING(Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/109.0.0.0 Safari/537.36)
     -> http.flavor: STRING(1.1)
     -> net.transport: STRING(ip_tcp)
     -> net.host.ip: STRING(::1)
     -> net.host.port: INT(8080)
     -> net.peer.ip: STRING(::1)
     -> net.peer.port: INT(50322)
     -> http.status_code: INT(410)
     -> http.status_text: STRING(GONE)
Span #1
    Trace ID       : 317adf38045b52a99bcde15d01fa5b3c
    Parent ID      : cca2305261e20ef6
    ID             : 785733c484f7ddfa
    Name           : HTTP GET
    Kind           : SPAN_KIND_CLIENT
    Start time     : 2023-01-24 19:56:31.086000128 +0000 UTC
    End time       : 2023-01-24 19:56:31.393211392 +0000 UTC
    Status code    : STATUS_CODE_UNSET
    Status message : 
Attributes:
     -> http.url: STRING(http://httpstat.us/410)
     -> http.method: STRING(GET)
     -> http.target: STRING(/410)
     -> net.peer.name: STRING(httpstat.us)
     -> http.host: STRING(httpstat.us:80)
     -> net.peer.ip: STRING(20.40.202.3)
     -> net.peer.port: INT(80)
     -> http.response_content_length_uncompressed: INT(8)
     -> http.status_code: INT(410)
     -> http.status_text: STRING(GONE)
     -> http.flavor: STRING(1.1)
     -> net.transport: STRING(ip_tcp)

2023-01-24T13:56:37.180-0600    debug   otlphttpexporter/otlp.go:128    Preparing to make HTTP request  {"kind": "exporter", "data_type": "traces", "name": "otlphttp/appdcloud", "url": "https://support-pdx-p01-c3.observe.appdynamics.com/data/v1/trace"}

[github-actions[bot]]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[biswajit-nanda]

Is there any update on this?

[pichlermarc]

@biswajit-nanda we have not gotten around to work on this one yet. I'm marking it up-for-grabs in case someone has some cycles to work on it.

[github-actions[bot]]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[pichlermarc]

This took me quite a while to figure out today:

It looks like this is already set correctly as long as the response handler subscribes to the data event on the IncomingMessage in the callback. I'm wondering if there's a reason why we set the span status only on the end and close events, even though we'd be able to set it on response already. :thinking:

[pichlermarc]

Very minimal reproduction:

// Will NOT add span status
   const req = http.get({
        hostname: 'httpstat.us',
        port: 80,
        path: '/410',
        method: 'GET',
    }, (response) => { });
    req.end();

// Will add span status as handling 'data' will also trigger 'end' later on, 
// the 'end' event is also what we register in the instrumentation.
   const req = http.get({
        hostname: 'httpstat.us',
        port: 80,
        path: '/410',
        method: 'GET',
    }, (response) => {
        response.on('data', (chunk) => {});
    });
    req.end();

[github-actions[bot]]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

[github-actions[bot]]

This issue was closed because it has been stale for 14 days with no activity.

[pichlermarc]

This is still happening (see reproducer). I'm unassigning myself as I won't have time to work on this for now.

[github-actions[bot]]

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.