This is an automated email from the ASF dual-hosted git repository.
asf-gitbox-commits pushed a commit to branch UNOMI-979-scheduler-lock-lease
in repository https://gitbox.apache.org/repos/asf/unomi.git
The following commit(s) were added to refs/heads/UNOMI-979-scheduler-lock-lease
by this push:
new 07d497569 UNOMI-979: Dump scheduler state and DEBUG trace when a
scheduler test fails
07d497569 is described below
commit 07d497569fe5d17abe226586cb948a8059355eb3
Author: Serge Huber <[email protected]>
AuthorDate: Mon Aug 17 14:13:23 2026 +0200
UNOMI-979: Dump scheduler state and DEBUG trace when a scheduler test fails
Every intermittent scheduler failure on CI so far has arrived as a bare
assertion message. The evidence needed to diagnose one - which node held a
lock,
when it was renewed, who judged it expired, what the store actually
contained -
is already logged as LOCK-DIAG lines, but only at DEBUG, and CI does not
run at
DEBUG. Re-running with -DTEST_LOG_LEVEL=DEBUG rarely helps because an
intermittent failure usually does not recur on demand. Both failures in the
previous CI run had to be diagnosed by reading code, and neither could be
reproduced locally even at matching core count under load.
SchedulerDiagnosticsExtension captures DEBUG for the scheduler and cluster
packages into a bounded in-memory ring buffer and dumps it, together with a
snapshot of every task document in the store, at the moment a test fails:
* The snapshot runs from TestExecutionExceptionHandler, which fires before
the
test's own @AfterEach, so it shows the state that caused the failure
rather
than what teardown left behind. It refreshes the index first, since the
query is search-based and would otherwise report "(none)" purely because
of
refresh lag. Per task it reports status, enabled, executing node, lock
owner,
lock date, lease, success and failure counts, next execution, history
size and
last error - the fields these failures actually turn on.
* Capture costs nothing on a passing test: the ring buffer is the only
consumer
of the DEBUG events, so nothing reaches the console unless a test fails.
Verified both ways - a passing run prints zero LOCK-DIAG lines, and a
failing
one prints the full trace.
* When -DTEST_LOG_LEVEL is set the extension stands aside entirely, so an
explicit request for console output still gets console output.
Wired into the four scheduler test classes with one annotation each. The
extension finds the persistence service by reflection so adding it to a test
class needs no other change.
Note for anyone touching these tests: mvn compile and test-compile in this
module report BUILD SUCCESS while skipping changed sources, and produced a
class
file with an unqualified annotation descriptor here
(TypeNotPresentException at
runtime). Use mvn clean when verifying a compile.
Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
---
.../scheduler/SchedulerDiagnosticsExtension.java | 271 +++++++++++++++++++++
.../scheduler/SchedulerServiceClusterRaceTest.java | 1 +
.../impl/scheduler/SchedulerServiceImplTest.java | 1 +
.../impl/scheduler/TaskExecutionManagerTest.java | 1 +
.../impl/scheduler/TaskLockManagerTest.java | 1 +
5 files changed, 275 insertions(+)
diff --git
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerDiagnosticsExtension.java
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerDiagnosticsExtension.java
new file mode 100644
index 000000000..73bf1eb5d
--- /dev/null
+++
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerDiagnosticsExtension.java
@@ -0,0 +1,271 @@
+/*
+ * 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.unomi.services.impl.scheduler;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.CyclicBufferAppender;
+import org.apache.unomi.api.tasks.ScheduledTask;
+import org.apache.unomi.persistence.spi.PersistenceService;
+import org.junit.jupiter.api.extension.AfterEachCallback;
+import org.junit.jupiter.api.extension.BeforeEachCallback;
+import org.junit.jupiter.api.extension.ExtensionContext;
+import org.junit.jupiter.api.extension.TestExecutionExceptionHandler;
+import org.slf4j.LoggerFactory;
+
+import java.lang.reflect.Field;
+import java.text.SimpleDateFormat;
+import java.util.Collection;
+import java.util.Date;
+import java.util.List;
+import java.util.Map;
+
+/**
+ * Makes an intermittent scheduler test failure diagnosable from the CI log it
failed in.
+ * <p>
+ * Scheduler failures are almost always about state and ordering: which node
held a lock, when it
+ * was renewed, who decided it had expired, what the store actually contained.
The scheduler already
+ * logs all of that as {@code LOCK-DIAG} lines, but only at DEBUG, and CI does
not run at DEBUG --
+ * so every intermittent failure historically arrived as a bare assertion
message with the evidence
+ * discarded. Re-running with {@code -DTEST_LOG_LEVEL=DEBUG} rarely helps,
because an intermittent
+ * failure usually does not recur on demand.
+ * <p>
+ * This extension therefore captures DEBUG for the scheduler packages into a
bounded in-memory ring
+ * buffer that costs nothing on a passing test, and dumps it -- together with
a snapshot of every
+ * task document in the store -- at the moment a test fails. The snapshot is
taken from
+ * {@link TestExecutionExceptionHandler}, which runs before the test's own
{@code @AfterEach}
+ * teardown, so the store is still alive and holds the state that caused the
failure rather than
+ * whatever cleanup left behind.
+ * <p>
+ * When {@code -DTEST_LOG_LEVEL} is set explicitly, the extension stays out of
the way and leaves
+ * logback's configured behaviour alone: an explicit request for console
output should get console
+ * output.
+ */
+public class SchedulerDiagnosticsExtension
+ implements BeforeEachCallback, AfterEachCallback,
TestExecutionExceptionHandler {
+
+ /** Enough lines to cover several checker ticks across a handful of nodes.
*/
+ private static final int BUFFER_SIZE = 4000;
+
+ /** Packages whose DEBUG output explains scheduler behaviour. */
+ private static final String[] CAPTURED_LOGGERS = {
+ "org.apache.unomi.services.impl.scheduler",
+ "org.apache.unomi.services.impl.cluster"
+ };
+
+ private static final String APPENDER_NAME =
"scheduler-diagnostics-ring-buffer";
+ private static final ExtensionContext.Namespace NAMESPACE =
+ ExtensionContext.Namespace.create(SchedulerDiagnosticsExtension.class);
+
+ private static boolean explicitLogLevelRequested() {
+ String requested = System.getProperty("TEST_LOG_LEVEL");
+ return requested != null && !requested.trim().isEmpty();
+ }
+
+ @Override
+ public void beforeEach(ExtensionContext context) {
+ if (explicitLogLevelRequested()) {
+ return;
+ }
+ if (!(LoggerFactory.getILoggerFactory() instanceof LoggerContext)) {
+ return; // not logback (shaded/OSGi runs); nothing to attach to
+ }
+ LoggerContext loggerContext = (LoggerContext)
LoggerFactory.getILoggerFactory();
+
+ CyclicBufferAppender<ILoggingEvent> buffer = new
CyclicBufferAppender<>();
+ buffer.setContext(loggerContext);
+ buffer.setName(APPENDER_NAME);
+ buffer.setMaxSize(BUFFER_SIZE);
+ buffer.start();
+
+ for (String name : CAPTURED_LOGGERS) {
+ ch.qos.logback.classic.Logger logger =
loggerContext.getLogger(name);
+ // additive=false keeps the captured DEBUG out of the console on
passing runs; the
+ // buffer dump below is the only consumer, and it only fires on
failure.
+ logger.setLevel(Level.DEBUG);
+ logger.setAdditive(false);
+ logger.addAppender(buffer);
+ }
+ context.getStore(NAMESPACE).put(APPENDER_NAME, buffer);
+ }
+
+ @Override
+ public void afterEach(ExtensionContext context) {
+ @SuppressWarnings("unchecked")
+ CyclicBufferAppender<ILoggingEvent> buffer =
+ context.getStore(NAMESPACE).remove(APPENDER_NAME,
CyclicBufferAppender.class);
+ if (buffer == null || !(LoggerFactory.getILoggerFactory() instanceof
LoggerContext)) {
+ return;
+ }
+ LoggerContext loggerContext = (LoggerContext)
LoggerFactory.getILoggerFactory();
+ for (String name : CAPTURED_LOGGERS) {
+ ch.qos.logback.classic.Logger logger =
loggerContext.getLogger(name);
+ logger.detachAppender(buffer);
+ logger.setAdditive(true);
+ logger.setLevel(null); // inherit from root again
+ }
+ buffer.stop();
+ }
+
+ @Override
+ public void handleTestExecutionException(ExtensionContext context,
Throwable throwable)
+ throws Throwable {
+ StringBuilder report = new StringBuilder();
+ report.append("\n================ SCHEDULER DIAGNOSTICS for ")
+ .append(context.getRequiredTestClass().getSimpleName()).append('.')
+ .append(context.getRequiredTestMethod().getName())
+ .append(" ================\n")
+ .append("Failure: ").append(throwable).append('\n');
+
+ appendTaskSnapshot(report, context);
+ appendBufferedLog(report, context);
+
+ report.append("================ END SCHEDULER DIAGNOSTICS
================\n");
+ // stdout, not a logger: this must survive whatever logging
configuration is in force, and
+ // Surefire captures stdout into the report the CI log shows.
+ System.out.println(report);
+
+ throw throwable;
+ }
+
+ /**
+ * Dumps every task document the test's persistence service can see. Taken
before teardown, so
+ * this is the state that produced the failure.
+ */
+ private void appendTaskSnapshot(StringBuilder report, ExtensionContext
context) {
+ report.append("\n-- task documents in the store at failure time --\n");
+ PersistenceService persistenceService =
findPersistenceService(context);
+ if (persistenceService == null) {
+ report.append(" (no PersistenceService field found on the test
instance)\n");
+ return;
+ }
+ try {
+ // getAllItems is search-based, and both the in-memory harness and
a real cluster hold a
+ // refresh interval behind the store. Force visibility first: the
test has already
+ // failed, so there is no state left worth preserving, and a
snapshot that silently
+ // reports "(none)" because of refresh lag is worse than useless.
+ try {
+ persistenceService.refreshIndex(ScheduledTask.class);
+ persistenceService.refresh();
+ } catch (Exception ignored) {
+ report.append(" (refresh before snapshot failed; list may lag
the store)\n");
+ }
+ List<ScheduledTask> tasks =
+ persistenceService.getAllItems(ScheduledTask.class, 0, -1,
null).getList();
+ if (tasks.isEmpty()) {
+ report.append(" (none)\n");
+ return;
+ }
+ SimpleDateFormat fmt = new SimpleDateFormat("HH:mm:ss.SSS");
+ for (ScheduledTask task : tasks) {
+ report.append(" ").append(task.getItemId())
+ .append(" type=").append(task.getTaskType())
+ .append(" status=").append(task.getStatus())
+ .append(" enabled=").append(task.isEnabled())
+ .append(" execNode=").append(task.getExecutingNodeId())
+ .append(" lockOwner=").append(task.getLockOwner())
+ .append(" lockDate=")
+ .append(task.getLockDate() == null ? "null" :
fmt.format(task.getLockDate()))
+ .append("
lease=").append(task.getLockLeaseMillis()).append("ms")
+ .append(" success=").append(task.getSuccessCount())
+ .append(" failure=").append(task.getFailureCount())
+ .append(" nextExec=")
+ .append(task.getNextScheduledExecution() == null
+ ? "null" :
fmt.format(task.getNextScheduledExecution()))
+ .append(" history=").append(historySize(task))
+ .append(" lastError=").append(task.getLastError())
+ .append('\n');
+ }
+ } catch (Exception e) {
+ report.append(" (failed to read tasks: ").append(e).append(")\n");
+ }
+ }
+
+ private static int historySize(ScheduledTask task) {
+ Map<String, Object> details = task.getStatusDetails();
+ if (details == null) {
+ return 0;
+ }
+ Object history = details.get("executionHistory");
+ return history instanceof Collection ? ((Collection<?>)
history).size() : 0;
+ }
+
+ /**
+ * Finds a {@link PersistenceService} on the test instance. Reflection
rather than an interface
+ * the tests must implement: the point is that adding this extension to a
test class costs one
+ * annotation and no other change.
+ */
+ private PersistenceService findPersistenceService(ExtensionContext
context) {
+ Object testInstance = context.getTestInstance().orElse(null);
+ if (testInstance == null) {
+ return null;
+ }
+ for (Class<?> type = testInstance.getClass(); type != null; type =
type.getSuperclass()) {
+ for (Field field : type.getDeclaredFields()) {
+ if
(!PersistenceService.class.isAssignableFrom(field.getType())) {
+ continue;
+ }
+ try {
+ field.setAccessible(true);
+ PersistenceService value = (PersistenceService)
field.get(testInstance);
+ if (value != null) {
+ return value;
+ }
+ } catch (ReflectiveOperationException | RuntimeException
ignored) {
+ // Not readable; keep looking.
+ }
+ }
+ }
+ return null;
+ }
+
+ private void appendBufferedLog(StringBuilder report, ExtensionContext
context) {
+ @SuppressWarnings("unchecked")
+ CyclicBufferAppender<ILoggingEvent> buffer =
+ context.getStore(NAMESPACE).get(APPENDER_NAME,
CyclicBufferAppender.class);
+ if (buffer == null) {
+ report.append("\n-- captured scheduler DEBUG log --\n")
+ .append(" (not captured; -DTEST_LOG_LEVEL was set, so the log
went to the console)\n");
+ return;
+ }
+ int count = buffer.getLength();
+ report.append("\n-- captured scheduler DEBUG log (last ").append(count)
+ .append(" events, newest last) --\n");
+ if (count == 0) {
+ report.append(" (empty)\n");
+ return;
+ }
+ SimpleDateFormat fmt = new SimpleDateFormat("HH:mm:ss.SSS");
+ for (int i = 0; i < count; i++) {
+ ILoggingEvent event = buffer.get(i);
+ if (event == null) {
+ continue;
+ }
+ report.append(" ").append(fmt.format(new
Date(event.getTimeStamp())))
+ .append(" [").append(event.getThreadName()).append("] ")
+ .append(event.getLevel()).append(' ')
+ .append(shortLoggerName(event.getLoggerName())).append(" - ")
+ .append(event.getFormattedMessage()).append('\n');
+ }
+ }
+
+ private static String shortLoggerName(String loggerName) {
+ int lastDot = loggerName.lastIndexOf('.');
+ return lastDot < 0 ? loggerName : loggerName.substring(lastDot + 1);
+ }
+}
diff --git
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerServiceClusterRaceTest.java
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerServiceClusterRaceTest.java
index c967de791..d2ce88f7f 100644
---
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerServiceClusterRaceTest.java
+++
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerServiceClusterRaceTest.java
@@ -75,6 +75,7 @@ import static org.mockito.Mockito.when;
@ExtendWith(MockitoExtension.class)
@MockitoSettings(strictness = Strictness.LENIENT)
@Tag("ClusterTests")
+@ExtendWith(SchedulerDiagnosticsExtension.class)
public class SchedulerServiceClusterRaceTest {
private static final Logger LOGGER =
LoggerFactory.getLogger(SchedulerServiceClusterRaceTest.class);
diff --git
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerServiceImplTest.java
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerServiceImplTest.java
index 1be4eea88..0521f476b 100644
---
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerServiceImplTest.java
+++
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/SchedulerServiceImplTest.java
@@ -97,6 +97,7 @@ import static org.mockito.Mockito.when;
*/
@ExtendWith(MockitoExtension.class)
@MockitoSettings(strictness = Strictness.LENIENT)
+@ExtendWith(SchedulerDiagnosticsExtension.class)
public class SchedulerServiceImplTest {
private static final Logger LOGGER =
LoggerFactory.getLogger(SchedulerServiceImplTest.class);
diff --git
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/TaskExecutionManagerTest.java
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/TaskExecutionManagerTest.java
index f81b9c6e4..8aa3105b0 100644
---
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/TaskExecutionManagerTest.java
+++
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/TaskExecutionManagerTest.java
@@ -49,6 +49,7 @@ import static org.mockito.Mockito.*;
*/
@ExtendWith(MockitoExtension.class)
@MockitoSettings(strictness = Strictness.LENIENT)
+@ExtendWith(SchedulerDiagnosticsExtension.class)
public class TaskExecutionManagerTest {
private static final String NODE = "exec-node";
diff --git
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/TaskLockManagerTest.java
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/TaskLockManagerTest.java
index 25fe94bbc..57cec8d58 100644
---
a/services/src/test/java/org/apache/unomi/services/impl/scheduler/TaskLockManagerTest.java
+++
b/services/src/test/java/org/apache/unomi/services/impl/scheduler/TaskLockManagerTest.java
@@ -44,6 +44,7 @@ import static org.mockito.Mockito.*;
*/
@ExtendWith(MockitoExtension.class)
@MockitoSettings(strictness = Strictness.LENIENT)
+@ExtendWith(SchedulerDiagnosticsExtension.class)
public class TaskLockManagerTest {
private static final String NODE = "lock-node";
