This is an automated email from the ASF dual-hosted git repository.
dakirily pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/qpid-broker-j.git
The following commit(s) were added to refs/heads/main by this push:
new f74a069b49 QPID-8782: [Broker-J] Buffered broker logs can contain
incorrect diagnostic context (#456)
f74a069b49 is described below
commit f74a069b4916285a35f2e81c1173b2e4c45ec082
Author: usugumo <[email protected]>
AuthorDate: Thu Oct 29 10:27:05 2026 +0100
QPID-8782: [Broker-J] Buffered broker logs can contain incorrect diagnostic
context (#456)
---
.../logging/logback/RecordEventAppender.java | 3 +-
.../server/logging/logback/StartupAppender.java | 5 +-
.../logging/logback/RecordEventAppenderTest.java | 137 +++++++++++++++++++++
.../logging/logback/StartupAppenderTest.java | 110 ++++++++++++++++-
4 files changed, 250 insertions(+), 5 deletions(-)
diff --git
a/broker-plugins/logging-logback/src/main/java/org/apache/qpid/server/logging/logback/RecordEventAppender.java
b/broker-plugins/logging-logback/src/main/java/org/apache/qpid/server/logging/logback/RecordEventAppender.java
index fa105c790a..a075b1e3e6 100644
---
a/broker-plugins/logging-logback/src/main/java/org/apache/qpid/server/logging/logback/RecordEventAppender.java
+++
b/broker-plugins/logging-logback/src/main/java/org/apache/qpid/server/logging/logback/RecordEventAppender.java
@@ -54,10 +54,11 @@ public class RecordEventAppender extends
AppenderBase<ILoggingEvent>
}
@Override
- protected void append(ILoggingEvent eventObject)
+ protected void append(final ILoggingEvent eventObject)
{
if (isStarted())
{
+ eventObject.prepareForDeferredProcessing();
_buffer.add(new LogRecord(_recordId.incrementAndGet(),
eventObject));
}
}
diff --git
a/broker-plugins/logging-logback/src/main/java/org/apache/qpid/server/logging/logback/StartupAppender.java
b/broker-plugins/logging-logback/src/main/java/org/apache/qpid/server/logging/logback/StartupAppender.java
index 30988e14a8..39c46d209e 100644
---
a/broker-plugins/logging-logback/src/main/java/org/apache/qpid/server/logging/logback/StartupAppender.java
+++
b/broker-plugins/logging-logback/src/main/java/org/apache/qpid/server/logging/logback/StartupAppender.java
@@ -51,9 +51,10 @@ public class StartupAppender extends
AppenderBase<ILoggingEvent>
}
@Override
- protected synchronized void append(ILoggingEvent e)
+ protected synchronized void append(final ILoggingEvent event)
{
- _accumulatedLoggingEvents.add(e);
+ event.prepareForDeferredProcessing();
+ _accumulatedLoggingEvents.add(event);
}
public synchronized void replayAccumulatedEvents(Appender<ILoggingEvent>
appender)
diff --git
a/broker-plugins/logging-logback/src/test/java/org/apache/qpid/server/logging/logback/RecordEventAppenderTest.java
b/broker-plugins/logging-logback/src/test/java/org/apache/qpid/server/logging/logback/RecordEventAppenderTest.java
new file mode 100644
index 0000000000..cb4a8191e2
--- /dev/null
+++
b/broker-plugins/logging-logback/src/test/java/org/apache/qpid/server/logging/logback/RecordEventAppenderTest.java
@@ -0,0 +1,137 @@
+/*
+ *
+ * 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.qpid.server.logging.logback;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertFalse;
+
+import java.util.ArrayList;
+import java.util.List;
+import java.util.Map;
+import java.util.concurrent.FutureTask;
+import java.util.concurrent.TimeUnit;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.classic.util.LogbackMDCAdapter;
+import ch.qos.logback.core.read.ListAppender;
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+
+import org.apache.qpid.test.utils.UnitTestBase;
+
+class RecordEventAppenderTest extends UnitTestBase
+{
+ private LoggerContext _loggerContext;
+ private Logger _logger;
+ private RecordEventAppender _appender;
+ private ListAppender<ILoggingEvent> _events;
+
+ @BeforeEach
+ void setUp()
+ {
+ _loggerContext = new LoggerContext();
+ _loggerContext.setMDCAdapter(new LogbackMDCAdapter());
+ _loggerContext.start();
+ _logger = _loggerContext.getLogger(getTestClassName());
+ _logger.setLevel(Level.INFO);
+ _logger.setAdditive(false);
+ _appender = new RecordEventAppender(2);
+ _appender.setContext(_loggerContext);
+ _appender.start();
+ _logger.addAppender(_appender);
+
+ _events = new ListAppender<>();
+ _events.setContext(_loggerContext);
+ _events.start();
+ _logger.addAppender(_events);
+ }
+
+ @AfterEach
+ void tearDown()
+ {
+ _loggerContext.stop();
+ }
+
+ @Test
+ void testRecordsPreserveProducerThreadAndFormattedMessage() throws
Exception
+ {
+ logOnProducerThread();
+ final List<LogRecord> records = new ArrayList<>();
+ new LogRecorder(_appender).forEach(records::add);
+
+ assertEquals(2, records.size());
+ assertEquals(1, records.get(0).getId());
+ assertEquals("producer-thread", records.get(0).getThreadName());
+ assertEquals("value=before", records.get(0).getMessage());
+ assertEquals(2, records.get(1).getId());
+ assertEquals("producer-thread", records.get(1).getThreadName());
+ assertEquals("after clearing MDC", records.get(1).getMessage());
+ }
+
+ @Test
+ void testRecordsCaptureMdcWithoutCallerData() throws Exception
+ {
+ logOnProducerThread();
+ _loggerContext.getMDCAdapter().put("trace", "reader-mdc");
+
+ assertEquals(2, _events.list.size());
+ assertEquals(Map.of("trace", "producer-mdc"),
_events.list.get(0).getMDCPropertyMap());
+ assertEquals(Map.of(), _events.list.get(1).getMDCPropertyMap());
+ assertFalse(_events.list.get(0).hasCallerData());
+ assertFalse(_events.list.get(1).hasCallerData());
+ }
+
+ private void logOnProducerThread() throws Exception
+ {
+ final FutureTask<Void> task = new FutureTask<>(() ->
+ {
+ _loggerContext.getMDCAdapter().put("trace", "producer-mdc");
+ try
+ {
+ final StringBuilder argument = new StringBuilder("before");
+ _logger.info("value={}", argument);
+ argument.replace(0, argument.length(), "after");
+ _loggerContext.getMDCAdapter().clear();
+ _logger.info("after clearing MDC");
+ }
+ finally
+ {
+ _loggerContext.getMDCAdapter().clear();
+ }
+ }, null);
+ final Thread producer = new Thread(task, "producer-thread");
+ producer.start();
+ try
+ {
+ task.get(5, TimeUnit.SECONDS);
+ }
+ finally
+ {
+ producer.join(TimeUnit.SECONDS.toMillis(5));
+ }
+ assertFalse(producer.isAlive());
+ }
+}
diff --git
a/broker-plugins/logging-logback/src/test/java/org/apache/qpid/server/logging/logback/StartupAppenderTest.java
b/broker-plugins/logging-logback/src/test/java/org/apache/qpid/server/logging/logback/StartupAppenderTest.java
index e2a49400cf..eb507dab8e 100644
---
a/broker-plugins/logging-logback/src/test/java/org/apache/qpid/server/logging/logback/StartupAppenderTest.java
+++
b/broker-plugins/logging-logback/src/test/java/org/apache/qpid/server/logging/logback/StartupAppenderTest.java
@@ -21,6 +21,7 @@
package org.apache.qpid.server.logging.logback;
import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertFalse;
import static org.junit.jupiter.api.Assertions.assertTrue;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.verify;
@@ -34,12 +35,19 @@ import java.io.InputStreamReader;
import java.io.PrintStream;
import java.util.ArrayList;
import java.util.List;
+import java.util.Map;
+import java.util.concurrent.FutureTask;
+import java.util.concurrent.TimeUnit;
import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.PatternLayout;
import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.classic.util.LogbackMDCAdapter;
import ch.qos.logback.core.Appender;
-
+import ch.qos.logback.core.read.ListAppender;
+import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
@@ -48,14 +56,25 @@ import org.apache.qpid.test.utils.UnitTestBase;
@SuppressWarnings({"rawtypes", "unchecked"})
public class StartupAppenderTest extends UnitTestBase
{
+ private LoggerContext _loggerContext;
private StartupAppender _startupAppender;
@BeforeEach
public void setUp() throws Exception
{
+ _loggerContext = new LoggerContext();
+ _loggerContext.setMDCAdapter(new LogbackMDCAdapter());
+ _loggerContext.start();
_startupAppender = createAndStartStartupAppender();
}
+ @AfterEach
+ public void tearDown()
+ {
+ _startupAppender.stop();
+ _loggerContext.stop();
+ }
+
@Test
public void testLogToConsole() throws Exception
{
@@ -96,6 +115,7 @@ public class StartupAppenderTest extends UnitTestBase
{
setTestSystemProperty(StartupAppender.PROPERTY_STARTUP_FAILOVER_CONSOLE_LOG_LEVEL,
"DEBUG");
+ _startupAppender.stop();
_startupAppender = createAndStartStartupAppender();
final ILoggingEvent event1 =
createMockLoggingEvent("org.apache.qpid.Test", Level.WARN, "Test1",
"Test-Thread-1");
@@ -116,10 +136,96 @@ public class StartupAppenderTest extends UnitTestBase
assertTrue(lines.get(3).contains("Test4"));
}
+ @Test
+ public void testReplayPreservesProducerContextAndFormattedMessage() throws
Exception
+ {
+ logOnProducerThread();
+ final ListAppender<ILoggingEvent> replay = new ListAppender<>();
+ replay.setContext(_loggerContext);
+ replay.start();
+ final PatternLayout layout = new PatternLayout();
+ layout.setContext(_loggerContext);
+ layout.setPattern("%thread|%X{trace}|%msg");
+ layout.start();
+ try
+ {
+ for (final String readerMdc : List.of("first-reader",
"second-reader"))
+ {
+ _loggerContext.getMDCAdapter().put("trace", readerMdc);
+ replay.list.clear();
+ _startupAppender.replayAccumulatedEvents(replay);
+
+ assertEquals(2, replay.list.size());
+ assertEquals("producer-thread|producer-mdc|value=before",
layout.doLayout(replay.list.get(0)));
+ assertEquals("producer-thread||after clearing MDC",
layout.doLayout(replay.list.get(1)));
+ assertFalse(replay.list.get(0).hasCallerData());
+ assertFalse(replay.list.get(1).hasCallerData());
+ assertEquals(readerMdc,
_loggerContext.getMDCAdapter().get("trace"));
+ }
+ }
+ finally
+ {
+ layout.stop();
+ replay.stop();
+ }
+ }
+
+ @Test
+ public void testConsolePreservesProducerContextAndFormattedMessage()
throws Exception
+ {
+ logOnProducerThread();
+ _loggerContext.getMDCAdapter().put("qpid.log.prefix", "reader-prefix
");
+ final List<String> lines = logToConsoleAndCollectSystemOutputLines();
+
+ assertEquals(2, lines.size());
+ assertTrue(lines.get(0).startsWith("producer-prefix "));
+ assertTrue(lines.get(0).contains("[producer-thread]"));
+ assertTrue(lines.get(0).contains("value=before"));
+ assertFalse(lines.get(0).contains("value=after"));
+ assertFalse(lines.get(1).contains("reader-prefix"));
+ assertFalse(lines.get(1).contains("producer-prefix"));
+ }
+
+ private void logOnProducerThread() throws Exception
+ {
+ final Logger logger = _loggerContext.getLogger(getTestClassName());
+ logger.setLevel(Level.INFO);
+ logger.setAdditive(false);
+ logger.addAppender(_startupAppender);
+ final FutureTask<Void> task = new FutureTask<>(() ->
+ {
+ _loggerContext.getMDCAdapter().setContextMap(Map.of("trace",
"producer-mdc",
+ "qpid.log.prefix", "producer-prefix "));
+ try
+ {
+ final StringBuilder argument = new StringBuilder("before");
+ logger.info("value={}", argument);
+ argument.replace(0, argument.length(), "after");
+ _loggerContext.getMDCAdapter().clear();
+ logger.info("after clearing MDC");
+ }
+ finally
+ {
+ _loggerContext.getMDCAdapter().clear();
+ }
+ }, null);
+ final Thread producer = new Thread(task, "producer-thread");
+ producer.start();
+ try
+ {
+ task.get(5, TimeUnit.SECONDS);
+ }
+ finally
+ {
+ producer.join(TimeUnit.SECONDS.toMillis(5));
+ }
+ assertFalse(producer.isAlive());
+ }
+
private StartupAppender createAndStartStartupAppender()
{
final StartupAppender startupAppender = new StartupAppender();
- startupAppender.setContext(new LoggerContext());
+ startupAppender.setContext(_loggerContext);
startupAppender.start();
return startupAppender;
}
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
