Express instrumentation 0.33.0 breaks handling http_route metric attribute #1618

mkrudele · 2023-07-31T21:55:03Z

What version of OpenTelemetry are you using?

    "@opentelemetry/api": "1.4.1",
    "@opentelemetry/exporter-prometheus": "0.41.1",
    "@opentelemetry/instrumentation-express": "0.33.0",
    "@opentelemetry/instrumentation-http": "0.41.1",
    "@opentelemetry/sdk-node": "0.41.1",

What version of Node are you using?

v18.16.0

What did you do?

I'm using instrumentation-express to have the http_route attribute added to metrics. Not using traces, just metrics with Prometheus exporter.
It is working with "@opentelemetry/instrumentation-express": "0.32.4", getting this output when scraping metrics:

# HELP target_info Target metadata
# TYPE target_info gauge
target_info{service_name="unknown_service:node",telemetry_sdk_language="nodejs",telemetry_sdk_name="opentelemetry",telemetry_sdk_version="1.15.1",process_pid="48486",process_executable_name="node",process_executable_path="/Users/mcrudele/.nvm/versions/node/v18.16.0/bin/node",process_command_args="[\"/Users/mcrudele/.nvm/versions/node/v18.16.0/bin/node\",\"/Users/mcrudele/projects/michele-crudele/echo-server-instrumented/simple-express.js\"]",process_runtime_version="18.16.0",process_runtime_name="nodejs",process_runtime_description="Node.js",process_command="/Users/mcrudele/projects/michele-crudele/echo-server-instrumented/simple-express.js",process_owner="mcrudele"} 1
# HELP http_server_duration Measures the duration of inbound HTTP requests.
# UNIT http_server_duration ms
# TYPE http_server_duration histogram
http_server_duration_count{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello"} 1
http_server_duration_sum{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello"} 12
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="0"} 0
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="5"} 0
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="10"} 0
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="25"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="50"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="75"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="100"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="250"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="500"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="750"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="1000"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="2500"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="5000"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="7500"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="10000"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",http_route="/hello",le="+Inf"} 1
# HELP http_client_duration Measures the duration of outbound HTTP requests.
# UNIT http_client_duration ms
# TYPE http_client_duration histogram

It is no more working upgrading "@opentelemetry/instrumentation-express": "0.33.0".

# HELP target_info Target metadata
# TYPE target_info gauge
target_info{service_name="unknown_service:node",telemetry_sdk_language="nodejs",telemetry_sdk_name="opentelemetry",telemetry_sdk_version="1.15.1",process_pid="48522",process_executable_name="node",process_executable_path="/Users/mcrudele/.nvm/versions/node/v18.16.0/bin/node",process_command_args="[\"/Users/mcrudele/.nvm/versions/node/v18.16.0/bin/node\",\"/Users/mcrudele/projects/michele-crudele/echo-server-instrumented/simple-express.js\"]",process_runtime_version="18.16.0",process_runtime_name="nodejs",process_runtime_description="Node.js",process_command="/Users/mcrudele/projects/michele-crudele/echo-server-instrumented/simple-express.js",process_owner="mcrudele"} 1
# HELP http_server_duration Measures the duration of inbound HTTP requests.
# UNIT http_server_duration ms
# TYPE http_server_duration histogram
http_server_duration_count{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900"} 1
http_server_duration_sum{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900"} 13
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="0"} 0
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="5"} 0
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="10"} 0
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="25"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="50"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="75"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="100"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="250"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="500"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="750"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="1000"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="2500"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="5000"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="7500"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="10000"} 1
http_server_duration_bucket{http_scheme="http",http_method="GET",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="+Inf"} 1
# HELP http_client_duration Measures the duration of outbound HTTP requests.
# UNIT http_client_duration ms
# TYPE http_client_duration histogram

What did you expect to see?

The http_route attribute in http_server_duration_* metric.

What did you see instead?

The http_route attribute is not present in http_server_duration_* metric.

Additional context

Use this sample code to reproduce:

package.json

{
  "name": "simple-express",
  "version": "1.0.0",
  "main": "simple-express.js",
  "dependencies": {
    "@opentelemetry/api": "1.4.1",
    "@opentelemetry/exporter-prometheus": "0.41.1",
    "@opentelemetry/instrumentation-express": "0.33.0",
    "@opentelemetry/instrumentation-http": "0.41.1",
    "@opentelemetry/sdk-node": "0.41.1",
    "express": "4.18.2"
  },
  "author": "[email protected]",
  "license": "ISC"
}

simple-monitoring.js

const api = require('@opentelemetry/api');
const opentelemetry = require('@opentelemetry/sdk-node');
const { ConsoleSpanExporter, NoopSpanProcessor }  = require('@opentelemetry/sdk-trace-base');
const { PrometheusExporter } = require('@opentelemetry/exporter-prometheus');
const { HttpInstrumentation } = require('@opentelemetry/instrumentation-http');
const { ExpressInstrumentation, ExpressLayerType } = require('@opentelemetry/instrumentation-express');

const pPort = PrometheusExporter.DEFAULT_OPTIONS.port;
const pEndpoint = PrometheusExporter.DEFAULT_OPTIONS.endpoint;

const prometheusExporter = new PrometheusExporter(
    { preventServerStart: false },
    () => { console.log(`>>>> Prometheus scrape endpoint: http://localhost:${pPort}${pEndpoint}`); }
);

const httpInstrumentation = new HttpInstrumentation();
const expressInstrumentation = new ExpressInstrumentation();

const sdk = new opentelemetry.NodeSDK({
    metricReader: prometheusExporter,
    spanProcessor: new NoopSpanProcessor(), // This hack is due to this issue: https://github.com/open-telemetry/opentelemetry-js/issues/3683
    // We need to add express instrumentation to have the http_route attribute added to http server metrics:
    // see https://github.com/open-telemetry/opentelemetry-js/issues/3683
    instrumentations: [ httpInstrumentation, expressInstrumentation ]
});

sdk.start();
console.log('>>>> OpenTelemetry SDK started');

process.on("SIGTERM", () => {
  sdk
    .shutdown()
    .then(
      () => console.log('>>>> SDK shut down successfully'),
      (err) => console.log('>>>> Error shutting down SDK', err)
    )
    .finally(() => process.exit(0));
});

simple-express.js

#!/usr/bin/env node
 
require('./simple-monitoring.js');

const express = require('express');
const app = express();

app.use(express.json());
app.use(express.text({type:"*/*"}));
app.use(express.urlencoded({ extended: true })); // for parsing application/x-www-form-urlencoded

const port = process.argv[2] || 6900;

const processRequest = (req, res) => {
    const body = {
        message: `${req.method} ${req.url} processed`,
    };
    res.status(200).end(JSON.stringify(body));
};

app.use('/hello', (req, res) => {
    console.log(`Got ${req.method} ${req.url}`);
    
    processRequest(req, res); 
}); 
    
app.listen(port, () => {
    console.log(`Echo server is listnening on port ${port}`);
});

Run:

npm install
./simple-express.js, which will start the simple express server exposing the /hello route
curl -s -X GET "http://localhost:6900/hello" in a separate shell
Finally get the scraping enpdoint in your browser http://localhost:9464/metrics and verify the output I've pasted in the previous sections. You should get the http_route attribute when using the 0.32.4 version, while you should not when upgrading to 0.33.0.

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

Flarna · 2023-08-01T06:25:22Z

seems to be caused by #1557.
If I understand this correct the root cause is that setting the route is now within a type === ExpressLayerType.REQUEST_HANDLER which seems to be never true in above sample.

@chigia001 Any hints if there is a easy fix possible?

chigia001 · 2023-08-01T07:07:23Z

It might also related to #1615

chigia001 · 2023-08-01T07:09:36Z

I think droping the check for type === ExpressLayerType.REQUEST_HANDLER to make it the same as the old implementation regarding rpcMetadata.route

setRPCMetadata(
  context.active(),
  Object.assign(rpcMetadata, { route: route })
)

The old logic is a bit inconsistent between rpcMetadata.route and span name. And I pick a more strict logic 😢

Flarna · 2023-08-01T07:29:36Z

I don't think it's related to #1615 because the http.route attribute is completely missing here.

I ran above reproducer with debugger attached and everytime the instrumentation is called I saw type === 'middleware'. I guess this is not seen in tests because all tests seem to use a router.

Flarna · 2023-08-01T07:46:17Z

it's not related to using a Router or not. It's about installing a middleware via app.use/router.use vs installing a route handler via app.get/ router.get/app.all.

If I replace app.use('/hello', (req, res) => { above by app.all('/hello', (req, res) => { it works.

chigia001 · 2023-08-01T07:54:23Z

MY bad, different issue.

Let me create PR with additional test.

Flarna · 2023-08-01T08:36:58Z

Maybe setting the route should be even moved down below the isLayerIgnored check.

pichlermarc · 2023-08-02T16:36:44Z

@chigia001 would you mind if I assign you to this issue? 🙂

chigia001 · 2023-08-03T00:28:42Z

@pichlermarc Yes, I already have a PR for this.

mkrudele added the bug Something isn't working label Jul 31, 2023

chigia001 mentioned this issue Aug 1, 2023

fix(express): make rpcMetadata.route capture the last layer even when if the last layer is not REQUEST_HANDLER #1620

Merged

pichlermarc added the priority:p2 Bugs and spec inconsistencies which cause telemetry to be incomplete or incorrect label Aug 2, 2023

pichlermarc assigned chigia001 Aug 3, 2023

blumamir closed this as completed in #1620 Aug 13, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Express instrumentation 0.33.0 breaks handling http_route metric attribute #1618

Express instrumentation 0.33.0 breaks handling http_route metric attribute #1618

mkrudele commented Jul 31, 2023

Flarna commented Aug 1, 2023 •

edited

Loading

chigia001 commented Aug 1, 2023

chigia001 commented Aug 1, 2023 •

edited

Loading

Flarna commented Aug 1, 2023

Flarna commented Aug 1, 2023

chigia001 commented Aug 1, 2023 •

edited

Loading

Flarna commented Aug 1, 2023

pichlermarc commented Aug 2, 2023

chigia001 commented Aug 3, 2023

Express instrumentation 0.33.0 breaks handling http_route metric attribute #1618

Express instrumentation 0.33.0 breaks handling http_route metric attribute #1618

Comments

mkrudele commented Jul 31, 2023

What version of OpenTelemetry are you using?

What version of Node are you using?

What did you do?

What did you expect to see?

What did you see instead?

Additional context

package.json

simple-monitoring.js

simple-express.js

Flarna commented Aug 1, 2023 • edited Loading

chigia001 commented Aug 1, 2023

chigia001 commented Aug 1, 2023 • edited Loading

Flarna commented Aug 1, 2023

Flarna commented Aug 1, 2023

chigia001 commented Aug 1, 2023 • edited Loading

Flarna commented Aug 1, 2023

pichlermarc commented Aug 2, 2023

chigia001 commented Aug 3, 2023

Flarna commented Aug 1, 2023 •

edited

Loading

chigia001 commented Aug 1, 2023 •

edited

Loading

chigia001 commented Aug 1, 2023 •

edited

Loading