diff --git a/pom.xml b/pom.xml index 704ea73..d6e8169 100644 --- a/pom.xml +++ b/pom.xml @@ -49,6 +49,18 @@ lombok true + + + io.micrometer + micrometer-core + true + + + io.micrometer + micrometer-registry-prometheus + test + org.springframework.boot spring-boot-starter-test diff --git a/readme.md b/readme.md index f634ff9..5b4323a 100644 --- a/readme.md +++ b/readme.md @@ -56,6 +56,68 @@ To read email datasets from the database use this class: [QueryEmail.java](src%2 If you want to receive a report after each run of the scheduler, create a Bean implementing [EmailSchedulerCallback.java](src%2Fmain%2Fjava%2Fit%2Faboutbits%2Fspringboot%2Femailservice%2Flib%2FEmailSchedulerCallback.java) +### Metrics + +The library records Micrometer metrics for both schedulers. Micrometer is an optional dependency: if the +application provides a `MeterRegistry` the metrics are recorded, otherwise the library falls back to a no-op +and nothing changes. Nothing has to be enabled in this library. + +To scrape them, the application needs `spring-boot-starter-actuator` and `micrometer-registry-prometheus`, +plus the Prometheus endpoint: + +```yaml +management: + endpoints: + access: + default: none + web: + exposure: + include: + - health + - prometheus + endpoint: + health: + access: read-only + prometheus: + access: read-only +``` + +The following series are exposed: + +| Series | Type | Labels | Description | +|-------------------------------------------------|---------|--------------------------------------------------------------------------------|-------------------------------------------------------------------------------------------------| +| `app_email_send_duration_seconds` | timer | `mode`: `scheduled`, `direct`
`outcome`: `sent`, `retry`, `error` | One observation per send attempt. `retry` is an attempt that failed but is scheduled for another one, `error` an email that has given up. | +| `app_email_cleanup_duration_seconds` | timer | `outcome`: `cleaned`, `error` | One observation per attachment cleanup attempt. | +| `app_email_pass_duration_seconds` | timer | `job`: `send`, `cleanup`
`status`: `success`, `failed` | One observation per scheduler pass. `failed` means the pass itself broke, e.g. the database was unreachable. | +| `app_email_last_run_timestamp_seconds` | gauge | `job`: `send`, `cleanup` | When the scheduler last fired. Stalls if the scheduler is dead or the pod is down. | +| `app_email_last_success_timestamp_seconds` | gauge | `job`: `send`, `cleanup` | When a pass last got through. Stalls while passes keep failing. | +| `app_email_queue` | gauge | `state`: `pending`, `sending` | Emails per state, read after each send pass. The terminal states `SENT` and `ERROR` are left out: they only ever grow. Errors are counted by `app_email_send_duration_seconds_count{outcome="error"}`. | +| `app_email_queue_oldest_due_age_seconds` | gauge | `state`: `pending` | How long the oldest email that is already due has been waiting. `0` if nothing is due. | + +Two things to keep in mind when querying them: + +- **Aggregate the gauges with `max`, never `sum`.** The queue gauges are read from the database, so every pod + reports the same numbers - summing them multiplies the backlog by the number of pods. +- The queue gauges are only written by the send scheduler. With + `aboutbits.emailservice.scheduling.enabled=false` they are never registered, and the series are absent + rather than zero. + +Both timestamp gauges are registered on first use, so a pod that has not completed a pass since starting has +no series at all. This is deliberate: an alert reads an absent series the same way it reads a `NaN` starting +value, while a `0` starting value would look like decades of staleness after every deploy. + +The dashboards and alerts themselves belong to the consuming application, since they depend on how it is +deployed. As a starting point, a scheduler that has stopped firing and a backlog that is not being kept up +with read as: + +```promql +time() - max by (job) (app_email_last_run_timestamp_seconds) > 300 +max(app_email_queue_oldest_due_age_seconds) > 600 +``` + +If the application replaces the metrics sink with its own `EmailMetrics` bean, the library's one steps back; +whatever the application provides is called fail-safe, so a failing sink can never break a send. + ### Configuration To enable this service just add `@EnableEmailService` to your main class. You must also enable `@EnableScheduling` to allow the email queue to be processed. diff --git a/src/main/java/it/aboutbits/springboot/emailservice/EmailServiceConfiguration.java b/src/main/java/it/aboutbits/springboot/emailservice/EmailServiceConfiguration.java index 0c4bc36..eba5e8d 100644 --- a/src/main/java/it/aboutbits/springboot/emailservice/EmailServiceConfiguration.java +++ b/src/main/java/it/aboutbits/springboot/emailservice/EmailServiceConfiguration.java @@ -2,6 +2,7 @@ import it.aboutbits.springboot.emailservice.lib.AttachmentCleanerCallback; import it.aboutbits.springboot.emailservice.lib.AttachmentDataSource; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; import it.aboutbits.springboot.emailservice.lib.EmailSchedulerCallback; import it.aboutbits.springboot.emailservice.lib.application.CleanupAttachmentFiles; import it.aboutbits.springboot.emailservice.lib.application.EmailAttachmentMapper; @@ -14,6 +15,7 @@ import it.aboutbits.springboot.emailservice.lib.application.SendScheduledEmails; import it.aboutbits.springboot.emailservice.lib.application.UnavailableAttachmentDataSource; import it.aboutbits.springboot.emailservice.lib.jpa.EmailRepository; +import it.aboutbits.springboot.emailservice.lib.metrics.FailSafeEmailMetrics; import org.jspecify.annotations.NullMarked; import org.springframework.beans.factory.annotation.Value; import org.springframework.boot.autoconfigure.AutoConfigurationPackage; @@ -27,6 +29,10 @@ import java.time.Duration; import java.util.List; +/* + * Imported through EmailServiceImportSelector, never directly: see there for why the import is deferred + * and where the EmailMetrics bean comes from. + */ @AutoConfigurationPackage @NullMarked public class EmailServiceConfiguration { @@ -52,11 +58,13 @@ public QueryEmail queryEmail(EmailRepository emailRepository, EmailMapper emailM } @Bean + @SuppressWarnings("checkstyle:ParameterNumber") public ManageEmail manageEmail( EmailRepository emailRepository, JavaMailSender javaMailSender, AttachmentDataSource attachmentDataSource, EmailMapper emailMapper, + EmailMetrics emailMetrics, @Value("${aboutbits.emailservice.scheduling.max-attempts:3}") int maxAttempts, @Value("${aboutbits.emailservice.scheduling.interval:30000}") long schedulerIntervalMillis, PlatformTransactionManager transactionManager @@ -66,6 +74,7 @@ public ManageEmail manageEmail( javaMailSender, attachmentDataSource, emailMapper, + failSafe(emailMetrics), maxAttempts, Duration.ofMillis(schedulerIntervalMillis), transactionManager @@ -78,9 +87,16 @@ public SendScheduledEmails sendScheduledEmails( QueryEmail queryEmail, ManageEmail manageEmail, List callbacks, + EmailMetrics emailMetrics, @Value("${aboutbits.emailservice.scheduling.stuck-sending-recovery-threshold:PT30M}") Duration stuckSendingRecoveryThreshold ) { - return new SendScheduledEmails(queryEmail, manageEmail, callbacks, stuckSendingRecoveryThreshold); + return new SendScheduledEmails( + queryEmail, + manageEmail, + callbacks, + failSafe(emailMetrics), + stuckSendingRecoveryThreshold + ); } @Bean @@ -89,9 +105,16 @@ public CleanupAttachmentFiles cleanupAttachments( QueryEmail queryEmail, ManageEmail manageEmail, List callbacks, + EmailMetrics emailMetrics, @Value("${aboutbits.emailservice.scheduling.stuck-cleanup-recovery-threshold:PT30M}") Duration stuckCleanupRecoveryThreshold ) { - return new CleanupAttachmentFiles(queryEmail, manageEmail, callbacks, stuckCleanupRecoveryThreshold); + return new CleanupAttachmentFiles( + queryEmail, + manageEmail, + callbacks, + failSafe(emailMetrics), + stuckCleanupRecoveryThreshold + ); } @Bean @@ -99,4 +122,11 @@ public CleanupAttachmentFiles cleanupAttachments( public AttachmentDataSource attachmentDataSource() { return new UnavailableAttachmentDataSource(); } + + // The EmailMetrics bean itself stays whatever the application sees - the library's own or a + // replacement - but nothing inside the library talks to it unguarded: an email that went out over + // SMTP has to be persisted as SENT no matter what a metrics backend does. + private static EmailMetrics failSafe(EmailMetrics emailMetrics) { + return new FailSafeEmailMetrics(emailMetrics); + } } diff --git a/src/main/java/it/aboutbits/springboot/emailservice/EmailServiceImportSelector.java b/src/main/java/it/aboutbits/springboot/emailservice/EmailServiceImportSelector.java new file mode 100644 index 0000000..d397571 --- /dev/null +++ b/src/main/java/it/aboutbits/springboot/emailservice/EmailServiceImportSelector.java @@ -0,0 +1,38 @@ +package it.aboutbits.springboot.emailservice; + +import org.jspecify.annotations.NullMarked; +import org.springframework.context.annotation.DeferredImportSelector; +import org.springframework.core.Ordered; +import org.springframework.core.type.AnnotationMetadata; + +/* + * Registers the library the way an auto-configuration is registered: only after every configuration + * class of the application has been parsed. That is what lets the @ConditionalOnMissingBean fallbacks + * (AttachmentDataSource, EmailMetrics) see a replacement the application declares, even one declared + * in the very class that carries @EnableEmailService - a plain @Import is processed before the + * importing class, so such a replacement would only be found after the fallback has already been + * registered. + * + * The metrics configurations are listed here instead of being nested in EmailServiceConfiguration: + * Spring only picks up nested configuration classes below a class annotated @Configuration, and + * EmailServiceConfiguration is not one. + */ +@NullMarked +public class EmailServiceImportSelector implements DeferredImportSelector, Ordered { + @Override + public String[] selectImports(AnnotationMetadata importingClassMetadata) { + return new String[]{ + EmailServiceConfiguration.class.getName(), + MicrometerEmailMetricsConfiguration.class.getName(), + NoOpEmailMetricsConfiguration.class.getName() + }; + } + + // Spring Boot's auto-configuration runs at LOWEST_PRECEDENCE - 1 and expects the + // @AutoConfigurationPackage of EmailServiceConfiguration to be registered by then, since that is + // where it finds the entities and repositories of this library. + @Override + public int getOrder() { + return Ordered.LOWEST_PRECEDENCE - 2; + } +} diff --git a/src/main/java/it/aboutbits/springboot/emailservice/EnableEmailService.java b/src/main/java/it/aboutbits/springboot/emailservice/EnableEmailService.java index eb9f9bc..db8d157 100644 --- a/src/main/java/it/aboutbits/springboot/emailservice/EnableEmailService.java +++ b/src/main/java/it/aboutbits/springboot/emailservice/EnableEmailService.java @@ -9,6 +9,6 @@ @Target({ElementType.TYPE}) @Retention(RetentionPolicy.RUNTIME) -@Import({EmailServiceConfiguration.class}) +@Import({EmailServiceImportSelector.class}) public @interface EnableEmailService { } diff --git a/src/main/java/it/aboutbits/springboot/emailservice/MicrometerEmailMetricsConfiguration.java b/src/main/java/it/aboutbits/springboot/emailservice/MicrometerEmailMetricsConfiguration.java new file mode 100644 index 0000000..c0e2228 --- /dev/null +++ b/src/main/java/it/aboutbits/springboot/emailservice/MicrometerEmailMetricsConfiguration.java @@ -0,0 +1,38 @@ +package it.aboutbits.springboot.emailservice; + +import io.micrometer.core.instrument.MeterRegistry; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import it.aboutbits.springboot.emailservice.lib.metrics.MicrometerEmailMetrics; +import it.aboutbits.springboot.emailservice.lib.metrics.NoOpEmailMetrics; +import org.jspecify.annotations.NullMarked; +import org.springframework.beans.factory.ObjectProvider; +import org.springframework.boot.autoconfigure.condition.ConditionalOnClass; +import org.springframework.boot.autoconfigure.condition.ConditionalOnMissingBean; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; + +/* + * Micrometer is an optional dependency, so this configuration and NoOpEmailMetricsConfiguration are + * guarded by mutually exclusive class conditions rather than by bean ordering: exactly one of them ever + * applies, and this one, the only one referencing MeterRegistry, is only loaded once that class exists. + */ +@Configuration(proxyBeanMethods = false) +@ConditionalOnClass(name = "io.micrometer.core.instrument.MeterRegistry") +@NullMarked +class MicrometerEmailMetricsConfiguration { + // Micrometer on the classpath without a registry bean - micrometer-core without actuator - still + // leaves nothing to record into, hence the fallback rather than a required dependency. The same goes + // for several registries without a primary one: a library that only records "if a registry happens + // to be there" must not fail the whole context over an ambiguity it cannot resolve. + @Bean + @ConditionalOnMissingBean(EmailMetrics.class) + EmailMetrics emailMetrics(ObjectProvider meterRegistry) { + var registry = meterRegistry.getIfUnique(); + + if (registry == null) { + return new NoOpEmailMetrics(); + } + + return new MicrometerEmailMetrics(registry); + } +} diff --git a/src/main/java/it/aboutbits/springboot/emailservice/NoOpEmailMetricsConfiguration.java b/src/main/java/it/aboutbits/springboot/emailservice/NoOpEmailMetricsConfiguration.java new file mode 100644 index 0000000..9de0dfd --- /dev/null +++ b/src/main/java/it/aboutbits/springboot/emailservice/NoOpEmailMetricsConfiguration.java @@ -0,0 +1,21 @@ +package it.aboutbits.springboot.emailservice; + +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import it.aboutbits.springboot.emailservice.lib.metrics.NoOpEmailMetrics; +import org.jspecify.annotations.NullMarked; +import org.springframework.boot.autoconfigure.condition.ConditionalOnMissingBean; +import org.springframework.boot.autoconfigure.condition.ConditionalOnMissingClass; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; + +// Counterpart of MicrometerEmailMetricsConfiguration for applications without Micrometer on the classpath. +@Configuration(proxyBeanMethods = false) +@ConditionalOnMissingClass("io.micrometer.core.instrument.MeterRegistry") +@NullMarked +class NoOpEmailMetricsConfiguration { + @Bean + @ConditionalOnMissingBean(EmailMetrics.class) + EmailMetrics emailMetrics() { + return new NoOpEmailMetrics(); + } +} diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/EmailMetrics.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/EmailMetrics.java new file mode 100644 index 0000000..1627f43 --- /dev/null +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/EmailMetrics.java @@ -0,0 +1,86 @@ +package it.aboutbits.springboot.emailservice.lib; + +import org.jspecify.annotations.NullMarked; +import org.jspecify.annotations.Nullable; + +import java.time.Duration; +import java.util.function.Supplier; + +/* + * Sink for everything the schedulers learn while running. Implemented by the library against + * Micrometer when the consuming application provides a MeterRegistry, and by a no-op otherwise, + * so that neither the schedulers nor their callers need to know whether metrics are enabled. + */ +@NullMarked +public interface EmailMetrics { + void sendAttempt(SendMode mode, SendOutcome outcome, Duration duration); + + void cleanupAttempt(CleanupOutcome outcome, Duration duration); + + void pass(Job job, PassStatus status, Duration duration); + + // Takes a supplier because the snapshot costs database queries: a sink that has no backend to + // record into is expected to never read it. + void queue(Supplier snapshot); + + /* + * Runs a whole scheduler pass and records it, so that a database outage - the one failure the pass + * itself cannot report per email - still shows up as a failed pass before it propagates to the + * scheduler. Recorded in a finally block on purpose: an Error is a fired pass as much as an + * exception is, and last_run is defined as the time the scheduler last fired. + */ + default void timedPass(Job job, Runnable pass) { + var startNanos = System.nanoTime(); + var status = PassStatus.FAILED; + + try { + pass.run(); + status = PassStatus.SUCCESS; + } finally { + pass(job, status, Duration.ofNanos(System.nanoTime() - startNanos)); + } + } + + enum SendMode { + SCHEDULED, + DIRECT + } + + enum SendOutcome { + SENT, + // The attempt failed but the email is scheduled for another one, so it is not an error yet. + RETRY, + ERROR + } + + enum CleanupOutcome { + CLEANED, + ERROR + } + + enum Job { + SEND, + CLEANUP + } + + enum PassStatus { + SUCCESS, + FAILED + } + + /* + * State of the queue as a whole, read once per scheduler pass. Since every pod reads the same + * rows, the resulting series are identical across pods and must be aggregated with max(), not sum(). + * + * Only the two states an email passes through are counted. SENT and ERROR are terminal, so their + * counts only ever grow and say nothing about how the queue is doing right now; how many emails + * end in an error is already answered by the outcome tag of the send attempts. + */ + record QueueSnapshot( + long pending, + long sending, + // How long the oldest email that is already due has been waiting; null if nothing is due. + @Nullable Duration oldestDueAge + ) { + } +} 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 95cbf16..2c84bd6 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 @@ -2,6 +2,7 @@ import it.aboutbits.springboot.emailservice.lib.AttachmentCleanerCallback; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; import lombok.RequiredArgsConstructor; import lombok.extern.log4j.Log4j2; import org.jspecify.annotations.NullMarked; @@ -20,6 +21,7 @@ public class CleanupAttachmentFiles { private final QueryEmail queryEmail; private final ManageEmail manageEmail; private final List callbacks; + private final EmailMetrics emailMetrics; private final Duration stuckCleanupRecoveryThreshold; private long lastInfoLogMillis = System.currentTimeMillis(); @@ -28,6 +30,10 @@ public class CleanupAttachmentFiles { @Scheduled(initialDelayString = "${aboutbits.emailservice.scheduling.interval:30000}", fixedDelayString = "${aboutbits.emailservice.scheduling.interval:30000}") void cleanupAttachments() { + emailMetrics.timedPass(EmailMetrics.Job.CLEANUP, this::runPass); + } + + private void runPass() { logStartOfPass(); var staleCleanupBefore = OffsetDateTime.now().minus(stuckCleanupRecoveryThreshold); @@ -45,12 +51,19 @@ void cleanupAttachments() { } countClaimed++; + var startNanos = System.nanoTime(); + EmailMetrics.CleanupOutcome outcome; + try { manageEmail.completeClaimedCleanup(claimed.get()); countCleaned++; + outcome = EmailMetrics.CleanupOutcome.CLEANED; } catch (Exception _) { countError++; + outcome = EmailMetrics.CleanupOutcome.ERROR; } + + emailMetrics.cleanupAttempt(outcome, Duration.ofNanos(System.nanoTime() - startNanos)); } logEndOfPass(countCleaned, countError); diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/application/ManageEmail.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/application/ManageEmail.java index 12cc6ce..6c7f14a 100644 --- a/src/main/java/it/aboutbits/springboot/emailservice/lib/application/ManageEmail.java +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/application/ManageEmail.java @@ -3,6 +3,7 @@ import it.aboutbits.springboot.emailservice.lib.AttachmentDataSource; import it.aboutbits.springboot.emailservice.lib.EmailDto; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; import it.aboutbits.springboot.emailservice.lib.EmailState; import it.aboutbits.springboot.emailservice.lib.exception.AttachmentException; import it.aboutbits.springboot.emailservice.lib.exception.EmailException; @@ -41,15 +42,18 @@ public class ManageEmail { private final JavaMailSender mailSender; private final AttachmentDataSource attachmentDataSource; private final EmailMapper emailMapper; + private final EmailMetrics emailMetrics; private final int maxAttempts; private final Duration schedulerInterval; private final TransactionTemplate transactionTemplate; + @SuppressWarnings("checkstyle:ParameterNumber") public ManageEmail( EmailRepository emailRepository, JavaMailSender mailSender, AttachmentDataSource attachmentDataSource, EmailMapper emailMapper, + EmailMetrics emailMetrics, int maxAttempts, Duration schedulerInterval, PlatformTransactionManager transactionManager @@ -58,6 +62,7 @@ public ManageEmail( this.mailSender = mailSender; this.attachmentDataSource = attachmentDataSource; this.emailMapper = emailMapper; + this.emailMetrics = emailMetrics; this.maxAttempts = maxAttempts; this.schedulerInterval = schedulerInterval; // Persist the final email state in its own, independent transaction to never make it roll back @@ -89,17 +94,32 @@ public EmailDto sendOrFail(@Valid EmailParameter parameter) throws EmailExceptio email.setExecutionStartTime(OffsetDateTime.now()); email.incrementAttempts(); + var startNanos = System.nanoTime(); + EmailMetrics.SendOutcome outcome; + try { sendMail(email); email.setState(EmailState.SENT); email.setExecutionEndTime(OffsetDateTime.now()); + outcome = EmailMetrics.SendOutcome.SENT; } catch (MessagingException | AttachmentException | IOException | RuntimeException e) { log.error("Failed to send email: {}", email.getId(), e); email.setState(EmailState.ERROR); email.setExecutionEndTime(OffsetDateTime.now()); email.setErrorMessage(e.getMessage()); + outcome = EmailMetrics.SendOutcome.ERROR; } + // Recorded before persisting: the attempt against the SMTP server happened either way, and a + // failure to write down its result is reported on the scheduler pass, not on the attempt. Safe + // to do here only because the sink is fail-safe (see FailSafeEmailMetrics): nothing between the + // send and the save may throw, or a delivered email stays unpersisted and is sent again. + emailMetrics.sendAttempt( + EmailMetrics.SendMode.DIRECT, + outcome, + Duration.ofNanos(System.nanoTime() - startNanos) + ); + var savedEmail = transactionTemplate.execute(_ -> emailRepository.save(email)); if (savedEmail.getState() == EmailState.ERROR) { @@ -119,17 +139,22 @@ Optional tryClaimForSend(long id, OffsetDateTime staleSendingBefore) { // Actually try sending the claimed email Email completeClaimedSend(Email email) { + var startNanos = System.nanoTime(); + EmailMetrics.SendOutcome outcome; + try { sendMail(email); email.setState(EmailState.SENT); email.setExecutionEndTime(OffsetDateTime.now()); email.setErrorMessage(null); + outcome = EmailMetrics.SendOutcome.SENT; } catch (Exception e) { email.setExecutionEndTime(OffsetDateTime.now()); email.setErrorMessage(e.getMessage()); if (email.getAttempts() >= maxAttempts) { log.error("Failed to send email: {}", email.getId(), e); email.setState(EmailState.ERROR); + outcome = EmailMetrics.SendOutcome.ERROR; } else { log.warn("Failed to send email: {}; Will be tried again", email.getId(), e); email.setState(EmailState.PENDING); @@ -137,8 +162,20 @@ Email completeClaimedSend(Email email) { OffsetDateTime.now() .plus(schedulerInterval.multipliedBy((long) Math.pow(2, email.getAttempts()))) ); + outcome = EmailMetrics.SendOutcome.RETRY; } } + + // Recorded before persisting: the attempt against the SMTP server happened either way, and a + // failure to write down its result is reported on the scheduler pass, not on the attempt. Safe + // to do here only because the sink is fail-safe (see FailSafeEmailMetrics): nothing between the + // send and the save may throw, or a delivered email stays unpersisted and is sent again. + emailMetrics.sendAttempt( + EmailMetrics.SendMode.SCHEDULED, + outcome, + Duration.ofNanos(System.nanoTime() - startNanos) + ); + return transactionTemplate.execute(_ -> emailRepository.save(email)); } diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/application/QueryEmail.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/application/QueryEmail.java index dad15c7..17b583e 100644 --- a/src/main/java/it/aboutbits/springboot/emailservice/lib/application/QueryEmail.java +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/application/QueryEmail.java @@ -2,6 +2,7 @@ import it.aboutbits.springboot.emailservice.lib.EmailDto; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; import it.aboutbits.springboot.emailservice.lib.EmailState; import it.aboutbits.springboot.emailservice.lib.jpa.EmailRepository; import lombok.RequiredArgsConstructor; @@ -10,12 +11,15 @@ import org.springframework.data.domain.PageRequest; import org.springframework.data.domain.Sort; +import java.time.Duration; import java.time.OffsetDateTime; import java.util.Collection; import java.util.Collections; import java.util.List; import java.util.Optional; +import static java.util.stream.Collectors.toMap; + @RequiredArgsConstructor @NullMarked public class QueryEmail { @@ -50,6 +54,22 @@ List candidateIdsToCleanup(OffsetDateTime staleCleanupBefore) { return emailRepository.findCandidateIdsToCleanup(staleCleanupBefore); } + // Only PENDING and SENDING are counted; see EmailMetrics.QueueSnapshot for why the terminal states are not. + EmailMetrics.QueueSnapshot queueSnapshot() { + var now = OffsetDateTime.now(); + + var counts = emailRepository.countByStateIn(List.of(EmailState.PENDING, EmailState.SENDING)).stream() + .collect(toMap(EmailRepository.StateCount::getState, EmailRepository.StateCount::getTotal)); + + return new EmailMetrics.QueueSnapshot( + counts.getOrDefault(EmailState.PENDING, 0L), + counts.getOrDefault(EmailState.SENDING, 0L), + emailRepository.findOldestDueScheduledAt(now) + .map(scheduledAt -> Duration.between(scheduledAt, now)) + .orElse(null) + ); + } + public Optional byId(long id) { return emailRepository.findById(id).map(emailMapper::toDto); } 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 4926336..a1250fd 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 @@ -1,6 +1,7 @@ package it.aboutbits.springboot.emailservice.lib.application; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; import it.aboutbits.springboot.emailservice.lib.EmailSchedulerCallback; import it.aboutbits.springboot.emailservice.lib.model.Email; import lombok.extern.log4j.Log4j2; @@ -20,6 +21,7 @@ public class SendScheduledEmails { private final QueryEmail queryEmail; private final ManageEmail manageEmail; private final List callbacks; + private final EmailMetrics emailMetrics; private final Duration stuckSendingRecoveryThreshold; private long lastInfoLogMillis = System.currentTimeMillis(); @@ -30,16 +32,22 @@ public SendScheduledEmails( QueryEmail queryEmail, ManageEmail manageEmail, List callbacks, + EmailMetrics emailMetrics, Duration stuckSendingRecoveryThreshold ) { this.queryEmail = queryEmail; this.manageEmail = manageEmail; this.callbacks = callbacks; + this.emailMetrics = emailMetrics; this.stuckSendingRecoveryThreshold = stuckSendingRecoveryThreshold; } @Scheduled(initialDelayString = "${aboutbits.emailservice.scheduling.interval:30000}", fixedDelayString = "${aboutbits.emailservice.scheduling.interval:30000}") void sendEmails() { + emailMetrics.timedPass(EmailMetrics.Job.SEND, this::runPass); + } + + private void runPass() { logStartOfPass(); var staleSendingBefore = OffsetDateTime.now().minus(stuckSendingRecoveryThreshold); @@ -94,6 +102,11 @@ void sendEmails() { countError )); } + + // Read last: after draining, so that in healthy operation the backlog sits at zero and only + // grows when the queue is genuinely not being kept up with, and after the callbacks, so that a + // failing read cannot cost them their report of a pass whose sends all went through. + emailMetrics.queue(queryEmail::queueSnapshot); } private void logStartOfPass() { diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/jpa/EmailRepository.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/jpa/EmailRepository.java index f77d0d1..39f3dcc 100644 --- a/src/main/java/it/aboutbits/springboot/emailservice/lib/jpa/EmailRepository.java +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/jpa/EmailRepository.java @@ -84,6 +84,24 @@ int claimForSend( @Param("staleSendingBefore") OffsetDateTime staleSendingBefore ); + // Backlog readings for the metrics, one round trip for all states asked for. States without a + // single row are simply absent from the result. + @Query(""" + select e.state as state, count(e) as total from Email e + where e.state in :states + group by e.state + """) + List countByStateIn(@Param("states") Collection states); + + // How far behind the queue is: the schedule time of the oldest email that is already due. + // Empty if nothing is waiting. + @Query(""" + select min(e.scheduledAt) from Email e + where e.state = it.aboutbits.springboot.emailservice.lib.EmailState.PENDING + and e.scheduledAt < :now + """) + Optional findOldestDueScheduledAt(@Param("now") OffsetDateTime now); + // Plain read, no locking -> two pods may see overlapping candidate sets. // The atomic UPDATE in claimForCleanup arbitrates the actual claim. // Includes rows whose cleanup was abandoned by a crashed pod (past the stale threshold). @@ -118,4 +136,10 @@ int claimForCleanup( @Param("now") OffsetDateTime now, @Param("staleCleanupBefore") OffsetDateTime staleCleanupBefore ); + + interface StateCount { + EmailState getState(); + + long getTotal(); + } } diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/FailSafeEmailMetrics.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/FailSafeEmailMetrics.java new file mode 100644 index 0000000..867cfec --- /dev/null +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/FailSafeEmailMetrics.java @@ -0,0 +1,53 @@ +package it.aboutbits.springboot.emailservice.lib.metrics; + +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import lombok.RequiredArgsConstructor; +import lombok.extern.slf4j.Slf4j; +import org.jspecify.annotations.NullMarked; + +import java.time.Duration; +import java.util.function.Supplier; + +/* + * Keeps a failing sink from failing the work it observes. A registry configured to throw on + * registration failures, a meter filter rejecting a tag, or a bug in an application-provided + * EmailMetrics must never turn into an email that was delivered but not persisted as SENT, or into a + * scheduler pass that is reported as failed although every send in it went through. Recording is + * best-effort, so a failure is logged and the reading dropped. + */ +@RequiredArgsConstructor +@Slf4j +@NullMarked +public class FailSafeEmailMetrics implements EmailMetrics { + private final EmailMetrics delegate; + + @Override + public void sendAttempt(SendMode mode, SendOutcome outcome, Duration duration) { + record("send attempt", () -> delegate.sendAttempt(mode, outcome, duration)); + } + + @Override + public void cleanupAttempt(CleanupOutcome outcome, Duration duration) { + record("cleanup attempt", () -> delegate.cleanupAttempt(outcome, duration)); + } + + @Override + public void pass(Job job, PassStatus status, Duration duration) { + record("pass", () -> delegate.pass(job, status, duration)); + } + + // Also covers the snapshot supplier: reading the queue is only ever done for the metrics, so a + // database error while reading it is a lost reading, not a failed pass. + @Override + public void queue(Supplier snapshot) { + record("queue snapshot", () -> delegate.queue(snapshot)); + } + + private static void record(String reading, Runnable recording) { + try { + recording.run(); + } catch (RuntimeException e) { + log.warn("Recording the {} metric failed; the reading is dropped.", reading, e); + } + } +} diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/MicrometerEmailMetrics.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/MicrometerEmailMetrics.java new file mode 100644 index 0000000..292dfd2 --- /dev/null +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/MicrometerEmailMetrics.java @@ -0,0 +1,109 @@ +package it.aboutbits.springboot.emailservice.lib.metrics; + +import io.micrometer.core.instrument.Gauge; +import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.Tags; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import lombok.RequiredArgsConstructor; +import org.jspecify.annotations.NullMarked; + +import java.time.Duration; +import java.time.Instant; +import java.util.Locale; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicLong; +import java.util.function.Supplier; + +/* + * Series names are written out in Prometheus notation instead of Micrometer's dotted convention, + * so that the name in this file is character for character the name a dashboard or an alert queries. + */ +@RequiredArgsConstructor +@NullMarked +public class MicrometerEmailMetrics implements EmailMetrics { + private static final String SEND_METER = "app_email_send_duration"; + private static final String CLEANUP_METER = "app_email_cleanup_duration"; + private static final String PASS_METER = "app_email_pass_duration"; + private static final String LAST_RUN_METER = "app_email_last_run_timestamp_seconds"; + private static final String LAST_SUCCESS_METER = "app_email_last_success_timestamp_seconds"; + private static final String QUEUE_METER = "app_email_queue"; + private static final String QUEUE_AGE_METER = "app_email_queue_oldest_due_age_seconds"; + + private final MeterRegistry meterRegistry; + private final Map gauges = new ConcurrentHashMap<>(); + + @Override + public void sendAttempt(SendMode mode, SendOutcome outcome, Duration duration) { + meterRegistry.timer(SEND_METER, "mode", tag(mode), "outcome", tag(outcome)) + .record(duration); + } + + @Override + public void cleanupAttempt(CleanupOutcome outcome, Duration duration) { + meterRegistry.timer(CLEANUP_METER, "outcome", tag(outcome)) + .record(duration); + } + + @Override + public void pass(Job job, PassStatus status, Duration duration) { + meterRegistry.timer(PASS_METER, "job", tag(job), "status", tag(status)) + .record(duration); + + var now = Instant.now().getEpochSecond(); + + // A pass that found nothing to do still stamps last_run: the scheduler did fire, which is what + // last_run answers. Only last_success says the pass got through without hitting the database wall. + setGauge(LAST_RUN_METER, "job", tag(job), now); + if (status == PassStatus.SUCCESS) { + setGauge(LAST_SUCCESS_METER, "job", tag(job), now); + } + } + + @Override + public void queue(Supplier snapshot) { + var reading = snapshot.get(); + + setGauge(QUEUE_METER, "state", "pending", reading.pending()); + setGauge(QUEUE_METER, "state", "sending", reading.sending()); + + // Nothing due means nothing is waiting, which is an age of zero rather than a missing reading. + var oldestDueAge = reading.oldestDueAge(); + setGauge(QUEUE_AGE_METER, "state", "pending", oldestDueAge == null ? 0 : oldestDueAge.toSeconds()); + } + + /* + * Registered on first use rather than eagerly, so a pod that has never run a pass since start has no + * series at all. That reads the same to an alert as a NaN starting value would, and avoids the false + * alarm a 0 starting value causes after every deploy. + */ + private void setGauge(String meter, String tagKey, String tagValue, long value) { + gauges.computeIfAbsent(new GaugeId(meter, Tags.of(tagKey, tagValue)), this::registerGauge) + .set(value); + } + + private AtomicLong registerGauge(GaugeId id) { + // A gauge left behind by another instance on the same registry - a DevTools restart, a registry + // shared between contexts - keeps reading that instance's frozen holder for good: Micrometer + // returns the existing gauge on re-registration and silently ignores the new holder. Replacing + // it makes the newest instance the one that is read. + var leftBehind = meterRegistry.find(id.meter()).tags(id.tags()).gauge(); + if (leftBehind != null) { + meterRegistry.remove(leftBehind); + } + + var holder = new AtomicLong(); + Gauge.builder(id.meter(), holder, AtomicLong::doubleValue) + .tags(id.tags()) + .register(meterRegistry); + + return holder; + } + + private static String tag(Enum value) { + return value.name().toLowerCase(Locale.ROOT); + } + + private record GaugeId(String meter, Tags tags) { + } +} diff --git a/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/NoOpEmailMetrics.java b/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/NoOpEmailMetrics.java new file mode 100644 index 0000000..149e4f2 --- /dev/null +++ b/src/main/java/it/aboutbits/springboot/emailservice/lib/metrics/NoOpEmailMetrics.java @@ -0,0 +1,34 @@ +package it.aboutbits.springboot.emailservice.lib.metrics; + +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import org.jspecify.annotations.NullMarked; + +import java.time.Duration; +import java.util.function.Supplier; + +/* + * Used when the consuming application has no MeterRegistry. Recording stays a call into an + * empty method, so the schedulers can instrument themselves unconditionally. + */ +@NullMarked +public class NoOpEmailMetrics implements EmailMetrics { + @Override + public void sendAttempt(SendMode mode, SendOutcome outcome, Duration duration) { + // no metrics backend available + } + + @Override + public void cleanupAttempt(CleanupOutcome outcome, Duration duration) { + // no metrics backend available + } + + @Override + public void pass(Job job, PassStatus status, Duration duration) { + // no metrics backend available + } + + @Override + public void queue(Supplier snapshot) { + // no metrics backend available, so the snapshot is deliberately never read + } +} diff --git a/src/test/java/it/aboutbits/springboot/emailservice/EmailServiceConfigurationTest.java b/src/test/java/it/aboutbits/springboot/emailservice/EmailServiceConfigurationTest.java new file mode 100644 index 0000000..224b105 --- /dev/null +++ b/src/test/java/it/aboutbits/springboot/emailservice/EmailServiceConfigurationTest.java @@ -0,0 +1,119 @@ +package it.aboutbits.springboot.emailservice; + +import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import it.aboutbits.springboot.emailservice.lib.application.CleanupAttachmentFiles; +import it.aboutbits.springboot.emailservice.lib.application.ManageEmail; +import it.aboutbits.springboot.emailservice.lib.application.SendScheduledEmails; +import it.aboutbits.springboot.emailservice.lib.jpa.EmailRepository; +import it.aboutbits.springboot.emailservice.lib.metrics.MicrometerEmailMetrics; +import it.aboutbits.springboot.emailservice.lib.metrics.NoOpEmailMetrics; +import org.jspecify.annotations.NullMarked; +import org.junit.jupiter.api.Test; +import org.springframework.boot.convert.ApplicationConversionService; +import org.springframework.boot.test.context.FilteredClassLoader; +import org.springframework.boot.test.context.runner.ApplicationContextRunner; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.mail.javamail.JavaMailSender; +import org.springframework.transaction.PlatformTransactionManager; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.mockingDetails; + +/* + * Wires the library the way an application does - through @EnableEmailService and nothing else. Nothing + * here is component scanned, unlike in the @SpringBootTest suite, whose TestApplication happens to live in + * the library's own package and would find any configuration class of the library on its own. + */ +@NullMarked +class EmailServiceConfigurationTest { + private final ApplicationContextRunner contextRunner = new ApplicationContextRunner() + // What SpringApplication installs on its own and the library's Duration properties rely on. + .withInitializer(context -> context.getBeanFactory() + .setConversionService(ApplicationConversionService.getSharedInstance())) + .withPropertyValues("aboutbits.emailservice.migrations.enabled=false") + .withBean(EmailRepository.class, () -> mock(EmailRepository.class)) + .withBean(JavaMailSender.class, () -> mock(JavaMailSender.class)) + .withBean(PlatformTransactionManager.class, () -> mock(PlatformTransactionManager.class)); + + @Test + void givenOnlyEnableEmailService_context_shouldWireEverySchedulerAndService() { + contextRunner + .withUserConfiguration(Application.class) + .run(context -> { + assertThat(context.getStartupFailure()).isNull(); + assertThat(context.getBeansOfType(ManageEmail.class)).hasSize(1); + assertThat(context.getBeansOfType(SendScheduledEmails.class)).hasSize(1); + assertThat(context.getBeansOfType(CleanupAttachmentFiles.class)).hasSize(1); + assertThat(context.getBeansOfType(EmailMetrics.class)).hasSize(1); + }); + } + + @Test + void givenARegistry_emailMetrics_shouldRecordIntoMicrometer() { + contextRunner + .withUserConfiguration(Application.class) + .withBean(SimpleMeterRegistry.class) + .run(context -> assertThat(context.getBean(EmailMetrics.class)) + .isInstanceOf(MicrometerEmailMetrics.class)); + } + + @Test + void givenMicrometerWithoutARegistry_emailMetrics_shouldFallBackToTheNoOp() { + contextRunner + .withUserConfiguration(Application.class) + .run(context -> assertThat(context.getBean(EmailMetrics.class)) + .isInstanceOf(NoOpEmailMetrics.class)); + } + + @Test + void givenSeveralRegistriesAndNoPrimaryOne_emailMetrics_shouldFallBackToTheNoOpInsteadOfFailing() { + contextRunner + .withUserConfiguration(Application.class) + .withBean("first", SimpleMeterRegistry.class) + .withBean("second", SimpleMeterRegistry.class) + .run(context -> { + assertThat(context.getStartupFailure()).isNull(); + assertThat(context.getBean(EmailMetrics.class)).isInstanceOf(NoOpEmailMetrics.class); + }); + } + + @Test + void givenNoMicrometerOnTheClasspath_emailMetrics_shouldFallBackToTheNoOp() { + contextRunner + .withUserConfiguration(Application.class) + .withClassLoader(new FilteredClassLoader(MeterRegistry.class)) + .run(context -> assertThat(context.getBean(EmailMetrics.class)) + .isInstanceOf(NoOpEmailMetrics.class)); + } + + @Test + void givenTheApplicationDeclaresItsOwnEmailMetrics_emailMetrics_shouldBeThatOneAlone() { + contextRunner + .withUserConfiguration(ApplicationWithOwnMetrics.class) + .withBean(SimpleMeterRegistry.class) + .run(context -> { + assertThat(context.getBeansOfType(EmailMetrics.class)).hasSize(1); + assertThat(mockingDetails(context.getBean(EmailMetrics.class)).isMock()).isTrue(); + }); + } + + @Configuration(proxyBeanMethods = false) + @EnableEmailService + static class Application { + } + + // The replacement sits in the very class carrying @EnableEmailService, the place an application + // would put it, and the one place a plain @Import would parse too late to see. + @Configuration(proxyBeanMethods = false) + @EnableEmailService + static class ApplicationWithOwnMetrics { + @Bean + EmailMetrics ownEmailMetrics() { + return mock(EmailMetrics.class); + } + } +} diff --git a/src/test/java/it/aboutbits/springboot/emailservice/lib/application/QueryEmailTest.java b/src/test/java/it/aboutbits/springboot/emailservice/lib/application/QueryEmailTest.java index ff400c7..5a01851 100644 --- a/src/test/java/it/aboutbits/springboot/emailservice/lib/application/QueryEmailTest.java +++ b/src/test/java/it/aboutbits/springboot/emailservice/lib/application/QueryEmailTest.java @@ -13,6 +13,9 @@ import org.springframework.mail.javamail.JavaMailSender; import org.springframework.test.context.bean.override.mockito.MockitoBean; +import java.time.Duration; +import java.time.OffsetDateTime; +import java.time.temporal.ChronoUnit; import java.util.Set; import static org.assertj.core.api.Assertions.assertThat; @@ -94,4 +97,32 @@ void givenEmailNotification_byIdOrFail_shouldSuccess() { void givenNoEmailNotification_byIdOrFail_shouldFail() { assertThat(queryEmail.byId(123L)).isNotPresent(); } + + @Test + void givenEmailsInEveryState_queueSnapshot_shouldCountOnlyTheOpenOnesAndAgeTheOldestDueOne() { + emailRepository.saveAll(Set.of( + EmailFactory.once().scheduledAt(OffsetDateTime.now().minus(10, ChronoUnit.MINUTES)).build(), + EmailFactory.once().scheduledAt(OffsetDateTime.now().minus(5, ChronoUnit.MINUTES)).build(), + EmailFactory.once().scheduledAt(OffsetDateTime.now().plus(1, ChronoUnit.HOURS)).build(), + EmailFactory.once().state(EmailState.SENDING).build(), + EmailFactory.once().state(EmailState.SENT).build(), + EmailFactory.once().state(EmailState.ERROR).build() + )); + + var result = queryEmail.queueSnapshot(); + + assertThat(result.pending()).isEqualTo(3L); + assertThat(result.sending()).isEqualTo(1L); + assertThat(result.oldestDueAge()).isBetween(Duration.ofMinutes(9), Duration.ofMinutes(11)); + } + + @Test + void givenNothingIsDue_queueSnapshot_shouldReportNoAge() { + emailRepository.save(EmailFactory.once().scheduledAt(OffsetDateTime.now().plus(1, ChronoUnit.HOURS)).build()); + + var result = queryEmail.queueSnapshot(); + + assertThat(result.pending()).isEqualTo(1L); + assertThat(result.oldestDueAge()).isNull(); + } } diff --git a/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/FailSafeEmailMetricsTest.java b/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/FailSafeEmailMetricsTest.java new file mode 100644 index 0000000..c37578b --- /dev/null +++ b/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/FailSafeEmailMetricsTest.java @@ -0,0 +1,74 @@ +package it.aboutbits.springboot.emailservice.lib.metrics; + +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import org.jspecify.annotations.NullMarked; +import org.junit.jupiter.api.Test; + +import java.time.Duration; +import java.util.function.Supplier; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatCode; +import static org.assertj.core.api.Assertions.assertThatExceptionOfType; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.doThrow; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.verify; + +@NullMarked +class FailSafeEmailMetricsTest { + private final EmailMetrics delegate = mock(EmailMetrics.class); + private final FailSafeEmailMetrics sut = new FailSafeEmailMetrics(delegate); + + @Test + void givenAThrowingDelegate_sendAttempt_shouldNotPropagateTheFailure() { + doThrow(new IllegalStateException("registry rejected the meter")) + .when(delegate).sendAttempt(any(), any(), any()); + + assertThatCode(() -> sut.sendAttempt( + EmailMetrics.SendMode.SCHEDULED, + EmailMetrics.SendOutcome.SENT, + Duration.ofMillis(10) + )).doesNotThrowAnyException(); + } + + @Test + void givenAFailingSnapshot_queue_shouldNotPropagateTheFailure() { + doThrow(new IllegalStateException("database unreachable")) + .when(delegate).queue(any()); + + assertThatCode(() -> sut.queue(() -> new EmailMetrics.QueueSnapshot(0, 0, null))) + .doesNotThrowAnyException(); + } + + @Test + void givenAWorkingDelegate_queue_shouldPassTheSnapshotThroughUnread() { + Supplier snapshot = () -> new EmailMetrics.QueueSnapshot(1, 2, null); + + sut.queue(snapshot); + + verify(delegate).queue(snapshot); + } + + @Test + void givenAFailingPass_timedPass_shouldRecordTheFailureAndStillPropagateIt() { + assertThatExceptionOfType(IllegalStateException.class).isThrownBy( + () -> sut.timedPass(EmailMetrics.Job.SEND, () -> { + throw new IllegalStateException("database unreachable"); + }) + ); + + verify(delegate).pass(eq(EmailMetrics.Job.SEND), eq(EmailMetrics.PassStatus.FAILED), any()); + } + + @Test + void givenAPassThatGetsThrough_timedPass_shouldRecordASuccess() { + var passes = new int[1]; + + sut.timedPass(EmailMetrics.Job.CLEANUP, () -> passes[0]++); + + assertThat(passes[0]).isEqualTo(1); + verify(delegate).pass(eq(EmailMetrics.Job.CLEANUP), eq(EmailMetrics.PassStatus.SUCCESS), any()); + } +} diff --git a/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/MicrometerEmailMetricsTest.java b/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/MicrometerEmailMetricsTest.java new file mode 100644 index 0000000..105adb9 --- /dev/null +++ b/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/MicrometerEmailMetricsTest.java @@ -0,0 +1,148 @@ +package it.aboutbits.springboot.emailservice.lib.metrics; + +import io.micrometer.prometheusmetrics.PrometheusConfig; +import io.micrometer.prometheusmetrics.PrometheusMeterRegistry; +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import org.jspecify.annotations.NullMarked; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import java.time.Duration; + +import static org.assertj.core.api.Assertions.assertThat; + +/* + * Asserts the scrape output character for character, because the series names are the contract + * between this library and the dashboards and alerts querying it. Renaming a meter has to break + * a test here rather than a panel that silently stops drawing. + */ +@NullMarked +class MicrometerEmailMetricsTest { + private PrometheusMeterRegistry meterRegistry; + private MicrometerEmailMetrics sut; + + @BeforeEach + void setup() { + meterRegistry = new PrometheusMeterRegistry(PrometheusConfig.DEFAULT); + sut = new MicrometerEmailMetrics(meterRegistry); + } + + @Test + void givenAFailedScheduledSend_sendAttempt_shouldExposeTheAttemptByModeAndOutcome() { + sut.sendAttempt( + EmailMetrics.SendMode.SCHEDULED, + EmailMetrics.SendOutcome.ERROR, + Duration.ofMillis(120) + ); + + var scrape = meterRegistry.scrape(); + + assertThat(scrape).contains("app_email_send_duration_seconds_count"); + assertThat(scrape).contains("mode=\"scheduled\""); + assertThat(scrape).contains("outcome=\"error\""); + } + + @Test + void givenARetriedSend_sendAttempt_shouldSeparateRetriesFromErrors() { + sut.sendAttempt( + EmailMetrics.SendMode.SCHEDULED, + EmailMetrics.SendOutcome.RETRY, + Duration.ofMillis(120) + ); + + var scrape = meterRegistry.scrape(); + + assertThat(scrape).contains("outcome=\"retry\""); + assertThat(scrape).doesNotContain("outcome=\"error\""); + } + + @Test + void givenACleanedAttachment_cleanupAttempt_shouldExposeTheAttemptByOutcome() { + sut.cleanupAttempt(EmailMetrics.CleanupOutcome.CLEANED, Duration.ofMillis(30)); + + var scrape = meterRegistry.scrape(); + + assertThat(scrape).contains("app_email_cleanup_duration_seconds_count"); + assertThat(scrape).contains("outcome=\"cleaned\""); + } + + @Test + void givenASuccessfulPass_pass_shouldExposeTheDurationAndBothTimestamps() { + sut.pass(EmailMetrics.Job.SEND, EmailMetrics.PassStatus.SUCCESS, Duration.ofMillis(400)); + + var scrape = meterRegistry.scrape(); + + assertThat(scrape).contains("app_email_pass_duration_seconds_count"); + assertThat(scrape).contains("job=\"send\""); + assertThat(scrape).contains("status=\"success\""); + // The staleness alerts read these as "time() - max by (job) (...)", so no suffix may be appended. + assertThat(scrape).contains("app_email_last_run_timestamp_seconds{"); + assertThat(scrape).contains("app_email_last_success_timestamp_seconds{"); + } + + @Test + void givenOnlyFailedPasses_pass_shouldStampLastRunButNotLastSuccess() { + sut.pass(EmailMetrics.Job.SEND, EmailMetrics.PassStatus.FAILED, Duration.ofMillis(400)); + + var scrape = meterRegistry.scrape(); + + assertThat(scrape).contains("app_email_last_run_timestamp_seconds{"); + assertThat(scrape).doesNotContain("app_email_last_success_timestamp_seconds"); + } + + @Test + void givenNoPassHasRun_pass_shouldNotRegisterTimestampsAtAll() { + var scrape = meterRegistry.scrape(); + + // Absent rather than zero: a zero starting value would read as decades of staleness to an alert. + assertThat(scrape).doesNotContain("app_email_last_run_timestamp_seconds"); + assertThat(scrape).doesNotContain("app_email_last_success_timestamp_seconds"); + } + + @Test + void givenABacklog_queue_shouldExposeOneSeriesPerStateAndTheOldestAge() { + sut.queue(() -> new EmailMetrics.QueueSnapshot(12, 3, Duration.ofMinutes(5))); + + var scrape = meterRegistry.scrape(); + + assertThat(scrape).contains("app_email_queue{"); + assertThat(scrape).contains("app_email_queue_oldest_due_age_seconds{"); + + assertThat(gauge("app_email_queue", "pending")).isEqualTo(12d); + assertThat(gauge("app_email_queue", "sending")).isEqualTo(3d); + assertThat(gauge("app_email_queue_oldest_due_age_seconds", "pending")).isEqualTo(300d); + } + + @Test + void givenNothingIsDue_queue_shouldReportAnAgeOfZeroInsteadOfNoReading() { + sut.queue(() -> new EmailMetrics.QueueSnapshot(0, 0, null)); + + assertThat(gauge("app_email_queue_oldest_due_age_seconds", "pending")).isEqualTo(0d); + } + + @Test + void givenRepeatedSnapshots_queue_shouldKeepOneSeriesPerStateAndUpdateItInPlace() { + sut.queue(() -> new EmailMetrics.QueueSnapshot(12, 0, Duration.ofMinutes(5))); + sut.queue(() -> new EmailMetrics.QueueSnapshot(4, 0, Duration.ofMinutes(1))); + + assertThat(meterRegistry.find("app_email_queue").tag("state", "pending").gauges()).hasSize(1); + assertThat(gauge("app_email_queue", "pending")).isEqualTo(4d); + } + + @Test + void givenASecondInstanceOnTheSameRegistry_queue_shouldBeReadFromTheNewestInstance() { + sut.queue(() -> new EmailMetrics.QueueSnapshot(12, 0, Duration.ofMinutes(5))); + + // A DevTools restart or a registry shared between contexts: the old instance is gone, its + // gauge must not keep serving its last values as if the queue had frozen. + var replacement = new MicrometerEmailMetrics(meterRegistry); + replacement.queue(() -> new EmailMetrics.QueueSnapshot(4, 0, Duration.ofMinutes(1))); + + assertThat(meterRegistry.find("app_email_queue").tag("state", "pending").gauges()).hasSize(1); + assertThat(gauge("app_email_queue", "pending")).isEqualTo(4d); + } + + private double gauge(String name, String state) { + return meterRegistry.get(name).tag("state", state).gauge().value(); + } +} diff --git a/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/NoOpEmailMetricsTest.java b/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/NoOpEmailMetricsTest.java new file mode 100644 index 0000000..cb9b76c --- /dev/null +++ b/src/test/java/it/aboutbits/springboot/emailservice/lib/metrics/NoOpEmailMetricsTest.java @@ -0,0 +1,25 @@ +package it.aboutbits.springboot.emailservice.lib.metrics; + +import it.aboutbits.springboot.emailservice.lib.EmailMetrics; +import org.jspecify.annotations.NullMarked; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +@NullMarked +class NoOpEmailMetricsTest { + private final NoOpEmailMetrics sut = new NoOpEmailMetrics(); + + // The snapshot costs database queries, and without a backend they would be queries for nothing. + @Test + void givenNoBackend_queue_shouldNeverReadTheSnapshot() { + var reads = new int[1]; + + sut.queue(() -> { + reads[0]++; + return new EmailMetrics.QueueSnapshot(0, 0, null); + }); + + assertThat(reads[0]).isZero(); + } +}