Fix NPE in ConfigurationScheduler by ensuring scheduledFuture is chec…

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);
+        }
+    }
+}

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 + "}";
         }
     }
 

src/changelog/.2.x.x/2073_fix_ConfigurationScheduler_NPE.xml

@@ -0,0 +1,13 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<entry xmlns="https://logging.apache.org/xml/ns"
+       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+       xsi:schemaLocation="
+           https://logging.apache.org/xml/ns
+           https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
+       type="fixed">
+    <issue id="2073" link="https://github.com/apache/logging-log4j2/issues/2073"/>
+    <issue id="4118" link="https://github.com/apache/logging-log4j2/pull/4118"/>
+    <description format="asciidoc">
+        Fix `NullPointerException` in `ConfigurationScheduler` for a frequently executing cron schedule.
+    </description>
+</entry>