From 7460a3c90e9dde8c23b8341cb13ad07207b0ae80 Mon Sep 17 00:00:00 2001 From: Andreas Hufler Date: Thu, 18 Apr 2024 08:13:11 +0200 Subject: [PATCH] improve scheduler logging to only show relevant passes --- .../application/CleanupAttachmentFiles.java | 41 ++++++++++++++-- .../lib/application/SendScheduledEmails.java | 48 ++++++++++++++++--- 2 files changed, 77 insertions(+), 12 deletions(-) diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/application/CleanupAttachmentFiles.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/application/CleanupAttachmentFiles.java index af3954d..7476eb6 100644 --- a/src/main/java/it/aboutbits/springboot/emailservice/lib/application/CleanupAttachmentFiles.java +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/application/CleanupAttachmentFiles.java @@ -3,13 +3,14 @@ import it.aboutbits.springboot.emailservice.lib.AttachmentCleanerCallback; import it.aboutbits.springboot.emailservice.lib.exception.AttachmentException; -import lombok.AllArgsConstructor; +import lombok.RequiredArgsConstructor; import lombok.extern.log4j.Log4j2; import org.springframework.scheduling.annotation.Scheduled; +import java.time.Duration; import java.util.List; -@AllArgsConstructor +@RequiredArgsConstructor @Log4j2 public class CleanupAttachmentFiles { private static final String JOB_DESCRIPTION = "Cleanup attachments of sent Emails."; @@ -18,9 +19,13 @@ public class CleanupAttachmentFiles { private final ManageEmail manageEmail; private final List callbacks; + private long lastInfoLogMillis = System.currentTimeMillis(); + private long silentRuns = 0; + private boolean firstRun = true; + @Scheduled(initialDelayString = "${aboutbits.emailservice.scheduling.interval:30000}", fixedDelayString = "${aboutbits.emailservice.scheduling.interval:30000}") void cleanupAttachments() { - log.info("Start: " + JOB_DESCRIPTION); + logStartOfPass(); var emailsToCleanup = queryEmail.readyToCleanup(); @@ -35,8 +40,7 @@ void cleanupAttachments() { } } - log.info("Finished: " + JOB_DESCRIPTION); - log.info("Cleaned: {}, Errors: {}", countCleaned, countError); + logEndOfPass(countCleaned, countError); for (var callback : callbacks) { callback.report(new AttachmentCleanerCallback.Report( @@ -47,5 +51,32 @@ void cleanupAttachments() { } } + private void logStartOfPass() { + if (firstRun) { + log.info(JOB_DESCRIPTION + " | Job enabled."); + firstRun = false; + } + log.debug(JOB_DESCRIPTION + " | Start"); + } + private void logEndOfPass(int countCleaned, int countError) { + log.debug(JOB_DESCRIPTION + " | Finished"); + if (countCleaned > 0 || countError > 0) { + lastInfoLogMillis = System.currentTimeMillis(); + silentRuns = 0; + log.info(JOB_DESCRIPTION + " | Cleaned: {}, Errors: {}", countCleaned, countError); + } else { + log.debug(JOB_DESCRIPTION + " | Cleaned: {}, Errors: {}", countCleaned, countError); + silentRuns++; + } + + if (lastInfoLogMillis + Duration.ofHours(1).toMillis() < System.currentTimeMillis() && !log.isDebugEnabled()) { + log.info( + JOB_DESCRIPTION + " | Ran silently {} times. Enable debug logging to see all hidden passes.", + silentRuns + ); + lastInfoLogMillis = System.currentTimeMillis(); + silentRuns = 0; + } + } } diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/application/SendScheduledEmails.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/application/SendScheduledEmails.java index 4f6a767..107512b 100644 --- a/src/main/java/it/aboutbits/springboot/emailservice/lib/application/SendScheduledEmails.java +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/application/SendScheduledEmails.java @@ -2,13 +2,14 @@ import it.aboutbits.springboot.emailservice.lib.EmailSchedulerCallback; -import lombok.AllArgsConstructor; +import lombok.RequiredArgsConstructor; import lombok.extern.log4j.Log4j2; import org.springframework.scheduling.annotation.Scheduled; +import java.time.Duration; import java.util.List; -@AllArgsConstructor +@RequiredArgsConstructor @Log4j2 public class SendScheduledEmails { private static final String JOB_DESCRIPTION = "Sending open and failed email notifications."; @@ -17,9 +18,13 @@ public class SendScheduledEmails { private final ManageEmail manageEmail; private final List callbacks; + private long lastInfoLogMillis = System.currentTimeMillis(); + private long silentRuns = 0; + private boolean firstRun = true; + @Scheduled(initialDelayString = "${aboutbits.emailservice.scheduling.interval:30000}", fixedDelayString = "${aboutbits.emailservice.scheduling.interval:30000}") void sendEmails() { - log.info("Start: " + JOB_DESCRIPTION); + logStartOfPass(); var emailsToSend = queryEmail.readyToSend(); @@ -31,13 +36,13 @@ void sendEmails() { case ERROR -> countError++; case SENT -> countSent++; default -> log.warn( - "Email job produced an invalid notification result state: {}.", - updatedEmail.getState().name()); + JOB_DESCRIPTION + " | Job produced an invalid notification result state: {}.", + updatedEmail.getState().name() + ); } } - log.info("Finished: " + JOB_DESCRIPTION); - log.info("Sent: {}, Errors: {}", countSent, countError); + logEndOfPass(countSent, countError); for (var callback : callbacks) { callback.report(new EmailSchedulerCallback.Report( @@ -47,4 +52,33 @@ void sendEmails() { )); } } + + private void logStartOfPass() { + if (firstRun) { + log.info(JOB_DESCRIPTION + " | Job enabled."); + firstRun = false; + } + log.debug(JOB_DESCRIPTION + " | Start"); + } + + private void logEndOfPass(int countSent, int countError) { + log.debug(JOB_DESCRIPTION + " | Finished"); + if (countSent > 0 || countError > 0) { + lastInfoLogMillis = System.currentTimeMillis(); + silentRuns = 0; + log.info(JOB_DESCRIPTION + " | Sent: {}, Errors: {}", countSent, countError); + } else { + log.debug(JOB_DESCRIPTION + " | Sent: {}, Errors: {}", countSent, countError); + silentRuns++; + } + + if (lastInfoLogMillis + Duration.ofHours(1).toMillis() < System.currentTimeMillis() && !log.isDebugEnabled()) { + log.info( + JOB_DESCRIPTION + " | Ran silently {} times. Enable debug logging to see all hidden passes.", + silentRuns + ); + lastInfoLogMillis = System.currentTimeMillis(); + silentRuns = 0; + } + } }