Add timer accumulation logging and keyset key unit tests

Author: lizk886

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

@@ -85,9 +85,17 @@ public void handleKeysetKeyRefreshResponse(Boolean success) {
                 keysetKeyFailureStartTime.set(clock.instant());
                 LOGGER.warn(
                         "keyset keys sync started failing. shutdown timer started (will shutdown in 7 days if not recovered)");
-            } else if (Duration.between(t, clock.instant()).compareTo(this.keysetKeyShutdownWaitTime) > 0) {
-                LOGGER.error("keyset keys have been failing to sync for too long. shutting down operator");
-                this.shutdownService.Shutdown(1);
+            } else {
+                Duration elapsed = Duration.between(t, clock.instant());
+                LOGGER.debug("keyset keys sync still failing - timer at {} ({}d {}h {}m) / 7 days",
+                        elapsed,
+                        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);
+                }
             }
         }
     }

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

@@ -166,4 +166,81 @@ void saltsLogErrorAtInterval(VertxTestContext testContext) {
 
         testContext.completeNow();
     }
+
+    @Test
+    void shutdownOnKeysetKeyFailedTooLong(VertxTestContext testContext) {
+        ListAppender<ILoggingEvent> logWatcher = new ListAppender<>();
+        logWatcher.start();
+        ((Logger) LoggerFactory.getLogger(OperatorShutdownHandler.class)).addAppender(logWatcher);
+
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        Assertions.assertTrue(logWatcher.list.get(0).getFormattedMessage().contains("keyset keys sync failing"));
+        Assertions.assertTrue(logWatcher.list.get(1).getFormattedMessage().contains("keyset keys sync started failing"));
+
+        when(clock.instant()).thenAnswer(i -> Instant.now().plus(7, ChronoUnit.DAYS).plusSeconds(60));
+        try {
+            this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        } catch (RuntimeException e) {
+            verify(shutdownService).Shutdown(1);
+            Assertions.assertTrue(logWatcher.list.stream().anyMatch(log -> 
+                log.getFormattedMessage().contains("keyset keys have been failing to sync for too long")));
+            testContext.completeNow();
+        }
+    }
+
+    @Test
+    void keysetKeyRecoverOnSuccess(VertxTestContext testContext) {
+        ListAppender<ILoggingEvent> logWatcher = new ListAppender<>();
+        logWatcher.start();
+        ((Logger) LoggerFactory.getLogger(OperatorShutdownHandler.class)).addAppender(logWatcher);
+
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        when(clock.instant()).thenAnswer(i -> Instant.now().plus(3, ChronoUnit.DAYS));
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(true);
+
+        Assertions.assertTrue(logWatcher.list.stream().anyMatch(log -> 
+            log.getFormattedMessage().contains("keyset keys sync recovered")));
+
+        when(clock.instant()).thenAnswer(i -> Instant.now().plus(7, ChronoUnit.DAYS));
+        assertDoesNotThrow(() -> {
+            this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        });
+        verify(shutdownService, never()).Shutdown(anyInt());
+        testContext.completeNow();
+    }
+
+    @Test
+    void keysetKeyLogErrorAtInterval(VertxTestContext testContext) {
+        ListAppender<ILoggingEvent> logWatcher = new ListAppender<>();
+        logWatcher.start();
+        ((Logger) LoggerFactory.getLogger(OperatorShutdownHandler.class)).addAppender(logWatcher);
+
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        long errorLogCount1 = logWatcher.list.stream().filter(log -> 
+            log.getFormattedMessage().contains("keyset keys sync failing")).count();
+        
+        when(clock.instant()).thenAnswer(i -> Instant.now().plus(9, ChronoUnit.MINUTES));
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        long errorLogCount2 = logWatcher.list.stream().filter(log -> 
+            log.getFormattedMessage().contains("keyset keys sync failing")).count();
+        Assertions.assertEquals(errorLogCount1, errorLogCount2);
+        
+        when(clock.instant()).thenAnswer(i -> Instant.now().plus(11, ChronoUnit.MINUTES));
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(false);
+        long errorLogCount3 = logWatcher.list.stream().filter(log -> 
+            log.getFormattedMessage().contains("keyset keys sync failing")).count();
+        Assertions.assertTrue(errorLogCount3 > errorLogCount2);
+
+        testContext.completeNow();
+    }
+
+    @Test
+    void keysetKeyNoShutdownWhenAlwaysSuccessful(VertxTestContext testContext) {
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(true);
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(true);
+        this.operatorShutdownHandler.handleKeysetKeyRefreshResponse(true);
+
+        verify(shutdownService, never()).Shutdown(anyInt());
+        testContext.completeNow();
+    }
 }