This is an automated email from the ASF dual-hosted git repository.
ashishvijaywargiya pushed a commit to branch trunk
in repository https://gitbox.apache.org/repos/asf/ofbiz-framework.git
The following commit(s) were added to refs/heads/trunk by this push:
new bd0522c6e0 Tag testIntegration log lines with the test case that
produced them via MDC (Mapped Diagnostic Context) (#1662)
bd0522c6e0 is described below
commit bd0522c6e0c353956259b4ad7680a120ef8e6b3d
Author: Ashish Vijaywargiya <[email protected]>
AuthorDate: Sun Aug 16 23:15:19 2026 +0530
Tag testIntegration log lines with the test case that produced them via MDC
(Mapped Diagnostic Context) (#1662)
testIntegration runs JUnit tests inside the same OFBiz process, writing
to the same console/log files as normal server operation. A test that
deliberately
exercises a failure path (e.g. a service-error test) produces ERROR-level
log lines
that are visually indistinguishable from a real bug - nothing in the line
says it
was expected.
This sets a testCase field via Log4j2's ThreadContext (MDC) for the
duration of each test method - JUnit 3 via
Junit3ResultBridge.startTest/endTest, Jupiter
via JupiterTestExtension's JupiterClassRunner listener - and references it
in the console/ofbiz.log/error.log pattern:
... |%level{length=1}| %notEmpty{[TEST:%X{testCase}] }%message%n
%notEmpty{...} only renders when the key is set, so normal server output
is unaffected - the tag only appears on lines logged while a test method is
actually running, including nested framework calls on the same thread
(GenericDelegator, ServiceDispatcher, TransactionUtil, etc.), since MDC
rides the thread
automatically. Example:
... |ServiceDispatcher :578|E|
[TEST:GroovyDslServiceEngineTests#testGroovyServices] Error in Service
[testGroovyPingError]: Service result error
This reuses the same MDC pattern already established by CorrelationValve
for HTTP request correlation (requestId/visitId/userLoginId) - no new
logging
mechanism, no new dependency. The opt-in ECS JSON logging profile picks up
the new
field automatically, since it already resolves the whole MDC map
generically -
no template change needed.
Also adds a safety net (TestRunContainer.runSuiteEntries's loop and
JupiterClassRunner's outer finally) so the field can't get stranded on
the thread if a test's own run(TestResult) override lets an exception
escape before
its normal cleanup runs.
I got the idea to use MDC (Mapped Diagnostic Context) for OFBiz from the
below links:
- https://logging.apache.org/log4j/2.12.x/manual/thread-context.html
- https://www.baeldung.com/mdc-in-log4j-2-logback
Verified with `./gradlew "ofbiz --test component=service"`:
[TEST:Class#method] tags
appear exactly as designed on 270 log lines, propagate through nested
framework calls, and normal server bootstrap output (before any test runs)
carries
none. Full `./gradlew test` unit suite and the project's
checkstyle/codenarc checks
pass.
---
framework/base/config/log4j2.xml | 2 +-
.../apache/ofbiz/testtools/Junit3ResultBridge.java | 13 +++++-
.../ofbiz/testtools/JupiterTestExtension.java | 52 +++++++++++++---------
.../apache/ofbiz/testtools/TestRunContainer.java | 30 ++++++++-----
.../ofbiz/testtools/Junit3ResultBridgeTest.java | 30 +++++++++++++
.../ofbiz/testtools/JupiterClassRunnerTest.java | 20 +++++++++
.../ofbiz/testtools/TestRunContainerTest.java | 35 +++++++++++++++
7 files changed, 148 insertions(+), 34 deletions(-)
diff --git a/framework/base/config/log4j2.xml b/framework/base/config/log4j2.xml
index b114a8f991..64b3524604 100644
--- a/framework/base/config/log4j2.xml
+++ b/framework/base/config/log4j2.xml
@@ -27,7 +27,7 @@ under the License.
<Property name="lineToken_prod"></Property>
<Property name="includeLocation_dev">true</Property>
<Property name="includeLocation_prod">false</Property>
- <Property name="logPattern">%date{DEFAULT} |%-20.20thread
|%-30.30logger{1}${lineToken_${sys:ofbiz.env:-dev}}|%level{length=1}|
%message%n</Property>
+ <Property name="logPattern">%date{DEFAULT} |%-20.20thread
|%-30.30logger{1}${lineToken_${sys:ofbiz.env:-dev}}|%level{length=1}|
%notEmpty{[TEST:%X{testCase}] }%message%n</Property>
<Property
name="includeLocation">${includeLocation_${sys:ofbiz.env:-dev}}</Property>
<!--
Placeholder for the JSON event template used by the opt-in
structured logging appender
diff --git
a/framework/testtools/src/main/java/org/apache/ofbiz/testtools/Junit3ResultBridge.java
b/framework/testtools/src/main/java/org/apache/ofbiz/testtools/Junit3ResultBridge.java
index 069ab94c10..f0e9717577 100644
---
a/framework/testtools/src/main/java/org/apache/ofbiz/testtools/Junit3ResultBridge.java
+++
b/framework/testtools/src/main/java/org/apache/ofbiz/testtools/Junit3ResultBridge.java
@@ -22,6 +22,7 @@ import java.util.IdentityHashMap;
import java.util.List;
import java.util.Map;
+import org.apache.logging.log4j.ThreadContext;
import org.apache.ofbiz.testtools.SuiteReportSink.Outcome;
import junit.framework.AssertionFailedError;
@@ -54,6 +55,9 @@ final class Junit3ResultBridge implements TestListener {
private final Map<Test, Long> startTimes = new IdentityHashMap<>();
private final Map<Test, Outcome> outcomes = new IdentityHashMap<>();
+ // Must match the %X{testCase} reference in
framework/base/config/log4j2.xml's logPattern.
+ private static final String TEST_CASE_MDC_KEY = "testCase";
+
Junit3ResultBridge(SuiteReportSink... sinks) {
this.sinks = List.of(sinks);
}
@@ -61,6 +65,7 @@ final class Junit3ResultBridge implements TestListener {
@Override
public void startTest(Test test) {
startTimes.put(test, System.currentTimeMillis());
+ ThreadContext.put(TEST_CASE_MDC_KEY, test.getClass().getSimpleName() +
"#" + nameOf(test));
ReportingSupport.dispatch(sinks, sink ->
sink.testStarted(classnameOf(test), nameOf(test)));
}
@@ -80,8 +85,12 @@ final class Junit3ResultBridge implements TestListener {
// JUnit 3's dispatch order is always startTest ->
[addFailure|addError]* -> endTest, with
// endTest() called exactly once per test regardless of how many
addFailure()/addError() calls
// preceded it - so this is the single dispatch point for
testFinished().
- Outcome outcome = outcomes.remove(test);
- report(test, outcome != null ? outcome : Outcome.passed());
+ try {
+ Outcome outcome = outcomes.remove(test);
+ report(test, outcome != null ? outcome : Outcome.passed());
+ } finally {
+ ThreadContext.remove(TEST_CASE_MDC_KEY);
+ }
}
private void report(Test test, Outcome outcome) {
diff --git
a/framework/testtools/src/main/java/org/apache/ofbiz/testtools/JupiterTestExtension.java
b/framework/testtools/src/main/java/org/apache/ofbiz/testtools/JupiterTestExtension.java
index f9ac196d74..39ccfc814d 100644
---
a/framework/testtools/src/main/java/org/apache/ofbiz/testtools/JupiterTestExtension.java
+++
b/framework/testtools/src/main/java/org/apache/ofbiz/testtools/JupiterTestExtension.java
@@ -25,6 +25,7 @@ import java.util.Map;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
+import org.apache.logging.log4j.ThreadContext;
import org.apache.ofbiz.base.util.Debug;
import org.apache.ofbiz.entity.Delegator;
import org.apache.ofbiz.service.LocalDispatcher;
@@ -130,6 +131,9 @@ public class JupiterTestExtension implements
ParameterResolver, TestInstancePost
/** Read by build.gradle's `test` task ({@code excludeTags}) and by {@link
JunitJupiterTest}. */
public static final String INTEGRATION_TAG = "jupiterIntegration";
+ // Must match the %X{testCase} reference in
framework/base/config/log4j2.xml's logPattern.
+ static final String TEST_CASE_MDC_KEY = "testCase";
+
static final ThreadLocal<Delegator> CURRENT_DELEGATOR = new
ThreadLocal<>();
static final ThreadLocal<LocalDispatcher> CURRENT_DISPATCHER = new
ThreadLocal<>();
@@ -313,6 +317,7 @@ public class JupiterTestExtension implements
ParameterResolver, TestInstancePost
public void executionStarted(TestIdentifier
testIdentifier) {
if (testIdentifier.isTest()) {
startTimes.put(testIdentifier.getUniqueId(),
System.currentTimeMillis());
+ ThreadContext.put(TEST_CASE_MDC_KEY,
testClass.getSimpleName() + "#" + reportingName(testIdentifier));
ReportingSupport.dispatch(sinks, sink ->
sink.testStarted(testClass.getName(), reportingName(testIdentifier)));
}
}
@@ -331,33 +336,38 @@ public class JupiterTestExtension implements
ParameterResolver, TestInstancePost
reportContainerFailure(testIdentifier,
testExecutionResult);
return;
}
- String name = reportingName(testIdentifier);
- long elapsed = System.currentTimeMillis()
- -
startTimes.getOrDefault(testIdentifier.getUniqueId(),
System.currentTimeMillis());
- if (testExecutionResult.getStatus() ==
TestExecutionResult.Status.ABORTED) {
- // A JUnit 5 Assumptions.assumeTrue/assumeFalse
failure: a deliberate skip,
- // not a defect - logged, not reported as a
failure/error, the same way a
- // @Disabled test is reported via
executionSkipped() above, except that
- // testStarted()/testFinished() must still fire
here since the test already
- // started (see SuiteReportSink.Outcome's javadoc
for why this reports Passed).
-
testExecutionResult.getThrowable().ifPresent(throwable ->
- Debug.logInfo("[JUNIT] ABORTED: " +
testIdentifier.getDisplayName()
- + " (" + testClass.getName() + ")
- " + throwable.getMessage(), MODULE));
- ReportingSupport.dispatch(sinks, sink ->
sink.testFinished(testClass.getName(), name, elapsed, Outcome.passed()));
- return;
+ try {
+ String name = reportingName(testIdentifier);
+ long elapsed = System.currentTimeMillis()
+ -
startTimes.getOrDefault(testIdentifier.getUniqueId(),
System.currentTimeMillis());
+ if (testExecutionResult.getStatus() ==
TestExecutionResult.Status.ABORTED) {
+ // A JUnit 5
Assumptions.assumeTrue/assumeFalse failure: a deliberate skip,
+ // not a defect - logged, not reported as a
failure/error, the same way a
+ // @Disabled test is reported via
executionSkipped() above, except that
+ // testStarted()/testFinished() must still
fire here since the test already
+ // started (see SuiteReportSink.Outcome's
javadoc for why this reports Passed).
+
testExecutionResult.getThrowable().ifPresent(throwable ->
+ Debug.logInfo("[JUNIT] ABORTED: " +
testIdentifier.getDisplayName()
+ + " (" + testClass.getName() +
") - " + throwable.getMessage(), MODULE));
+ ReportingSupport.dispatch(sinks, sink ->
sink.testFinished(testClass.getName(), name, elapsed, Outcome.passed()));
+ return;
+ }
+ Outcome outcome =
testExecutionResult.getThrowable()
+ .map(throwable -> throwable instanceof
AssertionError
+ ?
Outcome.failure(throwable.getMessage(), throwable.getClass().getName(),
+
ReportingSupport.stackTraceOf(throwable))
+ : Outcome.error(throwable))
+ .orElseGet(Outcome::passed);
+ ReportingSupport.dispatch(sinks, sink ->
sink.testFinished(testClass.getName(), name, elapsed, outcome));
+ } finally {
+ ThreadContext.remove(TEST_CASE_MDC_KEY);
}
- Outcome outcome = testExecutionResult.getThrowable()
- .map(throwable -> throwable instanceof
AssertionError
- ?
Outcome.failure(throwable.getMessage(), throwable.getClass().getName(),
-
ReportingSupport.stackTraceOf(throwable))
- : Outcome.error(throwable))
- .orElseGet(Outcome::passed);
- ReportingSupport.dispatch(sinks, sink ->
sink.testFinished(testClass.getName(), name, elapsed, outcome));
}
});
} catch (Throwable t) {
reportClassExecutionFailure(t);
} finally {
+ ThreadContext.remove(TEST_CASE_MDC_KEY);
JupiterTestExtension.CURRENT_DELEGATOR.remove();
JupiterTestExtension.CURRENT_DISPATCHER.remove();
}
diff --git
a/framework/testtools/src/main/java/org/apache/ofbiz/testtools/TestRunContainer.java
b/framework/testtools/src/main/java/org/apache/ofbiz/testtools/TestRunContainer.java
index 05a4ad2c9f..055daf4af0 100644
---
a/framework/testtools/src/main/java/org/apache/ofbiz/testtools/TestRunContainer.java
+++
b/framework/testtools/src/main/java/org/apache/ofbiz/testtools/TestRunContainer.java
@@ -24,6 +24,7 @@ import java.io.FileOutputStream;
import java.util.List;
import java.util.Map;
+import org.apache.logging.log4j.ThreadContext;
import org.apache.ofbiz.base.container.Container;
import org.apache.ofbiz.base.container.ContainerException;
import org.apache.ofbiz.base.start.StartupCommand;
@@ -128,16 +129,25 @@ public class TestRunContainer implements Container {
TestResult junit3Result = new TestResult();
junit3Result.addListener(new Junit3ResultBridge(sinks));
for (SuiteEntry entry : entries) {
- if (entry instanceof Junit3Entry junit3Entry) {
- junit3Entry.test().run(junit3Result);
- } else if (entry instanceof JupiterEntry jupiterEntry) {
- new
JupiterTestExtension.JupiterClassRunner(jupiterEntry.testClass(), delegator,
dispatcher, sinks).run();
- } else {
- // SuiteEntry is sealed permits Junit3Entry, JupiterEntry, so
this is unreachable today -
- // but Java 17 doesn't support exhaustive switch over sealed
types without preview
- // features, so this explicit throw is the substitute: a
future third variant fails loudly
- // here instead of being silently skipped.
- throw new IllegalStateException("Unknown SuiteEntry type: " +
entry.getClass());
+ try {
+ if (entry instanceof Junit3Entry junit3Entry) {
+ junit3Entry.test().run(junit3Result);
+ } else if (entry instanceof JupiterEntry jupiterEntry) {
+ new
JupiterTestExtension.JupiterClassRunner(jupiterEntry.testClass(), delegator,
dispatcher, sinks).run();
+ } else {
+ // SuiteEntry is sealed permits Junit3Entry, JupiterEntry,
so this is unreachable today -
+ // but Java 17 doesn't support exhaustive switch over
sealed types without preview
+ // features, so this explicit throw is the substitute: a
future third variant fails loudly
+ // here instead of being silently skipped.
+ throw new IllegalStateException("Unknown SuiteEntry type:
" + entry.getClass());
+ }
+ } finally {
+ // Net for JUnit 3 test engines
(ServiceTest/SimpleMethodTest/EntityXmlAssertTest) whose
+ // own run(TestResult) overrides can let an unchecked
exception escape before reaching
+ // Junit3ResultBridge.endTest() - without this, testCase would
stay armed on this thread
+ // for every subsequent log line until the next test
overwrites it. Also correct (a no-op
+ // clearing an already-cleared key) for the two paths that
already clear it themselves.
+ ThreadContext.remove(JupiterTestExtension.TEST_CASE_MDC_KEY);
}
}
}
diff --git
a/framework/testtools/src/test/java/org/apache/ofbiz/testtools/Junit3ResultBridgeTest.java
b/framework/testtools/src/test/java/org/apache/ofbiz/testtools/Junit3ResultBridgeTest.java
index c70dcd624b..bbcb15d833 100644
---
a/framework/testtools/src/test/java/org/apache/ofbiz/testtools/Junit3ResultBridgeTest.java
+++
b/framework/testtools/src/test/java/org/apache/ofbiz/testtools/Junit3ResultBridgeTest.java
@@ -19,6 +19,7 @@
package org.apache.ofbiz.testtools;
import org.junit.jupiter.api.Test;
+import org.apache.logging.log4j.ThreadContext;
import junit.framework.AssertionFailedError;
import junit.framework.TestCase;
@@ -28,6 +29,7 @@ import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.contains;
import static org.hamcrest.Matchers.instanceOf;
import static org.hamcrest.Matchers.is;
+import static org.hamcrest.Matchers.nullValue;
class Junit3ResultBridgeTest {
@@ -82,6 +84,18 @@ class Junit3ResultBridgeTest {
assertThat(failure.message(), is("first failure"));
}
+ @Test
+ void tagsLogContextWithTestCaseDuringExecutionAndClearsItAfter() {
+ RecordingSink sink = new RecordingSink();
+ TestResult result = new TestResult();
+ result.addListener(new Junit3ResultBridge(sink));
+
+ new MdcCapturingCase().run(result);
+
+ assertThat(MdcCapturingCase.capturedTestCase(),
is("MdcCapturingCase#testCaptureMdc"));
+ assertThat(ThreadContext.get("testCase"), nullValue());
+ }
+
/**
* Mirrors how ServiceTest/SimpleMethodTest/EntityXmlAssertTest override
run(TestResult) directly -
* calling result.startTest(this), then multiple result.addFailure(this,
...) calls for one logical
@@ -103,6 +117,22 @@ class Junit3ResultBridgeTest {
}
}
+ public static class MdcCapturingCase extends TestCase {
+ private static String capturedTestCase;
+
+ MdcCapturingCase() {
+ super("testCaptureMdc");
+ }
+
+ public void testCaptureMdc() {
+ capturedTestCase = ThreadContext.get("testCase");
+ }
+
+ static String capturedTestCase() {
+ return capturedTestCase;
+ }
+ }
+
public static class PassingCase extends TestCase {
PassingCase() {
super("testPass");
diff --git
a/framework/testtools/src/test/java/org/apache/ofbiz/testtools/JupiterClassRunnerTest.java
b/framework/testtools/src/test/java/org/apache/ofbiz/testtools/JupiterClassRunnerTest.java
index b21e796a10..5c0636832c 100644
---
a/framework/testtools/src/test/java/org/apache/ofbiz/testtools/JupiterClassRunnerTest.java
+++
b/framework/testtools/src/test/java/org/apache/ofbiz/testtools/JupiterClassRunnerTest.java
@@ -22,6 +22,7 @@ import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
+import org.apache.logging.log4j.ThreadContext;
import org.apache.ofbiz.entity.Delegator;
import org.apache.ofbiz.service.LocalDispatcher;
import org.junit.jupiter.api.AfterEach;
@@ -143,6 +144,15 @@ class JupiterClassRunnerTest {
assertThat(JupiterTestExtension.CURRENT_DISPATCHER.get(), nullValue());
}
+ @Test
+ void tagsLogContextWithTestCaseDuringExecutionAndClearsItAfter() {
+ new JupiterTestExtension.JupiterClassRunner(MdcCapturingFixture.class,
mock(Delegator.class),
+ mock(LocalDispatcher.class), new RecordingSink()).run();
+
+ assertThat(MdcCapturingFixture.capturedTestCase,
is("MdcCapturingFixture#capturesMdc"));
+ assertThat(ThreadContext.get("testCase"), nullValue());
+ }
+
@Test
void reportsRealClassAndMethodNamesNotASharedSyntheticClass() {
RecordingSink sink = new RecordingSink();
@@ -231,6 +241,16 @@ class JupiterClassRunnerTest {
}
}
+ @Tag(JupiterTestExtension.INTEGRATION_TAG)
+ static class MdcCapturingFixture {
+ static String capturedTestCase;
+
+ @Test
+ void capturesMdc() {
+ capturedTestCase = ThreadContext.get("testCase");
+ }
+ }
+
@Tag(JupiterTestExtension.INTEGRATION_TAG)
@ExtendWith(JupiterTestExtension.class)
static class AssumptionFixture {
diff --git
a/framework/testtools/src/test/java/org/apache/ofbiz/testtools/TestRunContainerTest.java
b/framework/testtools/src/test/java/org/apache/ofbiz/testtools/TestRunContainerTest.java
index 7f052604ad..c547a656be 100644
---
a/framework/testtools/src/test/java/org/apache/ofbiz/testtools/TestRunContainerTest.java
+++
b/framework/testtools/src/test/java/org/apache/ofbiz/testtools/TestRunContainerTest.java
@@ -20,16 +20,20 @@ package org.apache.ofbiz.testtools;
import java.util.List;
+import org.apache.logging.log4j.ThreadContext;
import org.apache.ofbiz.entity.Delegator;
import org.apache.ofbiz.service.LocalDispatcher;
import org.junit.jupiter.api.Test;
import junit.framework.TestCase;
+import junit.framework.TestResult;
import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.contains;
import static org.hamcrest.Matchers.instanceOf;
import static org.hamcrest.Matchers.is;
+import static org.hamcrest.Matchers.nullValue;
+import static org.junit.jupiter.api.Assertions.assertThrows;
import static org.mockito.Mockito.mock;
/**
@@ -96,6 +100,17 @@ class TestRunContainerTest {
assertThat(sink.testFinishedCalls.get(0).outcome(),
instanceOf(SuiteReportSink.Outcome.Failure.class));
}
+ @Test
+ void
runSuiteEntriesClearsTheTestCaseMdcFieldEvenWhenAJunit3EngineEscapesBeforeEndTest()
{
+ RecordingSink sink = new RecordingSink();
+ List<SuiteEntry> entries = List.of(new SuiteEntry.Junit3Entry(new
StartsThenThrowsBeforeEndTestCase()));
+
+ assertThrows(RuntimeException.class, () ->
+ TestRunContainer.runSuiteEntries(entries,
mock(Delegator.class), mock(LocalDispatcher.class), sink));
+
+ assertThat(ThreadContext.get(JupiterTestExtension.TEST_CASE_MDC_KEY),
nullValue());
+ }
+
static class NamedCase extends TestCase {
NamedCase(String name) {
super(name);
@@ -123,4 +138,24 @@ class TestRunContainerTest {
void onlyTest() {
}
}
+
+ /**
+ * Mirrors how ServiceTest/SimpleMethodTest/EntityXmlAssertTest override
run(TestResult) directly -
+ * calling result.startTest(this) (which arms the testCase MDC field via
Junit3ResultBridge.startTest())
+ * themselves, then running the test's own logic before reaching
result.endTest(this). An unchecked
+ * exception thrown from that logic - as opposed to the
addFailure()/addError() calls those engines
+ * normally make - propagates straight out of run(TestResult), skipping
endTest() (and therefore
+ * Junit3ResultBridge.endTest()'s ThreadContext.remove()) entirely.
+ */
+ static class StartsThenThrowsBeforeEndTestCase extends TestCase {
+ StartsThenThrowsBeforeEndTestCase() {
+ super("startsThenThrows");
+ }
+
+ @Override
+ public void run(TestResult result) {
+ result.startTest(this);
+ throw new RuntimeException("escaped before endTest()");
+ }
+ }
}
