Inconsistent behaviour with natchez & opentelemetry

[barryoneill]

• discord conversation

background

For the last while, I've been using natchez-extras-datadog-stable to send metrics. For various reasons (mostly due to correlating with other datadog-internal generated traces), DataDog support tells me that the preferred solution is to have the instrumented JVM send the metrics, and not do it myself (via the blaze client impl above).

Their recommended solution for me is to create opentelemetry traces. The datadog agent (instrumented in the JVM) will automatically pick these up and convert/dispatch them to datadog.

Issue

I dropped natchez-extras-datadog-stable and using just natchez-opentelementry from this project. I am able to create an trace that does indeed get picked up and sent to datadog - which is great!

The problem starts when I try to mix http4s middleware into the mix.

I've tried both

• NatchezMiddleware from natchez-http4s
• ServerMiddleware from natchez-http4s-otel and

No matter what I try, I can't seem to get traces from the instrumented routes to show up, even though this is the same EntryPoint instance that I can directly invoke to get valid traces created.

reproducing the issue

I did find a hacky way to intercept and view the traces that datadog is ignoring, and it does appear the difference is that
when I directly use the entrypoint, a valid traceID is set. When I use the middleware, this is 0 (datadog requires a non-zero 64 bit signed int)

If it helps, I created an example application - https://github.com/barryoneill/natchez-otel-datadog-experiments - that:

• creates a natchez-opentelemetry EndPoint
• manually creates a span (A) using the EndPoint directly
• starts two http4s services, instrumented using the same Endpoint as test A, one using natchez-http4s and the other natchez-http4s-otel
• makes a POST call to each service, which results in an OTel trace being created (B) and (C)

Outcome:

• A has a valid traceID (and in the real world, shows up in datadog)
• B and C have a 0 value (and in the real world, don't show up in datadog)

Sample output:

+--------------+-----------------------+-----------------------+----------------------------------------+---------------------+---------------------+--------------------------------------------------------------------+--------------+-----------+---------------+
| When         | Operation Name        | Resource Name         | DD Trace Id                            | DD Span Id          | DDParentSpanId      | Tags                                                               | Service Name | Span Type | Duration (ms) |
+--------------+-----------------------+-----------------------+----------------------------------------+---------------------+---------------------+--------------------------------------------------------------------+--------------+-----------+---------------+
| 15:43:46.337 | Direct_Endpoint_Usage | Direct_Endpoint_Usage |  64b: 000000000000000014576a24b90b8d37 | 4054336080662395000 | 0                   | _dd.profiling.enabled=0                                            | fooSvc       | internal  | 6             |
|              |                       |                       |                                        |                     |                     | _dd.trace_span_attribute_schema=0                                  |              |           |               |
|              |                       |                       |                                        |                     |                     | env=fooEnv                                                         |              |           |               |
|              |                       |                       |                                        |                     |                     | language=jvm                                                       |              |           |               |
|              |                       |                       |                                        |                     |                     | process_id=48250                                                   |              |           |               |
|              |                       |                       |                                        |                     |                     | runtime-id=3fc5a447-09d8-4916-a267-9c0189ba6666                    |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.id=133                                                      |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.name=io-compute-7                                           |              |           |               |
| 15:43:46.352 | /biz                  | POST /biz             | 128b: 00000000000000000000000000000000 | 4308140243084585245 | 0                   | _dd.profiling.enabled=0                                            | fooSvc       | internal  | 961           |
|              |                       |                       |                                        |                     |                     | _dd.trace_span_attribute_schema=0                                  |              |           |               |
|              |                       |                       |                                        |                     |                     | env=fooEnv                                                         |              |           |               |
|              |                       |                       |                                        |                     |                     | http.method=POST                                                   |              |           |               |
|              |                       |                       |                                        |                     |                     | http.status_code=200                                               |              |           |               |
|              |                       |                       |                                        |                     |                     | http.url=/biz                                                      |              |           |               |
|              |                       |                       |                                        |                     |                     | language=jvm                                                       |              |           |               |
|              |                       |                       |                                        |                     |                     | process_id=48250                                                   |              |           |               |
|              |                       |                       |                                        |                     |                     | runtime-id=3fc5a447-09d8-4916-a267-9c0189ba6666                    |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.id=129                                                      |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.name=io-compute-3                                           |              |           |               |
| 15:43:46.597 | fakeBizLogic          | fakeBizLogic          | 128b: 00000000000000000000000000000000 | 5724611567296865609 | 4308140243084585245 | businessAttr=STONKS                                                | fooSvc       | internal  | 417           |
|              |                       |                       |                                        |                     |                     | env=fooEnv                                                         |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.id=129                                                      |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.name=io-compute-3                                           |              |           |               |
| 15:43:47.327 | Http Server - POST    | POST /biz             | 128b: 00000000000000000000000000000000 | 7224963246604818194 | 0                   | _dd.profiling.enabled=0                                            | fooSvc       | internal  | 1240          |
|              |                       |                       |                                        |                     |                     | _dd.trace_span_attribute_schema=0                                  |              |           |               |
|              |                       |                       |                                        |                     |                     | env=fooEnv                                                         |              |           |               |
|              |                       |                       |                                        |                     |                     | exit.case=succeeded                                                |              |           |               |
|              |                       |                       |                                        |                     |                     | http.client_ip=127.0.0.1                                           |              |           |               |
|              |                       |                       |                                        |                     |                     | http.flavor=1.1                                                    |              |           |               |
|              |                       |                       |                                        |                     |                     | http.host=localhost:9000                                           |              |           |               |
|              |                       |                       |                                        |                     |                     | http.method=POST                                                   |              |           |               |
|              |                       |                       |                                        |                     |                     | http.request.header.string.accept=text/*                           |              |           |               |
|              |                       |                       |                                        |                     |                     | http.request.header.string.connection=keep-alive                   |              |           |               |
|              |                       |                       |                                        |                     |                     | http.request.header.string.content_length=0                        |              |           |               |
|              |                       |                       |                                        |                     |                     | http.request.header.string.date=Thu, 13 Jul 2023 19:43:47 GMT      |              |           |               |
|              |                       |                       |                                        |                     |                     | http.request.header.string.host=localhost:9000                     |              |           |               |
|              |                       |                       |                                        |                     |                     | http.request.header.string.user_agent=http4s-ember/0.23.22         |              |           |               |
|              |                       |                       |                                        |                     |                     | http.request_content_length=0                                      |              |           |               |
|              |                       |                       |                                        |                     |                     | http.response.header.string.content_length=13                      |              |           |               |
|              |                       |                       |                                        |                     |                     | http.response.header.string.content_type=text/plain; charset=UTF-8 |              |           |               |
|              |                       |                       |                                        |                     |                     | http.response_content_length=13                                    |              |           |               |
|              |                       |                       |                                        |                     |                     | http.status_code=200                                               |              |           |               |
|              |                       |                       |                                        |                     |                     | http.target=/biz                                                   |              |           |               |
|              |                       |                       |                                        |                     |                     | http.url=/biz                                                      |              |           |               |
|              |                       |                       |                                        |                     |                     | http.user_agent=http4s-ember/0.23.22                               |              |           |               |
|              |                       |                       |                                        |                     |                     | language=jvm                                                       |              |           |               |
|              |                       |                       |                                        |                     |                     | net.peer.ip=127.0.0.1                                              |              |           |               |
|              |                       |                       |                                        |                     |                     | net.peer.port=56766                                                |              |           |               |
|              |                       |                       |                                        |                     |                     | process_id=48250                                                   |              |           |               |
|              |                       |                       |                                        |                     |                     | runtime-id=3fc5a447-09d8-4916-a267-9c0189ba6666                    |              |           |               |
|              |                       |                       |                                        |                     |                     | span.kind=server                                                   |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.id=135                                                      |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.name=io-compute-9                                           |              |           |               |
| 15:43:47.775 | fakeBizLogic          | fakeBizLogic          | 128b: 00000000000000000000000000000000 | 8328755773498611729 | 7224963246604818194 | businessAttr=STONKS                                                | fooSvc       | internal  | 336           |
|              |                       |                       |                                        |                     |                     | env=fooEnv                                                         |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.id=135                                                      |              |           |               |
|              |                       |                       |                                        |                     |                     | thread.name=io-compute-9                                           |              |           |               |
+--------------+-----------------------+-----------------------+----------------------------------------+---------------------+---------------------+--------------------------------------------------------------------+--------------+-----------+---------------+
15:43:48.606 ERR appserver[dd.service=fooSvc, dd.env=fooEnv] 4 out of 5 datadog spans had empty traceIds

[barryoneill]

Natchez conversation link