This is an automated email from the ASF dual-hosted git repository. asf-gitbox-commits pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/cayenne.git
commit c69fd67632d478a9ef0dc2affe19ca4d6e3a7543 Author: Andrus Adamchik <[email protected]> AuthorDate: Sat Jul 4 18:20:46 2026 -0400 CAY-2912 Compact SQL logger trying a new format --- .../org/apache/cayenne/access/LoggingObserver.java | 6 +- .../org/apache/cayenne/log/Slf4jSqlLogger.java | 53 +++++++------- .../org/apache/cayenne/log/SqlBindingRenderer.java | 24 +++---- .../apache/cayenne/access/LoggingObserverTest.java | 15 ++++ .../org/apache/cayenne/log/Slf4jSqlLoggerTest.java | 80 ++++++++++++---------- 5 files changed, 99 insertions(+), 79 deletions(-) diff --git a/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java b/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java index 04feb4793..07be51b70 100644 --- a/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java +++ b/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java @@ -77,7 +77,11 @@ class LoggingObserver implements OperationObserver { private void reportUpdate(int rowCount) { if (headerEmitted) { - logger.logAlsoUpdate(rowCount); + // a trailing zero update count is driver noise (e.g. a stored procedure's completion status reported + // after its result set), so skip the stray "also updated:0" line + if (rowCount != 0) { + logger.logAlsoUpdate(rowCount); + } } else { logger.logUpdate(current, rowCount, generatedKeys != null ? generatedKeys : List.of(), elapsedMillis()); headerEmitted = true; diff --git a/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java b/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java index 5a44635c8..a531ce1f5 100644 --- a/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java +++ b/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java @@ -53,8 +53,9 @@ public class Slf4jSqlLogger implements SqlLogger { @Override public void logSelect(TranslatedStatement statement, int rowCount, long durationMillis) { if (LOGGER.isInfoEnabled()) { - StringBuilder buffer = new StringBuilder(buildStatementLine(statement, "selected:", rowCount)); - appendDuration(buffer, durationMillis); + StringBuilder buffer = new StringBuilder(); + appendStatementLine(buffer, statement, "selected:", rowCount); + buffer.append(" time_ms:").append(durationMillis); LOGGER.info(buffer.toString()); } } @@ -63,15 +64,15 @@ public class Slf4jSqlLogger implements SqlLogger { public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys, long durationMillis) { if (LOGGER.isInfoEnabled()) { - StringBuilder buffer = new StringBuilder(buildStatementLine(statement, "updated:", rowCount)); + StringBuilder buffer = new StringBuilder(); + appendStatementLine(buffer, statement, "updated:", rowCount); if (generatedKeys != null && !generatedKeys.isEmpty()) { - buffer.append(" [generated:"); + buffer.append(" generated:"); for (Map<String, ?> keys : generatedKeys) { SqlBindingRenderer.appendGeneratedKeys(buffer, keys); } - buffer.append(']'); } - appendDuration(buffer, durationMillis); + buffer.append(" time_ms:").append(durationMillis); LOGGER.info(buffer.toString()); } } @@ -79,47 +80,45 @@ public class Slf4jSqlLogger implements SqlLogger { @Override public void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis) { if (LOGGER.isErrorEnabled()) { - LOGGER.error(buildErrorLine(statement, error, durationMillis)); + StringBuilder buffer = new StringBuilder(); + appendErrorLine(buffer, statement, error, durationMillis); + LOGGER.error(buffer.toString()); } } - protected String buildStatementLine(TranslatedStatement statement, String resultLabel, int rowCount) { - StringBuilder buffer = buildSqlAndBindings(statement); - return buffer.append('[').append(resultLabel).append(rowCount).append(']').toString(); + void appendStatementLine(StringBuilder buffer, TranslatedStatement statement, String resultLabel, int rowCount) { + appendSqlAndBindings(buffer, statement); + buffer.append(' ').append(resultLabel).append(rowCount); } - protected String buildErrorLine(TranslatedStatement statement, Throwable error, long durationMillis) { - StringBuilder buffer = buildSqlAndBindings(statement); - buffer.append("[time_ms:").append(durationMillis).append(']'); - buffer.append(" [*** error: ").append(error != null ? error.getMessage() : null).append(']'); - return buffer.toString(); + void appendErrorLine(StringBuilder buffer, TranslatedStatement statement, Throwable error, long durationMillis) { + appendSqlAndBindings(buffer, statement); + buffer.append(" time_ms:").append(durationMillis); + buffer.append(" error: ").append(error != null ? error.getMessage() : null); } - // builds "SQL [bind:[...]] " with a guaranteed trailing space, ready for a result or error suffix - private StringBuilder buildSqlAndBindings(TranslatedStatement statement) { - StringBuilder buffer = new StringBuilder(statement.sql()).append(' '); + private void appendSqlAndBindings(StringBuilder buffer, TranslatedStatement statement) { + buffer.append(statement.sql()).append(" |"); + int lengthWithoutBindings = buffer.length(); + buffer.append(' '); SqlBindingRenderer.appendBindings(buffer, statement, batchRowThreshold); - if (buffer.charAt(buffer.length() - 1) != ' ') { - buffer.append(' '); + if (buffer.length() == lengthWithoutBindings + 1) { + // no bindings were rendered - drop the separator space so the next block follows "|" directly + buffer.setLength(lengthWithoutBindings); } - return buffer; - } - - private static void appendDuration(StringBuilder buffer, long durationMillis) { - buffer.append(" [time_ms:").append(durationMillis).append(']'); } @Override public void logAlsoSelect(int rowCount) { if (LOGGER.isInfoEnabled()) { - LOGGER.info("also [selected:{}]", rowCount); + LOGGER.info("also selected:{}", rowCount); } } @Override public void logAlsoUpdate(int rowCount) { if (LOGGER.isInfoEnabled()) { - LOGGER.info("also [updated:{}]", rowCount); + LOGGER.info("also updated:{}", rowCount); } } diff --git a/cayenne/src/main/java/org/apache/cayenne/log/SqlBindingRenderer.java b/cayenne/src/main/java/org/apache/cayenne/log/SqlBindingRenderer.java index 4a87fb027..8c50c5bdb 100644 --- a/cayenne/src/main/java/org/apache/cayenne/log/SqlBindingRenderer.java +++ b/cayenne/src/main/java/org/apache/cayenne/log/SqlBindingRenderer.java @@ -33,16 +33,10 @@ import java.util.Map; /** * Renders the parameter bindings of a {@link TranslatedStatement} in the compact {@code bind:[...]} form used by - * {@link SqlLogger} and by exception messages. Shared so that logged and thrown SQL look identical. + * {@link SqlLogger}. */ class SqlBindingRenderer { - /** - * Appends the {@code bind:[...]} fragment for the given statement to the buffer, or nothing if the statement has - * no bindings. Batch bindings with more rows than {@code batchRowThreshold} are truncated to first row, - * {@code ..<eliddedCount>..}, last row. - */ - @SuppressWarnings({"rawtypes", "unchecked"}) public static void appendBindings(StringBuilder buffer, TranslatedStatement statement, int batchRowThreshold) { switch (statement) { case TranslatedSelect s -> appendParameters(buffer, s.bindings()); @@ -73,7 +67,7 @@ class SqlBindingRenderer { if (bindings.length == 0) { return; } - buffer.append("[bind:["); + buffer.append("bind:["); for (int i = 0; i < bindings.length; i++) { if (i > 0) { buffer.append(","); @@ -81,14 +75,14 @@ class SqlBindingRenderer { PSParameter<?> b = bindings[i]; appendNamedValue(buffer, b.attribute() != null ? b.attribute().getName() : null, b.binder(), b.value()); } - buffer.append("]]"); + buffer.append("]"); } private static void appendCallParameters(StringBuilder buffer, CSParameter<?>[] params) { if (params.length == 0) { return; } - buffer.append("[bind:["); + buffer.append("bind:["); for (int i = 0; i < params.length; i++) { if (i > 0) { buffer.append(","); @@ -96,7 +90,7 @@ class SqlBindingRenderer { CSParameter<?> b = params[i]; appendNamedValue(buffer, b.param() != null ? b.param().getName() : null, b.binder(), b.value()); } - buffer.append("]]"); + buffer.append("]"); } private static void appendBatch(StringBuilder buffer, PSBatchParameter[] bindings, int batchRowThreshold) { @@ -118,8 +112,8 @@ class SqlBindingRenderer { } // rows are delimited by their own [...] brackets, so no extra list bracket is needed: a single-row batch - // reads as [bind:[...]] and a multi-row batch as [bind:[...][...]] - never a doubled [[...]] - buffer.append("[bind:"); + // reads as bind:[...] and a multi-row batch as bind:[...][...] - never a doubled [[...]] + buffer.append("bind:"); if (rows > batchRowThreshold) { // show up to batchRowThreshold rows split evenly between head and tail, eliding the middle. For an odd // threshold the head gets the extra row, so head + tail == batchRowThreshold and the elided count is @@ -138,7 +132,6 @@ class SqlBindingRenderer { appendBatchRow(buffer, bindings, r); } } - buffer.append(']'); } private static void appendBatchRow(StringBuilder buffer, PSBatchParameter[] bindings, int row) { @@ -157,8 +150,7 @@ class SqlBindingRenderer { } } - @SuppressWarnings({"rawtypes", "unchecked"}) - private static void appendNamedValue(StringBuilder buffer, String name, ExtendedType binder, Object value) { + private static void appendNamedValue(StringBuilder buffer, String name, ExtendedType<?> binder, Object value) { if (name != null) { buffer.append(name).append(':'); } diff --git a/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java b/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java index 9358eb794..e5833db27 100644 --- a/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java +++ b/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java @@ -160,6 +160,21 @@ public class LoggingObserverTest { assertEquals(List.of("selected:5", "also updated:10", "also updated:20"), logger.calls); } + @Test + public void trailingZeroUpdateCountNotReportedAsAlso() { + // a stored procedure reports its completion status as a 0 update count after the result set - this must not + // surface as a stray "also updated:0" line + CapturingLogger logger = new CapturingLogger(); + LoggingObserver observer = observer(logger); + + observer.nextStatement(null, procedure()); + observer.nextRows(null, List.of(new Object())); + observer.nextCount(null, 0); + observer.onSuccess(); + + assertEquals(List.of("selected:1"), logger.calls); + } + @Test public void emptyBatchCountDoesNotEmitStrayUpdate() { // a SQLTemplate SELECT reports its (absent) update counts via an empty nextBatchCount - must not log diff --git a/cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java b/cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java index 337edb1b9..9829861b3 100644 --- a/cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java +++ b/cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java @@ -24,6 +24,7 @@ import org.apache.cayenne.access.jdbc.PSParameter; import org.apache.cayenne.access.jdbc.RSColumn; import org.apache.cayenne.access.translator.TranslatedBatch; import org.apache.cayenne.access.translator.TranslatedSelect; +import org.apache.cayenne.access.translator.TranslatedStatement; import org.apache.cayenne.configuration.Constants; import org.apache.cayenne.configuration.RuntimeProperties; import org.apache.cayenne.map.DbAttribute; @@ -55,8 +56,16 @@ public class Slf4jSqlLoggerTest { return new Slf4jSqlLogger(props); } - private static PSParameter<?> ps(String name, Object value) { - return new PSParameter<>(value, 1, Types.INTEGER, 0, null, new DbAttribute(name)); + private static String line(Slf4jSqlLogger logger, TranslatedStatement statement, String label, int count) { + StringBuilder buffer = new StringBuilder(); + logger.appendStatementLine(buffer, statement, label, count); + return buffer.toString(); + } + + private static String errorLine(Slf4jSqlLogger logger, TranslatedStatement statement, Throwable error, long durationMillis) { + StringBuilder buffer = new StringBuilder(); + logger.appendErrorLine(buffer, statement, error, durationMillis); + return buffer.toString(); } // a single-placeholder batch whose id values are 0..rows-1, so each logged row is identifiable by its value @@ -73,23 +82,24 @@ public class Slf4jSqlLoggerTest { public void selectLineWithSingleBinding() { TranslatedSelect select = new TranslatedSelect( "SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?", - new PSParameter<?>[]{ps("user_id", 15)}, + new PSParameter<?>[]{new PSParameter<>(15, 1, Types.INTEGER, 0, null, new DbAttribute("user_id"))}, new RSColumn[0], false, false); - assertEquals("SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? [bind:[user_id:15]] [selected:1]", - logger.buildStatementLine(select, "selected:", 1)); + assertEquals( + "SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? | bind:[user_id:15] selected:1", + line(logger, select, "selected:", 1)); } @Test public void errorLineCarriesBindingsMessageAndDuration() { TranslatedSelect select = new TranslatedSelect( "SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?", - new PSParameter<?>[]{ps("user_id", 15)}, + new PSParameter<?>[]{new PSParameter<>(15, 1, Types.INTEGER, 0, null, new DbAttribute("user_id"))}, new RSColumn[0], false, false); - assertEquals("SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? [bind:[user_id:15]] " - + "[time_ms:1000] [*** error: bad column]", - logger.buildErrorLine(select, new RuntimeException("bad column"), 1000)); + assertEquals( + "SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? | bind:[user_id:15] time_ms:1000 error: bad column", + errorLine(logger, select, new RuntimeException("bad column"), 1000)); } @Test @@ -97,8 +107,9 @@ public class Slf4jSqlLoggerTest { TranslatedSelect select = new TranslatedSelect( "SELECT t0.id FROM my_table t0", new PSParameter<?>[0], new RSColumn[0], false, false); - assertEquals("SELECT t0.id FROM my_table t0 [selected:0]", - logger.buildStatementLine(select, "selected:", 0)); + assertEquals( + "SELECT t0.id FROM my_table t0 | selected:0", + line(logger, select, "selected:", 0)); } @Test @@ -112,9 +123,9 @@ public class Slf4jSqlLoggerTest { TranslatedBatch batch = new TranslatedBatch( "INSERT INTO table1(id, name) VALUES(?, ?)", new PSBatchParameter[]{id, name}); - assertEquals("INSERT INTO table1(id, name) VALUES(?, ?) " - + "[bind:[id:3,name:'n3'][id:1,name:'n1']..2..[id:2,name:'n2']] [updated:5]", - logger.buildStatementLine(batch, "updated:", 5)); + assertEquals( + "INSERT INTO table1(id, name) VALUES(?, ?) | bind:[id:3,name:'n3'][id:1,name:'n1']..2..[id:2,name:'n2'] updated:5", + line(logger, batch, "updated:", 5)); } @Test @@ -127,8 +138,9 @@ public class Slf4jSqlLoggerTest { TranslatedBatch batch = new TranslatedBatch( "INSERT INTO ARTIST(ARTIST_ID, ARTIST_NAME) VALUES(?, ?)", new PSBatchParameter[]{id, name}); - assertEquals("INSERT INTO ARTIST(ARTIST_ID, ARTIST_NAME) VALUES(?, ?) [bind:[ARTIST_ID:200,ARTIST_NAME:'Test']] [updated:1]", - logger.buildStatementLine(batch, "updated:", 1)); + assertEquals( + "INSERT INTO ARTIST(ARTIST_ID, ARTIST_NAME) VALUES(?, ?) | bind:[ARTIST_ID:200,ARTIST_NAME:'Test'] updated:1", + line(logger, batch, "updated:", 1)); } @Test @@ -136,49 +148,47 @@ public class Slf4jSqlLoggerTest { PSBatchParameter id = new PSBatchParameter( new Object[]{3, 2}, 1, Types.INTEGER, 0, new DbAttribute("id")); - TranslatedBatch batch = new TranslatedBatch( - "INSERT INTO table1(id) VALUES(?)", new PSBatchParameter[]{id}); - - assertEquals("INSERT INTO table1(id) VALUES(?) [bind:[id:3][id:2]] [updated:2]", - logger.buildStatementLine(batch, "updated:", 2)); + TranslatedBatch batch = new TranslatedBatch("INSERT INTO table1(id) VALUES(?)", new PSBatchParameter[]{id}); + assertEquals("INSERT INTO table1(id) VALUES(?) | bind:[id:3][id:2] updated:2", + line(logger, batch, "updated:", 2)); } @Test public void batchLineEvenThresholdSplitsEvenly() { // even threshold 4 -> head 2, tail 2; 10 rows -> middle 6 elided - assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1]..6..[id:8][id:9]] [updated:10]", - loggerWithThreshold(4).buildStatementLine(idBatch(10), "updated:", 10)); + assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1]..6..[id:8][id:9] updated:10", + line(loggerWithThreshold(4), idBatch(10), "updated:", 10)); } @Test public void batchLineShowsAllRowsAtThreshold() { // exactly threshold rows -> nothing elided - assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1][id:2][id:3]] [updated:4]", - loggerWithThreshold(4).buildStatementLine(idBatch(4), "updated:", 4)); + assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1][id:2][id:3] updated:4", + line(loggerWithThreshold(4), idBatch(4), "updated:", 4)); } @Test public void batchLineElidesExactlyOneAboveThreshold() { // one row above threshold 4 -> head 2, tail 2, a single row elided - assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1]..1..[id:3][id:4]] [updated:5]", - loggerWithThreshold(4).buildStatementLine(idBatch(5), "updated:", 5)); + assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1]..1..[id:3][id:4] updated:5", + line(loggerWithThreshold(4), idBatch(5), "updated:", 5)); } @Test public void batchLineThresholdOfOneOrTwoClampsToTwo() { // threshold 1 and 2 both clamp to 2 -> head 1, tail 1 - assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0]..3..[id:4]] [updated:5]", - loggerWithThreshold(1).buildStatementLine(idBatch(5), "updated:", 5)); - assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0]..3..[id:4]] [updated:5]", - loggerWithThreshold(2).buildStatementLine(idBatch(5), "updated:", 5)); + assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0]..3..[id:4] updated:5", + line(loggerWithThreshold(1), idBatch(5), "updated:", 5)); + assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0]..3..[id:4] updated:5", + line(loggerWithThreshold(2), idBatch(5), "updated:", 5)); } @Test public void batchLineNonPositiveThresholdDisablesTruncation() { // threshold 0 or negative -> no truncation, every row logged - assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1][id:2][id:3][id:4]] [updated:5]", - loggerWithThreshold(0).buildStatementLine(idBatch(5), "updated:", 5)); - assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1][id:2][id:3][id:4]] [updated:5]", - loggerWithThreshold(-1).buildStatementLine(idBatch(5), "updated:", 5)); + assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1][id:2][id:3][id:4] updated:5", + line(loggerWithThreshold(0), idBatch(5), "updated:", 5)); + assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1][id:2][id:3][id:4] updated:5", + line(loggerWithThreshold(-1), idBatch(5), "updated:", 5)); } }
