Debezium Tracing Bug: Wrong Span Propagation

by Admin 45 views
Debezium Tracing Bug: Wrong Span Propagation

Hey guys! Let's dive into a bit of a tricky issue we've uncovered with Debezium's tracing capabilities, specifically related to the ActivateTracingSpan SMT.

Debezium Connector and Version: PostgresConnector 2.6.0.Final

We're currently using the Debezium PostgresConnector version 2.6.0.Final. This is a pretty common setup for folks looking to capture changes from their PostgreSQL databases and stream them into Kafka. The connector itself has been rock solid for us, but this tracing quirk has us scratching our heads a bit.

Connector Configuration: A Deep Dive

Here's the nitty-gritty of our connector configuration. We've got a whole bunch of transformations set up, including the one causing us a bit of grief – transforms.tracing.type: io.debezium.transforms.tracing.ActivateTracingSpan. We're aiming to integrate OpenTelemetry for tracing, which is super important for understanding the flow of data and pinpointing bottlenecks in our distributed systems. The configuration below shows how we're setting up topics, schema handling, and crucially, the tracing transformation. We've included a bunch of other transformations like unwrap, ReplaceField, moveHeadersToValue, and dropPrefix, along with predicates to manage heartbeat and signal events. It's a fairly standard setup for capturing specific tables (public.orders) and routing the output. The main thing to note is the presence of transforms.tracing.type and its associated settings, including transforms.tracing.tracing.with.context.field.only: "true", which we thought would give us the fine-grained control we needed. We've also configured predicates like isHeartbeat and isDebeziumSignal to ensure our tracing logic is applied only to relevant events. This configuration is key to understanding the problem, as it sets the stage for how Debezium processes and transforms the data before sending it to Kafka.

{
  "name": "orders-cloud-v1-connector",
  "config": {
    "connector.class": "io.debezium.connector.postgresql.PostgresConnector",
    "plugin.name": "pgoutput",
    "snapshot.mode": "initial",
    "topic.prefix": "orders-cloud-v1",
    "topic.heartbeat.prefix": "sys_debezium-heartbeat",
    "table.include.list": "public.orders",
    "message.key.columns": "public.orders:id",
    "slot.name": "orders_slot",
    "publication.name": "orders_publication",
    "publication.autocreate.mode": "disabled",
    "database.dbname": "productsdb",
    "database.hostname": "localhost",
    "database.port": "5432",
    "database.user": "postgres",
    "database.password": "postgres",
    "key.converter" : "org.apache.kafka.connect.storage.StringConverter",
    "key.converter.schemas.enable": false,
    "value.converter": "org.apache.kafka.connect.json.JsonConverter",
    "value.converter.schemas.enable": false,
    "decimal.handling.mode": "precise",
    "tombstones.on.delete": false,
    "null.handling.mode": "keep",
    "heartbeat.interval.ms": "15000",
    "transforms": "filterSignalEvents,tracing,unwrap,ReplaceField,moveHeadersToValue,dropPrefix",
    "transforms.addMetadataHeaders.type": "org.apache.kafka.connect.transforms.HeaderFrom$Value",
    "transforms.addMetadataHeaders.fields": "source,op,transaction",
    "transforms.addMetadataHeaders.headers": "source,op,transaction",
    "transforms.addMetadataHeaders.operation": "copy",
    "transforms.addMetadataHeaders.predicate": "isHeartbeat",
    "transforms.addMetadataHeaders.negate": true,
    "transforms.unwrap.type": "io.debezium.transforms.ExtractNewRecordState",
    "transforms.unwrap.add.fields": "op,lsn",
    "transforms.unwrap.delete.handling.mode": "rewrite",
    "transforms.unwrap.drop.tombstones": "true",
    "transforms.setSchemaMetadata.type": "org.apache.kafka.connect.transforms.SetSchemaMetadata$Value",
    "transforms.setSchemaMetadata.schema.name": "music.Order",
    "transforms.setSchemaMetadata.predicate": "isHeartbeat",
    "transforms.setSchemaMetadata.negate": true,
    "transforms.dropPrefix.type": "org.apache.kafka.connect.transforms.RegexRouter",
    "transforms.dropPrefix.regex": "orders-cloud-v1\.public\.(.*)",
    "transforms.dropPrefix.replacement": "music.subscriptions.order.events",
    "transforms.dropPrefix.predicate": "isHeartbeat",
    "transforms.dropPrefix.negate": true,
    "transforms.filterSignalEvents.type": "org.apache.kafka.connect.transforms.Filter",
    "transforms.filterSignalEvents.predicate": "isDebeziumSignal",
    "transforms.tracing.type": "io.debezium.transforms.tracing.ActivateTracingSpan",
    "transforms.tracing.tracing.with.context.field.only": "true",
    "transforms.ReplaceField.type": "org.apache.kafka.connect.transforms.ReplaceField$Value",
    "transforms.ReplaceField.exclude": "tracingspancontext",
    "transforms.moveHeadersToValue.type": "io.debezium.transforms.HeaderToValue",
    "transforms.moveHeadersToValue.operation": "copy",
    "transforms.moveHeadersToValue.headers": "traceparent",
    "transforms.moveHeadersToValue.fields": "traceparent",
    "predicates": "isHeartbeat,isDebeziumSignal",
    "predicates.isHeartbeat.type": "org.apache.kafka.connect.transforms.predicates.TopicNameMatches",
    "predicates.isHeartbeat.pattern": "sys_debezium-heartbeat.*",
    "predicates.isDebeziumSignal.type": "org.apache.kafka.connect.transforms.predicates.TopicNameMatches",
    "predicates.isDebeziumSignal.pattern": "orders-cloud-v1\.public\.debezium_signal",
    "signal.enabled.channels": "source",
    "signal.data.collection": "public.debezium_signal"
  }
}

Database Version and Deployment Mode: PostgreSQL 15

We're running PostgreSQL version 15 on-premises. This version is quite capable, and we haven't encountered any specific issues with it interacting with Debezium, other than this particular tracing problem. The on-premises setup means we have full control over the database environment, which simplifies some aspects of troubleshooting, but also means we're responsible for managing all the infrastructure ourselves.

Expected Behavior: Following the Documentation

What we expect to happen is pretty straightforward, and it's based directly on the Debezium documentation for tracing. The ActivateTracingSpan SMT is supposed to insert a traceparent header with the span representing the debezium-read operation. This makes perfect sense because debezium-read is the operation that actually fetches the change event from the database log. We want our tracing system to correctly attribute the downstream events to this specific read operation. The documentation clearly states that this SMT should help propagate these spans, allowing us to trace the origin of the data effectively. When you're dealing with microservices and asynchronous communication, having accurate span propagation is absolutely crucial for debugging and performance monitoring. It allows you to stitch together the entire journey of a data change from its source to its final destination, providing invaluable insights.

Actual Behavior: A Confusing Span Propagation

Here's where things get a bit hairy, guys. Instead of the debezium-read span, the ActivateTracingSpan SMT is inserting a traceparent header with the db-log-write operation's span. This is quite confusing because db-log-write seems like an internal Debezium operation, not the primary event capture step. We've attached screenshots to illustrate this. In the first image, you can see that the debezium-read span is identified as 1e611f3956e57496. However, when we look at the traceparent header information (in the second image, seen via Offset Explorer), it shows a different span, 7ae54a0fcd89eaa4, which corresponds to db-log-write.

This discrepancy is problematic because it breaks the expected tracing context. When this spans data is sent to our tracing backend (like Jaeger or Zipkin), it misattributes the origin of the event. We're essentially tracing an internal Debezium process instead of the actual database read operation. This can lead to incorrect performance analysis and make it harder to identify the true source of latency or errors. We've also observed similar behavior with the EventRouter SMT, and if we add a Debezium interceptor, it ends up adding an onSend span as a child of the db-log-write span and sends that db-log-write span as the traceparent to Kafka. This further solidifies our observation that the db-log-write span is being prioritized or incorrectly propagated.

Debezium Read Span

Image 1: Showing the expected debezium-read span ID.

Offset Explorer Traceparent

Image 2: Showing the traceparent header containing the incorrect db-log-write span ID.

Latest Release Behavior

We haven't yet had a chance to test this specific issue with the absolute latest released Debezium version. This is something we're planning to do to see if this behavior has been addressed in more recent updates. Verifying with alpha/beta/CR versions is also a great idea to catch potential regressions or fixes before they hit stable releases.

Connector Logs

We can provide connector logs at DEBUG or TRACE level if needed for further investigation. Please let us know what specific log snippets would be most helpful.

Reproduction Steps: A Simple Setup

Reproducing this issue is relatively straightforward. Here’s how you can do it:

  1. Create the orders table:

    create table orders (
    id uuid not null primary key,
    client_id uuid not null,
    tracingspancontext varchar(255)
);

  2. Create the publication and replication slot:

    select pg_create_logical_replication_slot('orders_slot', 'pgoutput');
create publication orders_publication for table orders;

  3. Start Kafka Connect: Ensure Kafka Connect is started with the necessary OpenTelemetry JARs on the classpath. This is crucial for the tracing SMT to function correctly.

  4. Register the Connector: Use the Kafka Connect REST API to register the connector with the configuration provided in the section above. Make sure all the transformations, especially ActivateTracingSpan, are included.

Once set up, you should be able to observe the incorrect traceparent propagation as described in the 'Actual Behavior' section.

This bug report actually highlights a broader goal: improving OpenTelemetry Integration within Debezium. While the ActivateTracingSpan SMT is a step in the right direction, this issue shows there's room for refinement.

Use Case/Requirement: Seamless Distributed Tracing

The primary use case we aim to address is achieving seamless distributed tracing for data flowing through Debezium. In a microservices architecture, understanding the end-to-end journey of a piece of data is critical for debugging, performance monitoring, and overall system observability. Accurate span propagation ensures that when a change event is processed by Debezium and sent to Kafka, the associated trace context correctly reflects the operation that produced the event. This allows us to connect the dots between different services and identify where potential issues lie. We want to be able to look at a trace and clearly see the Debezium read operation, followed by Kafka processing, and then subsequent service consumption, all linked together seamlessly.

Implementation Ideas: Refining Span Context Propagation

Based on our observations, it seems like the issue might stem from the lifecycle of the spans within the ActivateTracingSpan SMT. Specifically, the debezium-read span appears to be started and closed within a finally block that's part of the db-log-write operation. The context is then being put into the record headers after the debezium-read span has already closed. This means the db-log-write span is the one that gets written to the traceparent header.

As suggested in the issue details (TracingSpanUtil.java#L73), perhaps the context should be added to the headers before the debezium-read span closure. This would ensure that the correct span (debezium-read) is captured and propagated, rather than the encompassing db-log-write operation.

We believe a more robust implementation would involve ensuring that the ActivateTracingSpan SMT correctly identifies and captures the specific span responsible for reading the data from the source, rather than a more general or encompassing span. This would greatly enhance the accuracy and utility of the tracing information provided by Debezium. We're eager to see this improved for better observability!