diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/ConfigurationSchedulerTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/ConfigurationSchedulerTest.java new file mode 100644 index 00000000000..06d85ec9ace --- /dev/null +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/ConfigurationSchedulerTest.java @@ -0,0 +1,83 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you 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 permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.config; + +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import java.util.Date; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; +import org.apache.logging.log4j.core.util.CronExpression; +import org.junit.jupiter.api.Test; + +class ConfigurationSchedulerTest { + + @Test + void testScheduleWithCronRaceCondition() throws Exception { + final CountDownLatch firstRunLatch = new CountDownLatch(1); + final CountDownLatch secondRunLatch = new CountDownLatch(1); + + final Runnable command = () -> { + if (firstRunLatch.getCount() > 0) { + firstRunLatch.countDown(); + } else { + secondRunLatch.countDown(); + } + }; + + final ConfigurationScheduler scheduler = new ConfigurationScheduler() { + private final AtomicBoolean first = new AtomicBoolean(true); + + @Override + public ScheduledFuture schedule(final Runnable cmd, final long delay, final TimeUnit unit) { + if (first.compareAndSet(true, false)) { + final ScheduledFuture future = super.schedule(cmd, 0, TimeUnit.MILLISECONDS); + try { + assertTrue(firstRunLatch.await(5, TimeUnit.SECONDS), "First run failed, likely NPE"); + + Thread.sleep(100); + } catch (final InterruptedException e) { + Thread.currentThread().interrupt(); + } + return future; + } + return super.schedule(cmd, delay, unit); + } + }; + + try { + scheduler.incrementScheduledItems(); + scheduler.start(); + + final CronExpression cron = new CronExpression("0/1 * * * * ?"); + + final ScheduledFuture future = scheduler.scheduleWithCron(cron, new Date(), command); + + future.cancel(false); + + assertFalse( + secondRunLatch.await(2, TimeUnit.SECONDS), + "Task ran after cancellation. Monotonic reset is broken."); + + } finally { + scheduler.stop(1, TimeUnit.SECONDS); + } + } +} diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java index c71911990a9..26f0b7a6dbd 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java @@ -147,10 +147,20 @@ public CronScheduledFuture scheduleWithCron(final CronExpression cronExpressi public CronScheduledFuture scheduleWithCron( final CronExpression cronExpression, final Date startDate, final Runnable command) { final Date fireDate = cronExpression.getNextValidTimeAfter(startDate == null ? new Date() : startDate); + final CronRunnable runnable = new CronRunnable(command, cronExpression); - final ScheduledFuture future = schedule(runnable, nextFireInterval(fireDate), TimeUnit.MILLISECONDS); - final CronScheduledFuture cronScheduledFuture = new CronScheduledFuture<>(future, fireDate); + final CronScheduledFuture cronScheduledFuture = new CronScheduledFuture<>(null, fireDate); runnable.setScheduledFuture(cronScheduledFuture); + + final ScheduledFuture future = schedule(runnable, nextFireInterval(fireDate), TimeUnit.MILLISECONDS); + + synchronized (cronScheduledFuture) { + Date currentFireTime = cronScheduledFuture.getFireTime(); + if (currentFireTime == null || !currentFireTime.after(fireDate)) { + cronScheduledFuture.reset(future, fireDate); + } + } + LOGGER.debug( "{} scheduled cron expression {} to fire at {}", name, cronExpression.getCronExpression(), fireDate); return cronScheduledFuture; @@ -231,7 +241,8 @@ public void setScheduledFuture(final CronScheduledFuture future) { @Override public void run() { try { - final long millis = scheduledFuture.getFireTime().getTime() - System.currentTimeMillis(); + Date fireTime = (scheduledFuture != null) ? scheduledFuture.getFireTime() : null; + long millis = (fireTime != null) ? (fireTime.getTime() - System.currentTimeMillis()) : 0L; if (millis > 0) { LOGGER.debug("{} Cron thread woke up {} millis early. Sleeping", name, millis); try { @@ -251,13 +262,24 @@ public void run() { name, cronExpression.getCronExpression(), fireDate); - scheduledFuture.reset(future, fireDate); + + if (scheduledFuture != null) { + synchronized (scheduledFuture) { + Date currentFireTime = scheduledFuture.getFireTime(); + if (currentFireTime == null || currentFireTime.before(fireDate)) { + scheduledFuture.reset(future, fireDate); + } + } + } } } @Override public String toString() { - return "CronRunnable{" + cronExpression.getCronExpression() + " - " + scheduledFuture.getFireTime(); + String fireTimeStr = (scheduledFuture != null && scheduledFuture.getFireTime() != null) + ? scheduledFuture.getFireTime().toString() + : "unassigned"; + return "CronRunnable{" + cronExpression.getCronExpression() + " - " + fireTimeStr + "}"; } } diff --git a/src/changelog/.2.x.x/2073_fix_ConfigurationScheduler_NPE.xml b/src/changelog/.2.x.x/2073_fix_ConfigurationScheduler_NPE.xml new file mode 100644 index 00000000000..ead17f8cfa7 --- /dev/null +++ b/src/changelog/.2.x.x/2073_fix_ConfigurationScheduler_NPE.xml @@ -0,0 +1,13 @@ + + + + + + Fix `NullPointerException` in `ConfigurationScheduler` for a frequently executing cron schedule. + + \ No newline at end of file