Bug description
We found such below log lines in our production environment, which misses the duration information at the end of the line.
... Job: [FlowJob: [name=...]] completed with the following parameters: [...] and the following status: [FAILED] in
Digging into a little bit of the code, I found that when a job is finished
|
if (logger.isInfoEnabled()) { |
|
Duration jobExecutionDuration = BatchMetrics.calculateDuration(jobExecution.getStartTime(), |
|
jobExecution.getEndTime()); |
|
logger.info("Job: [" + job + "] completed with the following parameters: [" + jobParameters |
|
+ "] and the following status: [" + jobExecution.getStatus() + "]" |
|
+ (jobExecutionDuration == null ? "" |
|
: " in " + BatchMetrics.formatDuration(jobExecutionDuration))); |
|
} |
an info level log entry gets emitted by the framework. However if the start and the end date is essentially the same, the BatchMetrics.formatDuration method returns an empty String because of the duration.isZero() condition.
|
public static String formatDuration(@Nullable Duration duration) { |
|
if (duration == null || duration.isZero() || duration.isNegative()) { |
|
return ""; |
|
} |
Environment
Java21 (temurin)
Spring Batch 5.2.2
File based H2 DB is used
Steps to reproduce
Start a lot of batch jobs which completes fast.
Expected behavior
Honestly I don't know, but at least a 0ms would be better than nothing. Something like this:
Job: [FlowJob: [name=...]] completed with the following parameters: [...] and the following status: [FAILED] in 0ms
Minimal Complete Reproducible example
The below test fails for 5.2.2:
@Test
void testFormatDurationWhenCalculationReturnsZeroDuration() {
var startDate = LocalDateTime.now();
// create end date from the string representation of start date to ensure both dates are equal, but different references.
// In reality there is another LocalDateTime.now() call, but that could return a different time, which could cause flaky tests.
var endDate = LocalDateTime.parse(startDate.toString());
var calculateDuration = BatchMetrics.calculateDuration(startDate, endDate);
Assertions.assertNotNull(calculateDuration, "Calculated duration is a null reference!");
var formattedDurationString = BatchMetrics.formatDuration(calculateDuration);
Assertions.assertTrue(StringUtils.hasText(formattedDurationString), formattedDurationString);
}
Bug description
We found such below log lines in our production environment, which misses the duration information at the end of the line.
...
Job: [FlowJob: [name=...]] completed with the following parameters: [...] and the following status: [FAILED] inDigging into a little bit of the code, I found that when a job is finished
spring-batch/spring-batch-core/src/main/java/org/springframework/batch/core/launch/support/TaskExecutorJobLauncher.java
Lines 221 to 228 in 11ec7f1
an info level log entry gets emitted by the framework. However if the start and the end date is essentially the same, the
BatchMetrics.formatDurationmethod returns an emptyStringbecause of theduration.isZero()condition.spring-batch/spring-batch-core/src/main/java/org/springframework/batch/core/observability/BatchMetrics.java
Lines 69 to 72 in 11ec7f1
Environment
Java21 (temurin)
Spring Batch 5.2.2
File based H2 DB is used
Steps to reproduce
Start a lot of batch jobs which completes fast.
Expected behavior
Honestly I don't know, but at least a
0mswould be better than nothing. Something like this:Job: [FlowJob: [name=...]] completed with the following parameters: [...] and the following status: [FAILED] in 0msMinimal Complete Reproducible example
The below test fails for 5.2.2: