I have a Spring Boot app with some integration tests inspecting the results from front-end operations on data in the database.
The app uses DataNucleus JPA underneath spring-data-jpa and spring-data-rest, with an in-memory database, e.g. Derby, set up automatically via Spring Boot testing.
I used to use Hibernate, but I swopped it for DataNucleus. The tests all passed with Hibernate, but now my test JdbcTemplate queries are hanging, as though JPA isn't releasing its locks.
I've tried it with H2 (fails silently), Derby (hangs until time-out) and HSQLDB (hangs forever).
I have tried various work-arounds, e.g. without transactions @Transactional(Transactional.TxType.NEVER) or with/without commits @Rollback(true/false)
Spring Boot instantiates the datasource automatically and injects it into the EntityManagerFactory and the JdbcTemplate.
This is the test:
@ExtendWith(SpringExtension.class)
@SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.MOCK,
classes = { TestDataSourceConfig.class })
@EnableAutoConfiguration
@AutoConfigureMockMvc
@AutoConfigureTestDatabase(connection = EmbeddedDatabaseConnection.DERBY)
@Transactional
public class SymbolRestTests {
@Autowired
private MockMvc mockMvc;
@Autowired
private JdbcTemplate jdbcTemplate;
@Autowired
private SymbolRepository symbolRepository;
@PersistenceContext
private EntityManager entityManager;
@Before
public void setUp() throws Exception {
symbolRepository.deleteAll();
entityManager.flush();
entityManager.clear();
}
@Test
public void shouldCreateEntity() throws Exception {
String testTitle = "TEST.CODE.1";
String testExtra = "Test for SymbolRestTests.java";
String json = createJsonExample(testTitle, testExtra, true);
MockHttpServletRequestBuilder requestBuilder =
post("/symbols").content(json);
mockMvc.perform(requestBuilder)
.andExpect(status().isCreated())
.andExpect(header().string("Location",
containsString("symbols/")));
entityManager.flush();
entityManager.close(); // this didn't help
String sql = "SELECT count(*) FROM symbol WHERE title = ?";
// exception thrown on this next line
int count = jdbcTemplate.queryForObject(
sql, new Object[] { testTitle }, Integer.class);
Assert.assertThat(count, is(1));
}
}
and this is the error from HSQLDB (seems to be the most informative):
org.springframework.dao.CannotAcquireLockException: PreparedStatementCallback;
SQL [SELECT count(*) FROM symbol WHERE title = ?];
A lock could not be obtained within the time requested;
nested exception is java.sql.SQLTransactionRollbackException:
A lock could not be obtained within the time requested
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:259)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:649)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:684)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:716)
at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:726)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:794)
at org.springframework.jdbc.core.JdbcTemplate.queryForObject(JdbcTemplate.java:813)
at com.gis.integration.SymbolRestTests.shouldCreateEntity(SymbolRestTests.java:127)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:316)
at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:114)
at org.junit.jupiter.engine.descriptor.MethodTestDescriptor.lambda$invokeTestMethod$6(MethodTestDescriptor.java:171)
at org.junit.jupiter.engine.execution.ThrowableCollector.execute(ThrowableCollector.java:40)
at org.junit.jupiter.engine.descriptor.MethodTestDescriptor.invokeTestMethod(MethodTestDescriptor.java:168)
at org.junit.jupiter.engine.descriptor.MethodTestDescriptor.execute(MethodTestDescriptor.java:115)
at org.junit.jupiter.engine.descriptor.MethodTestDescriptor.execute(MethodTestDescriptor.java:57)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.lambda$execute$1(HierarchicalTestExecutor.java:81)
at org.junit.platform.engine.support.hierarchical.SingleTestExecutor.executeSafely(SingleTestExecutor.java:66)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:76)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.lambda$execute$1(HierarchicalTestExecutor.java:91)
at org.junit.platform.engine.support.hierarchical.SingleTestExecutor.executeSafely(SingleTestExecutor.java:66)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:76)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.lambda$execute$1(HierarchicalTestExecutor.java:91)
at org.junit.platform.engine.support.hierarchical.SingleTestExecutor.executeSafely(SingleTestExecutor.java:66)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:76)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:51)
at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:43)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:137)
at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:87)
at org.junit.platform.launcher.Launcher.execute(Launcher.java:93)
at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:61)
at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:51)
at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
Caused by: java.sql.SQLTransactionRollbackException: A lock could not be obtained within the time requested
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedResultSet.closeOnTransactionError(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedResultSet.next(Unknown Source)
at org.springframework.jdbc.core.RowMapperResultSetExtractor.extractData(RowMapperResultSetExtractor.java:92)
at org.springframework.jdbc.core.RowMapperResultSetExtractor.extractData(RowMapperResultSetExtractor.java:60)
at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:697)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:633)
... 35 more
Caused by: ERROR 40XL1: A lock could not be obtained within the time requested
at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source)
at org.apache.derby.impl.services.locks.ConcurrentLockSet.zeroDurationLockObject(Unknown Source)
at org.apache.derby.impl.services.locks.AbstractPool.zeroDurationlockObject(Unknown Source)
at org.apache.derby.impl.services.locks.ConcurrentPool.zeroDurationlockObject(Unknown Source)
at org.apache.derby.impl.store.raw.xact.RowLocking2nohold.lockRecordForRead(Unknown Source)
at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)
at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(Unknown Source)
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(Unknown Source)
at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(Unknown Source)
at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(Unknown Source)
at org.apache.derby.impl.store.access.btree.BTreeScan.fetchNextGroup(Unknown Source)
at org.apache.derby.impl.sql.execute.BulkTableScanResultSet.reloadArray(Unknown Source)
at org.apache.derby.impl.sql.execute.BulkTableScanResultSet.getNextRowCore(Unknown Source)
at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(Unknown Source)
at org.apache.derby.impl.sql.execute.ScalarAggregateResultSet.getRowFromResultSet(Unknown Source)
at org.apache.derby.impl.sql.execute.ScalarAggregateResultSet.getNextRowCore(Unknown Source)
at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(Unknown Source)
at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(Unknown Source)
... 41 more
Update using DataNucleus transaction documentation I have added some DataNucleus-specific properties to the persistence.xml (without result):
<?xml version="1.0" encoding="UTF-8" ?>
<persistence version="2.1"
xmlns="http://xmlns.jcp.org/xml/ns/persistence"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence
persistence_2_1.xsd">
<persistence-unit name="test">
<provider>org.datanucleus.api.jpa.PersistenceProviderImpl</provider>
<exclude-unlisted-classes>false</exclude-unlisted-classes>
<properties>
<property name="datanucleus.schema.autoCreateAll" value="true"/>
<property name="datanucleus.transactionIsolation" value="read-uncommitted"/>
<property name="datanucleus.NontransactionalRead" value="true"/>
<property name="datanucleus.NontransactionalWrite" value="true"/>
</properties>
</persistence-unit>
</persistence>
UPDATE #2 The log output at DEBUG level showing the DataNucleus-JPA/JdbcTemplate log statements (first the JPA INSERT, then the JdbcTemplate SELECT COUNT(*)):
2017-06-09 14:56:18.055 DEBUG 9492 --- [ main] DataNucleus.Connection : ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@5621a671 [conn=org.apache.derby.impl.jdbc.EmbedConnection@2006fdaa, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" is being committed.
2017-06-09 14:56:18.055 DEBUG 9492 --- [ main] DataNucleus.Connection : ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@5621a671 [conn=org.apache.derby.impl.jdbc.EmbedConnection@2006fdaa, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true]" closed
2017-06-09 14:56:18.068 DEBUG 9492 --- [ main] DataNucleus.Persistence : Object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" being inserted into table "SYMBOL"
2017-06-09 14:56:18.071 DEBUG 9492 --- [ main] DataNucleus.Connection : ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@63a7af06 [conn=null, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" opened with isolation level "read-uncommitted" and auto-commit=false
2017-06-09 14:56:18.074 DEBUG 9492 --- [ main] DataNucleus.Transaction : Running enlist operation on resource: org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@3d4b45b, error code TMNOFLAGS and transaction: [DataNucleus Transaction, ID=Xid= , enlisted resources=[]]
2017-06-09 14:56:18.076 DEBUG 9492 --- [ main] DataNucleus.Connection : ManagedConnection(enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@63a7af06 [conn=org.apache.derby.impl.jdbc.EmbedConnection@19d76106, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" starting for transaction "Xid= " with flags "0"
2017-06-09 14:56:18.078 DEBUG 9492 --- [ main] DataNucleus.Connection : ManagedConnection added to the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@63a7af06 [conn=org.apache.derby.impl.jdbc.EmbedConnection@19d76106, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextImpl@2c47a053" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@204c5ddf]"
2017-06-09 14:56:18.125 DEBUG 9492 --- [ main] DataNucleus.Datastore : Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@37753b69" for connection "org.apache.derby.impl.jdbc.EmbedConnection@19d76106"
2017-06-09 14:56:18.134 DEBUG 9492 --- [ main] DataNucleus.Datastore.Native : INSERT INTO SYMBOL (ACTIVE,CREATED,EXTRA,GLOBAL_READ,GLOBAL_WRITE,LAST_MODIFIED,TITLE) VALUES (<'Y'>,<2017-06-09>,<null>,<'N'>,<'N'>,<2017-06-09>,<'TEST.CODE.1'>)
2017-06-09 14:56:18.169 DEBUG 9492 --- [ main] DataNucleus.Datastore.Persist : Execution Time = 36 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@37753b69"
2017-06-09 14:56:18.172 DEBUG 9492 --- [ main] DataNucleus.Datastore.Persist : Object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" was inserted in the datastore and was given strategy value of "1"
2017-06-09 14:56:18.179 DEBUG 9492 --- [ main] DataNucleus.Cache : Object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" (id="org.datanucleus.identity.IdentityReference@93fb44") being changed to be referenced by id="com.bp.gis.tardis.entity.SymbolEntity:1" in Level 1 cache
2017-06-09 14:56:18.180 DEBUG 9492 --- [ main] DataNucleus.Cache : Object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" (id="com.bp.gis.tardis.entity.SymbolEntity:1") added to Level 1 cache (loadedFlags="[YYYYYYYYY]")
2017-06-09 14:56:18.180 DEBUG 9492 --- [ main] DataNucleus.Transaction : Object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" (id="org.datanucleus.identity.IdentityReference@93fb44") enlisted in transactional cache is now enlisted using id="com.bp.gis.tardis.entity.SymbolEntity:1"
2017-06-09 14:56:18.181 DEBUG 9492 --- [ main] DataNucleus.Persistence : Insert of object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" is calling insertPostProcessing for field "com.bp.gis.tardis.entity.SymbolEntity.timeSeriesList"
2017-06-09 14:56:18.181 DEBUG 9492 --- [ main] DataNucleus.Datastore : Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@37753b69"
2017-06-09 14:56:18.181 DEBUG 9492 --- [ main] DataNucleus.Persistence : Insert of object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" is calling postInsert for field "com.bp.gis.tardis.entity.SymbolEntity.timeSeriesList"
2017-06-09 14:56:18.205 DEBUG 9492 --- [ main] DataNucleus.Persistence : Object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" field "timeSeriesList" is replaced by a SCO wrapper of type "org.datanucleus.store.types.wrappers.backed.List" [cache-values=true, lazy-loading=true, allow-nulls=true]
2017-06-09 14:56:18.207 DEBUG 9492 --- [ main] DataNucleus.Persistence : ExecutionContext.internalFlush() process finished
2017-06-09 14:56:18.218 DEBUG 9492 --- [ main] o.s.jdbc.core.JdbcTemplate : Executing prepared SQL query
2017-06-09 14:56:18.220 DEBUG 9492 --- [ main] o.s.jdbc.core.JdbcTemplate : Executing prepared SQL statement [SELECT count(*) FROM symbol WHERE title = ?]
2017-06-09 14:56:18.250 TRACE 9492 --- [ main] o.s.jdbc.core.StatementCreatorUtils : Setting SQL statement parameter value: column index 1, parameter value [TEST.CODE.1], value class [java.lang.String], SQL type unknown
2017-06-09 14:57:18.298 INFO 9492 --- [ main] o.s.b.f.xml.XmlBeanDefinitionReader : Loading XML bean definitions from class path resource [org/springframework/jdbc/support/sql-error-codes.xml]
2017-06-09 14:57:18.390 INFO 9492 --- [ main] o.s.jdbc.support.SQLErrorCodesFactory : SQLErrorCodes loaded: [DB2, Derby, H2, HSQL, Informix, MS-SQL, MySQL, Oracle, PostgreSQL, Sybase, Hana]
MockHttpServletRequest:
HTTP Method = POST
Request URI = /symbols
Parameters = {}
Headers = {}
Handler:
Type = org.springframework.data.rest.webmvc.RepositoryEntityController
Method = public org.springframework.http.ResponseEntity<org.springframework.hateoas.ResourceSupport> org.springframework.data.rest.webmvc.RepositoryEntityController.postCollectionResource(org.springframework.data.rest.webmvc.RootResourceInformation,org.springframework.data.rest.webmvc.PersistentEntityResource,org.springframework.data.rest.webmvc.PersistentEntityResourceAssembler,java.lang.String) throws org.springframework.web.HttpRequestMethodNotSupportedException
Async:
Async started = false
Async result = null
Resolved Exception:
Type = null
ModelAndView:
View name = null
View = null
Model = null
FlashMap:
Attributes = null
MockHttpServletResponse:
Status = 201
Error message = null
Headers = {X-Application-Context=[application:-1], Location=[http://localhost/symbols/0]}
Content type = null
Body =
Forwarded URL = null
Redirected URL = http://localhost/symbols/0
Cookies = []
2017-06-09 14:57:18.424 DEBUG 9492 --- [ main] DataNucleus.Transaction : Transaction rolling back for ExecutionContext org.datanucleus.ExecutionContextImpl@2c47a053
2017-06-09 14:57:18.429 DEBUG 9492 --- [ main] DataNucleus.Lifecycle : Object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" (id="com.bp.gis.tardis.entity.SymbolEntity:1") has a lifecycle change : "P_NEW"->""
2017-06-09 14:57:18.447 DEBUG 9492 --- [ main] DataNucleus.Transaction : Object "com.bp.gis.tardis.entity.SymbolEntity@59c08cf1" (id="com.bp.gis.tardis.entity.SymbolEntity:1") was evicted from transactional cache
2017-06-09 14:57:18.448 DEBUG 9492 --- [ main] DataNucleus.Persistence : Disconnecting com.bp.gis.tardis.entity.SymbolEntity@59c08cf1 from StateManager[pc=com.bp.gis.tardis.entity.SymbolEntity@59c08cf1, lifecycle=P_NEW]
2017-06-09 14:57:18.451 DEBUG 9492 --- [ main] DataNucleus.Cache : Object with id="com.bp.gis.tardis.entity.SymbolEntity:1" being removed from Level 1 cache [current cache size = 1]
2017-06-09 14:57:18.451 DEBUG 9492 --- [ main] DataNucleus.Transaction : Rolling back [DataNucleus Transaction, ID=Xid= , enlisted resources=[org.datanucleus.store.rdbms.ConnectionFactoryImpl$EmulatedXAResource@3d4b45b]]
2017-06-09 14:57:18.452 DEBUG 9492 --- [ main] DataNucleus.Connection : ManagedConnection(enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@63a7af06 [conn=org.apache.derby.impl.jdbc.EmbedConnection@19d76106, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" rolling back for transaction "Xid= "
2017-06-09 14:57:18.461 DEBUG 9492 --- [ main] DataNucleus.Connection : ManagedConnection(non-enlisted) "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@63a7af06 [conn=org.apache.derby.impl.jdbc.EmbedConnection@19d76106, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" closed
2017-06-09 14:57:18.461 DEBUG 9492 --- [ main] DataNucleus.Connection : ManagedConnection removed from the pool : "org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@63a7af06 [conn=org.apache.derby.impl.jdbc.EmbedConnection@19d76106, commitOnRelease=false, closeOnRelease=false, closeOnTxnEnd=true]" for key="org.datanucleus.ExecutionContextImpl@2c47a053" in factory="ConnectionFactory:tx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@204c5ddf]"
2017-06-09 14:57:18.462 DEBUG 9492 --- [ main] DataNucleus.Transaction : Transaction rolled back in 38 ms
2017-06-09 14:57:18.462 DEBUG 9492 --- [ main] DataNucleus.Persistence : ExecutionContext "org.datanucleus.ExecutionContextImpl@2c47a053" closed
2017-06-09 14:57:18.463 INFO 9492 --- [ main] o.s.t.c.transaction.TransactionContext : Rolled back transaction for test context [DefaultTestContext@1f6f0fe2 testClass = SymbolRestTests, testInstance = com.bp.gis.tardis.integration.SymbolRestTests@22604c7e, testMethod = shouldCreateEntity@SymbolRestTests, testException = org.springframework.dao.CannotAcquireLockException: PreparedStatementCallback; SQL [SELECT count(*) FROM symbol WHERE title = ?]; A lock could not be obtained within the time requested; nested exception is java.sql.SQLTransactionRollbackException: A lock could not be obtained within the time requested, mergedContextConfiguration = [WebMergedContextConfiguration@3a48c398 testClass = SymbolRestTests, locations = '{}', classes = '{class com.bp.gis.tardis.config.TestDataSourceConfig, class com.bp.gis.tardis.config.TestDataSourceConfig}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{logging.level.DataNucleus=DEBUG, logging.level.com.bp.gis.tardis=TRACE, logging.level.org.springframework.jdbc.core=TRACE, security.basic.enabled=false, org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true}', contextCustomizers = set[[ImportsContextCustomizer@1b4ba615 key = [@org.springframework.boot.autoconfigure.AutoConfigurationPackage(), @org.junit.FixMethodOrder(value=NAME_ASCENDING), @org.springframework.context.annotation.Import(value=[class org.springframework.boot.autoconfigure.AutoConfigurationPackages$Registrar]), @org.springframework.boot.test.autoconfigure.jdbc.AutoConfigureTestDatabase(replace=ANY, connection=DERBY), @org.springframework.boot.autoconfigure.EnableAutoConfiguration(exclude=[], excludeName=[]), @org.springframework.test.context.BootstrapWith(value=class org.springframework.boot.test.context.SpringBootTestContextBootstrapper), @org.junit.jupiter.api.extension.ExtendWith(value=[class org.springframework.test.context.junit.jupiter.SpringExtension]), @org.springframework.transaction.annotation.Transactional(propagation=REQUIRED, rollbackForClassName=[], readOnly=false, isolation=DEFAULT, transactionManager=, noRollbackFor=[], noRollbackForClassName=[], value=, timeout=-1, rollbackFor=[]), @org.springframework.boot.test.autoconfigure.web.servlet.AutoConfigureMockMvc(webDriverEnabled=true, print=DEFAULT, webClientEnabled=true, secure=true, addFilters=true, printOnlyOnFailure=true), @org.springframework.boot.autoconfigure.ImportAutoConfiguration(value=[], exclude=[], classes=[]), @org.junit.platform.commons.meta.API(value=Experimental), @org.springframework.context.annotation.Import(value=[class org.springframework.boot.autoconfigure.ImportAutoConfigurationImportSelector]), @org.springframework.boot.test.autoconfigure.properties.PropertyMapping(value=spring.test.mockmvc, skip=NO), @org.springframework.boot.test.context.SpringBootTest(webEnvironment=MOCK, value=[], properties=[logging.level.DataNucleus=DEBUG, logging.level.com.bp.gis.tardis=TRACE, logging.level.org.springframework.jdbc.core=TRACE, security.basic.enabled=false], classes=[class com.bp.gis.tardis.config.TestDataSourceConfig]), @org.springframework.boot.test.autoconfigure.properties.PropertyMapping(value=spring.test.database, skip=NO), @org.springframework.context.annotation.Import(value=[class org.springframework.boot.autoconfigure.EnableAutoConfigurationImportSelector])]], org.springframework.boot.test.context.SpringBootTestContextCustomizer@702657cc, org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@6025e1b6, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@0, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@e30f6a3a, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@1ff4931d], resourceBasePath = 'src/main/webapp', contextLoader = 'org.springframework.boot.test.context.SpringBootContextLoader', parent = [null]]].
UPDATE #3
The logging shows the INSERT by DataNucleus, followed several log statements that all look kosher about entity objects, and then comes
ExecutionContext.internalFlush() process finished
which sounds like the DataNucleus EntityManager flushing. Then comes the logging statement from Spring's JdbcTemplate which wants to read what JPA insert, and it all goes wrong.
