This is an automated email from the ASF dual-hosted git repository. joerghoh pushed a commit to branch SLING-13361 in repository https://gitbox.apache.org/repos/asf/sling-org-apache-sling-engine.git
commit f563b5d3308adc0cfae6b9bd7659789b7cd779b8 Author: Joerg Hoh <[email protected]> AuthorDate: Tue Sep 22 14:51:57 2026 +0200 SLING-13361 escape data for the RequestProgressTrackerLogFilter --- .../debug/RequestProgressTrackerLogFilter.java | 46 +++++++- .../debug/RequestProgressTrackerLogFilterTest.java | 117 +++++++++++++++++++++ 2 files changed, 159 insertions(+), 4 deletions(-) diff --git a/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java b/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java index 0fae220..de45734 100644 --- a/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java +++ b/src/main/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilter.java @@ -131,11 +131,10 @@ public class RequestProgressTrackerLogFilter implements Filter { private void logCompactFormat(RequestProgressTracker rpt) { final Iterator<String> messages = rpt.getMessages(); - final StringBuilder sb = new StringBuilder("\n"); + final StringBuilder sb = new StringBuilder(); while (messages.hasNext()) { - sb.append(messages.next()); + sb.append('\n').append(escapeLogMessage(messages.next())); } - sb.setLength(sb.length() - 1); log.debug(sb.toString()); } @@ -146,10 +145,49 @@ public class RequestProgressTrackerLogFilter implements Filter { } final Iterator<String> it = rpt.getMessages(); while (it.hasNext()) { - log.debug("REQUEST_{} - " + it.next(), requestId); + log.debug("REQUEST_{} - {}", requestId, escapeLogMessage(it.next())); } } + /** + * Escapes a request progress tracker message for logging. + * <p> + * Tracker messages embed request-derived, attacker-controllable data + * (container-decoded path info, selectors, suffix, request URI). Escaping + * embedded CR and LF prevents such data from forging additional log lines + * (log injection, CWE-117). Messages must also always be passed to SLF4J + * as a parameter - never concatenated into the format string - so that + * attacker-supplied <code>{}</code> sequences are not substituted. The + * line terminator the tracker appends to each message is removed. + * + * @param message the tracker message, may be <code>null</code> + * @return the escaped message + */ + static String escapeLogMessage(final String message) { + if (message == null) { + return null; + } + // strip the line terminator the tracker appends to each message + int end = message.length(); + while (end > 0 && (message.charAt(end - 1) == '\n' || message.charAt(end - 1) == '\r')) { + end--; + } + StringBuilder sb = null; + for (int i = 0; i < end; i++) { + final char c = message.charAt(i); + if (c == '\n' || c == '\r') { + if (sb == null) { + sb = new StringBuilder(end + 8); + sb.append(message, 0, i); + } + sb.append(c == '\n' ? "\\n" : "\\r"); + } else if (sb != null) { + sb.append(c); + } + } + return sb != null ? sb.toString() : message.substring(0, end); + } + private String extractExtension(SlingJakartaHttpServletRequest request) { final RequestPathInfo requestPathInfo = request.getRequestPathInfo(); String extension = requestPathInfo.getExtension(); diff --git a/src/test/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilterTest.java b/src/test/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilterTest.java index 37ca80b..c258adc 100644 --- a/src/test/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilterTest.java +++ b/src/test/java/org/apache/sling/engine/impl/debug/RequestProgressTrackerLogFilterTest.java @@ -19,13 +19,24 @@ package org.apache.sling.engine.impl.debug; import java.lang.annotation.Annotation; +import java.lang.reflect.Field; import java.lang.reflect.Method; +import java.util.Arrays; +import java.util.Iterator; import org.apache.sling.api.request.RequestProgressTracker; import org.apache.sling.api.request.builder.Builders; import org.junit.Test; +import org.mockito.ArgumentCaptor; +import org.mockito.Mockito; +import org.slf4j.Logger; +import org.slf4j.helpers.MessageFormatter; +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertNull; import static org.junit.Assert.assertTrue; +import static org.mockito.Mockito.times; /** Partial tests of RequestProgressTrackerLogFilter */ public class RequestProgressTrackerLogFilterTest { @@ -89,6 +100,112 @@ public class RequestProgressTrackerLogFilterTest { assertTrue("Expecting min ratio of " + minExpectedRatio + ", got " + ratio, ratio > minExpectedRatio); } + @Test + public void testEscapeLogMessageEscapesCrLf() { + // a percent-encoded CR/LF in the request path is decoded by the + // container, recorded by the tracker and must not forge log lines + assertEquals( + "17 LOG Method=GET, PathInfo=/content/x\\r\\n2026-08-11 FAKE admin login OK", + RequestProgressTrackerLogFilter.escapeLogMessage( + "17 LOG Method=GET, PathInfo=/content/x\r\n2026-08-11 FAKE admin login OK\n")); + } + + @Test + public void testEscapeLogMessageKeepsBenignMessage() { + assertEquals( + "20 TIMER_START{handleSecurity}", + RequestProgressTrackerLogFilter.escapeLogMessage("20 TIMER_START{handleSecurity}\n")); + assertEquals("", RequestProgressTrackerLogFilter.escapeLogMessage("\n")); + assertNull(RequestProgressTrackerLogFilter.escapeLogMessage(null)); + } + + /** + * Replaces the filter's private final SLF4J {@code Logger} with a mock so + * the exact arguments reaching the logger can be captured. + */ + private Logger injectMockLogger(final RequestProgressTrackerLogFilter filter) throws Exception { + final Logger logger = Mockito.mock(Logger.class); + final Field logField = RequestProgressTrackerLogFilter.class.getDeclaredField("log"); + logField.setAccessible(true); + logField.set(filter, logger); + return logger; + } + + private void invokeLogFormat( + final RequestProgressTrackerLogFilter filter, final String methodName, final RequestProgressTracker rpt) + throws Exception { + final Method method = filter.getClass().getDeclaredMethod(methodName, RequestProgressTracker.class); + method.setAccessible(true); + method.invoke(filter, rpt); + } + + private RequestProgressTracker rptWithMessages(final String... messages) { + final RequestProgressTracker rpt = Mockito.mock(RequestProgressTracker.class); + final Iterator<String> it = Arrays.asList(messages).iterator(); + Mockito.when(rpt.getMessages()).thenAnswer(invocation -> it); + return rpt; + } + + @Test + public void testLogDefaultFormatNeverConcatenatesMessageIntoFormatStringAndEscapesCrLf() throws Exception { + // a percent-encoded CR/LF in the request path, decoded by the + // container and recorded by the tracker, plus a literal "{}" that an + // attacker could use to try to smuggle an extra SLF4J placeholder + final String attackerMessage = "17 LOG Method=GET, PathInfo=/content/x\r\n2026-08-11 FAKE admin login OK {}"; + final RequestProgressTracker rpt = rptWithMessages(attackerMessage); + + final RequestProgressTrackerLogFilter filter = new RequestProgressTrackerLogFilter(); + final Logger logger = injectMockLogger(filter); + + invokeLogFormat(filter, "logDefaultFormat", rpt); + + // the message must be passed to SLF4J as a parameter, never + // concatenated into the format string itself - otherwise attacker + // supplied "{}" sequences would be (mis)interpreted as placeholders + final ArgumentCaptor<String> formatCaptor = ArgumentCaptor.forClass(String.class); + final ArgumentCaptor<Object> requestIdCaptor = ArgumentCaptor.forClass(Object.class); + final ArgumentCaptor<Object> messageCaptor = ArgumentCaptor.forClass(Object.class); + Mockito.verify(logger, times(1)) + .debug(formatCaptor.capture(), requestIdCaptor.capture(), messageCaptor.capture()); + + assertEquals("REQUEST_{} - {}", formatCaptor.getValue()); + final String escapedMessage = (String) messageCaptor.getValue(); + assertFalse(escapedMessage.contains("\r")); + assertFalse(escapedMessage.contains("\n")); + + // simulate the actual SLF4J rendering to prove the injected CRLF can + // no longer forge a new log record and the attacker's literal "{}" + // is not treated as an additional placeholder + final String rendered = MessageFormatter.arrayFormat( + formatCaptor.getValue(), new Object[] {requestIdCaptor.getValue(), messageCaptor.getValue()}) + .getMessage(); + assertFalse(rendered.contains("\r")); + assertFalse(rendered.contains("\n")); + assertEquals( + "REQUEST_1 - 17 LOG Method=GET, PathInfo=/content/x\\r\\n2026-08-11 FAKE admin login OK {}", rendered); + } + + @Test + public void testLogCompactFormatEscapesEveryMessageBeforeJoining() throws Exception { + final String benign = "20 TIMER_START{handleSecurity}"; + final String attackerMessage = "17 LOG Method=GET, PathInfo=/content/x\r\nFORGED admin login OK"; + final RequestProgressTracker rpt = rptWithMessages(benign, attackerMessage); + + final RequestProgressTrackerLogFilter filter = new RequestProgressTrackerLogFilter(); + final Logger logger = injectMockLogger(filter); + + invokeLogFormat(filter, "logCompactFormat", rpt); + + final ArgumentCaptor<String> messageCaptor = ArgumentCaptor.forClass(String.class); + Mockito.verify(logger, times(1)).debug(messageCaptor.capture()); + + final String logged = messageCaptor.getValue(); + assertFalse(logged.contains("\r")); + assertFalse("no raw newline may remain other than the message separators", logged.contains("\r\n")); + assertEquals( + "\n" + benign + "\n" + "17 LOG Method=GET, PathInfo=/content/x\\r\\nFORGED admin login OK", logged); + } + @Test public void testConfigMsec() throws Exception { final RequestProgressTrackerLogFilter filter = new RequestProgressTrackerLogFilter();
