http.target and http.url attributes not set in metrics attributes

[mkrudele]

What happened?

Steps to Reproduce

Unzip the code.zip to get the code to reproduce the problem.
code.zip

npm install
chmod +x simple-express.js
./simple-express.js

Run one or more curl -X GET "localhost:6900/proxy_call" from a terminal.
You should see from the simple-express terminal something like:

OTEL_TRACES_EXPORTER is empty. Using default otlp exporter.
>>>> OpenTelemetry SDK started
Echo server is listnening on port 6900
>>>> Prometheus scrape endpoint: http://localhost:9464/metrics
Proxying POST /
{"stack":"Error: connect ECONNREFUSED ::1:4318\n    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)\n    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17)","message":"connect ECONNREFUSED ::1:4318","errno":"-61","code":"ECONNREFUSED","syscall":"connect","address":"::1","port":"4318","name":"Error"}

First problem:
Is this an issue?

{"stack":"Error: connect ECONNREFUSED ::1:4318\n    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)\n    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17)","message":"connect ECONNREFUSED ::1:4318","errno":"-61","code":"ECONNREFUSED","syscall":"connect","address":"::1","port":"4318","name":"Error"}

That was not happening with versions 0.35.1 of the packages.

Second problem:

I was expecting to see an attribute http_target (or http_route or whatever) in the ghost_http_server_duration metric, and the attribute http_url (or equivalent name) in the ghost_http_client_duration metric, as described in this issue #3553 (which should be part of the 0.36.0 version).
However, nothing changed since the previous version 0.35.1. To prove just point your browser to http://localhost:9464/metrics. You should get this:

Did I miss something? Is there any config step to follow to enable such attributes in the HTTP metrics?

Expected Result

Expected target path attribute to incoming and outcoming http requests as requested with this issue #3553.

Actual Result

Not getting target path attribute in incoming and outcoming http requests.

Additional Details

OpenTelemetry Setup Code

Look at the file simple-monitoring.js in code.zip.

package.json

Look at the file package.json in code.zip.

Relevant log output

Sample ./simple-express.js output:  

OTEL_TRACES_EXPORTER is empty. Using default otlp exporter.
>>>> OpenTelemetry SDK started
Echo server is listnening on port 6900
>>>> Prometheus scrape endpoint: http://localhost:9464/metrics
Proxying POST /
Proxying GET /
{"stack":"Error: connect ECONNREFUSED ::1:4318\n    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)\n    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17)","message":"connect ECONNREFUSED ::1:4318","errno":"-61","code":"ECONNREFUSED","syscall":"connect","address":"::1","port":"4318","name":"Error"}
Proxying GET /
{"stack":"Error: connect ECONNREFUSED ::1:4318\n    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)\n    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17)","message":"connect ECONNREFUSED ::1:4318","errno":"-61","code":"ECONNREFUSED","syscall":"connect","address":"::1","port":"4318","name":"Error"}
Got GET /
{"stack":"Error: connect ECONNREFUSED ::1:4318\n    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)\n    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17)","message":"connect ECONNREFUSED ::1:4318","errno":"-61","code":"ECONNREFUSED","syscall":"connect","address":"::1","port":"4318","name":"Error"}

Sample http://localhost:9464/metrics output:  
# 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.10.0",process_pid="27985",process_executable_name="node",process_command="/Users/mcrudele/projects/michele-crudele/echo-server-instrumented/simple-express.js",process_command_line="/Users/mcrudele/.nvm/versions/node/v18.14.2/bin/node /Users/mcrudele/projects/michele-crudele/echo-server-instrumented/simple-express.js",process_runtime_version="18.14.2",process_runtime_name="nodejs",process_runtime_description="Node.js"} 1
# HELP ghost_http_server_duration measures the duration of the inbound HTTP requests
# UNIT ghost_http_server_duration ms
# TYPE ghost_http_server_duration histogram
ghost_http_server_duration_count{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900"} 1 1678986413960
ghost_http_server_duration_sum{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900"} 264 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="0"} 0 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="5"} 0 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="10"} 0 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="25"} 0 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="50"} 0 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="75"} 0 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="100"} 0 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="250"} 0 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="500"} 1 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="1000"} 1 1678986413960
ghost_http_server_duration_bucket{http_scheme="http",http_method="POST",net_host_name="localhost",http_flavor="1.1",http_status_code="200",net_host_port="6900",le="+Inf"} 1 1678986413960
ghost_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"} 3 1678986413960
ghost_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"} 462 1678986413960
ghost_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 1678986413960
ghost_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"} 1 1678986413960
ghost_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"} 1 1678986413960
ghost_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 1678986413960
ghost_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 1678986413960
ghost_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 1678986413960
ghost_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 1678986413960
ghost_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"} 3 1678986413960
ghost_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"} 3 1678986413960
ghost_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"} 3 1678986413960
ghost_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"} 3 1678986413960
# HELP ghost_http_client_duration measures the duration of the outbound HTTP requests
# UNIT ghost_http_client_duration ms
# TYPE ghost_http_client_duration histogram
ghost_http_client_duration_count{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1"} 3 1678986413960
ghost_http_client_duration_sum{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1"} 707 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="0"} 0 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="5"} 0 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="10"} 0 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="25"} 0 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="50"} 0 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="75"} 0 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="100"} 0 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="250"} 2 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="500"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="1000"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="GET",net_peer_name="example.com",net_peer_port="80",http_status_code="200",http_flavor="1.1",le="+Inf"} 3 1678986413960
ghost_http_client_duration_count{http_method="POST",net_peer_name="localhost"} 3 1678986413960
ghost_http_client_duration_sum{http_method="POST",net_peer_name="localhost"} 6 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="0"} 0 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="5"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="10"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="25"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="50"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="75"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="100"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="250"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="500"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="1000"} 3 1678986413960
ghost_http_client_duration_bucket{http_method="POST",net_peer_name="localhost",le="+Inf"} 3 1678986413960

[pichlermarc]

Hi @mkrudele, thanks for reaching out. And thank you for providing the reproducer, that is very helpful 🙂

Second problem:

I was expecting to see an attribute http_target (or http_route or whatever) in the ghost_http_server_duration metric, and the attribute http_url (or equivalent name) in the ghost_http_client_duration metric, as described in this issue #3553 (which should be part of the 0.36.0 version).
However, nothing changed since the previous version 0.35.1. To prove just point your browser to http://localhost:9464/metrics. You should get this:

Did I miss something? Is there any config step to follow to enable such attributes in the HTTP metrics?

It looks like the route is never set in this instrumentation, it is just taken over from any other instrumentation that adds it (such as @opentelemetry/instrumentation-express, which is missing in this case). I'm not too familiar with the HTTP instrumentation, but I think the origin of the http.route attribute can only ever be the HTTP server framework instrumentation (@opentelemetry/instrumentation-express in this example).

Could you check if adding @opentelemetry/instrumentation-express works for you? 🤔

[mkrudele]

@pichlermarc I tried adding instrumentation-express and it seems to work. I can see the http_route added to the http_server_duration metric. However it is still missing on the http_client_duration metric.

@hermogenes since you implemented te feature, would you shed the lights on how is it supposed to work?

Our need is pretty simple. We'd like to have the attribute http_route set on both, incoming and outgoing requests, so on http_server_request and http_client_request.
We'd prefer to stay with the instrumentation-http package only for footprint reasons. So I tried adding a requestHook like below:

const httpInstrumentation = new HttpInstrumentation({
    requestHook: (span, request) => {
        span.setAttribute('http.route', request.path);
    }
});

but now way, the http_route is not added to the metric.

[Flarna]

The http route is something only the HTTP server internal knows - it's likely a pattern applied to the received path. The HTTP client can't know this detail.

HTTP client sends the path as part of the url. But compared to the route the path tends to have a high cardinality and it therefore not a good choice as part of the span name or metric dimension.
e.g. the route might be something like /todos/:id to extract the numeric id. Client call this via /todos/1, /todos/3456,... which all end up on the same route.

see otel http spec for more details.

[mkrudele]

@Flarna Thanks for the link to the specs. That's more clear. I understand the point about http client.

Still have a question about whether it is possible with the requestHook to add custom attributes to the http_server_request and http_client_request metrics, or that's forbidden by the specs. It seems that any attribute I set is not shown by /metrics endpoint.

[Flarna]

Looking into the code it seems the http.route attribute is copied over from span to metric in incoming response (see here).

So even if you add http.route in the request hook for client and server it will effect only the server metric but client and server span.

or that's forbidden by the specs

If you redefine http.route in your app it's your decision and perfectly fine. I would not do this in any public available npm module as it will result in incompatibility/confusion sooner or later. Also backend tools might have some built in logic in showing/interpreting specified attributes so you might confuse them.

I think a more generic approach would be to enhance the hooks (or add new ones) to allow setting attributes on metrics.

[pichlermarc]

Continued investigation:

First problem:
Is this an issue?

{"stack":"Error: connect ECONNREFUSED ::1:4318\n    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1494:16)\n    >at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17)","message":"connect ECONNREFUSED >::1:4318","errno":"-61","code":"ECONNREFUSED","syscall":"connect","address":"::1","port":"4318","name":"Error"}

That was not happening with versions 0.35.1 of the packages.

This looks like it is the default exporter bubbling up to the globalErrorHandler. By default, using NodeSDK, an otlp exporter is instantiated. If there's no collector on localhost:4318, this error is logged. Looking closer into it, this may be related to #3627, where an INFO diagnostics logger is instantiated by default, which looks unintentional 🤔

I'll open a PR so that no logger is instantiated when the env var is unset. 🙂

In the meantime, you can remedy this error log by either of the following options:

• passing your own exporter to the NodeSDK constructor (will override defaults)
• pointing the default exporter to an OTLP endpoint using the standard OTEL_EXPORTER_OTLP_* environment variables.
• setting OTLP_TRACES_EXPORTER=none (will turn off the exporter)
• setting OTEL_LOG_LEVEL=none (will turn off diagnostics logging entirely)

[pichlermarc]

@mkrudele Currently, we only add the attributes from the metrics HTTP semantic conventions spec, and we drop any others that are present on the span as to avoid high-cardinality metrics.

As @Flarna said, we could enhance the hooks or add new ones to allow users to add their own attributes. Feel free to open a feature-request issue for this. 🙂

As it looks like this issue is a feature request (adding/enhancing the hooks) and a bug report (INFO logger instantiated by default), I'll tag this as priority 3 (problems in end-user apps not related to correctness)

[pichlermarc]

With #3593 merged, the fix for Problem 1 (DiagConsoleLogger instantiated by default, classified as bug) should be included in the next release.

I'm closing this issue as we now have #3694 to track the feature request part of this issue (initially stated as Problem 2). 🙂