TraceId and TransactionId stop displaying in Console Appender after running Java application with -javaagent

Version: 7.17 (per local docker-compose Quick start development environment | APM User Guide [7.17] | Elastic)

Is there anything special in your setup? We were originally using the micrometer-tracing-brave-bridge and exporting spans to Zipkin and are now trying to move from OpenTracing to OpenTelemetry using the Elastic Agent. In the original setup, we updated the logback.xml pattern with %black(%date{ISO8601}) %highlight(%-5level) [%blue(%X{traceId:-}) %magenta(%X{spanId:-})] %yellow(%C{1}): %msg%n%throwable and trace/span ids were shown and propagated correctly across services.

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
After changing the micrometer dependencies to otel and running the application in IntelliJ with the VM option with the elastic-apm 1.42.0 java agent, and updating logback from traceId to trace.id && spanId to transaction.id, none of the ids are being displayed in the Console. The requests can be seen in Kibana Observability, and the trace ids show up across services. Also, the transactions do not display the waterfall from service to service. I'm not sure what the problem is.

I came across this (Get started | ECS Logging Java Reference [1.x] | Elastic) and added the logging dependency, but it doesn't seem to help.

Any ideas on what to do to get the trace.id and transaction.id to display in the console and propagate correctly across services (as well as have the waterfall show all the services correctly)?

Provide logs and/or server output (if relevant):

Relevant sections of effective pom:

      <dependency>
        <groupId>co.elastic.logging</groupId>
        <artifactId>logback-ecs-encoder</artifactId>
        <version>1.5.0</version>
      </dependency>
      <dependency>
        <groupId>io.micrometer</groupId>
        <artifactId>micrometer-tracing</artifactId>
        <version>1.1.1</version>
      </dependency>
      <dependency>
        <groupId>io.micrometer</groupId>
        <artifactId>micrometer-tracing-bridge-otel</artifactId>
        <version>1.1.1</version>
      </dependency>
    <dependency>
      <groupId>io.opentelemetry</groupId>
      <artifactId>opentelemetry-exporter-otlp</artifactId>
      <version>1.25.0</version>
      <scope>compile</scope>
    </dependency>
    <dependency>
      <groupId>co.elastic.logging</groupId>
      <artifactId>logback-ecs-encoder</artifactId>
      <version>1.5.0</version>
      <scope>compile</scope>
    </dependency>

Relevant sections of application.yml

management:
  tracing:
    sampling:
      probability: 1.0
    propagation:
      type: w3c
    enabled: true
    baggage:
      enabled: true
  metrics:
    distribution:
      percentiles-histogram:
        http:
          server:
            requests: true
  endpoints:
    web:
      exposure:
        include:
          - "prometheus"
          - "refresh"
  otlp:
    tracing:
      endpoint: http://localhost:8200

Relevant sections of elasticapm.properties

application_packages=com.example
server_urls=http://localhost:8200
environment=development
log_ecs_reformatting=SHADE
log_level=INFO
capture_body=transactions
capture_headers=true
transaction_ignore_user_agents=kube-probe,GoogleHC
use_path_as_transaction_name=true

There's a lot here and it's a little confusing. Let's take one thing at a time. You say

The requests can be seen in Kibana Observability, and the trace ids show up across services

by this I understand that when you look at Elastic APM UI (which is in Kibana) you can see the transactions? Is that correct? In what way do you see the transactions, because you go on to say

Also, the transactions do not display the waterfall from service to service

which I'm not sure whether you mean you see no waterfall displays at all, or just that the waterfall only shows spans within the service and none going to or from other services

I'm trying first to establish what the APM is showing, as the entries in the logs are really a different matter

Hi Jack, thanks for the quick response!

When I run the API previously without all of the changes or the javaagent, and hit a test endpoint, the logs displayed something like this:

2023-08-22 06:53:36,845 DEBUG [98935a7860566ab937fcb59e49bb41b2 5be4a64964f07f4b] o.s.c.l.LogFormatUtils: GET "/api/v1", parameters={} 
2023-08-22 06:53:36,853 INFO  [98935a7860566ab937fcb59e49bb41b2 5be4a64964f07f4b] c.p.p.f.a.v.HealthCheckController: v1 healthy af 
2023-08-22 06:53:36,873 DEBUG [98935a7860566ab937fcb59e49bb41b2 5be4a64964f07f4b] o.s.w.s.FrameworkServlet: Completed 200 OK 

The logback pattern used was [%blue(%X{traceId}) %magenta(%X{spanId})]

when you look at Elastic APM UI (which is in Kibana) you can see the transactions? Is that correct? In what way do you see the transactions

Here is the test endpoint, which simply calls an open endpoint on a second instance running locally:

    @Operation(summary = "Health check tracing via rest template")
    @RequestMapping(value = "trace/rt/{port}", method = RequestMethod.GET)
    public ResponseEntity<ResponseMessage<Object>> healthTraceRestTemplate(@PathVariable int port) {

        String url = "http://localhost:" + port + "/api/v1";

        Map<String, String> headers = new HashMap<>();

        RequestEntity<Map<String, String>> request = new RequestEntity<>(null, HttpMethod.GET, URI.create(url));

        log.info("sending request to other service"); // Since we're in an observation scope - this log line will contain tracing MDC entries ...
        ResponseEntity<ResponseMessage> response = restTemplate.getForEntity(URI.create(url), ResponseMessage.class); // Boot's RestTemplate instrumentation creates a child span here
        log.info("got response [{}]", response); // ... so will this line

        String message = new HealthyMessage().getMessage("trace");
        log.info(message);
        return ResponseEntity.ok().body(ResponseMessage.aResponse().withCode(HttpStatus.OK).withMessage(message).withStatus(ResponseMessage.Status.success).build());
    }

When I run both with the javaagent, I see it in the UI, but not the waterfall showing the second service being called:

Clicking it shows this trace.id: 1ed657d4c88e176808edac54c63e3053

The other service shows the endpoint was hit, with the correct traceparent: 00-1ed657d4c88e176808edac54c63e3053-2ec7259ff58b7c80-01 and also shows the correct trace.id

I was expecting to see this (which I did see for a few requests early yesterday), so I'm not sure what I did to change that behavior:

But running with the javaagent stops the trace info from showing in the console (even with the updated pattern [%blue(%X{trace.id}) %magenta(%X{transaction.id})])

2023-08-22 07:00:00,293 DEBUG [ ] o.s.c.l.LogFormatUtils: GET "/api/trace/rt/8099", parameters={} 
2023-08-22 07:00:00,317 INFO  [ ] c.p.p.f.a.v.HealthCheckController: sending request to other service 
2023-08-22 07:00:00,678 INFO  [ ] c.p.p.f.a.v.HealthCheckController: got response [<200 OK OK,ResponseMessage(status=success, code=200, message=v1 healthy af, dataType=null, length=0, totalItems=null, totalPages=0, pageNum=0, pageSize=0, offset=0, data=null, timestamp=Tue Aug 22 07:00:00 PDT 2023, responseTime=null),[Vary:"Origin", "Access-Control-Request-Method", "Access-Control-Request-Headers", X-Content-Type-Options:"nosniff", X-XSS-Protection:"0", Cache-Control:"no-cache, no-store, max-age=0, must-revalidate", Pragma:"no-cache", Expires:"0", X-Frame-Options:"DENY", Content-Type:"application/json", Transfer-Encoding:"chunked", Date:"Tue, 22 Aug 2023 14:00:00 GMT", Keep-Alive:"timeout=60", Connection:"keep-alive"]>] 
2023-08-22 07:00:00,686 INFO  [ ] c.p.p.f.a.v.HealthCheckController: trace healthy af 
2023-08-22 07:00:00,712 DEBUG [ ] o.s.w.s.FrameworkServlet: Completed 200 OK 

Okay, so the transactions and the UI looks fine - you were seeing the correct waterfall (I don't know
why the later one shows just one service, you'd need to check the DEBUG logs and look at the transaction/span start and end logs to see).

Now, let's switch to the logs. We don't support explicit patterns to include the trace/transaction IDs, this is done automatically by the agent. You want to step through the instructions, in particular the logback EcsEncoder (assuming you're not using spring). Keep your logback config as simple as possible initially, then once it's working you can experiment to get exactly what you want

Hi Jack,
Any idea why the waterfall doesn't display across the services?

Any idea why the waterfall doesn't display across the services?

In your previous response you showed the expected waterfall with the HTTP client span and the transaction of the downstream service.

You'll need to find out what you changed so that this waterfall is suddenly broken. Looking at the screenshot from your other response it seems like the HTTP client span is not being traced correctly.

Could you maybe try removing the micrometer-tracing-bridge-otel and opentelemetry-exporter-otlp dependencies? You definitely won't need opentelemetry-exporter-otlp because when running with the agent the agent will take care of exporting the data.

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.