Some OTLP spans are captured as transactions (SQL queries)

[SylvainJuge]

APM Server version (apm-server version): 8.0.0

Description of the problem including expected versus actual behavior:

When starting our opbeans Java application with OpenTelemetry instrumentation agent, the calls to the database are instrumented.
When the application starts, there are a few calls to the database to insert test data.
Those calls to database are captured as OTel spans and sent to Elastic APM.

The issue here is that those spans are a CLIENT spans, and such spans are not expected to create transactions.

With Elastic APM Agents, the lack of a transaction to "wrap" those database calls make them not captured.

Steps to reproduce:

We assume here that a local APM Server is running on the local system and listening to 0.0.0.0:8200 to allow docker images to communicate with it. Re-building once the opbeans java app docker image is required as not-yet-released changes are required.

git clone git@github.com:elastic/opbeans-java.git && cd opbeans-java

docker run \
    -d \
    -p 8080:8080 \
    --add-host=host.docker.internal:host-gateway \
    -e ELASTIC_APM_SERVICE_NAME=opbeans-otel-agent \
    -e APM_AGENT_TYPE=opentelemetry \
    -e ELASTIC_APM_SERVER_URL=http://host.docker.internal:8200 \
    -e ELASTIC_APM_APPLICATION_PACKAGES=co.elastic.apm.opbeans \
    -e ELASTIC_APM_ENABLE_LOG_CORRELATION=true \
    -e ELASTIC_APM_PROFILING_INFERRED_SPANS_ENABLED=true \
    -e ELASTIC_APM_ENABLE_EXPERIMENTAL_INSTRUMENTATIONS=true \
    -e ELASTIC_APM_ENVIRONMENT=production \
    -e OTEL_RESOURCE_ATTRIBUTES=service.name=opbeans-otel-agent,deployment.environment=production \
    -e OTEL_EXPORTER_OTLP_ENDPOINT=http://host.docker.internal:8200 \
    -e OTEL_EXPORTER_OTLP_PROTOCOL=grpc \
    -e OTEL_TRACES_EXPORTER=otlp \
    -e OTEL_METRICS_EXPORTER=otlp \
    $(docker build -q .)

The spans are visible in the Traces view in Kibana:

And they are stored as transactions in Elasticsearch:

We can find them with the following KQL query : processor.event :"transaction" and labels.db_name:*.

Sample document

{
  "_index": ".ds-traces-apm-default-2022.02.11-000001",
  "_id": "azVdVX8BZeM1SYi_5UVK",
  "_version": 1,
  "_score": 1,
  "_source": {
    "process": {
      "pid": 7,
      "command_line": "/opt/java/openjdk:bin:java -javaagent:/app/opentelemetry-javaagent.jar -Dspring.profiles.active= -Dserver.port= -Dserver.address=0.0.0.0 -Dspring.datasource.url= -Dspring.datasource.driverClassName= -Dspring.jpa.database= -Dotel.instrumentation.runtime-metrics.enabled=true",
      "executable": "/opt/java/openjdk:bin:java"
    },
    "agent": {
      "name": "opentelemetry/java",
      "version": "1.10.1"
    },
    "data_stream.namespace": "default",
    "processor": {
      "name": "transaction",
      "event": "transaction"
    },
    "data_stream.type": "traces",
    "labels": {
      "process_runtime_description": "AdoptOpenJDK OpenJDK 64-Bit Server VM 14.0.2+12",
      "db_connection_string": "h2:mem:",
      "db_name": "testdb",
      "thread_name": "main",
      "db_statement": "INSERT INTO order_lines (order_id, amount, product_id) VALUES (?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?",
      "db_user": "sa",
      "db_system": "h2",
      "db_operation": "INSERT",
      "db_sql_table": "order_lines",
      "telemetry_auto_version": "1.10.1"
    },
    "observer": {
      "hostname": "Sylvain-x390",
      "id": "fbcbceb8-fadd-4ef0-b1a6-8c59c3447eee",
      "ephemeral_id": "935f4827-150a-40d3-8ad8-430ba042c2e9",
      "type": "apm-server",
      "version": "8.0.0",
      "version_major": 8
    },
    "trace": {
      "id": "44a566ca6cf5f476a6a95c512a21b63b"
    },
    "@timestamp": "2022-03-04T14:38:07.849Z",
    "ecs": {
      "version": "1.12.0"
    },
    "service": {
      "node": {
        "name": "e244e6b6cd9a"
      },
      "environment": "production",
      "framework": {
        "name": "io.opentelemetry.jdbc",
        "version": "1.10.1"
      },
      "name": "opbeans-otel-agent",
      "runtime": {
        "name": "OpenJDK Runtime Environment",
        "version": "14.0.2+12"
      },
      "language": {
        "name": "java"
      }
    },
    "numeric_labels": {
      "thread_id": 1
    },
    "data_stream.dataset": "apm",
    "host": {
      "hostname": "e244e6b6cd9a",
      "os": {
        "type": "linux",
        "platform": "linux",
        "full": "Linux 5.13.0-28-generic"
      },
      "name": "e244e6b6cd9a",
      "architecture": "amd64"
    },
    "event": {
      "agent_id_status": "missing",
      "ingested": "2022-03-04T14:38:11Z",
      "outcome": "unknown"
    },
    "transaction": {
      "duration": {
        "us": 76039
      },
      "name": "INSERT testdb.order_lines",
      "id": "b9c7170926893b55",
      "type": "unknown",
      "sampled": true
    },
    "timestamp": {
      "us": 1646404687849876
    }
  },
  "fields": {
    "transaction.name.text": [
      "INSERT testdb.order_lines"
    ],
    "labels.process_runtime_description": [
      "AdoptOpenJDK OpenJDK 64-Bit Server VM 14.0.2+12"
    ],
    "labels.db_name": [
      "testdb"
    ],
    "host.os.full": [
      "Linux 5.13.0-28-generic"
    ],
    "host.hostname": [
      "e244e6b6cd9a"
    ],
    "process.pid": [
      7
    ],
    "service.language.name": [
      "java"
    ],
    "labels.thread_name": [
      "main"
    ],
    "transaction.id": [
      "b9c7170926893b55"
    ],
    "labels.telemetry_auto_version": [
      "1.10.1"
    ],
    "processor.event": [
      "transaction"
    ],
    "agent.name": [
      "opentelemetry/java"
    ],
    "host.name": [
      "e244e6b6cd9a"
    ],
    "event.agent_id_status": [
      "missing"
    ],
    "event.outcome": [
      "unknown"
    ],
    "labels.db_statement": [
      "INSERT INTO order_lines (order_id, amount, product_id) VALUES (?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?, ?, ?),(?"
    ],
    "host.os.type": [
      "linux"
    ],
    "processor.name": [
      "transaction"
    ],
    "transaction.duration.us": [
      76039
    ],
    "service.runtime.version": [
      "14.0.2+12"
    ],
    "data_stream.type": [
      "traces"
    ],
    "host.architecture": [
      "amd64"
    ],
    "labels.db_sql_table": [
      "order_lines"
    ],
    "labels.db_operation": [
      "INSERT"
    ],
    "labels.db_connection_string": [
      "h2:mem:"
    ],
    "observer.id": [
      "fbcbceb8-fadd-4ef0-b1a6-8c59c3447eee"
    ],
    "timestamp.us": [
      1646404687849876
    ],
    "observer.version": [
      "8.0.0"
    ],
    "ecs.version": [
      "1.12.0"
    ],
    "observer.type": [
      "apm-server"
    ],
    "transaction.name": [
      "INSERT testdb.order_lines"
    ],
    "agent.version": [
      "1.10.1"
    ],
    "numeric_labels.thread_id": [
      1
    ],
    "labels.db_user": [
      "sa"
    ],
    "labels.db_system": [
      "h2"
    ],
    "service.framework.version": [
      "1.10.1"
    ],
    "service.node.name": [
      "e244e6b6cd9a"
    ],
    "transaction.sampled": [
      true
    ],
    "trace.id": [
      "44a566ca6cf5f476a6a95c512a21b63b"
    ],
    "process.executable": [
      "/opt/java/openjdk:bin:java"
    ],
    "service.environment": [
      "production"
    ],
    "service.name": [
      "opbeans-otel-agent"
    ],
    "service.framework.name": [
      "io.opentelemetry.jdbc"
    ],
    "data_stream.namespace": [
      "default"
    ],
    "service.runtime.name": [
      "OpenJDK Runtime Environment"
    ],
    "observer.version_major": [
      8
    ],
    "observer.hostname": [
      "Sylvain-x390"
    ],
    "transaction.type": [
      "unknown"
    ],
    "event.ingested": [
      "2022-03-04T14:38:11.000Z"
    ],
    "@timestamp": [
      "2022-03-04T14:38:07.849Z"
    ],
    "observer.ephemeral_id": [
      "935f4827-150a-40d3-8ad8-430ba042c2e9"
    ],
    "host.os.platform": [
      "linux"
    ],
    "data_stream.dataset": [
      "apm"
    ],
    "process.command_line": [
      "/opt/java/openjdk:bin:java -javaagent:/app/opentelemetry-javaagent.jar -Dspring.profiles.active= -Dserver.port= -Dserver.address=0.0.0.0 -Dspring.datasource.url= -Dspring.datasource.driverClassName= -Dspring.jpa.database= -Dotel.instrumentation.runtime-metrics.enabled=true"
    ]
  }
}

[axw]

This is intentional, and happening because there's no parent ID: all trace roots are "transactions".

I'm not convinced we should use the CLIENT span kind to automatically drop these. What about INTERNAL spans (the default span kind)? Should we drop those?

[SylvainJuge]

I see, heuristics on span kind still remain heuristics, thus prone to errors.
Would open-telemetry/oteps#182 allow to properly solve this in an elegant way without heuristics on APM server ?

[axw]

@SylvainJuge we would still create transactions for trace roots, so that OTEP wouldn't change anything.