open-telemetry / open-telemetry/opentelemetry-java-instrumentation

Trace ID/Context is not propagated into spring-cloud-stream-binder-rabbit backed by org.springframework.integration.channel.FluxMessageChannel

Open
#3,096 7 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug repro provided
Dominant language
Java
Stars
2.6k
Forks
1.2k
Avg merge
2d 18h
Merged PRs (30d)
228

Description

Describe the bug
The rabbitmq instrumentation advice generates a new trace and span due to missing trace context inside reactor bounded scheduler thread worker.

// Root trace
2021-05-26 16:09:06,220 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] r.netty.http.server.HttpServerOperations: 249 - [id:5ed2c6d3, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Increasing pending responses, now 1
2021-05-26 16:09:06,231 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52]     reactor.netty.http.server.HttpServer: 249 - [id:5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@68f7f0b5
2021-05-26 16:09:06,258 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] web.server.adapter.HttpWebHandlerAdapter:  91 - [5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] HTTP POST "/order/api/v1/orders"
.....

2021-05-26 16:09:06,741  INFO [s0-io-4] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] etry.showcase.order.service.OrderService:  61 - Build order message sent
......

2021-05-26 16:09:06,741 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] k.integration.channel.FluxMessageChannel: 191 - preSend on channel 'bean 'builderOrders_integrationflow.channel#0'', message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=23cb91dc-dcc7-cbaf-b2ad-e204a43249b6, timestamp=1622059746741}]
// New trace ID can be see here cce14d6d190397c5e3b05201b74db9df
[otel.javaagent 2021-05-26 16:09:06:794 -0400] [boundedElastic-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'builderOrders -> builderOrders send' : cce14d6d190397c5e3b05201b74db9df 5fd16696c9cf875e PRODUCER [tracer: io.opentelemetry.javaagent.rabbitmq-2.7:1.3.0-SNAPSHOT] AttributesMap{data={messaging.destination=builderOrders, messaging.message_payload_size_bytes=259, thread.id=38, net.peer.ip=127.0.0.1, thread.name=boundedElastic-1, messaging.system=rabbitmq, net.peer.name=localhost, net.peer.port=5672, messaging.destination_kind=queue, rabbitmq.delivery_mode=2}, capacity=128, totalAddedValues=10}

Steps to reproduce

Repo

Start rabbit:

docker run -d --hostname rabbit --name rabbit -p 5672:5672 -p 15672:15672  rabbitmq:3-management

Start Cassandra

docker network create cassandra-network 
docker run --name test-cassandra -d -p 9042:9042 --network cassandra-network cassandra:latest

Create Cassandra keyspace:

docker run -it --network cassandra-network --rm cassandra cqlsh test-cassandra
>> CREATE KEYSPACE IF NOT EXISTS opentelemetry WITH REPLICATION = { 'class' : 'SimpleStrategy', 'replication_factor' : 3 };
>> exit

Run app

./gradlew :order-service:bootRun -PjvmArgs='-javaagent:/your/path/opentelemetry-java-instrumentation/javaagent/build/libs/openteletry-javaagent-1.3.0-SNAPSHOT-all.jar -Dotel.javaagent.debug=true -Dotel.javaagent.experimental.thread-propagation-debugger.enabled=true'

Send HTTP request:

curl --request POST  http://localhost:8080/order/api/v1/orders -H 'Content-Type: application/json' -H 'Accept: application/json' -d '{"item":"item1", "accountId":"account123"}' -i

Sample response:

HTTP/1.1 201 Created
Location: http://localhost:8080/order/api/v1/orders
Content-Type: application/json
TraceID: 64224325fe02c948645ce2f93af3d5fa
Content-Length: 259

{"orderKey":{"accountId":"account123","orderId":"2b1d679b-d193-451c-9106-f667659a16b1"},"item":"item1","createdBy":"user-principal","createdDate":"2021-05-26T20:09:06.557307Z","lastModifiedBy":"user-principal","lastModifiedDate":"2021-05-26T20:09:06.557307Z"}

What did you expect to see?
Root trace context to be propagated to reactor bounded scheduler thread workers.

What did you see instead?
Root trace context is missing inside reactor bounded scheduler thread worker which causes rabbitmq instrumentation to generate a new trace ID.

What version are you using?
1.3.0-SNAPSHOT-all.jar - c1452b9

Environment

./gradlew -version

------------------------------------------------------------
Gradle 7.0.1
------------------------------------------------------------

Build time:   2021-05-10 16:08:58 UTC
Revision:     67e618faef187783dadd03a34fdab9dc71b85b19

Kotlin:       1.4.31
Groovy:       3.0.7
Ant:          Apache Ant(TM) version 1.10.9 compiled on September 27 2020
JVM:          16.0.1 (AdoptOpenJDK 16.0.1+9)
OS:           Mac OS X 10.15.7 x86_64

More logs

2021-05-26 16:08:40,722  INFO [restartedMain] [TraceID:] [SpanID:] elemetry.showcase.order.OrderApplication:  61 - Started OrderApplication in 8.714 seconds (JVM running for 10.685)
2021-05-26 16:08:40,723  INFO [restartedMain] [TraceID:] [SpanID:] availability.ApplicationAvailabilityBean:  75 - Application availability state LivenessState changed from CORRECT to CORRECT
2021-05-26 16:08:40,723  INFO [restartedMain] [TraceID:] [SpanID:] availability.ApplicationAvailabilityBean:  75 - Application availability state ReadinessState changed from ACCEPTING_TRAFFIC to ACCEPTING_TRAFFIC
[otel.javaagent 2021-05-26 16:08:41:320 -0400] [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:41:322 -0400] [grpc-nio-worker-ELG-1-7] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:42:569 -0400] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Counter 'SqlStatementSanitizer cache miss' : 1
[otel.javaagent 2021-05-26 16:08:42:921 -0400] [grpc-nio-worker-ELG-1-9] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:42:923 -0400] [grpc-nio-worker-ELG-1-10] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:45:377 -0400] [grpc-nio-worker-ELG-1-12] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:45:378 -0400] [grpc-nio-worker-ELG-1-1] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:45:618 -0400] [grpc-default-executor-1] ERROR io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter - Failed to export spans. Server is UNAVAILABLE. Make sure your collector is running and reachable from this network. Full error message:UNAVAILABLE: io exception
[otel.javaagent 2021-05-26 16:08:45:618 -0400] [BatchSpanProcessor_WorkerThread-1] DEBUG io.opentelemetry.sdk.trace.export.BatchSpanProcessor$Worker - Exporter failed
[otel.javaagent 2021-05-26 16:08:49:220 -0400] [grpc-nio-worker-ELG-1-3] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:49:222 -0400] [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:56:107 -0400] [grpc-nio-worker-ELG-1-7] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:08:56:108 -0400] [grpc-nio-worker-ELG-1-8] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:09:06:105 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed reactor.netty.channel.ChannelOperationsHandler -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:124 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed io.netty.handler.codec.http.HttpServerCodec$HttpServerRequestDecoder -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:139 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed io.netty.handler.codec.http.HttpServerCodec$HttpServerResponseEncoder -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:142 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Applying instrumentation: executor [class io.opentelemetry.javaagent.instrumentation.javaconcurrent.ExecutorInstrumentationModule] on jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:143 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Applying instrumentation: netty [class io.opentelemetry.javaagent.instrumentation.netty.v4_1.NettyInstrumentationModule] on jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:148 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed reactor.netty.http.server.HttpTrafficHandler -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:161 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed reactor.netty.ReactorNetty$ExtractorHandler -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
2021-05-26 16:09:06,188 DEBUG [reactor-http-nio-2] [TraceID:] [SpanID:] r.netty.http.server.HttpServerOperations: 244 - [id:5ed2c6d3, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] New http connection, requesting read
2021-05-26 16:09:06,188 DEBUG [reactor-http-nio-2] [TraceID:] [SpanID:]  reactor.netty.transport.TransportConfig: 249 - [id:5ed2c6d3, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Initialized pipeline DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpServerCodec), (io.opentelemetry.javaagent.instrumentation.netty.v4_1.server.HttpServerTracingHandler = io.opentelemetry.javaagent.instrumentation.netty.v4_1.server.HttpServerTracingHandler), (reactor.left.httpTrafficHandler = reactor.netty.http.server.HttpTrafficHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
[otel.javaagent 2021-05-26 16:09:06:192 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed reactor.netty.http.server.HttpTrafficHandler$IdleTimeoutHandler -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:219 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed reactor.netty.http.server.HAProxyMessageReader -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
2021-05-26 16:09:06,220 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] r.netty.http.server.HttpServerOperations: 249 - [id:5ed2c6d3, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Increasing pending responses, now 1
2021-05-26 16:09:06,231 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52]     reactor.netty.http.server.HttpServer: 249 - [id:5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@68f7f0b5
2021-05-26 16:09:06,258 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] web.server.adapter.HttpWebHandlerAdapter:  91 - [5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] HTTP POST "/order/api/v1/orders"
[otel.javaagent 2021-05-26 16:09:06:284 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Applying instrumentation: executor [class io.opentelemetry.javaagent.instrumentation.javaconcurrent.ExecutorInstrumentationModule] on jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:295 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed reactor.core.publisher.MonoEmpty -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
2021-05-26 16:09:06,311 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] ion.server.support.RouterFunctionMapping: 189 - [5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Mapped to com.stefvic.opentelemetry.showcase.order.rest.OrderRouter$$Lambda$1172/0x0000000801294dc8@128fd364
[otel.javaagent 2021-05-26 16:09:06:398 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Applying instrumentation: opentelemetry-api [class io.opentelemetry.javaagent.instrumentation.opentelemetryapi.OpenTelemetryApiInstrumentationModule] on jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:398 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.HelperInjector - Injecting classes onto classloader jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3 -> [io.opentelemetry.javaagent.instrumentation.opentelemetryapi.trace.Bridging, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.trace.BridgedTraceFlags, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.trace.Bridging$1, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.trace.ApplicationSpan, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.context.AgentContextStorage, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.context.AgentContextStorage$AgentContextWrapper, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.baggage.BaggageBridging, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.ApplicationOpenTelemetry, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.trace.ApplicationTracerProvider, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.context.propagation.ApplicationContextPropagators, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.trace.ApplicationTracer, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.context.propagation.ApplicationTextMapPropagator, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.trace.ApplicationSpan$Builder, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.context.propagation.ApplicationTextMapPropagator$AgentSetter, io.opentelemetry.javaagent.instrumentation.opentelemetryapi.context.propagation.ApplicationTextMapPropagator$AgentGetter]
[otel.javaagent 2021-05-26 16:09:06:407 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed io.opentelemetry.context.LazyStorage -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:412 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Applying instrumentation: opentelemetry-api [class io.opentelemetry.javaagent.instrumentation.opentelemetryapi.OpenTelemetryApiInstrumentationModule] on jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:414 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed io.opentelemetry.context.ArrayBasedContext -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
2021-05-26 16:09:06,468 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52]        reactor.netty.channel.FluxReceive: 249 - [id:5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
2021-05-26 16:09:06,498 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] work.http.codec.json.Jackson2JsonDecoder: 147 - [5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Decoded [com.stefvic.opentelemetry.showcase.order.rest.AccountOrder@62123761]
[otel.javaagent 2021-05-26 16:09:06:519 -0400] [reactor-http-nio-2] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'ReactiveCrudRepository.save' : 64224325fe02c948645ce2f93af3d5fa 292c9e2430c15ea8 INTERNAL [tracer: io.opentelemetry.javaagent.spring-data-1.8:1.3.0-SNAPSHOT] AttributesMap{data={thread.id=61, thread.name=reactor-http-nio-2}, capacity=128, totalAddedValues=2}
2021-05-26 16:09:06,564 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] ork.data.auditing.AuditingHandlerSupport: 144 - Touched Order(orderKey=OrderKey(accountId=account123, orderId=2b1d679b-d193-451c-9106-f667659a16b1), item=item1, isNew=true, createdBy=user-principal, createdDate=2021-05-26T20:09:06.557307Z, lastModifiedBy=user-principal, lastModifiedDate=2021-05-26T20:09:06.557307Z) - Last modification at 2021-05-26T16:09:06.557307 by user-principal
2021-05-26 16:09:06,566 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 503 - Property is a compositeKey
2021-05-26 16:09:06,569 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 522 - doWithProperties Property.type java.lang.String, Property.value account123
2021-05-26 16:09:06,570 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 539 - Adding map.entry [account_id] - [account123]
2021-05-26 16:09:06,570 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 522 - doWithProperties Property.type java.lang.String, Property.value 2b1d679b-d193-451c-9106-f667659a16b1
2021-05-26 16:09:06,570 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 539 - Adding map.entry [order_id] - [2b1d679b-d193-451c-9106-f667659a16b1]
2021-05-26 16:09:06,571 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 522 - doWithProperties Property.type java.lang.String, Property.value user-principal
2021-05-26 16:09:06,571 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 539 - Adding map.entry [createdby] - [user-principal]
2021-05-26 16:09:06,571 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 522 - doWithProperties Property.type java.time.Instant, Property.value 2021-05-26T20:09:06.557307Z
2021-05-26 16:09:06,571 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 539 - Adding map.entry [createddate] - [2021-05-26T20:09:06.557307Z]
2021-05-26 16:09:06,571 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 522 - doWithProperties Property.type java.lang.String, Property.value item1
2021-05-26 16:09:06,571 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 539 - Adding map.entry [item] - [item1]
2021-05-26 16:09:06,572 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 522 - doWithProperties Property.type java.lang.String, Property.value user-principal
2021-05-26 16:09:06,572 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 539 - Adding map.entry [lastmodifiedby] - [user-principal]
2021-05-26 16:09:06,572 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 522 - doWithProperties Property.type java.time.Instant, Property.value 2021-05-26T20:09:06.557307Z
2021-05-26 16:09:06,572 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.core.convert.MappingCassandraConverter: 539 - Adding map.entry [lastmodifieddate] - [2021-05-26T20:09:06.557307Z]
2021-05-26 16:09:06,616 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.cassandra.core.cql.ReactiveCqlTemplate: 539 - Preparing statement [INSERT INTO "order" (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?)] using org.springframework.data.cassandra.core.ReactiveCassandraTemplate$PreparedStatementHandler@6ff6047e
2021-05-26 16:09:06,617 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] ql.session.DefaultBridgedReactiveSession: 179 - Preparing statement [INSERT INTO "order" (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?)]
[otel.javaagent 2021-05-26 16:09:06:627 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.instrumentation.api.concurrent.RunnableWrapper - Wrapping runnable task com.datastax.oss.driver.internal.core.channel.DefaultWriteCoalescer$Flusher$$Lambda$892/0x00000008013ea2f8@6aafcc5c
[otel.javaagent 2021-05-26 16:09:06:628 -0400] [reactor-http-nio-2] DEBUG io.opentelemetry.javaagent.instrumentation.api.concurrent.State - Failed to set parent context because another parent context is already set io.opentelemetry.javaagent.instrumentation.api.concurrent.State@6ab8d567: new: {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=9}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, opentelemetry-traces-server-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=9}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@32463bb5]}, old: {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=9}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, opentelemetry-traces-server-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=9}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@2733a481]}
2021-05-26 16:09:06,632 DEBUG [s0-io-4] [TraceID:] [SpanID:] er.internal.core.channel.InFlightHandler: 243 - [s0|id: 0xfaf0422c, L:/127.0.0.1:63909 - R:/127.0.0.1:9042] Got last response on in-flight stream id 0, completing and releasing
2021-05-26 16:09:06,669 DEBUG [s0-io-4] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] a.cassandra.core.cql.ReactiveCqlTemplate: 573 - Executing prepared statement [INSERT INTO "order" (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?)]
2021-05-26 16:09:06,680 DEBUG [s0-io-4] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] ql.session.DefaultBridgedReactiveSession: 150 - Executing statement [INSERT INTO "order" (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?)]
[otel.javaagent 2021-05-26 16:09:06:681 -0400] [s0-io-4] DEBUG io.opentelemetry.javaagent.instrumentation.api.concurrent.RunnableWrapper - Wrapping runnable task com.datastax.oss.driver.internal.core.channel.DefaultWriteCoalescer$Flusher$$Lambda$892/0x00000008013ea2f8@2d50cffd
[otel.javaagent 2021-05-26 16:09:06:681 -0400] [s0-io-4] DEBUG io.opentelemetry.javaagent.instrumentation.api.concurrent.State - Failed to set parent context because another parent context is already set io.opentelemetry.javaagent.instrumentation.api.concurrent.State@22d8ec92: new: {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=f6d0ad6f56ea3dd7, parentSpanContext=ImmutableSpanContext{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, name=INSERT opentelemetry.account_id, kind=CLIENT, attributes=AttributesMap{data={db.operation=INSERT, thread.id=34, thread.name=s0-io-4, db.name=opentelemetry, db.cassandra.table=account_id, db.statement=INSERT INTO ? (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?), db.system=cassandra}, capacity=128, totalAddedValues=7}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746680675779, endEpochNanos=0}, opentelemetry-traces-server-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=9}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, opentelemetry-traces-client-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=f6d0ad6f56ea3dd7, parentSpanContext=ImmutableSpanContext{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, name=INSERT opentelemetry.account_id, kind=CLIENT, attributes=AttributesMap{data={db.operation=INSERT, thread.id=34, thread.name=s0-io-4, db.name=opentelemetry, db.cassandra.table=account_id, db.statement=INSERT INTO ? (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?), db.system=cassandra}, capacity=128, totalAddedValues=7}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746680675779, endEpochNanos=0}, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@494bebf5]}, old: {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=f6d0ad6f56ea3dd7, parentSpanContext=ImmutableSpanContext{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, name=INSERT opentelemetry.account_id, kind=CLIENT, attributes=AttributesMap{data={db.operation=INSERT, thread.id=34, thread.name=s0-io-4, db.name=opentelemetry, db.cassandra.table=account_id, db.statement=INSERT INTO ? (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?), db.system=cassandra}, capacity=128, totalAddedValues=7}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746680675779, endEpochNanos=0}, opentelemetry-traces-server-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=9}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, opentelemetry-traces-client-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=f6d0ad6f56ea3dd7, parentSpanContext=ImmutableSpanContext{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, name=INSERT opentelemetry.account_id, kind=CLIENT, attributes=AttributesMap{data={db.operation=INSERT, thread.id=34, thread.name=s0-io-4, db.name=opentelemetry, db.cassandra.table=account_id, db.statement=INSERT INTO ? (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?), db.system=cassandra}, capacity=128, totalAddedValues=7}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1622059746680675779, endEpochNanos=0}, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@60c56fa9]}
2021-05-26 16:09:06,690 DEBUG [s0-io-4] [TraceID:] [SpanID:] er.internal.core.channel.InFlightHandler: 243 - [s0|id: 0xfaf0422c, L:/127.0.0.1:63909 - R:/127.0.0.1:9042] Got last response on in-flight stream id 0, completing and releasing
[otel.javaagent 2021-05-26 16:09:06:690 -0400] [s0-io-4] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'INSERT opentelemetry.account_id' : 64224325fe02c948645ce2f93af3d5fa f6d0ad6f56ea3dd7 CLIENT [tracer: io.opentelemetry.javaagent.cassandra-4.0:1.3.0-SNAPSHOT] AttributesMap{data={db.cassandra.coordinator.dc=datacenter1, thread.id=34, db.name=opentelemetry, db.cassandra.table=account_id, net.peer.name=localhost, db.cassandra.consistency_level=LOCAL_ONE, db.system=cassandra, db.cassandra.speculative_execution_count=0, db.operation=INSERT, thread.name=s0-io-4, net.peer.ip=127.0.0.1, db.cassandra.idempotence=true, net.peer.port=9042, db.statement=INSERT INTO ? (account_id,order_id,createdby,createddate,item,lastmodifiedby,lastmodifieddate) VALUES (?,?,?,?,?,?,?), db.cassandra.coordinator.id=6d0b6299-d8a6-45f8-88ce-9238e5fe2566}, capacity=128, totalAddedValues=15}
2021-05-26 16:09:06,727  INFO [s0-io-4] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] etry.showcase.order.service.OrderService:  43 - Order created successfully: Order(orderKey=OrderKey(accountId=account123, orderId=2b1d679b-d193-451c-9106-f667659a16b1), item=item1, isNew=true, createdBy=user-principal, createdDate=2021-05-26T20:09:06.557307Z, lastModifiedBy=user-principal, lastModifiedDate=2021-05-26T20:09:06.557307Z)
2021-05-26 16:09:06,741 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] k.integration.channel.FluxMessageChannel: 191 - preSend on channel 'bean 'builderOrders_integrationflow.channel#0'', message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=23cb91dc-dcc7-cbaf-b2ad-e204a43249b6, timestamp=1622059746741}]
2021-05-26 16:09:06,741  INFO [s0-io-4] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] etry.showcase.order.service.OrderService:  61 - Build order message sent
2021-05-26 16:09:06,744 DEBUG [s0-io-4] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] work.http.codec.json.Jackson2JsonEncoder: 147 - [5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Encoding [Order(orderKey=OrderKey(accountId=account123, orderId=2b1d679b-d193-451c-9106-f667659a16b1), item=it (truncated)...]
2021-05-26 16:09:06,746 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] .integration.router.MethodInvokingRouter: 191 - bean 'builderOrders_integrationflow.router#0' for component 'builderOrders_integrationflow.org.springframework.integration.config.ConsumerEndpointFactoryBean#0' received message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=23cb91dc-dcc7-cbaf-b2ad-e204a43249b6, timestamp=1622059746741}]
2021-05-26 16:09:06,746 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] am.messaging.DirectWithAttributesChannel: 191 - preSend on channel 'bean 'builderOrders-out-0'', message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=23cb91dc-dcc7-cbaf-b2ad-e204a43249b6, timestamp=1622059746741}]
2021-05-26 16:09:06,746 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] tractMessageChannelBinder$SendingHandler: 191 - org.springframework.cloud.stream.binder.AbstractMessageChannelBinder$SendingHandler@18862014 received message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=23cb91dc-dcc7-cbaf-b2ad-e204a43249b6, timestamp=1622059746741}]
[otel.javaagent 2021-05-26 16:09:06:747 -0400] [s0-io-4] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Applying instrumentation: executor [class io.opentelemetry.javaagent.instrumentation.javaconcurrent.ExecutorInstrumentationModule] on jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
2021-05-26 16:09:06,750 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ation.amqp.outbound.AmqpOutboundEndpoint: 191 - org.springframework.integration.amqp.outbound.AmqpOutboundEndpoint@1e50626 received message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=e6e4fb90-d3b1-27fc-6699-4158653843b1, timestamp=1622059746750}]
[otel.javaagent 2021-05-26 16:09:06:753 -0400] [s0-io-4] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed reactor.netty.http.HttpOperations$PostHeadersNettyOutbound -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
2021-05-26 16:09:06,755 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] pping.AbstractHeaderMapper$HeaderMatcher: 544 - headerName=[contentType] WILL be mapped, matched pattern=*
[otel.javaagent 2021-05-26 16:09:06:761 -0400] [s0-io-4] DEBUG io.opentelemetry.javaagent.extension.instrumentation.InstrumentationModule - Applying instrumentation: executor [class io.opentelemetry.javaagent.instrumentation.javaconcurrent.ExecutorInstrumentationModule] on jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
2021-05-26 16:09:06,761  INFO [boundedElastic-1] [TraceID:] [SpanID:] bbit.connection.CachingConnectionFactory: 638 - Attempting to connect to: [localhost:5672]
[otel.javaagent 2021-05-26 16:09:06:765 -0400] [s0-io-4] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed io.netty.channel.AbstractChannelHandlerContext$WriteTask -- jdk.internal.loader.ClassLoaders$AppClassLoader@7ad041f3
[otel.javaagent 2021-05-26 16:09:06:766 -0400] [s0-io-4] DEBUG io.opentelemetry.javaagent.instrumentation.api.concurrent.State - Failed to set parent context because another parent context is already set io.opentelemetry.javaagent.instrumentation.api.concurrent.State@13bad4ea: new: {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, order_id=2b1d679b-d193-451c-9106-f667659a16b1, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=2, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, opentelemetry-traces-server-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, order_id=2b1d679b-d193-451c-9106-f667659a16b1, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=2, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@5d6a51a]}, old: {opentelemetry-trace-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, order_id=2b1d679b-d193-451c-9106-f667659a16b1, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=2, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, opentelemetry-traces-server-span-key=RecordEventsReadableSpan{traceId=64224325fe02c948645ce2f93af3d5fa, spanId=586b294e5c289c52, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=/api/v1/orders, kind=SERVER, attributes=AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, order_id=2b1d679b-d193-451c-9106-f667659a16b1, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=10}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=2, totalRecordedLinks=0, startEpochNanos=1622059746216709920, endEpochNanos=0}, thread-propagation-locations=[[Ljava.lang.StackTraceElement;@6635cb59]}
2021-05-26 16:09:06,776 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] r.netty.http.server.HttpServerOperations: 249 - [id:5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Decreasing pending responses, now 0
2021-05-26 16:09:06,776  INFO [boundedElastic-1] [TraceID:] [SpanID:] bbit.connection.CachingConnectionFactory: 589 - Created new connection: rabbitConnectionFactory.publisher#28d484ba:0/SimpleConnection@44efe82f [delegate=amqp://guest@127.0.0.1:5672/, localPort= 63960]
2021-05-26 16:09:06,776 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ingframework.retry.support.RetryTemplate: 324 - Retry: count=0
2021-05-26 16:09:06,776 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ngframework.amqp.rabbit.core.RabbitAdmin: 563 - Initializing declarations
2021-05-26 16:09:06,776 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ngframework.amqp.rabbit.core.RabbitAdmin: 601 - Nothing to declare
2021-05-26 16:09:06,776 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ingframework.retry.support.RetryTemplate: 324 - Retry: count=0
2021-05-26 16:09:06,776 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ngframework.amqp.rabbit.core.RabbitAdmin: 563 - Initializing declarations
2021-05-26 16:09:06,777 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ramework.amqp.rabbit.core.RabbitTemplate:2226 - Executing callback RabbitAdmin$$Lambda$1914/0x000000080179c3b8 on RabbitMQ Channel: Cached Rabbit Channel: AMQChannel(amqp://guest@127.0.0.1:5672/,1), conn: Proxy@d2291f7 Shared Rabbit Connection: SimpleConnection@6985541c [delegate=amqp://guest@127.0.0.1:5672/, localPort= 63918]
2021-05-26 16:09:06,777 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ngframework.amqp.rabbit.core.RabbitAdmin: 670 - declaring Exchange 'builderOrders'
[otel.javaagent 2021-05-26 16:09:06:779 -0400] [reactor-http-nio-2] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'OrderRouter.lambda' : 64224325fe02c948645ce2f93af3d5fa 4438092ef7cfcdc8 INTERNAL [tracer: io.opentelemetry.javaagent.spring-webflux-5.0:1.3.0-SNAPSHOT] AttributesMap{data={thread.id=61, thread.name=reactor-http-nio-2}, capacity=128, totalAddedValues=2}
[otel.javaagent 2021-05-26 16:09:06:780 -0400] [boundedElastic-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'exchange.declare' : 074b2ab96e08009ea2f6e291fe5a3f47 4cc25f21c420b661 CLIENT [tracer: io.opentelemetry.javaagent.rabbitmq-2.7:1.3.0-SNAPSHOT] AttributesMap{data={thread.id=38, net.peer.ip=127.0.0.1, thread.name=boundedElastic-1, messaging.system=rabbitmq, net.peer.name=localhost, net.peer.port=5672, messaging.destination_kind=queue}, capacity=128, totalAddedValues=7}
2021-05-26 16:09:06,780 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ngframework.amqp.rabbit.core.RabbitAdmin: 610 - Declarations finished
2021-05-26 16:09:06,782 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] web.server.adapter.HttpWebHandlerAdapter:  91 - [5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Completed 201 CREATED
2021-05-26 16:09:06,783 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] bbit.connection.CachingConnectionFactory: 651 - Creating cached Rabbit Channel from AMQChannel(amqp://guest@127.0.0.1:5672/,1)
2021-05-26 16:09:06,784 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ramework.amqp.rabbit.core.RabbitTemplate:2226 - Executing callback RabbitTemplate$$Lambda$1912/0x000000080179abb8 on RabbitMQ Channel: Cached Rabbit Channel: AMQChannel(amqp://guest@127.0.0.1:5672/,1), conn: Proxy@2c2747d4 Shared Rabbit Connection: SimpleConnection@44efe82f [delegate=amqp://guest@127.0.0.1:5672/, localPort= 63960]
2021-05-26 16:09:06,789 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ramework.amqp.rabbit.core.RabbitTemplate:2391 - Publishing message [(Body:'{"orderKey":{"accountId":"account123","orderId":"2b1d679b-d193-451c-9106-f667659a16b1"},"item":"item1","createdBy":"user-principal","createdDate":"2021-05-26T20:09:06.557307Z","lastModifiedBy":"user-principal","lastModifiedDate":"2021-05-26T20:09:06.557307Z"}' MessageProperties [headers={}, timestamp=Wed May 26 16:09:06 EDT 2021, messageId=e6e4fb90-d3b1-27fc-6699-4158653843b1, contentType=application/json, contentLength=0, deliveryMode=PERSISTENT, priority=0, deliveryTag=0])] on exchange [builderOrders], routingKey = [builderOrders]
2021-05-26 16:09:06,788 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] r.netty.http.server.HttpServerOperations: 244 - [id:5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Last HTTP response frame
[otel.javaagent 2021-05-26 16:09:06:790 -0400] [reactor-http-nio-2] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - '/api/v1/orders' : 64224325fe02c948645ce2f93af3d5fa 586b294e5c289c52 SERVER [tracer: io.opentelemetry.javaagent.netty-4.1:1.3.0-SNAPSHOT] AttributesMap{data={http.url=http://localhost:8080/order/api/v1/orders, thread.id=61, net.peer.ip=0:0:0:0:0:0:0:1, thread.name=reactor-http-nio-2, http.method=POST, order_id=2b1d679b-d193-451c-9106-f667659a16b1, http.client_ip=0:0:0:0:0:0:0:1, net.peer.port=63958, http.status_code=201, http.user_agent=curl/7.64.1, http.flavor=1.1}, capacity=128, totalAddedValues=11}
2021-05-26 16:09:06,790 DEBUG [reactor-http-nio-2] [TraceID:64224325fe02c948645ce2f93af3d5fa] [SpanID:586b294e5c289c52] r.netty.http.server.HttpServerOperations: 244 - [id:5ed2c6d3-1, L:/[0:0:0:0:0:0:0:1]:8080 - R:/[0:0:0:0:0:0:0:1]:63958] Last HTTP packet was sent, terminating the channel
[otel.javaagent 2021-05-26 16:09:06:794 -0400] [boundedElastic-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'builderOrders -> builderOrders send' : cce14d6d190397c5e3b05201b74db9df 5fd16696c9cf875e PRODUCER [tracer: io.opentelemetry.javaagent.rabbitmq-2.7:1.3.0-SNAPSHOT] AttributesMap{data={messaging.destination=builderOrders, messaging.message_payload_size_bytes=259, thread.id=38, net.peer.ip=127.0.0.1, thread.name=boundedElastic-1, messaging.system=rabbitmq, net.peer.name=localhost, net.peer.port=5672, messaging.destination_kind=queue, rabbitmq.delivery_mode=2}, capacity=128, totalAddedValues=10}
2021-05-26 16:09:06,794 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] ation.amqp.outbound.AmqpOutboundEndpoint: 191 - handler 'org.springframework.integration.amqp.outbound.AmqpOutboundEndpoint@1e50626' produced no reply for request Message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=e6e4fb90-d3b1-27fc-6699-4158653843b1, timestamp=1622059746750}]
2021-05-26 16:09:06,797 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] am.messaging.DirectWithAttributesChannel: 191 - postSend (sent=true) on channel 'bean 'builderOrders-out-0'', message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=23cb91dc-dcc7-cbaf-b2ad-e204a43249b6, timestamp=1622059746741}]
2021-05-26 16:09:06,799 DEBUG [boundedElastic-1] [TraceID:] [SpanID:] k.integration.channel.FluxMessageChannel: 191 - postSend (sent=true) on channel 'bean 'builderOrders_integrationflow.channel#0'', message: GenericMessage [payload=byte[259], headers={contentType=application/json, id=23cb91dc-dcc7-cbaf-b2ad-e204a43249b6, timestamp=1622059746741}]
[otel.javaagent 2021-05-26 16:09:07:332 -0400] [grpc-nio-worker-ELG-1-10] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:09:07:333 -0400] [grpc-nio-worker-ELG-1-11] DEBUG io.grpc.netty.shaded.io.grpc.netty.Utils - Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
[otel.javaagent 2021-05-26 16:09:07:570 -0400] [supportability_metrics_reporter] DEBUG io.opentelemetry.javaagent.shaded.instrumentation.api.internal.SupportabilityMetrics - Counter 'SqlStatementSanitizer cache miss' : 1
2021-05-26 16:09:09,487 DEBUG [s0-io-3] [TraceID:] [SpanID:] r.internal.core.channel.HeartbeatHandler:  56 - Connection was inactive for 30 seconds, sending heartbeat
2021-05-26 16:09:09,492 DEBUG [s0-io-3] [TraceID:] [SpanID:] er.internal.core.channel.InFlightHandler: 243 - [s0|control|id: 0xfd88ab97, L:/127.0.0.1:63908 - R:/127.0.0.1:9042] Got last response on in-flight stream id 0, completing and releasing
2021-05-26 16:09:09,492 DEBUG [s0-io-3] [TraceID:] [SpanID:] r.internal.core.channel.HeartbeatHandler:  85 - [id: 0xfd88ab97, L:/127.0.0.1:63908 - R:/127.0.0.1:9042] Heartbeat query succeeded
[otel.javaagent 2021-05-26 16:09:10:642 -0400] [BatchSpanProcessor_WorkerThread-1] ERROR io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter - Failed to export spans. Server is UNAVAILABLE. Make sure your collector is running and reachable from this network. Full error message:UNAVAILABLE: io exception
[otel.javaagent 2021-05-26 16:09:10:642 -0400] [BatchSpanProcessor_WorkerThread-1] DEBUG io.opentelemetry.sdk.trace.export.BatchSpanProcessor$Worker - Exporter failed

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Reproduce with the linked opentelemetry-showcase rabbitmq-latest-otel setup and the listed RabbitMQ, Cassandra, and Gradle commands. Start at FluxMessageChannel on boundedElastic-1 and the RabbitMQ instrumentation advice; done means the root trace context is present there and the RabbitMQ span keeps the root trace ID instead of creating a new one.

Written by the indexing model from the issue text.

Assessment

Tech stack
java, rabbitmq, spring
Domain
backend, distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.