This is an automated email from the ASF dual-hosted git repository.
xiangfu0 pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/pinot.git
The following commit(s) were added to refs/heads/master by this push:
new c6116095f7d Log a query on a single line (#19453)
c6116095f7d is described below
commit c6116095f7d3834613649c770d75fed7dd5a874a
Author: shivam-startree <[email protected]>
AuthorDate: Wed Sep 9 05:05:27 2026 +0530
Log a query on a single line (#19453)
* Log a query on a single line
Collapses CR/LF runs in a query to a single space before it is logged.
Clients routinely submit pretty-printed SQL -- JDBC and BI tools do it by
default -- and the broker logs the query verbatim. A single log event then
renders as one physical line per line of SQL as soon as anything downstream
splits on newlines: a container runtime, a log shipper, a file tailer.
Measured on one production broker, 60s, 3,995 queries:
"SQL query for request <id>:" header lines 3,995
continuation lines after it 30,975 (7.8 per query)
completion stats lines 3,994
continuation lines after those 30,969 (7.8 per query)
------------------------------------------------------
total unmarked SQL lines 61,944 = 79.4% of that
broker's entire
log volume
Collapsing newlines removes those 61,944 lines while keeping both log
records and every field they carry -- 2 lines per query instead of 15.5.
The continuation lines are worse than merely numerous. They carry no
timestamp, level or logger name, so nothing downstream can filter, sample
or attribute them, and a multiline log collector will attach them to
whichever record happened to precede them -- silently corrupting an
unrelated log entry as well as the query.
Applied inside redactQuery, which every query-logging call site in the
broker already routes through (~45 of them across QueryLogger,
BaseSingleStageBrokerRequestHandler and MultiStageBrokerRequestHandler),
so the broker's error and cancellation paths get the same treatment rather
than just the two QueryLogger sites. Every caller is a log statement, so
normalising there is consistent with the method's purpose.
Only line breaks are touched. Indentation and spacing within a line are
left alone, so the logged text stays as close to what the client sent as a
single-line rendering allows and remains copy-pasteable. The FULL and
LITERAL_VALUES redaction modes are unaffected -- neither returns a
multi-line value.
Adds two tests, one per log site, and a generateParams overload so a test
can supply the query text.
* Escape line breaks rather than collapsing them
Review catch: replacing a newline with a space is not semantics-preserving.
A newline terminates a line comment, and Pinot's grammar accepts both forms
(SINGLE_LINE_COMMENT in Parser.jj: ("//"|"--")(~["\n","\r"])* ...), so
SELECT a -- note
FROM t
would have been logged as
SELECT a -- note FROM t
which no longer parses, and no longer means what was actually run. The
logged query is a debugging aid people copy and replay, so silently
changing it is worse than leaving it on several lines.
Escaping CR/LF as \r and \n keeps the record on one physical line without
removing or reinterpreting a single character. Queries already on one line
are returned untouched, so nothing changes for the common case.
Checked for an existing helper first: LoggerUtils is the runtime log-level
API, and commons-text is managed in the root pom but not a pinot-broker
dependency -- and StringEscapeUtils.escapeJava would be too aggressive
here, escaping double quotes and unicode and so mangling quoted
identifiers. There is no existing precedent in the tree for escaping
newlines in logged user-supplied text, hence the local two-character
replace.
Tests: reworked for the escaped form, plus a regression test for the line
comment case above and one asserting a single-line query is passed through
unchanged.
* Make single-line query log escaping reversible
---------
Co-authored-by: Xiang Fu <[email protected]>
---
.../apache/pinot/broker/querylog/QueryLogger.java | 16 ++-
.../pinot/broker/querylog/QueryLoggerTest.java | 133 ++++++++++++++++++++-
2 files changed, 146 insertions(+), 3 deletions(-)
diff --git
a/pinot-broker/src/main/java/org/apache/pinot/broker/querylog/QueryLogger.java
b/pinot-broker/src/main/java/org/apache/pinot/broker/querylog/QueryLogger.java
index 2e30a87108e..6276ddeb265 100644
---
a/pinot-broker/src/main/java/org/apache/pinot/broker/querylog/QueryLogger.java
+++
b/pinot-broker/src/main/java/org/apache/pinot/broker/querylog/QueryLogger.java
@@ -50,7 +50,7 @@ public class QueryLogger {
private static final String FULLY_REDACTED = "REDACTED";
public enum SqlRedactionMode {
- // Log the full SQL query text as-is.
+ // Log the full SQL query text with backslashes and line endings escaped.
// e.g. "SELECT name FROM users WHERE id = 42 AND status = 'active'"
NONE,
// Replace literal values with placeholders using the query fingerprint,
preserving query structure.
@@ -201,10 +201,22 @@ public class QueryLogger {
return queryFingerprint != null ? queryFingerprint.getFingerprint() :
FINGERPRINT_FAILED_QUERY_REDACTED;
case NONE:
default:
- return query;
+ return toSingleLine(query);
}
}
+ /// Escapes backslashes, CR and LF as `\\`, `\r` and `\n` so the query
occupies a single log line.
+ /// A line ending can terminate a `--` or `//` comment, so replacing it with
a space changes SQL semantics.
+ /// Escaping existing backslashes distinguishes literal escape sequences
from encoded line endings.
+ /// Decode these three escape sequences in a single pass before replaying
untruncated logged SQL.
+ @Nullable
+ private static String toSingleLine(@Nullable String query) {
+ if (query == null || (query.indexOf('\\') < 0 && query.indexOf('\n') < 0
&& query.indexOf('\r') < 0)) {
+ return query;
+ }
+ return query.replace("\\", "\\\\").replace("\r", "\\r").replace("\n",
"\\n");
+ }
+
private boolean shouldForceLog(@Nullable QueryLogParams params) {
if (params == null) {
return false;
diff --git
a/pinot-broker/src/test/java/org/apache/pinot/broker/querylog/QueryLoggerTest.java
b/pinot-broker/src/test/java/org/apache/pinot/broker/querylog/QueryLoggerTest.java
index 80583db3b5f..58dd30cc3e8 100644
---
a/pinot-broker/src/test/java/org/apache/pinot/broker/querylog/QueryLoggerTest.java
+++
b/pinot-broker/src/test/java/org/apache/pinot/broker/querylog/QueryLoggerTest.java
@@ -41,10 +41,15 @@ import org.slf4j.Logger;
import org.testng.Assert;
import org.testng.annotations.AfterMethod;
import org.testng.annotations.BeforeMethod;
+import org.testng.annotations.DataProvider;
import org.testng.annotations.Test;
import static org.apache.pinot.broker.querylog.QueryLogger.SqlRedactionMode;
+import static org.mockito.Mockito.when;
import static org.mockito.MockitoAnnotations.openMocks;
+import static org.testng.Assert.assertEquals;
+import static org.testng.Assert.assertFalse;
+import static org.testng.Assert.assertTrue;
@SuppressWarnings("UnstableApiUsage")
@@ -225,6 +230,126 @@ public class QueryLoggerTest {
Assert.assertTrue(_infoLog.get(0).contains("SQL query for request 123"));
}
+ @Test
+ public void shouldLogMultiLineQueryOnASingleLine() {
+ // Given: a client that submits pretty-printed SQL, as JDBC/BI tools
routinely do
+ when(_logRateLimiter.tryAcquire()).thenReturn(true);
+ QueryLogger queryLogger = new QueryLogger(_logRateLimiter, 10_000, true,
true,
+ SqlRedactionMode.NONE, _logger, _droppedRateLimiter);
+ String prettyPrinted = "SELECT id, name\nFROM users\r\nWHERE id =
42\nLIMIT 10";
+
+ // When:
+ queryLogger.logQueryReceived(123L, prettyPrinted, null);
+
+ // Then: one record, on one physical line
+ assertEquals(_infoLog.size(), 1);
+ String logged = _infoLog.get(0);
+ assertFalse(logged.contains("\n"), "logged query must not contain a line
feed: " + logged);
+ assertFalse(logged.contains("\r"), "logged query must not contain a
carriage return: " + logged);
+ // and the breaks are escaped, not discarded, so nothing is lost
+ assertTrue(logged.contains("SELECT id, name\\nFROM users\\r\\nWHERE id =
42\\nLIMIT 10"), logged);
+ }
+
+ @DataProvider(name = "lineComments")
+ public Object[][] lineComments() {
+ return new Object[][]{{"--"}, {"//"}};
+ }
+
+ @Test(dataProvider = "lineComments")
+ public void shouldNotBreakLineCommentsWhenLoggingOnASingleLine(String
commentPrefix) {
+ // Given: a query whose line comment is terminated by the newline. Pinot's
grammar accepts both
+ // "--" and "//" line comments (SINGLE_LINE_COMMENT in Parser.jj), so
replacing the break with a
+ // space would pull "FROM t" into the comment and change what the logged
query means.
+ when(_logRateLimiter.tryAcquire()).thenReturn(true);
+ QueryLogger queryLogger = new QueryLogger(_logRateLimiter, 10_000, true,
true,
+ SqlRedactionMode.NONE, _logger, _droppedRateLimiter);
+
+ // When:
+ String query = "SELECT a " + commentPrefix + " note\nFROM t";
+ queryLogger.logQueryReceived(123L, query, null);
+
+ // Then:
+ assertEquals(_infoLog.size(), 1);
+ String logged = _infoLog.get(0);
+ assertFalse(logged.contains("\n"), logged);
+ assertEquals(logged, "SQL query for request 123: SELECT a " +
commentPrefix + " note\\nFROM t");
+ assertEquals(logged.substring("SQL query for request 123:
".length()).translateEscapes(), query);
+ assertFalse(logged.contains(commentPrefix + " note FROM t"),
+ "the comment must not swallow the rest of the statement: " + logged);
+ }
+
+ @Test
+ public void shouldLeaveASingleLineQueryUntouched() {
+ // Given:
+ when(_logRateLimiter.tryAcquire()).thenReturn(true);
+ QueryLogger queryLogger = new QueryLogger(_logRateLimiter, 10_000, true,
true,
+ SqlRedactionMode.NONE, _logger, _droppedRateLimiter);
+
+ // When:
+ queryLogger.logQueryReceived(123L, "SELECT a FROM t WHERE s = 'x'", null);
+
+ // Then: no escaping applied to a query that was already on one line
+ assertEquals(_infoLog.size(), 1);
+ assertTrue(_infoLog.get(0).contains("SELECT a FROM t WHERE s = 'x'"),
_infoLog.get(0));
+ }
+
+ @Test
+ public void shouldLogMultiLineQueryOnASingleLineOnCompletion() {
+ // Given: the completion record carries the query too, so it needs the
same treatment
+ when(_logRateLimiter.tryAcquire()).thenReturn(true);
+ QueryLogger queryLogger = new QueryLogger(_logRateLimiter, 10_000, true,
false,
+ SqlRedactionMode.NONE, _logger, _droppedRateLimiter);
+ QueryLogger.QueryLogParams params =
+ generateParams(false, false, 0, 456, null, "SELECT id\nFROM
users\nLIMIT 1");
+
+ // When:
+ queryLogger.logQueryCompleted(params, true);
+
+ // Then:
+ assertEquals(_infoLog.size(), 1);
+ String logged = _infoLog.get(0);
+ assertFalse(logged.contains("\n"), logged);
+ assertTrue(logged.contains("query=SELECT id\\nFROM users\\nLIMIT 1"),
logged);
+ }
+
+ @DataProvider(name = "queriesWithEscapedCharacters")
+ public Object[][] queriesWithEscapedCharacters() {
+ return new Object[][]{
+ {"SELECT 'a\nb' FROM t", "SELECT 'a\\nb' FROM t"},
+ {"SELECT 'a\\nb' FROM t", "SELECT 'a\\\\nb' FROM t"},
+ {"SELECT 'a\rb' FROM t", "SELECT 'a\\rb' FROM t"},
+ {"SELECT 'a\\rb' FROM t", "SELECT 'a\\\\rb' FROM t"},
+ {"SELECT 'a\\\nb' FROM t", "SELECT 'a\\\\\\nb' FROM t"},
+ {"SELECT 'a\n\\b' FROM t", "SELECT 'a\\n\\\\b' FROM t"},
+ {"SELECT 'a\\\r\nb' FROM t", "SELECT 'a\\\\\\r\\nb' FROM t"},
+ {"SELECT 'a\\\\b' FROM t", "SELECT 'a\\\\\\\\b' FROM t"},
+ {"SELECT '\\d+\\s+\\w+' FROM t", "SELECT '\\\\d+\\\\s+\\\\w+' FROM t"},
+ {"SELECT '\\t\\b\\f\\141' FROM t", "SELECT '\\\\t\\\\b\\\\f\\\\141'
FROM t"},
+ {"SELECT\t'a\tb' FROM t", "SELECT\t'a\tb' FROM t"}
+ };
+ }
+
+ @Test(dataProvider = "queriesWithEscapedCharacters")
+ public void shouldLogQueryWithReversibleEscaping(String query, String
expected) {
+ when(_logRateLimiter.tryAcquire()).thenReturn(true);
+ QueryLogger queryLogger = new QueryLogger(_logRateLimiter, 10_000, true,
true,
+ SqlRedactionMode.NONE, _logger, _droppedRateLimiter);
+
+ queryLogger.logQueryReceived(123L, query, null);
+ queryLogger.logQueryCompleted(generateParams(false, false, 0, 456, null,
query), true);
+
+ assertEquals(_infoLog.size(), 2);
+ String receivedQuery = _infoLog.get(0).substring("SQL query for request
123: ".length());
+ String completedLog = _infoLog.get(1);
+ String completedQuery =
completedLog.substring(completedLog.indexOf(",query=") + ",query=".length());
+ for (String loggedQuery : List.of(receivedQuery, completedQuery)) {
+ assertEquals(loggedQuery, expected);
+ assertFalse(loggedQuery.contains("\n"));
+ assertFalse(loggedQuery.contains("\r"));
+ assertEquals(loggedQuery.translateEscapes(), query);
+ }
+ }
+
@Test
public void shouldNotLogQueryReceivedWhenRateLimited() {
// Given: rate limiter denies
@@ -476,9 +601,15 @@ public class QueryLoggerTest {
private QueryLogger.QueryLogParams generateParams(boolean
numGroupsLimitReached, boolean numGroupsWarningLimitReached,
int numExceptions, long timeUsedMs, QueryFingerprint queryFingerprint) {
+ return generateParams(numGroupsLimitReached, numGroupsWarningLimitReached,
numExceptions, timeUsedMs,
+ queryFingerprint, "SELECT * FROM foo");
+ }
+
+ private QueryLogger.QueryLogParams generateParams(boolean
numGroupsLimitReached, boolean numGroupsWarningLimitReached,
+ int numExceptions, long timeUsedMs, QueryFingerprint queryFingerprint,
String query) {
RequestContext requestContext = new DefaultRequestContext();
requestContext.setRequestId(123);
- requestContext.setQuery("SELECT * FROM foo");
+ requestContext.setQuery(query);
requestContext.setNumUnavailableSegments(21);
if (queryFingerprint != null) {
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
