CAY-2912 Compact SQL logger

andrus · andrus · commit 410e8ebcfe86 · 2026-07-04T08:05:08.000-04:00
cleanup
diff --git a/cayenne/src/main/java/org/apache/cayenne/access/DataDomainQueryAction.java b/cayenne/src/main/java/org/apache/cayenne/access/DataDomainQueryAction.java
@@ -679,11 +679,9 @@ public void nextRows(Query q, ResultIterator<?> it) {
     }
 
     @Override
-    public void nextGeneratedRows(Query query, ResultIterator<?> keys, List<ObjectId> idsToUpdate) {
+    public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {
         if (keys != null) {
-            try (keys) {
-                nextRows(query, keys.allRows());
-            }
+            nextRows(query, keys);
         }
     }
 
diff --git a/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java b/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java
@@ -19,6 +19,7 @@
 
 package org.apache.cayenne.access;
 
+import org.apache.cayenne.DataRow;
 import org.apache.cayenne.ObjectId;
 import org.apache.cayenne.ResultIterator;
 import org.apache.cayenne.access.translator.TranslatedBatch;
@@ -150,7 +151,10 @@ public void nextRows(Query q, ResultIterator<?> it) {
     }
 
     @Override
-    public void nextGeneratedRows(Query query, ResultIterator<?> keys, List<ObjectId> idsToUpdate) {
+    public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {
+        for (DataRow key : keys) {
+            logger.logGeneratedKey(key);
+        }
         delegate.nextGeneratedRows(query, keys, idsToUpdate);
     }
 
diff --git a/cayenne/src/main/java/org/apache/cayenne/access/OperationObserver.java b/cayenne/src/main/java/org/apache/cayenne/access/OperationObserver.java
@@ -20,6 +20,7 @@
 package org.apache.cayenne.access;
 
 import org.apache.cayenne.CayenneRuntimeException;
+import org.apache.cayenne.DataRow;
 import org.apache.cayenne.ObjectId;
 import org.apache.cayenne.ResultIterator;
 import org.apache.cayenne.access.translator.TranslatedStatement;
@@ -96,9 +97,9 @@ default void nextRows(Query q, ResultIterator<?> it) {
     /**
      * Callback method invoked after each batch of generated values is read during an update.
      *
-     * @since 4.2
+     * @since 5.0
      */
-    default void nextGeneratedRows(Query query, ResultIterator<?> keys, List<ObjectId> idsToUpdate) {
+    default void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {
     }
 
     /**
diff --git a/cayenne/src/main/java/org/apache/cayenne/access/flush/DefaultDataDomainFlushAction.java b/cayenne/src/main/java/org/apache/cayenne/access/flush/DefaultDataDomainFlushAction.java
@@ -38,7 +38,6 @@
 import org.apache.cayenne.access.flush.operation.UpdateDbRowOp;
 import org.apache.cayenne.graph.CompoundDiff;
 import org.apache.cayenne.graph.GraphDiff;
-import org.apache.cayenne.log.SqlLogger;
 import org.apache.cayenne.map.EntityResolver;
 import org.apache.cayenne.query.Query;
 
@@ -61,16 +60,14 @@ public class DefaultDataDomainFlushAction implements DataDomainFlushAction {
 
     protected final DataDomain dataDomain;
     protected final DbRowOpSorter dbRowOpSorter;
-    protected final SqlLogger sqlLogger;
     protected final OperationObserver observer;
     protected final DeleteDbRowOpFactory deleteDbRowOpFactory;
 
     protected DefaultDataDomainFlushAction(DataDomain dataDomain, DbRowOpSorter dbRowOpSorter,
-                                           SqlLogger sqlLogger, DeleteDbRowOpFactory deleteDbRowOpFactory) {
+                                           DeleteDbRowOpFactory deleteDbRowOpFactory) {
         this.dataDomain = dataDomain;
         this.dbRowOpSorter = dbRowOpSorter;
-        this.sqlLogger = sqlLogger;
-        this.observer = new FlushObserver(sqlLogger);
+        this.observer = new FlushObserver();
         this.deleteDbRowOpFactory = deleteDbRowOpFactory;
     }
 
diff --git a/cayenne/src/main/java/org/apache/cayenne/access/flush/DefaultDataDomainFlushActionFactory.java b/cayenne/src/main/java/org/apache/cayenne/access/flush/DefaultDataDomainFlushActionFactory.java
@@ -23,7 +23,6 @@
 import org.apache.cayenne.access.flush.operation.DbRowOpSorter;
 import org.apache.cayenne.access.flush.operation.DeleteDbRowOpFactory;
 import org.apache.cayenne.di.Inject;
-import org.apache.cayenne.log.SqlLogger;
 
 /**
  * Factory that produces {@link DefaultDataDomainFlushAction}.
@@ -35,14 +34,11 @@ public class DefaultDataDomainFlushActionFactory implements DataDomainFlushActio
     @Inject
     private DbRowOpSorter operationSorter;
 
-    @Inject
-    private SqlLogger sqlLogger;
-
     @Inject
     private DeleteDbRowOpFactory deleteDbRowOpFactory;
 
     @Override
     public DataDomainFlushAction createFlushAction(DataDomain dataDomain) {
-        return new DefaultDataDomainFlushAction(dataDomain, operationSorter, sqlLogger, deleteDbRowOpFactory);
+        return new DefaultDataDomainFlushAction(dataDomain, operationSorter, deleteDbRowOpFactory);
     }
 }
diff --git a/cayenne/src/main/java/org/apache/cayenne/access/flush/FlushObserver.java b/cayenne/src/main/java/org/apache/cayenne/access/flush/FlushObserver.java
@@ -24,7 +24,6 @@
 import org.apache.cayenne.ObjectId;
 import org.apache.cayenne.ResultIterator;
 import org.apache.cayenne.access.OperationObserver;
-import org.apache.cayenne.log.SqlLogger;
 import org.apache.cayenne.map.DbAttribute;
 import org.apache.cayenne.query.InsertBatchQuery;
 import org.apache.cayenne.query.Query;
@@ -37,12 +36,6 @@
  */
 class FlushObserver implements OperationObserver {
 
-    private final SqlLogger logger;
-
-    public FlushObserver(SqlLogger logger) {
-        this.logger = logger;
-    }
-
     @Override
     public void nextQueryException(Query query, Exception ex) {
         throw new CayenneRuntimeException("Raising from query exception.", Util.unwindException(ex));
@@ -57,14 +50,7 @@ public void nextGlobalException(Exception ex) {
      * Processes generated keys.
      */
     @Override
-    @SuppressWarnings("unchecked")
-    public void nextGeneratedRows(Query query, ResultIterator<?> keysIterator, List<ObjectId> idsToUpdate) {
-
-        // read and close the iterator before doing anything else
-        List<DataRow> keys;
-        try (keysIterator) {
-            keys = (List<DataRow>) keysIterator.allRows();
-        }
+    public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {
 
         if (!(query instanceof InsertBatchQuery batch)) {
             throw new CayenneRuntimeException("Generated keys only supported for InsertBatchQuery, instead got %s", query);
@@ -104,9 +90,6 @@ public void nextGeneratedRows(Query query, ResultIterator<?> keysIterator, List<
 	                }
 	                
 	
-	                // log the generated PK
-	                logger.logGeneratedKey(attribute, value);
-
 	                // I guess we should override any existing value,
 	                // as generated key is the latest thing that exists in the DB.
 	                idToUpdate.getReplacementIdMap().put(attribute.getName(), value);
diff --git a/cayenne/src/main/java/org/apache/cayenne/access/jdbc/BatchAction.java b/cayenne/src/main/java/org/apache/cayenne/access/jdbc/BatchAction.java
@@ -20,6 +20,7 @@
 package org.apache.cayenne.access.jdbc;
 
 import org.apache.cayenne.CayenneRuntimeException;
+import org.apache.cayenne.DataRow;
 import org.apache.cayenne.ObjectId;
 import org.apache.cayenne.ResultIterator;
 import org.apache.cayenne.access.DataNode;
@@ -292,13 +293,19 @@ protected void processGeneratedKeys(Statement statement, OperationObserver obser
 
 		RowReader<?> rowReader = dataNode.getRowReaderFactory()
 				.rowReader(keyColumns, query.getMetaData(dataNode.getEntityResolver()), dataNode.getAdapter());
-		ResultIterator iterator = new RSIterator(null, keysRS, rowReader);
+
+		// generated keys are small (one row per inserted row), so materialize them here rather than passing a live,
+		// single-use iterator to the observer
+		List<DataRow> keys;
+		try (ResultIterator<?> iterator = new RSIterator(null, keysRS, rowReader)) {
+			keys = (List<DataRow>) iterator.allRows();
+		}
 
 		List<ObjectId> objectIds = new ArrayList<>(rows.size());
 		for(BatchQueryRow row : rows) {
 			objectIds.add(row.getObjectId());
 		}
-		observer.nextGeneratedRows(query, iterator, objectIds);
+		observer.nextGeneratedRows(query, keys, objectIds);
 	}
 
 	private String typeForGeneratedPK(DbAttribute key) {
diff --git a/cayenne/src/main/java/org/apache/cayenne/access/jdbc/EJBQLAction.java b/cayenne/src/main/java/org/apache/cayenne/access/jdbc/EJBQLAction.java
@@ -18,6 +18,7 @@
  ****************************************************************/
 package org.apache.cayenne.access.jdbc;
 
+import org.apache.cayenne.DataRow;
 import org.apache.cayenne.ObjectId;
 import org.apache.cayenne.ResultIterator;
 import org.apache.cayenne.access.DataNode;
@@ -161,7 +162,7 @@ public void nextRows(Query query, ResultIterator<?> it) {
         }
 
         @Override
-        public void nextGeneratedRows(Query query, ResultIterator<?> keys, List<ObjectId> idsToUpdate) {
+        public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {
             delegate.nextGeneratedRows(originalQuery, keys, idsToUpdate);
         }
 
diff --git a/cayenne/src/main/java/org/apache/cayenne/dba/sqlserver/SQLServerProcedureAction.java b/cayenne/src/main/java/org/apache/cayenne/dba/sqlserver/SQLServerProcedureAction.java
@@ -19,6 +19,7 @@
 
 package org.apache.cayenne.dba.sqlserver;
 
+import org.apache.cayenne.DataRow;
 import org.apache.cayenne.ObjectId;
 import org.apache.cayenne.ResultIterator;
 import org.apache.cayenne.access.DataNode;
@@ -174,7 +175,7 @@ public void nextGlobalException(Exception ex) {
 		}
 
 		@Override
-		public void nextGeneratedRows(Query query, ResultIterator<?> keys, List<ObjectId> idsToUpdate) {
+		public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {
 			observer.nextGeneratedRows(query, keys, idsToUpdate);
 		}
 
diff --git a/cayenne/src/main/java/org/apache/cayenne/log/NoopSqlLogger.java b/cayenne/src/main/java/org/apache/cayenne/log/NoopSqlLogger.java
@@ -19,7 +19,8 @@
 package org.apache.cayenne.log;
 
 import org.apache.cayenne.access.translator.TranslatedStatement;
-import org.apache.cayenne.map.DbAttribute;
+
+import java.util.Map;
 
 /**
  * A no-op {@link SqlLogger}. Used as a null-object default in contexts that run without a configured logger, such as
@@ -61,7 +62,7 @@ public void logAlsoUpdate(int rowCount) {
     }
 
     @Override
-    public void logGeneratedKey(DbAttribute attribute, Object value) {
+    public void logGeneratedKey(Map<String, ?> keys) {
     }
 
     @Override
diff --git a/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java b/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java
@@ -20,13 +20,14 @@
 package org.apache.cayenne.log;
 
 import org.apache.cayenne.access.translator.TranslatedStatement;
-import org.apache.cayenne.map.DbAttribute;
 import org.apache.cayenne.configuration.Constants;
 import org.apache.cayenne.configuration.RuntimeProperties;
 import org.apache.cayenne.di.Inject;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
+import java.util.Map;
+
 /**
  * A {@link SqlLogger} that emits compact, single-line messages through slf4j-api under the fixed logger name
  * {@code cayenne-sql}. Statement lines are logged at INFO; transaction boundaries at DEBUG.
@@ -88,9 +89,11 @@ public void logAlsoUpdate(int rowCount) {
     }
 
     @Override
-    public void logGeneratedKey(DbAttribute attribute, Object value) {
+    public void logGeneratedKey(Map<String, ?> keys) {
         if (LOGGER.isInfoEnabled()) {
-            LOGGER.info("generated PK {}:{}", attribute.getName(), value);
+            StringBuilder buffer = new StringBuilder("generated PK ");
+            SqlBindingRenderer.appendGeneratedKeys(buffer, keys);
+            LOGGER.info(buffer.toString());
         }
     }
 
diff --git a/cayenne/src/main/java/org/apache/cayenne/log/SqlBindingRenderer.java b/cayenne/src/main/java/org/apache/cayenne/log/SqlBindingRenderer.java
@@ -29,13 +29,13 @@
 import org.apache.cayenne.access.translator.TranslatedStatement;
 import org.apache.cayenne.access.types.ExtendedType;
 
+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.
- *
- * @since 5.0
  */
-public class SqlBindingRenderer {
+class SqlBindingRenderer {
 
     /**
      * Appends the {@code bind:[...]} fragment for the given statement to the buffer, or nothing if the statement has
@@ -52,6 +52,23 @@ public static void appendBindings(StringBuilder buffer, TranslatedStatement stat
         }
     }
 
+    /**
+     * Appends the generated keys of a single row as a {@code [name:value,...]} fragment, using the same value
+     * formatting as parameter bindings.
+     */
+    public static void appendGeneratedKeys(StringBuilder buffer, Map<String, ?> keys) {
+        buffer.append('[');
+        boolean first = true;
+        for (Map.Entry<String, ?> entry : keys.entrySet()) {
+            if (!first) {
+                buffer.append(',');
+            }
+            first = false;
+            appendNamedValue(buffer, entry.getKey(), null, entry.getValue());
+        }
+        buffer.append(']');
+    }
+
     private static void appendParameters(StringBuilder buffer, PSParameter<?>[] bindings) {
         if (bindings.length == 0) {
             return;
diff --git a/cayenne/src/main/java/org/apache/cayenne/log/SqlLogger.java b/cayenne/src/main/java/org/apache/cayenne/log/SqlLogger.java
@@ -20,7 +20,8 @@
 package org.apache.cayenne.log;
 
 import org.apache.cayenne.access.translator.TranslatedStatement;
-import org.apache.cayenne.map.DbAttribute;
+
+import java.util.Map;
 
 /**
  * A logging service used by Cayenne to output database interactions as compact, single-line messages.
@@ -59,9 +60,9 @@ public interface SqlLogger {
     void logAlsoUpdate(int rowCount);
 
     /**
-     * Logs a database-generated primary key value.
+     * Logs the database-generated keys of a single inserted row as one compact, comma-separated line.
      */
-    void logGeneratedKey(DbAttribute attribute, Object value);
+    void logGeneratedKey(Map<String, ?> keys);
 
     /**
      * Logs a transaction start boundary (emitted at DEBUG level).
diff --git a/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java b/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java
@@ -19,6 +19,7 @@
 
 package org.apache.cayenne.access;
 
+import org.apache.cayenne.DataRow;
 import org.apache.cayenne.access.jdbc.CSParameter;
 import org.apache.cayenne.access.jdbc.PSBatchParameter;
 import org.apache.cayenne.access.jdbc.PSParameter;
@@ -28,11 +29,11 @@
 import org.apache.cayenne.access.translator.TranslatedSelect;
 import org.apache.cayenne.access.translator.TranslatedStatement;
 import org.apache.cayenne.log.SqlLogger;
-import org.apache.cayenne.map.DbAttribute;
 import org.junit.jupiter.api.Test;
 
 import java.util.ArrayList;
 import java.util.List;
+import java.util.Map;
 
 import static java.util.Arrays.asList;
 import static org.junit.jupiter.api.Assertions.assertEquals;
@@ -53,9 +54,6 @@ private static TranslatedProcedure procedure() {
         return new TranslatedProcedure("call p()", new CSParameter<?>[0]);
     }
 
-    /**
-     * A capturing {@link SqlLogger} that records the sequence of statement calls for assertions.
-     */
     private static class CapturingLogger implements SqlLogger {
         final List<String> calls = new ArrayList<>();
 
@@ -85,8 +83,10 @@ public void logAlsoUpdate(int rowCount) {
         }
 
         @Override
-        public void logGeneratedKey(DbAttribute attribute, Object value) {
-            calls.add("generated PK " + attribute.getName() + ":" + value);
+        public void logGeneratedKey(Map<String, ?> keys) {
+            StringBuilder buffer = new StringBuilder("generated PK");
+            keys.forEach((name, value) -> buffer.append(' ').append(name).append('=').append(value));
+            calls.add(buffer.toString());
         }
 
         @Override
@@ -164,6 +164,19 @@ public void emptyBatchCountDoesNotEmitStrayUpdate() {
         assertEquals(List.of("selected:2"), logger.calls);
     }
 
+    @Test
+    public void generatedRowsLogKeysUsingDataRowLabels() {
+        CapturingLogger logger = new CapturingLogger();
+        LoggingObserver observer = observer(logger);
+
+        DataRow row = new DataRow(1);
+        row.put("ARTIST_ID", 42L);
+
+        observer.nextGeneratedRows(null, List.of(row), List.of());
+
+        assertEquals(List.of("generated PK ARTIST_ID=42"), logger.calls);
+    }
+
     @Test
     public void newStatementFlushesPreviousBatch() {
         CapturingLogger logger = new CapturingLogger();
diff --git a/cayenne/src/test/java/org/apache/cayenne/access/MockOperationObserver.java b/cayenne/src/test/java/org/apache/cayenne/access/MockOperationObserver.java

Original file line number	Diff line number	Diff line change
`@@ -679,11 +679,9 @@ public void nextRows(Query q, ResultIterator<?> it) {`
`679`	`679`	`}`
`680`	`680`
`681`	`681`	`@Override`
`682`		`- public void nextGeneratedRows(Query query, ResultIterator<?> keys, List<ObjectId> idsToUpdate) {`
	`682`	`+ public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {`
`683`	`683`	`if (keys != null) {`
`684`		`- try (keys) {`
`685`		`- nextRows(query, keys.allRows());`
`686`		`- }`
	`684`	`+ nextRows(query, keys);`
`687`	`685`	`}`
`688`	`686`	`}`
`689`	`687`
Original file line number	Diff line number	Diff line change
`@@ -18,6 +18,7 @@`
`18`	`18`	`****************************************************************/`
`19`	`19`	`package org.apache.cayenne.access.jdbc;`
`20`	`20`
	`21`	`+import org.apache.cayenne.DataRow;`
`21`	`22`	`import org.apache.cayenne.ObjectId;`
`22`	`23`	`import org.apache.cayenne.ResultIterator;`
`23`	`24`	`import org.apache.cayenne.access.DataNode;`
`@@ -161,7 +162,7 @@ public void nextRows(Query query, ResultIterator<?> it) {`
`161`	`162`	`}`
`162`	`163`
`163`	`164`	`@Override`
`164`		`- public void nextGeneratedRows(Query query, ResultIterator<?> keys, List<ObjectId> idsToUpdate) {`
	`165`	`+ public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {`
`165`	`166`	`delegate.nextGeneratedRows(originalQuery, keys, idsToUpdate);`
`166`	`167`	`}`
`167`	`168`
Original file line number	Diff line number	Diff line change
`@@ -19,6 +19,7 @@`
`19`	`19`
`20`	`20`	`package org.apache.cayenne.dba.sqlserver;`
`21`	`21`
	`22`	`+import org.apache.cayenne.DataRow;`
`22`	`23`	`import org.apache.cayenne.ObjectId;`
`23`	`24`	`import org.apache.cayenne.ResultIterator;`
`24`	`25`	`import org.apache.cayenne.access.DataNode;`
`@@ -174,7 +175,7 @@ public void nextGlobalException(Exception ex) {`
`174`	`175`	`}`
`175`	`176`
`176`	`177`	`@Override`
`177`		`- public void nextGeneratedRows(Query query, ResultIterator<?> keys, List<ObjectId> idsToUpdate) {`
	`178`	`+ public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> idsToUpdate) {`
`178`	`179`	`observer.nextGeneratedRows(query, keys, idsToUpdate);`
`179`	`180`	`}`
`180`	`181`
Original file line number	Diff line number	Diff line change
`@@ -19,7 +19,8 @@`
`19`	`19`	`package org.apache.cayenne.log;`
`20`	`20`
`21`	`21`	`import org.apache.cayenne.access.translator.TranslatedStatement;`
`22`		`-import org.apache.cayenne.map.DbAttribute;`
	`22`	`+`
	`23`	`+import java.util.Map;`
`23`	`24`
`24`	`25`	`/**`
`25`	`26`	`* A no-op {@link SqlLogger}. Used as a null-object default in contexts that run without a configured logger, such as`
`@@ -61,7 +62,7 @@ public void logAlsoUpdate(int rowCount) {`
`61`	`62`	`}`
`62`	`63`
`63`	`64`	`@Override`
`64`		`- public void logGeneratedKey(DbAttribute attribute, Object value) {`
	`65`	`+ public void logGeneratedKey(Map<String, ?> keys) {`
`65`	`66`	`}`
`66`	`67`
`67`	`68`	`@Override`