Span and Trace Id are not being exported in Spring Batch (Spring Boot 3.4.1).

[gsenaa]

We are implementing an internal library to collect logs and traces from Spring Batch applications and standalone applications in general.

When running a test application, the TraceId and SpanId are propagated within the application and appear in the logs. However, they are not exported. Exemples:

Logs(logback) have span information:

2024-12-26T09:29:39.567-03:00  INFO 14120 --- [  restartedMain] [97a1e490fdd6cd24754ef56ba28f2d10-5c8c24e1b096eeed] i.o.e.logging.LoggingSpanExporter        : 'HikariDataSource.getConnection' : 97a1e490fdd6cd24754ef56ba28f2d10 393da51424bdb952 INTERNAL [tracer: io.opentelemetry.jdbc:2.9.0-alpha] AttributesMap{data={code.function=getConnection, db.system=h2, db.connection_string=h2:mem:, code.namespace=com.zaxxer.hikari.HikariDataSource, db.name=89aa5b4f-2086-427f-8438-8f19e8a73f8a}, capacity=128, totalAddedValues=5}
2024-12-26T09:29:39.568-03:00  INFO 14120 --- [  restartedMain] [97a1e490fdd6cd24754ef56ba28f2d10-5c8c24e1b096eeed] Main                                     : Hello World Batch.
2024-12-26T09:29:39.569-03:00  INFO 14120 --- [  restartedMain] [97a1e490fdd6cd24754ef56ba28f2d10-5c8c24e1b096eeed] i.o.e.logging.LoggingSpanExporter        : 'UPDATE 89aa5b4f-2086-427f-8438-8f19e8a73f8a.BATCH_STEP_EXECUTION_CONTEXT' : 97a1e490fdd6cd24754ef56ba28f2d10 d21c67ba9071de9e CLIENT [tracer: io.opentelemetry.jdbc:2.9.0-alpha] AttributesMap{data={db.statement=UPDATE BATCH_STEP_EXECUTION_CONTEXT SET SHORT_CONTEXT = ?, SERIALIZED_CONTEXT = ? WHERE STEP_EXECUTION_ID = ? , db.system=h2, db.connection_string=h2:mem:, db.name=89aa5b4f-2086-427f-8438-8f19e8a73f8a, db.sql.table=BATCH_STEP_EXECUTION_CONTEXT, db.operation=UPDATE}, capacity=128, totalAddedValues=6}

Logs(SystemOutLogRecordExporter) when exported loose span information:

2024-12-26T12:29:39.567Z INFO ''HikariDataSource.getConnection' : 97a1e490fdd6cd24754ef56ba28f2d10 393da51424bdb952 INTERNAL [tracer: io.opentelemetry.jdbc:2.9.0-alpha] AttributesMap{data={code.function=getConnection, db.system=h2, db.connection_string=h2:mem:, code.namespace=com.zaxxer.hikari.HikariDataSource, db.name=89aa5b4f-2086-427f-8438-8f19e8a73f8a}, capacity=128, totalAddedValues=5}' : 00000000000000000000000000000000 0000000000000000 [scopeInfo: io.opentelemetry.exporter.logging.LoggingSpanExporter:] {}
2024-12-26T12:29:39.568Z INFO 'Hello World Batch.' : 00000000000000000000000000000000 0000000000000000 [scopeInfo: Main:] {}
2024-12-26T12:29:39.569Z INFO ''UPDATE 89aa5b4f-2086-427f-8438-8f19e8a73f8a.BATCH_STEP_EXECUTION_CONTEXT' : 97a1e490fdd6cd24754ef56ba28f2d10 d21c67ba9071de9e CLIENT [tracer: io.opentelemetry.jdbc:2.9.0-alpha] AttributesMap{data={db.statement=UPDATE BATCH_STEP_EXECUTION_CONTEXT SET SHORT_CONTEXT = ?, SERIALIZED_CONTEXT = ? WHERE STEP_EXECUTION_ID = ? , db.system=h2, db.connection_string=h2:mem:, db.name=89aa5b4f-2086-427f-8438-8f19e8a73f8a, db.sql.table=BATCH_STEP_EXECUTION_CONTEXT, db.operation=UPDATE}, capacity=128, totalAddedValues=6}' : 00000000000000000000000000000000 0000000000000000 [scopeInfo: io.opentelemetry.exporter.logging.LoggingSpanExporter:] {}

Environment

• Using Spring Boot 3.4.1
• (Micrometer on spring boot dependencies): micrometer.version 1.14.2 and micrometer-tracing.version 1.4.1
• OS:
• Java version: 21.0.4

To Reproduce
The test application we use is a simple Hello World for Spring Batch. In the properties, we set OpenTelemetry to export the traceId and spanId to the console.

The code and properties used:

Java code:

import org.springframework.batch.core.Job;
import org.springframework.batch.core.Step;
import org.springframework.batch.core.StepContribution;
import org.springframework.batch.core.job.builder.JobBuilder;
import org.springframework.batch.core.repository.JobRepository;
import org.springframework.batch.core.scope.context.ChunkContext;
import org.springframework.batch.core.step.builder.StepBuilder;
import org.springframework.batch.core.step.tasklet.Tasklet;
import org.springframework.batch.repeat.RepeatStatus;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;
import org.springframework.jdbc.support.JdbcTransactionManager;
import org.springframework.lang.Nullable;

import lombok.extern.slf4j.Slf4j;

@SpringBootApplication
@Slf4j
public class Main {

    public static void main(String[] args) {
        System.exit(
            SpringApplication.exit(
                SpringApplication.run(Main.class, args)
            )
        );
    }

    @Bean
    public Step step(JobRepository jobRepository, JdbcTransactionManager transactionManager) {
        log.info("Teste");
        return new StepBuilder("step", jobRepository).tasklet(teste(), transactionManager).build();
    }

    @Bean
    public Job job(JobRepository jobRepository, Step step) {
        return new JobBuilder("job", jobRepository).start(step).build();
    }

    public Tasklet teste() {
        return new Tasklet() {
            @SuppressWarnings("null")
            @Override
            @Nullable
            public RepeatStatus execute(StepContribution contribution, ChunkContext chunkContext) throws Exception {
                log.info("Hello World Batch.");
                return RepeatStatus.FINISHED;
            }
        };
    }

}

application.yml:

spring:
  threads:
    virtual:
      enabled: true

otel:
  logs:
    exporter: console
  traces:
    exporter: console
  metrics:
    exporter: none
  instrumentation:
    annotations:
      enabled: true
    logback-appender:
      enabled: true
    micrometer:
      enabled: true

pom.xml

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
 <modelVersion>4.0.0</modelVersion>

 <parent>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-parent</artifactId>
  <version>3.4.1</version>
 </parent>

    <groupId>br.com.example</groupId>
    <artifactId>example-batch-test</artifactId>
    <version>1.0.0-SNAPSHOT</version>

    <name>Example Batch Test</name>
    <description>
    </description>

    <properties>
        <java.version>21</java.version>
  <opentelemetry.instrumentation.version>2.9.0</opentelemetry.instrumentation.version>
    </properties>

 <dependencies>
  <dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter-batch</artifactId>
  </dependency>
  <dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter-actuator</artifactId>
  </dependency>
  <dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-devtools</artifactId>
   <scope>runtime</scope>
  </dependency>
  <dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter-aop</artifactId>
  </dependency>
  <dependency>
   <groupId>org.projectlombok</groupId>
   <artifactId>lombok</artifactId>
   <scope>provided</scope>
  </dependency>
  <dependency>
   <groupId>com.h2database</groupId>
   <artifactId>h2</artifactId>
   <scope>runtime</scope>
  </dependency>
  <dependency>
   <groupId>io.opentelemetry.instrumentation</groupId>
   <artifactId>opentelemetry-spring-boot-starter</artifactId>
  </dependency>
  <dependency>
   <groupId>io.micrometer</groupId>
   <artifactId>micrometer-tracing-bridge-otel</artifactId>
  </dependency>
  <dependency>
   <groupId>io.opentelemetry</groupId>
   <artifactId>opentelemetry-exporter-logging</artifactId>
  </dependency>
 </dependencies>

 <dependencyManagement>
 <dependencies>
  <dependency>
   <groupId>io.opentelemetry.instrumentation</groupId>
   <artifactId>opentelemetry-instrumentation-bom</artifactId>
   <version>${opentelemetry.instrumentation.version}</version>
   <type>pom</type>
   <scope>import</scope>
  </dependency>
 </dependencies>
</project>

Expected behavior
We expected the traceId and spanId to be in the exported logs, as you can see in the previous log in the bug explanation

2024-12-26T12:29:39.568Z INFO 'Hello World Batch.' : 00000000000000000000000000000000 0000000000000000 [scopeInfo: Main:] {}

Additional context
We tested the same job on a route in a Spring web application, and everything worked as expected.

[shakuzen]

  <dependency>
   <groupId>io.opentelemetry.instrumentation</groupId>
   <artifactId>opentelemetry-spring-boot-starter</artifactId>
  </dependency>
  <dependency>
   <groupId>io.micrometer</groupId>
   <artifactId>micrometer-tracing-bridge-otel</artifactId>
  </dependency>

I suspect you're ending up with double instrumentation that may be causing issues. I don't know if the instrumentation in the third-party opentelemetry-spring-boot-starter backs off when the native instrumentation in Spring projects via Micrometer Observation is enabled. See this note in the Spring Boot docs. What's the reason you're using both?

[gsenaa]

We need both libraries because Micrometer only exports traces and metrics. However, OpenTelemetry handles the export of logs.

OpenTelemetry does not generate the same set of metrics as Micrometer by default. Additionally, the micrometer-tracing-bridge dependency is necessary because the correlationId is only added to the logs when it is included in the project.

We observed while debugging the application that the logs are sent immediately when calling any of the logger methods if the application is web-based. However, when the application is standalone, as in the mentioned case, the logs are sent only at the end of everything, at which point Context.getCurrent() returns null.

Lastly, this same configuration works correctly when the application is web-based, just by adding the spring-boot-starter-web dependency and creating a RestController that executes the same batch.

[jonatan-ivanov]

We need both libraries because Micrometer only exports traces and metrics.

I would say Spring Boot sets up exporting traces and metrics by default. Micrometer can emit all kinds of outputs through its Observation API (see ObservationHandler), the output can be literally anything (I recommend watching this talk). I think what you need is similar to ObservationTextPublisher. I would encourage you to create a @Bean of ObservationTextPublisher to see if it produces logs for you (it should), then try to implement your own ObservationHandler for your needs (you can copy parts of ObservationTextPublisher).

Another way of emitting this kind of information to logs is adding io.opentelemetry:opentelemetry-exporter-logging as a dependency and creating a @Bean of LoggingSpanExporter, Boot should auto-configure it for you and you should get the same output.

In both cases, you should be able to remove the starter.

OpenTelemetry does not generate the same set of metrics as Micrometer by default.

This is because OTel has its own set of naming conventions. Micrometer has support to change the naming convention through the ObservationConvention and we are planning to add support to the OTel naming conventions but currently the OTel naming conventions are not stable yet (this means that they can break you in prod). In the meantime you can implement your own ObservationConventions and inject them, instrumentation in Spring supports user-provided conventions so you can replace what you want to but we recommend using the defaults.

We observed while debugging the application that...

I'm not sure I understand this completely but could you please check if registering an ObservationHandler (or LoggingSpanExporter) to emit logs solves this issue?
I think OTel does not support Spring Batch that's why you see different behaviors in batch and web?

Lastly, this same configuration works correctly...

Same as the previous one.

[Renan-Di]

Hi @jonatan-ivanov, thanks for the attention.

As you pointed out, we are referencing micrometer-tracing-bridge-otel. This is because Micrometer provides more metrics than the OpenTelemetry (OTel) library. It is not only the naming convention that differs; Micrometer has a broad set of metrics (Tomcat, JVM, filesystem, etc.). So, in order to export the same set of metrics, we need to activate otel.instrumentation.micrometer.enabled, which requires this library.

As you can see in the provided pom.xml, we are already using io.opentelemetry:opentelemetry-exporter-logging to help debug this situation. What we have observed is that the traceId is being generated correctly for the batch logs, but when I log something inside a step, for example, the traceId shows only on the console. However, when the actual logs are sent to the collector (in this case, the logs are sent to system out via otel.logs.exporter=console), we only see the traceId on internal logs of the batching system, like when it updates the database tables. My log messages show no traceId.

Another difference is that when we start the batch from a RestController, we see that the logs are exported immediately after the actual log message. The same occurs with the spans, but in the standalone scenario, the spans are immediate, but the logs are exported only at the end.

Example logs generated by the code provided

[jonatan-ivanov]

As you pointed out, we are referencing micrometer-tracing-bridge-otel. This is because Micrometer provides more metrics than the OpenTelemetry (OTel) library.

I'm not sure what's the connection, the tracing bridge is for tracing data not for metrics.

Micrometer has a broad set of metrics (Tomcat, JVM, filesystem, etc.). So, in order to export the same set of metrics, we need to activate otel.instrumentation.micrometer.enabled, which requires this library.

You don't need to, Micrometer produces those metrics on its own, you can configure its OTLP registry if you want to use the OpenTelemetry Protocol.

As you can see in the provided pom.xml, we are already using io.opentelemetry:opentelemetry-exporter-logging to help debug this situation. What we have observed is that the traceId is being generated correctly for the batch logs, but when I log something inside a step, for example, the traceId shows only on the console. However, when the actual logs are sent to the collector (in this case, the logs are sent to system out via otel.logs.exporter=console), we only see the traceId on internal logs of the batching system, like when it updates the database tables. My log messages show no traceId.

I see it in your POM but please read the rest of the paragraph, have you tried removing opentelemetry-spring-boot-starter and using ObservationTextPublisher or configuring ObservationTextPublisher instead?

[github-actions]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.