Transactions and service map are not working properly in Kubernetes

manuexcd · May 30, 2024, 11:58am

Kibana version:
8.7
Elasticsearch version:
8.7
APM Server version:
8.7
APM Agent language and version:
apm-agent-java:1.43.0
Original install method (e.g. download page, yum, deb, from source, etc.) and version:
ECK Operator
Fresh install or upgraded from other version?
Fresh install
Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
I have successfully monitored everything related to APM while developing my Java application (version 17) with Spring Boot (version 2.7.14). I could see all the spans of the transactions as well as the links in the Service Map. When deploying the application in Kubernetes and monitoring it, the transactions do not show any spans and the Service Map does not show any links.

The first row shows the Kubernetes app (tested in AKS, k3s and minikube) and the second row shows the local app (tested containerized and uncontainerized):

In both cases, this is my APM config:

ELASTIC_APM_SERVICE_NAME: my-service-name
ELASTIC_APM_SERVER_URLS: https://myurl.com
ELASTIC_APM_SECRET_TOKEN: secret-token
ELASTIC_APM_ENVIRONMENT: env
ELASTIC_APM_APPLICATION_PACKAGES: "my.packages"

Note that I had to enable the use_path_as_transaction_name option to show transaction names. Otherwise, 'unknown transaction' was shown.

Sylvain_Juge · May 30, 2024, 1:42pm

Hi, can you capture the agent logs with log_level=debug when deployed in k8s ?

You should be able to see startSpan and endSpan in the logs when the spans are captured.

If there is any error sending the data, it should also be visible in the logs.

For the traces I see "1 of 1" and "1 of 4" respectively, could you try to also trigger more transactions (like a few dozen spread over a minute or more) just to be sure it's not something happening for the first few executions of the transaction ?

manuexcd · May 30, 2024, 2:02pm

These are the logs when I make an HTTP request to my app:

2024-05-30 13:55:55,605 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ActiveStack - Activating OTelBridgeContext[{opentelemetry-baggage-key={}, opentelemetry-trace-span-key=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, opentelemetry-traces-span-key-server=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, org.springframework.cloud.sleuth.otel.bridge.OtelHttpServerHandler.request=org.springframework.cloud.sleuth.instrument.web.servlet.HttpServletRequestWrapper@558f5b5a}] on thread 64
2024-05-30 13:55:55,605 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08) (1)
2024-05-30 13:55:55,605 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08)
2024-05-30 13:55:55,605 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ActiveStack - Activating '' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08) on thread 64
2024-05-30 13:55:55,605 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08) (2)
2024-05-30 13:55:55,605 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08) (3)
2024-05-30 13:55:55,605 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ActiveStack - Activating OTelBridgeContext[{opentelemetry-baggage-key={}, opentelemetry-trace-span-key=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, opentelemetry-traces-span-key-server=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, org.springframework.cloud.sleuth.otel.bridge.OtelHttpServerHandler.request=org.springframework.cloud.sleuth.instrument.web.servlet.HttpServletRequestWrapper@558f5b5a}] on thread 64
2024-05-30 13:55:55,613 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ActiveStack - Activating OTelBridgeContext[{opentelemetry-baggage-key={}, opentelemetry-trace-span-key=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=f10862c1a35e1109, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, opentelemetry-traces-span-key-server=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, org.springframework.cloud.sleuth.otel.bridge.OtelHttpServerHandler.request=org.springframework.cloud.sleuth.instrument.web.servlet.HttpServletRequestWrapper@558f5b5a, opentelemetry-traces-span-key-client=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=f10862c1a35e1109, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, org.springframework.cloud.sleuth.otel.bridge.OtelHttpClientHandler.request=org.springframework.cloud.sleuth.instrument.web.mvc.TracingClientHttpRequestInterceptor$HttpRequestWrapper@51f71378}] on thread 64
2024-05-30 13:55:55,614 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ActiveStack - Deactivating OTelBridgeContext[{opentelemetry-baggage-key={}, opentelemetry-trace-span-key=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=f10862c1a35e1109, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, opentelemetry-traces-span-key-server=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, org.springframework.cloud.sleuth.otel.bridge.OtelHttpServerHandler.request=org.springframework.cloud.sleuth.instrument.web.servlet.HttpServletRequestWrapper@558f5b5a, opentelemetry-traces-span-key-client=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=f10862c1a35e1109, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, org.springframework.cloud.sleuth.otel.bridge.OtelHttpClientHandler.request=org.springframework.cloud.sleuth.instrument.web.mvc.TracingClientHttpRequestInterceptor$HttpRequestWrapper@51f71378}] on thread 64
2024-05-30 13:55:55,621 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ActiveStack - Deactivating OTelBridgeContext[{opentelemetry-baggage-key={}, opentelemetry-trace-span-key=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, opentelemetry-traces-span-key-server=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, org.springframework.cloud.sleuth.otel.bridge.OtelHttpServerHandler.request=org.springframework.cloud.sleuth.instrument.web.servlet.HttpServletRequestWrapper@558f5b5a}] on thread 64
2024-05-30 13:55:55,622 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ActiveStack - Deactivating 'GET /prioritization/dg/request/study/1' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08) on thread 64
2024-05-30 13:55:55,622 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'GET /prioritization/dg/request/study/1' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08) (2)
2024-05-30 13:55:55,622 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - endTransaction 'GET /prioritization/dg/request/study/1' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08)
2024-05-30 13:55:55,622 [http-nio-8080-exec-4] DEBUG co.elastic.apm.agent.impl.ActiveStack - Deactivating OTelBridgeContext[{opentelemetry-baggage-key={}, opentelemetry-trace-span-key=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, opentelemetry-traces-span-key-server=PropagatedSpan{ImmutableSpanContext{traceId=2eaba5eaff94ab1a49eaf0438d873171, spanId=a3cbb530d9f322dd, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}}, org.springframework.cloud.sleuth.otel.bridge.OtelHttpServerHandler.request=org.springframework.cloud.sleuth.instrument.web.servlet.HttpServletRequestWrapper@558f5b5a}] on thread 64
2024-05-30 13:55:55,628 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving ERROR event (sequence 13280)
2024-05-30 13:55:55,628 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.util.UrlConnectionUtils - Opening https://apm.healthincode.com/intake/v2/events without proxy
2024-05-30 13:55:55,628 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.AbstractIntakeApiHandler - Starting new request to https://apm.healthincode.com/intake/v2/events
2024-05-30 13:55:55,630 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10 seconds
2024-05-30 13:55:55,631 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving ERROR event (sequence 13281)
2024-05-30 13:55:55,632 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 13282)
2024-05-30 13:55:55,632 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'GET /prioritization/dg/request/study/1' 00-725a598293a7279b6364e06620779df9-eb685a6b2b534d0c-01 (68a1fb08) (1)

No matter how many transactions I make, the result is the same.

Sylvain_Juge · May 30, 2024, 2:43pm

Here there is no span created or activated between startTransaction and endTransaction captured by the agent, the whole transaction seems to be executed on a single thread http-nio-8080-exec-4.

You should do the same experiment with the non-k8s version and inspect the logs for any differences:

the spans must be created, visible with startSpan and endSpan in the logs
do the spans execute on a different thread than the main request ? if the transaction and the spans are on the same thread then it means it's synchronous and there is no complex delegation (and if the app is the same, I can't see how that would behave differently in two environments).

Also worth checking the agent effective configuration between the two deployments, it's shown in the first few lines of the agent log.

manuexcd · May 31, 2024, 9:22am

I have done an analysis of the transactions that are displayed correctly and those that are not. I have seen that the ones displayed correctly have the following field service.framework.name: Spring Web MVC, and the ones that are not have the following field service.framework.name: Servlet API. I think the problem might be here, but I do not understand why this is happening.