Fix repeated rotation due to insufficient time resolution (#207)

CHANGELOG.md

@@ -14,6 +14,10 @@
  limitations under the License.
 -->
 
+### (????-??-??) v0.9.7
+
+- Fix repeated rotations in time-sensitive policies when time resolution is not good enough (#207)
+
 ### (2023-10-23) v0.9.6
 
 - Avoid using `FileInputStream`, since it requires a full-GC for clean-up. (#174, #175)

README.md

@@ -170,6 +170,7 @@ methods.
 - [Christoph (pitschr) Pitschmann](https://github.com/pitschr) (Windows-specific
   fixes, `RotationCallback#onOpen()` method, Java 9 module name, scheduler
   shutdown at exit)
+- [broafka-ottokar](https://github.com/broafka-ottokar) (repeated rotation due to insufficient time resolution #207)
 - [David (kc7bfi) Robison](https://github.com/kc7bfi) (NPE due to write after close in #26)
 - [Jonas (yawkat) Konrad](https://yawk.at/) (`RotatingFileOutputStream`
   thread-safety improvements)

src/main/java/com/vlkan/rfos/policy/TimeBasedRotationPolicy.java

@@ -56,22 +56,33 @@ public void acceptWrite(long byteCount) {
 
     @Override
     public synchronized void start(Rotatable rotatable) {
+        start(rotatable, null);
+    }
+
+    private void start(Rotatable rotatable, Instant lastTriggerInstant) {
         RotationConfig config = rotatable.getConfig();
         Clock clock = config.getClock();
         Instant currentInstant = clock.now();
         Instant triggerInstant = getTriggerInstant(clock);
-        long triggerDelayMillis = Duration.between(currentInstant, triggerInstant).toMillis();
-        Runnable task = createTask(rotatable, triggerInstant);
+        long triggerDelayNanos = Duration.between(currentInstant, triggerInstant).toNanos();
+        Runnable task = createTask(rotatable, lastTriggerInstant, triggerInstant);
         this.scheduledFuture = config
                 .getExecutorService()
-                .schedule(task, triggerDelayMillis, TimeUnit.MILLISECONDS);
+                .schedule(task, triggerDelayNanos, TimeUnit.NANOSECONDS);
     }
 
-    private Runnable createTask(Rotatable rotatable, Instant triggerInstant) {
+    private Runnable createTask(Rotatable rotatable, Instant lastTriggerInstant, Instant triggerInstant) {
         return () -> {
-            getLogger().debug("triggering {triggerInstant={}}", triggerInstant);
-            rotatable.rotate(TimeBasedRotationPolicy.this, triggerInstant);
-            start(rotatable);
+            // Avoid triggering repeatedly for the very same instant.
+            // This can happen due to:
+            // 1. Code execution is faster than the time resolution provided by the clock
+            // 2. Clocks can return a value twice (due to daylight time savings, monotonically-increasing design, etc.)
+            boolean uniqueTriggerInstant = lastTriggerInstant == null || triggerInstant.isAfter(lastTriggerInstant);
+            if (uniqueTriggerInstant) {
+                getLogger().debug("triggering {triggerInstant={}}", triggerInstant);
+                rotatable.rotate(TimeBasedRotationPolicy.this, triggerInstant);
+            }
+            start(rotatable, triggerInstant);
         };
     }
 

src/test/java/com/vlkan/rfos/RotatingFileOutputStreamTest.java

@@ -804,7 +804,7 @@ void test_time_based_policies_are_stopped_after_close() throws Exception {
                 .when(executorService.schedule(
                         Mockito.any(Runnable.class),
                         Mockito.anyLong(),
-                        Mockito.same(TimeUnit.MILLISECONDS)))
+                        Mockito.same(TimeUnit.NANOSECONDS)))
                 .thenAnswer((Answer<ScheduledFuture<?>>) invocationOnMock -> scheduledFuture);
         Mockito.when(executorService.toString()).thenReturn("MockedScheduledExecutorService");
 
@@ -835,7 +835,7 @@ void test_time_based_policies_are_stopped_after_close() throws Exception {
                 .schedule(
                         Mockito.any(Runnable.class),
                         Mockito.anyLong(),
-                        Mockito.same(TimeUnit.MILLISECONDS));
+                        Mockito.same(TimeUnit.NANOSECONDS));
 
         // Verify the task cancellation.
         inOrder

src/test/java/com/vlkan/rfos/policy/DailyRotationPolicyTest.java

@@ -48,7 +48,7 @@ void test() {
                 .when(executorService.schedule(
                         Mockito.any(Runnable.class),
                         Mockito.anyLong(),
-                        Mockito.same(TimeUnit.MILLISECONDS)))
+                        Mockito.same(TimeUnit.NANOSECONDS)))
                 .thenAnswer(new Answer<ScheduledFuture<?>>() {
 
                     private int invocationCount = 0;
@@ -69,11 +69,11 @@ public ScheduledFuture<?> answer(InvocationOnMock invocation) {
         // Create the clock mock.
         Clock clock = Mockito.mock(Clock.class);
         Instant midnight1 = Instant.parse("2017-12-29T00:00:00.000Z");
-        long waitPeriod1Millis = 1_000;
-        Instant now1 = midnight1.minus(Duration.ofMillis(waitPeriod1Millis));
+        Duration waitPeriod1 = Duration.ofSeconds(1);
+        Instant now1 = midnight1.minus(waitPeriod1);
         Instant midnight2 = Instant.parse("2017-12-30T00:00:00.000Z");
-        long waitPeriod2Millis = 2_000;
-        Instant now2 = midnight2.minus(Duration.ofMillis(waitPeriod2Millis));
+        Duration waitPeriod2 = Duration.ofSeconds(2);
+        Instant now2 = midnight2.minus(waitPeriod2);
         Mockito
                 .when(clock.now())
                 .thenReturn(now1)
@@ -108,8 +108,8 @@ public ScheduledFuture<?> answer(InvocationOnMock invocation) {
                 .verify(executorService)
                 .schedule(
                         Mockito.any(Runnable.class),
-                        Mockito.eq(waitPeriod1Millis),
-                        Mockito.same(TimeUnit.MILLISECONDS));
+                        Mockito.eq(waitPeriod1.toNanos()),
+                        Mockito.same(TimeUnit.NANOSECONDS));
 
         // Verify the 1st rotation.
         Mockito
@@ -121,8 +121,8 @@ public ScheduledFuture<?> answer(InvocationOnMock invocation) {
                 .verify(executorService, Mockito.atLeastOnce())
                 .schedule(
                         Mockito.any(Runnable.class),
-                        Mockito.eq(waitPeriod2Millis),
-                        Mockito.same(TimeUnit.MILLISECONDS));
+                        Mockito.eq(waitPeriod2.toNanos()),
+                        Mockito.same(TimeUnit.NANOSECONDS));
 
         // Verify the 2nd rotation.
         Mockito

src/test/java/com/vlkan/rfos/policy/TimeBasedRotationPolicyTest.java

@@ -0,0 +1,115 @@
+/*
+ * Copyright 2018-2023 Volkan Yazıcı <[email protected]>
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *        http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permits and
+ * limitations under the License.
+ */
+
+package com.vlkan.rfos.policy;
+
+import com.vlkan.rfos.Clock;
+import com.vlkan.rfos.Rotatable;
+import com.vlkan.rfos.RotationConfig;
+import org.junit.jupiter.api.Test;
+import org.mockito.Mockito;
+import org.mockito.invocation.InvocationOnMock;
+import org.mockito.stubbing.Answer;
+import org.slf4j.Logger;
+
+import java.time.Instant;
+import java.util.concurrent.ScheduledExecutorService;
+import java.util.concurrent.ScheduledFuture;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicInteger;
+
+import static java.time.Instant.EPOCH;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.ArgumentMatchers.anyLong;
+import static org.mockito.ArgumentMatchers.eq;
+import static org.mockito.ArgumentMatchers.same;
+import static org.mockito.Mockito.doAnswer;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
+
+class TimeBasedRotationPolicyTest {
+
+    @Test
+    void quick_task_scheduling_should_not_cause_repeated_rotations() {
+
+        // Mock a system where everything happens very fast, that is, at the very same time!
+        // This is a contrived assumption, but probable.
+        // This can happen due to:
+        // 1. Code execution is faster than the time resolution provided by the clock
+        // 2. Clocks can return a value twice (due to daylight time savings, monotonically-increasing design, etc.)
+        Clock clock = mock(Clock.class);
+        when(clock.now()).thenReturn(EPOCH);
+
+        // Create an executor that runs *the first two* tasks immediately (i.e., without any delay!) and discards the rest.
+        // Why the first two?
+        // 1. The first time `start()` is run manually (by `RotatingFileOutputStream`), it will schedule a task.
+        // 2. When `start()` is run by the scheduled task, it will schedule a task, again.
+        // 3. We need to stop here, otherwise we will be looping around step #2.
+        ScheduledExecutorService executor = mock(ScheduledExecutorService.class);
+        when(executor.schedule(any(Runnable.class), anyLong(), any()))
+                .thenAnswer(new Answer<ScheduledFuture<?>>() {
+
+                    private final AtomicInteger invocationCounter = new AtomicInteger(0);
+
+                    @Override
+                    public ScheduledFuture<?> answer(InvocationOnMock invocation) {
+                        if (invocationCounter.getAndIncrement() < 2) {
+                            Runnable task = invocation.getArgument(0);
+                            task.run();
+                        }
+                        return null;
+                    }
+
+                });
+
+        // Create the rotation configuration
+        RotationConfig config = mock(RotationConfig.class);
+        when(config.getClock()).thenReturn(clock);
+        when(config.getExecutorService()).thenReturn(executor);
+
+        // Create the rotatable
+        Rotatable rotatable = mock(Rotatable.class);
+        when(rotatable.getConfig()).thenReturn(config);
+
+        // Create and start the policy
+        PerNanoRotationPolicy policy = new PerNanoRotationPolicy();
+        policy.start(rotatable);
+
+        // Verify there was only a single rotation
+        verify(rotatable, times(1)).rotate(any(), any());
+
+    }
+
+    private static class PerNanoRotationPolicy extends TimeBasedRotationPolicy {
+
+        private static final Logger LOGGER = mock(Logger.class);
+
+        @Override
+        public Instant getTriggerInstant(Clock clock) {
+            // Choose a sub-millisecond delay
+            return clock.now().plusNanos(1);
+        }
+
+        @Override
+        protected Logger getLogger() {
+            return LOGGER;
+        }
+
+    }
+
+}