log failure at an interval

Author: lizk886

src/main/java/com/uid2/operator/vertx/OperatorShutdownHandler.java

@@ -16,13 +16,15 @@
 public class OperatorShutdownHandler {
     private static final Logger LOGGER = LoggerFactory.getLogger(OperatorShutdownHandler.class);
     private static final int SALT_FAILURE_LOG_INTERVAL_MINUTES = 10;
+    private static final int KEYSET_KEY_FAILURE_LOG_INTERVAL_MINUTES = 10;
     private final Duration attestShutdownWaitTime;
     private final Duration saltShutdownWaitTime;
     private final Duration keysetKeyShutdownWaitTime;
     private final AtomicReference<Instant> attestFailureStartTime = new AtomicReference<>(null);
     private final AtomicReference<Instant> saltFailureStartTime = new AtomicReference<>(null);
     private final AtomicReference<Instant> keysetKeyFailureStartTime = new AtomicReference<>(null);
     private final AtomicReference<Instant> lastSaltFailureLogTime = new AtomicReference<>(null);
+    private final AtomicReference<Instant> lastKeysetKeyFailureLogTime = new AtomicReference<>(null);
     private final Clock clock;
     private final ShutdownService shutdownService;
 
@@ -61,18 +63,17 @@ public void logSaltFailureAtInterval() {
     public void handleKeysetKeyRefreshResponse(Boolean success) {
         if (success) {
             keysetKeyFailureStartTime.set(null);
+            lastKeysetKeyFailureLogTime.set(null);
             LOGGER.debug("keyset keys sync successful"); 
         } else {
             Instant t = keysetKeyFailureStartTime.get();
             if (t == null) {
                 keysetKeyFailureStartTime.set(clock.instant());
+                lastKeysetKeyFailureLogTime.set(clock.instant());
                 LOGGER.warn("keyset keys sync started failing. shutdown timer started");
             } else {
+                logKeysetKeyFailureProgressAtInterval(t);
                 Duration elapsed = Duration.between(t, clock.instant());
-                LOGGER.debug("keyset keys sync still failing - elapsed time: {}d {}h {}m",
-                        elapsed.toDays(),
-                        elapsed.toHoursPart(),
-                        elapsed.toMinutesPart());
                 if (elapsed.compareTo(this.keysetKeyShutdownWaitTime) > 0) {
                     LOGGER.error("keyset keys have been failing to sync for too long. shutting down operator");
                     this.shutdownService.Shutdown(1);
@@ -81,6 +82,18 @@ public void handleKeysetKeyRefreshResponse(Boolean success) {
         }
     }
 
+    private void logKeysetKeyFailureProgressAtInterval(Instant failureStartTime) {
+        Instant lastLogTime = lastKeysetKeyFailureLogTime.get();
+        if (lastLogTime == null || clock.instant().isAfter(lastLogTime.plus(KEYSET_KEY_FAILURE_LOG_INTERVAL_MINUTES, ChronoUnit.MINUTES))) {
+            Duration elapsed = Duration.between(failureStartTime, clock.instant());
+            LOGGER.warn("keyset keys sync still failing - elapsed time: {}d {}h {}m",
+                    elapsed.toDays(),
+                    elapsed.toHoursPart(),
+                    elapsed.toMinutesPart());
+            lastKeysetKeyFailureLogTime.set(clock.instant());
+        }
+    }
+
     public void handleAttestResponse(Pair<AttestationResponseCode, String> response) {
         if (response.left() == AttestationResponseCode.AttestationFailure) {
             LOGGER.error("core attestation failed with AttestationFailure, shutting down operator, core response: {}", response.right());

src/test/java/com/uid2/operator/OperatorShutdownHandlerTest.java

@@ -211,4 +211,29 @@ void keysetKeyNoShutdownWhenAlwaysSuccessful(VertxTestContext testContext) {
         verify(shutdownService, never()).Shutdown(anyInt());
         testContext.completeNow();
     }
+
+    @Test
+    void keysetKeyLogProgressAtInterval(VertxTestContext testContext) {
+        ListAppender<ILoggingEvent> logWatcher = new ListAppender<>();
+        logWatcher.start();
+        ((Logger) LoggerFactory.getLogger(OperatorShutdownHandler.class)).addAppender(logWatcher);
+
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        long warnLogCount1 = logWatcher.list.stream().filter(log -> 
+            log.getFormattedMessage().contains("keyset keys sync still failing")).count();
+        
+        when(clock.instant()).thenAnswer(i -> Instant.now().plus(30, ChronoUnit.MINUTES));
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        long warnLogCount2 = logWatcher.list.stream().filter(log -> 
+            log.getFormattedMessage().contains("keyset keys sync still failing")).count();
+        Assertions.assertEquals(warnLogCount1, warnLogCount2);
+        
+        when(clock.instant()).thenAnswer(i -> Instant.now().plus(61, ChronoUnit.MINUTES));
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        long warnLogCount3 = logWatcher.list.stream().filter(log -> 
+            log.getFormattedMessage().contains("keyset keys sync still failing")).count();
+        Assertions.assertTrue(warnLogCount3 > warnLogCount2);
+
+        testContext.completeNow();
+    }
 }