Exporting Span throws class cast exception when artemis queue messages are consumed

[Raushan-Sapiens]

We are using java agent 1.30.0 for service which consumes queue message and have other APIs and exports span to collector. Instrumentations for APIs works well and spans are exported well to the collector.

But when queue messages are consumed, spans are failed to export. I see below error in logs

[otel.javaagent 2024-09-11 06:51:31:602 +0000] [BatchSpanProcessor_WorkerThread-1] WARN io.opentelemetry.sdk.trace.export.BatchSpanProcessor - Exporter threw an Exception
java.lang.ClassCastException: class java.lang.Double cannot be cast to class java.lang.Long (java.lang.Double and java.lang.Long are in module java.base of loader 'bootstrap')
at io.opentelemetry.exporter.internal.otlp.KeyValueMarshaler$ArrayValueMarshaler.createInt64(KeyValueMarshaler.java:223)
at io.opentelemetry.exporter.internal.otlp.KeyValueMarshaler.create(KeyValueMarshaler.java:84)
at io.opentelemetry.exporter.internal.otlp.KeyValueMarshaler.access$000(KeyValueMarshaler.java:30)
at io.opentelemetry.exporter.internal.otlp.KeyValueMarshaler$1.accept(KeyValueMarshaler.java:48)
at io.opentelemetry.exporter.internal.otlp.KeyValueMarshaler$1.accept(KeyValueMarshaler.java:43)
at java.base/java.util.HashMap.forEach(HashMap.java:1421)
at io.opentelemetry.sdk.internal.AttributesMap.forEach(AttributesMap.java:88)
at io.opentelemetry.exporter.internal.otlp.KeyValueMarshaler.createRepeated(KeyValueMarshaler.java:42)
at io.opentelemetry.exporter.internal.otlp.traces.SpanMarshaler.create(SpanMarshaler.java:44)
at io.opentelemetry.exporter.internal.marshal.MarshalerUtil.groupByResourceAndScope(MarshalerUtil.java:67)
at io.opentelemetry.exporter.internal.otlp.traces.ResourceSpansMarshaler.groupByResourceAndScope(ResourceSpansMarshaler.java:96)
at io.opentelemetry.exporter.internal.otlp.traces.ResourceSpansMarshaler.create(ResourceSpansMarshaler.java:37)
at io.opentelemetry.exporter.internal.otlp.traces.TraceRequestMarshaler.create(TraceRequestMarshaler.java:32)
at io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter.export(OtlpGrpcSpanExporter.java:71)
at io.opentelemetry.sdk.trace.export.BatchSpanProcessor$Worker.exportCurrentBatch(BatchSpanProcessor.java:327)
at io.opentelemetry.sdk.trace.export.BatchSpanProcessor$Worker.run(BatchSpanProcessor.java:245)
at java.base/java.lang.Thread.run(Thread.java:833)

How can we fix/debug this? Any suggestions please

[laurit]

Can you reproduce this at will? I'd firstly try with the latest version of the agent and see if it changes anything. If the problem persists and you can reproduce this then I'd attach debugger and set exception breakpoint for ClassCastException. Looking at the stack trace it looks like there is an attribute of type long array but the values list contains a double. Debugger could help verifying whether this is the case and the name of the attribute and the span could help to identify where it comes from.

[Raushan-Sapiens]

Sure will provide a minimal application to reproduce this issue. This transactions begins with Couchbase DCP client where it picks the data from DB and sends to queue.

So probably, span attributes are injected with Double values instead of Long when it get's picked up by DCP client.

By any means can we see the values populated in span attributes? I see only setattributes are exposed to the service.

[Raushan-Sapiens]

@laurit I tried to log spans in otel collector. I don't see any error in attributes

ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope com.idit.designer.workspace.consumer.WorkspaceOutboxConsumer 
LogRecord #0
ObservedTimestamp: 2024-09-19 06:43:13.53715709 +0000 UTC
Timestamp: 2024-09-19 06:43:13.537138789 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(Received message={"_class":"com.idit.test.WorkspaceOutboxEntry","domain":"PRODUCT","entityAudit":{"createdBy":"test_user","createdOn":{"epochTimeMilli":1726728192221,"offsetSeconds":0},"updatedBy":"test_user","updatedOn":{"epochTimeMilli":1726728192221,"offsetSeconds":0}},"entityId":1052265,"entityKey":"q6_wNr9sQ-y6Hbt2jcsScg==","entityNumber":243,"groupEntityId":1052265,"groupEntityNumber":"PRODUCT","groupKey":"q6_wNr9sQ-y6Hbt2jcsScg==","groupNames":[{"locale":"en_US","translation":"dsadadas"}],"groupSeqNumber":1,"otelTraceContextMap":{"spanId":"0000000000000000","traceId":"00000000000000000000000000000000"},"workspaceId":"3WVae2UMRNe4J9x_1LoIxA=="})
Trace ID: 7a0a2d455b92d67521b222ce34bdf0b3
Span ID: 661ece441815f063
Flags: 1
LogRecord #1
ObservedTimestamp: 2024-09-19 06:43:13.576178633 +0000 UTC
Timestamp: 2024-09-19 06:43:13.576162933 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(Received message={"_class":"com.idit.test.WorkspaceOutboxEntry","domain":"PRODUCT","entityAudit":{"createdBy":"test_user","createdOn":{"epochTimeMilli":1726728192801,"offsetSeconds":0},"updatedBy":"test_user","updatedOn":{"epochTimeMilli":1726728192801,"offsetSeconds":0}},"entityId":1043873,"entityKey":"g7Az1N34QzWxaDeCQlRRoA==","entityNumber":244,"groupEntityId":1052265,"groupEntityNumber":"PRODUCT","groupKey":"q6_wNr9sQ-y6Hbt2jcsScg==","groupNames":[{"locale":"en_US","translation":"dsadadas"}],"groupSeqNumber":1,"groupVersionNumber":1,"otelTraceContextMap":{"spanId":"0000000000000000","traceId":"00000000000000000000000000000000"},"workspaceId":"3WVae2UMRNe4J9x_1LoIxA=="})
Trace ID: a524d60748d909577d190b2ffe36a14a
Span ID: ebe0517c97dabc7b
Flags: 1
LogRecord #2
ObservedTimestamp: 2024-09-19 06:43:13.583608961 +0000 UTC
Timestamp: 2024-09-19 06:43:13.583599161 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(Received message={"_class":"com.idit.test.WorkspaceOutboxEntry","domain":"PRODUCT","entityAudit":{"createdBy":"test_user","createdOn":{"epochTimeMilli":1726728192917,"offsetSeconds":0},"updatedBy":"test_user","updatedOn":{"epochTimeMilli":1726728192917,"offsetSeconds":0}},"entityKey":"BDI2tVyISyCZbcOjSTjTjg==","entityNumber":170,"groupEntityId":1052265,"groupEntityNumber":"PRODUCT","groupKey":"q6_wNr9sQ-y6Hbt2jcsScg==","groupNames":[{"locale":"en_US","translation":"dsadadas"}],"groupSeqNumber":1,"otelTraceContextMap":{"spanId":"0000000000000000","traceId":"00000000000000000000000000000000"},"workspaceId":"3WVae2UMRNe4J9x_1LoIxA=="})
Trace ID: 5573f8579901b823d92dfd58e39e6a6a
Span ID: ed3aa9a23e0bd255
Flags: 1
LogRecord #3
ObservedTimestamp: 2024-09-19 06:43:13.601001125 +0000 UTC
Timestamp: 2024-09-19 06:43:13.600992225 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(Received message={"_class":"com.idit.test.WorkspaceOutboxEntry","domain":"PRODUCT","entityAudit":{"createdBy":"test_user","createdOn":{"epochTimeMilli":1726728193100,"offsetSeconds":0},"updatedBy":"test_user","updatedOn":{"epochTimeMilli":1726728193100,"offsetSeconds":0}},"entityKey":"ucUCCRH0Szu7DjvDKfFT4Q==","entityNumber":18390,"groupEntityId":1052265,"groupEntityNumber":"PRODUCT","groupKey":"q6_wNr9sQ-y6Hbt2jcsScg==","groupNames":[{"locale":"en_US","translation":"dsadadas"}],"groupSeqNumber":1,"otelTraceContextMap":{"spanId":"0000000000000000","traceId":"00000000000000000000000000000000"},"workspaceId":"3WVae2UMRNe4J9x_1LoIxA=="})
Trace ID: e09f84f57b101f02e82b4680ea9fc95d
Span ID: 57b1066bbfd36902
Flags: 1
LogRecord #4
ObservedTimestamp: 2024-09-19 06:43:13.636805457 +0000 UTC
Timestamp: 2024-09-19 06:43:13.636795757 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(Received message={"_class":"com.idit.test.WorkspaceOutboxEntry","domain":"PRODUCT","entityAudit":{"createdBy":"test_user","createdOn":{"epochTimeMilli":1726728193202,"offsetSeconds":0},"updatedBy":"test_user","updatedOn":{"epochTimeMilli":1726728193202,"offsetSeconds":0}},"entityKey":"yh6V2Fo-Q1GFvjXMLNThIA==","entityNumber":512,"groupEntityId":1052265,"groupEntityNumber":"PRODUCT","groupKey":"q6_wNr9sQ-y6Hbt2jcsScg==","groupNames":[{"locale":"en_US","translation":"dsadadas"}],"groupSeqNumber":1,"otelTraceContextMap":{"spanId":"0000000000000000","traceId":"00000000000000000000000000000000"},"workspaceId":"3WVae2UMRNe4J9x_1LoIxA=="})
Trace ID: 2594f9d98b348a162bf204c1f1aaa563
Span ID: 557db6e864d35f66
Flags: 1
LogRecord #5
ObservedTimestamp: 2024-09-19 06:43:13.679059013 +0000 UTC
Timestamp: 2024-09-19 06:43:13.679051213 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(Received message={"_class":"com.idit.test.WorkspaceOutboxEntry","domain":"PRODUCT","entityAudit":{"createdBy":"test_user","createdOn":{"epochTimeMilli":1726728193299,"offsetSeconds":0},"updatedBy":"test_user","updatedOn":{"epochTimeMilli":1726728193299,"offsetSeconds":0}},"entityId":1041224,"entityKey":"pRedWn80T-ylCHOtMS7p7w==","entityNumber":17515,"groupEntityId":1052265,"groupEntityNumber":"PRODUCT","groupKey":"q6_wNr9sQ-y6Hbt2jcsScg==","groupNames":[{"locale":"en_US","translation":"dsadadas"}],"groupSeqNumber":1,"groupVersionNumber":1,"otelTraceContextMap":{"spanId":"0000000000000000","traceId":"00000000000000000000000000000000"},"workspaceId":"3WVae2UMRNe4J9x_1LoIxA=="})
Trace ID: 0b7d7ff31c01c4b3a2297d4d510150cc
Span ID: a1cacfba264378f4
Flags: 1
LogRecord #6
ObservedTimestamp: 2024-09-19 06:43:13.688656348 +0000 UTC
Timestamp: 2024-09-19 06:43:13.688649748 +0000 UTC
SeverityText: INFO
SeverityNumber: Info(9)
Body: Str(Received message={"_class":"com.idit.test.WorkspaceOutboxEntry","domain":"PRODUCT","entityAudit":{"createdBy":"test_user","createdOn":{"epochTimeMilli":1726728193411,"offsetSeconds":0},"updatedBy":"test_user","updatedOn":{"epochTimeMilli":1726728193411,"offsetSeconds":0}},"entityKey":"2jhl1OZ5TCO2a4vNBPRxMw==","entityNumber":261,"groupEntityId":1052265,"groupEntityNumber":"PRODUCT","groupKey":"q6_wNr9sQ-y6Hbt2jcsScg==","groupNames":[{"locale":"en_US","translation":"dsadadas"}],"groupSeqNumber":1,"otelTraceContextMap":{"spanId":"0000000000000000","traceId":"00000000000000000000000000000000"},"workspaceId":"3WVae2UMRNe4J9x_1LoIxA=="})
Trace ID: b3c2a2a262331e2f66ab7ddc78043eba
Span ID: d294044bfd4ce641
Flags: 1
	{"kind": "exporter", "data_type": "logs", "name": "logging"}
2024/09/19 06:43:14 http: superfluous response.WriteHeader call from go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp/internal/request.(*RespWriterWrapper).writeHeader (resp_writer_wrapper.go:78)
2024-09-19T06:43:19.505Z	info	TracesExporter	{"kind": "exporter", "data_type": "traces", "name": "logging", "resource spans": 1, "spans": 353}
2024-09-19T06:43:19.511Z	info	ResourceSpans #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.24.0
Resource attributes:
     -> host.arch: Str(amd64)
     -> host.name: Str(designer-workspace-68d767f88f-xc626)
     -> os.description: Str(Linux 5.15.0-1036-azure)
     -> os.type: Str(linux)
     -> process.command_args: Slice(["/usr/local/openjdk-17/bin/java","-javaagent:/opt/agents/opentelemetry-javaagent.jar","-Dotel.resource.attributes=service.name=,deployment.environment=","--add-opens","java.base/java.math=ALL-UNNAMED","-jar","workspace.jar"])
     -> process.executable.path: Str(/usr/local/openjdk-17/bin/java)
     -> process.pid: Int(1)
     -> process.runtime.description: Str(Oracle Corporation OpenJDK 64-Bit Server VM 17.0.2+8-86)
     -> process.runtime.name: Str(OpenJDK Runtime Environment)
     -> process.runtime.version: Str(17.0.2+8-86)
     -> service.instance.id: Str(9a331f78-d4ba-4c04-83d9-e6d678aab99e)
     -> service.name: Str(designer-workspace)
     -> service.version: Str(0.1.0-SNAPSHOT)
     -> telemetry.distro.name: Str(opentelemetry-java-instrumentation)
     -> telemetry.distro.version: Str(2.7.0)
     -> telemetry.sdk.language: Str(java)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(1.41.0)

FYI: I'm in process of creating docker compose for the services to reproduce. Any idea or guess, what;s wrong?

[laurit]

In collector you can only see spans that were successfully exported, but you are interested in a span that fails to export.

[Raushan-Sapiens]

hey @laurit.. Unfortunately not able to create sample code to reproduce with docker compose locally. It works well. Issue only occurs in Azure k8s environment with the same configuration.

Tried to intercept agent exporter and log span attributes but doesn't work well. can you please help in this with any kind of docs OR reference repo.

Any other ideas please. thanks!

[laurit]

Can you reproduce this at will? If you can then you could set the trace exporter to console (see https://opentelemetry.io/docs/languages/java/configuration/#properties-exporters) Assuming that there aren't too many spans I'd imaging that it is possible to find the offending attribute (a list that contains a double). If you can't reproduce it at will then you could write an agent extension that wraps the span exporter using https://github.com/open-telemetry/opentelemetry-java/blob/de13ff183a24aef45dc2df8a4422e612765ea32a/sdk-extensions/autoconfigure-spi/src/main/java/io/opentelemetry/sdk/autoconfigure/spi/AutoConfigurationCustomizer.java#L64 After you have wrapped the exporter before you delegate to the original exporter you can examine the span data and check whether there is an attribute where key is a long array, but values list contains a double. If you find the offending span you can log it. If you decide to go down this route then I'd start by first creating an app that reproduce the issue so you could verify whether your custom exporter can catch it.