From 19a033ea8f9399af0a54f2b8f8d2086a26564048 Mon Sep 17 00:00:00 2001 From: Volkan Yazici Date: Fri, 1 Mar 2024 11:05:27 +0100 Subject: [PATCH] Fix repeated rotation due to insufficient time resolution (#207) --- CHANGELOG.md | 4 + README.md | 1 + .../rfos/policy/TimeBasedRotationPolicy.java | 25 ++-- .../rfos/RotatingFileOutputStreamTest.java | 4 +- .../rfos/policy/DailyRotationPolicyTest.java | 18 +-- .../policy/TimeBasedRotationPolicyTest.java | 115 ++++++++++++++++++ 6 files changed, 149 insertions(+), 18 deletions(-) create mode 100644 src/test/java/com/vlkan/rfos/policy/TimeBasedRotationPolicyTest.java diff --git a/CHANGELOG.md b/CHANGELOG.md index 7d8d5ba..dbf1f24 100644 --- a/CHANGELOG.md +++ b/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) diff --git a/README.md b/README.md index f8b53fc..a82d31b 100644 --- a/README.md +++ b/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) diff --git a/src/main/java/com/vlkan/rfos/policy/TimeBasedRotationPolicy.java b/src/main/java/com/vlkan/rfos/policy/TimeBasedRotationPolicy.java index 248fb95..12bd3b5 100644 --- a/src/main/java/com/vlkan/rfos/policy/TimeBasedRotationPolicy.java +++ b/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); }; } diff --git a/src/test/java/com/vlkan/rfos/RotatingFileOutputStreamTest.java b/src/test/java/com/vlkan/rfos/RotatingFileOutputStreamTest.java index dbb65cb..acd8875 100644 --- a/src/test/java/com/vlkan/rfos/RotatingFileOutputStreamTest.java +++ b/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>) 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 diff --git a/src/test/java/com/vlkan/rfos/policy/DailyRotationPolicyTest.java b/src/test/java/com/vlkan/rfos/policy/DailyRotationPolicyTest.java index d1be95b..eee2efa 100644 --- a/src/test/java/com/vlkan/rfos/policy/DailyRotationPolicyTest.java +++ b/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>() { 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 diff --git a/src/test/java/com/vlkan/rfos/policy/TimeBasedRotationPolicyTest.java b/src/test/java/com/vlkan/rfos/policy/TimeBasedRotationPolicyTest.java new file mode 100644 index 0000000..5027fd6 --- /dev/null +++ b/src/test/java/com/vlkan/rfos/policy/TimeBasedRotationPolicyTest.java @@ -0,0 +1,115 @@ +/* + * Copyright 2018-2023 Volkan Yazıcı + * + * 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>() { + + 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; + } + + } + +}