Add example of logging inside scheduled operation

[mfvanek]

package io.github.mfvanek.spring.boot3.test.service;

import io.micrometer.core.instrument.Counter;
import io.micrometer.core.instrument.MeterRegistry;
import lombok.extern.slf4j.Slf4j;
import org.springframework.jdbc.core.JdbcTemplate;
import org.springframework.scheduling.annotation.EnableScheduling;
import org.springframework.scheduling.annotation.Scheduled;
import org.springframework.stereotype.Service;

import java.nio.charset.StandardCharsets;
import java.time.Instant;
import java.time.OffsetDateTime;
import java.util.List;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;
import javax.annotation.Nonnull;

@Slf4j
@Service
@EnableScheduling
public class MyVeryImportantScheduledOperation {

    private final JdbcTemplate jdbcTemplate;
    private final Counter doStaffStartsCounter;
    private final Counter doStaffNoDataCounter;
    private final AtomicLong lastProcessedId = new AtomicLong();

    public MyVeryImportantScheduledOperation(JdbcTemplate jdbcTemplate, MeterRegistry meterRegistry) {
        this.jdbcTemplate = jdbcTemplate;
        this.doStaffStartsCounter = Counter.builder("do-staff-starts")
            .description("Indicates count of starts of scheduled doStaff method")
            .register(meterRegistry);
        this.doStaffNoDataCounter = Counter.builder("do-staff-no-data")
            .description("Indicates count of runs of scheduled doStaff method when no data for processing found")
            .register(meterRegistry);
    }

    @Scheduled(fixedDelay = 10L, timeUnit = TimeUnit.SECONDS)
    public void doStaff() {
        final long startTime = System.nanoTime();
        // log.info("doStaff is started"); // bad
        log.debug("doStaff is started"); // good
        doStaffStartsCounter.increment();
        try {
            final List<DataForProcess> data = getDataForProcessing();
            if (!data.isEmpty()) {
                log.debug("Found {} rows to process", data.size());
                if (log.isTraceEnabled()) {
                    final int limit = Math.min(20, data.size());
                    log.trace("First {} rows to process {}", limit, data.stream().limit(limit).toList());
                }
                doSomethingUseful(data);
                lastProcessedId.set(data.get(data.size() - 1).id());
            } else {
                log.debug("Nothing to do at this time");
                doStaffNoDataCounter.increment();
            }
        } finally {
            final long elapsedMillis = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTime);
            // log.info("doStaff is finished. Elapsed {}ms", elapsedMillis); // bad
            log.debug("doStaff is finished. Elapsed {}ms", elapsedMillis); // good
        }
    }

    private void doSomethingUseful(@Nonnull List<DataForProcess> data) {
        final long totalSizeOfBodies = data.stream()
            .mapToLong(d -> d.body.getBytes(StandardCharsets.UTF_8).length)
            .sum();
        log.info("Successfully processed {} bytes", totalSizeOfBodies);
    }

    private List<DataForProcess> getDataForProcessing() {
        final long minId = lastProcessedId.get();
        return jdbcTemplate.query("select * from otel_demo.storage where id > ?::bigint order by id", (rs, rowNum) -> {
            long id = rs.getLong("id");
            OffsetDateTime createdAt = rs.getObject("created_at", OffsetDateTime.class);
            String body = rs.getString("message");
            return new DataForProcess(id, createdAt.toInstant(), body);
        }, minId);
    }

    record DataForProcess (long id, Instant createdAt, String body) {}
}