Skip to content

Minor logging issue when a step or job completes instantly #5037

@janossch

Description

@janossch

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);
    }

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions