UnstableConsole Output

Skipping 3,098 KB.. Full Log
10:53:43,824 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:43,824 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:43,826 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:43,833 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryContainerSize WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey == 0" since the connection used is closing
10:53:43,833 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.isEmpty()" and param "ElementA[name="S.Element 3.2"]":
10:53:43,833 INFO  [main][General] >> result=Owner 5
10:53:43,833 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
10:53:44,597 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:53:44,599 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:53:44,612 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:53:44,615 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:53:47,106 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:53:47,106 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:53:47,106 INFO  [main][Cumulus4jStoreManager] =======================================================
10:53:47,108 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:53:47,108 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:53:47,130 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:53:47,131 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:53:47,137 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.join.ElementASetOwner" not found !
10:53:47,138 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.join.ElementA" not found !
10:53:47,251 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:47,253 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryContainerSize WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey == :compareToArgument" since the connection used is closing
10:53:47,254 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.size() == 3" and param "ElementA[name="S.Element 3.2"]":
10:53:47,254 INFO  [main][General] >> result=Owner 3
10:53:47,254 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.1, S.Element 3.3, S.Element 3.2
10:53:47,255 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,256 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,256 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:47,260 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID != :notThisObjectID" since the connection used is closing
10:53:47,261 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,261 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,262 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,263 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,264 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,264 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,265 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,266 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,266 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,267 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,268 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,269 INFO  [main][ElementASetQueryTest] invoke: found 4 ElementASetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "ElementA[name="S.Element 3.2"]":
10:53:47,269 INFO  [main][General] >> result=Owner 1
10:53:47,269 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.2, S.Element 1.4, S.Element 1.3, S.Element 1.1
10:53:47,269 INFO  [main][General] >> result=Owner 2
10:53:47,269 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.1, S.Element 2.2, S.Element 2.3, S.Element 2.4
10:53:47,269 INFO  [main][General] >> result=Owner 3
10:53:47,269 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.1, S.Element 3.3, S.Element 3.2
10:53:47,270 INFO  [main][General] >> result=Owner 4
10:53:47,270 INFO  [main][ElementASetQueryTest] invoke:   * Owner 4: S.Element 4.3
10:53:47,272 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,272 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,273 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:47,275 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID != :notThisObjectID" since the connection used is closing
10:53:47,276 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,277 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,278 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,278 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,279 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,280 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,281 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,281 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,282 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,283 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,284 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,285 INFO  [main][ElementASetQueryTest] invoke: found 3 ElementASetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "ElementA[name="S.Element 4.3"]":
10:53:47,285 INFO  [main][General] >> result=Owner 1
10:53:47,285 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.4, S.Element 1.1, S.Element 1.2, S.Element 1.3
10:53:47,285 INFO  [main][General] >> result=Owner 2
10:53:47,285 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.4, S.Element 2.1, S.Element 2.2, S.Element 2.3
10:53:47,285 INFO  [main][General] >> result=Owner 3
10:53:47,285 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.2, S.Element 3.1, S.Element 3.3
10:53:47,286 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,287 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,294 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:53:47,295 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,296 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,297 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,297 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,298 INFO  [main][ElementASetQueryTest] invoke: found 2 ElementASetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
10:53:47,298 INFO  [main][General] >> result=Owner 3
10:53:47,298 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.2, S.Element 3.1, S.Element 3.3
10:53:47,298 INFO  [main][General] >> result=Owner 5
10:53:47,298 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
10:53:47,300 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,300 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,302 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && :paramColl.contains(this.indexKey)" since the connection used is closing
10:53:47,304 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,304 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,305 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:47,306 INFO  [main][Query] Reading in results for query "SELECT UNIQUE this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:53:47,307 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,308 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.contains(:element)" and param "ElementA[name="S.Element 3.2"]":
10:53:47,308 INFO  [main][General] >> result=Owner 3
10:53:47,308 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.2, S.Element 3.1, S.Element 3.3
10:53:47,309 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,310 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,317 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:53:47,318 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,319 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,320 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,321 INFO  [main][ElementASetQueryTest] invoke: found 3 ElementASetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
10:53:47,321 INFO  [main][General] >> result=Owner 1
10:53:47,321 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.4, S.Element 1.1, S.Element 1.3, S.Element 1.2
10:53:47,321 INFO  [main][General] >> result=Owner 2
10:53:47,321 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.3, S.Element 2.2, S.Element 2.4, S.Element 2.1
10:53:47,321 INFO  [main][General] >> result=Owner 4
10:53:47,321 INFO  [main][ElementASetQueryTest] invoke:   * Owner 4: S.Element 4.3
10:53:47,323 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,323 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,324 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:47,328 INFO  [main][Query] Reading in results for query "SELECT UNIQUE this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:53:47,329 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,330 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.contains(elementVariable) && elementVariable == :element" and param "ElementA[name="S.Element 3.2"]":
10:53:47,330 INFO  [main][General] >> result=Owner 3
10:53:47,330 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.2, S.Element 3.1, S.Element 3.3
10:53:47,331 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,332 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,333 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:47,335 INFO  [main][Query] Reading in results for query "SELECT UNIQUE this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:53:47,336 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,336 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,338 INFO  [main][ElementASetQueryTest] invoke: found 4 ElementASetOwners for query-filter "!this.set.contains(:element)" and param "ElementA[name="S.Element 3.2"]":
10:53:47,338 INFO  [main][General] >> result=Owner 4
10:53:47,338 INFO  [main][ElementASetQueryTest] invoke:   * Owner 4: S.Element 4.3
10:53:47,338 INFO  [main][General] >> result=Owner 5
10:53:47,338 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
10:53:47,338 INFO  [main][General] >> result=Owner 1
10:53:47,338 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.1, S.Element 1.3, S.Element 1.4, S.Element 1.2
10:53:47,338 INFO  [main][General] >> result=Owner 2
10:53:47,338 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.2, S.Element 2.1, S.Element 2.4, S.Element 2.3
10:53:47,340 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,340 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,347 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:53:47,349 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,349 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,350 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,351 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,352 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,353 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,354 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,354 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,355 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,356 INFO  [main][ElementASetQueryTest] invoke: found 3 ElementASetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) < 0" and param "4":
10:53:47,357 INFO  [main][General] >> result=Owner 1
10:53:47,357 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.4, S.Element 1.1, S.Element 1.3, S.Element 1.2
10:53:47,357 INFO  [main][General] >> result=Owner 2
10:53:47,357 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.1, S.Element 2.2, S.Element 2.3, S.Element 2.4
10:53:47,357 INFO  [main][General] >> result=Owner 3
10:53:47,357 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.3, S.Element 3.1, S.Element 3.2
10:53:47,358 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,358 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,365 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:53:47,366 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,367 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,368 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,369 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,370 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,371 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,372 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,373 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,373 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,375 INFO  [main][ElementASetQueryTest] invoke: found 3 ElementASetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable.name.indexOf(:elementPart) >= 0)" and param "4":
10:53:47,375 INFO  [main][General] >> result=Owner 1
10:53:47,375 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.4, S.Element 1.1, S.Element 1.3, S.Element 1.2
10:53:47,375 INFO  [main][General] >> result=Owner 2
10:53:47,375 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.1, S.Element 2.4, S.Element 2.3, S.Element 2.2
10:53:47,375 INFO  [main][General] >> result=Owner 3
10:53:47,375 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.3, S.Element 3.2, S.Element 3.1
10:53:47,377 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,377 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,378 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:47,382 INFO  [main][Query] Reading in results for query "SELECT UNIQUE this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:53:47,383 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryLong WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:47,384 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,386 INFO  [main][ElementASetQueryTest] invoke: found 4 ElementASetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable == :element" and param "ElementA[name="S.Element 3.2"]":
10:53:47,386 INFO  [main][General] >> result=Owner 4
10:53:47,386 INFO  [main][ElementASetQueryTest] invoke:   * Owner 4: S.Element 4.3
10:53:47,386 INFO  [main][General] >> result=Owner 5
10:53:47,386 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
10:53:47,386 INFO  [main][General] >> result=Owner 1
10:53:47,386 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.4, S.Element 1.1, S.Element 1.2, S.Element 1.3
10:53:47,386 INFO  [main][General] >> result=Owner 2
10:53:47,386 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.3, S.Element 2.2, S.Element 2.4, S.Element 2.1
10:53:47,388 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:47,388 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
10:53:47,390 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:47,392 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryContainerSize WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey == 0" since the connection used is closing
10:53:47,392 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.isEmpty()" and param "ElementA[name="S.Element 3.2"]":
10:53:47,392 INFO  [main][General] >> result=Owner 5
10:53:47,392 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
10:53:47,393 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 26, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 11.831 sec
Running org.cumulus4j.store.test.collection.mappedby.Element3MapQueryTest
10:53:48,266 INFO  [main][JDOTransactionalRunner] run: Shutting down Derby (in case it was used before).
10:53:48,911 INFO  [main][AbstractJDOTransactionalTestClearingDatabase] clearDatabase: Clearing database (dropping all tables).
10:53:48,912 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:53:48,923 INFO  [main][CleanupUtil] cleanoutRDBMS: derbyDatabaseDir="/tmp/derby/cumulus4j" was deleted successfully.
10:53:48,923 WARN  [main][CleanupUtil] dropAllTables: 'ConnectionURL' property is not set for index datastore! Skipping!
10:53:48,924 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:53:48,924 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:53:48,938 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:53:49,164 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:53:55,276 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:53:55,276 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:53:55,276 INFO  [main][Cumulus4jStoreManager] =======================================================
10:53:55,278 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:53:55,278 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:53:55,413 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:53:55,545 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:53:55,664 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element3MapOwner" not found !
10:53:55,669 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element3" not found !
10:53:55,852 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:53:55,862 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches: found 3 Element3MapOwners for query-filter "this.map.containsKey(variable) && variable.name.indexOf(:queryParam) >= 0" and param "4":
10:53:55,863 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 1: Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="ddd", name="Element 1.4"]=ddd, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="ccc", name="Element 1.3"]=ccc
10:53:55,863 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 2: Element3[value="dd", name="Element 2.4"]=dd, Element3[value="aa", name="Element 2.1"]=aa, Element3[value="bb", name="Element 2.2"]=bb, Element3[value="cc", name="Element 2.3"]=cc
10:53:55,863 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
10:53:55,865 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:55,865 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:55,869 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:53:55,871 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches: found 3 Element3MapOwners for query-filter "this.map.containsValue(variable) && variable.indexOf(:queryParam) >= 0" and param "bb":
10:53:55,872 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 1: Element3[value="ddd", name="Element 1.4"]=ddd, Element3[value="ccc", name="Element 1.3"]=ccc, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="aaa", name="Element 1.1"]=aaa
10:53:55,872 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 2: Element3[value="aa", name="Element 2.1"]=aa, Element3[value="bb", name="Element 2.2"]=bb, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="dd", name="Element 2.4"]=dd
10:53:55,872 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
10:53:55,873 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:55,874 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:55,881 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:55,887 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:53:55,888 INFO  [main][Element3MapQueryTest] queryContainsKeyParameter: found 1 Element3MapOwners for query-filter "this.map.containsKey(:queryParam)" and param "Element3[value="b", name="Element 3.2"]":
10:53:55,888 INFO  [main][Element3MapQueryTest] queryContainsKeyParameter:   * Owner 3: Element3[value="c", name="Element 3.3"]=c, Element3[value="a", name="Element 3.1"]=a, Element3[value="b", name="Element 3.2"]=b
10:53:55,889 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:55,890 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:55,891 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:55,893 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:53:55,898 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:55,900 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter: found 5 Element3MapOwners for query-filter "!this.map.containsKey(:queryParam)" and param "Element3[value="b", name="Element 3.2"]":
10:53:55,900 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
10:53:55,901 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 1: Element3[value="ccc", name="Element 1.3"]=ccc, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="ddd", name="Element 1.4"]=ddd
10:53:55,901 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 5: 
10:53:55,901 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
10:53:55,901 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 2: Element3[value="aa", name="Element 2.1"]=aa, Element3[value="bb", name="Element 2.2"]=bb, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="dd", name="Element 2.4"]=dd
10:53:55,902 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:55,903 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:55,905 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:55,907 INFO  [main][Element3MapQueryTest] queryContainsValueParameter: found 2 Element3MapOwners for query-filter "this.map.containsValue(:queryParam)" and param "ccc":
10:53:55,908 INFO  [main][Element3MapQueryTest] queryContainsValueParameter:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
10:53:55,908 INFO  [main][Element3MapQueryTest] queryContainsValueParameter:   * Owner 1: Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="ccc", name="Element 1.3"]=ccc, Element3[value="ddd", name="Element 1.4"]=ddd, Element3[value="bbb", name="Element 1.2"]=bbb
10:53:55,909 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:55,910 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:55,911 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:55,912 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:55,914 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter: found 4 Element3MapOwners for query-filter "!this.map.containsValue(:queryParam)" and param "ccc":
10:53:55,914 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 5: 
10:53:55,914 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
10:53:55,914 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 2: Element3[value="dd", name="Element 2.4"]=dd, Element3[value="bb", name="Element 2.2"]=bb, Element3[value="aa", name="Element 2.1"]=aa, Element3[value="cc", name="Element 2.3"]=cc
10:53:55,914 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 3: Element3[value="c", name="Element 3.3"]=c, Element3[value="a", name="Element 3.1"]=a, Element3[value="b", name="Element 3.2"]=b
10:53:56,430 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:53:56,434 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:53:56,460 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:53:56,932 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:53:58,943 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:53:58,943 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:53:58,943 INFO  [main][Cumulus4jStoreManager] =======================================================
10:53:58,944 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:53:58,944 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:53:58,973 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:53:58,974 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:53:58,982 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element3MapOwner" not found !
10:53:58,984 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element3" not found !
10:53:59,123 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:53:59,125 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches: found 3 Element3MapOwners for query-filter "this.map.containsKey(variable) && variable.name.indexOf(:queryParam) >= 0" and param "4":
10:53:59,126 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 1: Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="ddd", name="Element 1.4"]=ddd, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="ccc", name="Element 1.3"]=ccc
10:53:59,126 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 2: Element3[value="bb", name="Element 2.2"]=bb, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="aa", name="Element 2.1"]=aa, Element3[value="dd", name="Element 2.4"]=dd
10:53:59,126 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
10:53:59,128 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:59,128 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:59,132 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:53:59,134 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches: found 3 Element3MapOwners for query-filter "this.map.containsValue(variable) && variable.indexOf(:queryParam) >= 0" and param "bb":
10:53:59,134 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 1: Element3[value="ccc", name="Element 1.3"]=ccc, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="ddd", name="Element 1.4"]=ddd
10:53:59,134 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 2: Element3[value="dd", name="Element 2.4"]=dd, Element3[value="bb", name="Element 2.2"]=bb, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="aa", name="Element 2.1"]=aa
10:53:59,134 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
10:53:59,136 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:59,136 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:59,137 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:59,139 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:53:59,140 INFO  [main][Element3MapQueryTest] queryContainsKeyParameter: found 1 Element3MapOwners for query-filter "this.map.containsKey(:queryParam)" and param "Element3[value="b", name="Element 3.2"]":
10:53:59,140 INFO  [main][Element3MapQueryTest] queryContainsKeyParameter:   * Owner 3: Element3[value="c", name="Element 3.3"]=c, Element3[value="b", name="Element 3.2"]=b, Element3[value="a", name="Element 3.1"]=a
10:53:59,141 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:59,141 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:59,143 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:53:59,145 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:53:59,145 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:59,147 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter: found 5 Element3MapOwners for query-filter "!this.map.containsKey(:queryParam)" and param "Element3[value="b", name="Element 3.2"]":
10:53:59,147 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 2: Element3[value="cc", name="Element 2.3"]=cc, Element3[value="aa", name="Element 2.1"]=aa, Element3[value="dd", name="Element 2.4"]=dd, Element3[value="bb", name="Element 2.2"]=bb
10:53:59,148 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
10:53:59,148 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 1: Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="ccc", name="Element 1.3"]=ccc, Element3[value="ddd", name="Element 1.4"]=ddd
10:53:59,148 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 5: 
10:53:59,148 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
10:53:59,150 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:59,150 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:59,152 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:59,153 INFO  [main][Element3MapQueryTest] queryContainsValueParameter: found 2 Element3MapOwners for query-filter "this.map.containsValue(:queryParam)" and param "ccc":
10:53:59,153 INFO  [main][Element3MapQueryTest] queryContainsValueParameter:   * Owner 1: Element3[value="ccc", name="Element 1.3"]=ccc, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="ddd", name="Element 1.4"]=ddd
10:53:59,153 INFO  [main][Element3MapQueryTest] queryContainsValueParameter:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
10:53:59,155 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:59,155 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
10:53:59,157 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:53:59,158 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:53:59,160 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter: found 4 Element3MapOwners for query-filter "!this.map.containsValue(:queryParam)" and param "ccc":
10:53:59,160 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 2: Element3[value="bb", name="Element 2.2"]=bb, Element3[value="dd", name="Element 2.4"]=dd, Element3[value="aa", name="Element 2.1"]=aa, Element3[value="cc", name="Element 2.3"]=cc
10:53:59,160 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 3: Element3[value="c", name="Element 3.3"]=c, Element3[value="a", name="Element 3.1"]=a, Element3[value="b", name="Element 3.2"]=b
10:53:59,160 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 5: 
10:53:59,160 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
10:53:59,160 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 12, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 11.669 sec
Running org.cumulus4j.store.test.collection.mappedby.Element2MapQueryTest
10:53:59,941 INFO  [main][JDOTransactionalRunner] run: Shutting down Derby (in case it was used before).
10:54:00,866 INFO  [main][AbstractJDOTransactionalTestClearingDatabase] clearDatabase: Clearing database (dropping all tables).
10:54:00,867 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:00,878 INFO  [main][CleanupUtil] cleanoutRDBMS: derbyDatabaseDir="/tmp/derby/cumulus4j" was deleted successfully.
10:54:00,878 WARN  [main][CleanupUtil] dropAllTables: 'ConnectionURL' property is not set for index datastore! Skipping!
10:54:00,879 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:54:00,879 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:00,897 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:54:01,309 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:54:06,650 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:54:06,651 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:54:06,651 INFO  [main][Cumulus4jStoreManager] =======================================================
10:54:06,654 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:54:06,655 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:54:06,766 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:06,892 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:07,028 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element2MapOwner" not found !
10:54:07,032 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element2" not found !
10:54:07,206 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:54:07,216 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches: found 3 Element2MapOwners for query-filter "this.map.containsKey(variable) && variable.indexOf(:queryParam) >= 0" and param "bb":
10:54:07,217 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:07,217 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:07,217 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:07,218 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,219 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,228 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:07,234 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches: found 4 Element2MapOwners for query-filter "this.map.containsKey(variable) && variable.indexOf(:queryParam) < 0" and param "bb":
10:54:07,234 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:07,234 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:07,234 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:07,235 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:07,236 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,236 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,243 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:54:07,245 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches: found 3 Element2MapOwners for query-filter "this.map.containsValue(variable) && variable.name.indexOf(:queryParam) >= 0" and param "4":
10:54:07,245 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:07,246 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:07,246 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:07,247 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,247 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,251 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:07,255 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches: found 4 Element2MapOwners for query-filter "this.map.containsKey(variable) && !(variable.indexOf(:queryParam) >= 0)" and param "bb":
10:54:07,255 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:07,255 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:07,256 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:07,256 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:07,257 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,258 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,264 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:07,269 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches: found 4 Element2MapOwners for query-filter "this.map.containsValue(variable) && !(variable.name.indexOf(:queryParam) >= 0)" and param "4":
10:54:07,269 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:07,270 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:07,270 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:07,270 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:07,271 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,271 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,278 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:07,282 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches: found 4 Element2MapOwners for query-filter "this.map.containsValue(variable) && variable.name.indexOf(:queryParam) < 0" and param "4":
10:54:07,283 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:07,283 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:07,283 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:07,283 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:07,285 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,285 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,292 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:54:07,294 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter: found 2 Element2MapOwners for query-filter "this.map.containsKey(:queryParam)" and param "ccc":
10:54:07,294 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:07,294 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:07,295 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,296 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,297 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:54:07,303 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,305 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter: found 4 Element2MapOwners for query-filter "!this.map.containsKey(:queryParam)" and param "ccc":
10:54:07,305 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 5: 
10:54:07,305 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:07,305 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:07,305 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:07,306 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,307 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,308 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:07,315 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:07,316 INFO  [main][Element2MapQueryTest] queryContainsValueParameter: found 1 Element2MapOwners for query-filter "this.map.containsValue(:queryParam)" and param "Element2[key="b", name="Element 3.2"]":
10:54:07,316 INFO  [main][Element2MapQueryTest] queryContainsValueParameter:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:07,317 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,318 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:07,319 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:07,321 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:07,322 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:07,325 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter: found 5 Element2MapOwners for query-filter "!this.map.containsValue(:queryParam)" and param "Element2[key="b", name="Element 3.2"]":
10:54:07,325 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:07,325 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:07,325 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 5: 
10:54:07,325 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:07,325 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:08,279 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:54:08,282 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:08,300 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:54:08,478 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:54:10,814 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:54:10,814 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:54:10,814 INFO  [main][Cumulus4jStoreManager] =======================================================
10:54:10,815 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:54:10,815 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:54:10,835 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:10,836 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:10,844 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element2MapOwner" not found !
10:54:10,845 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element2" not found !
10:54:11,001 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:54:11,004 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches: found 3 Element2MapOwners for query-filter "this.map.containsKey(variable) && variable.indexOf(:queryParam) >= 0" and param "bb":
10:54:11,004 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:11,004 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:11,004 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:11,006 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,006 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,009 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:11,018 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches: found 4 Element2MapOwners for query-filter "this.map.containsKey(variable) && variable.indexOf(:queryParam) < 0" and param "bb":
10:54:11,019 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:11,019 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:11,019 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:11,019 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:11,021 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,021 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,028 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:54:11,030 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches: found 3 Element2MapOwners for query-filter "this.map.containsValue(variable) && variable.name.indexOf(:queryParam) >= 0" and param "4":
10:54:11,030 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:11,030 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:11,030 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:11,032 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,032 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,036 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:11,041 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches: found 4 Element2MapOwners for query-filter "this.map.containsKey(variable) && !(variable.indexOf(:queryParam) >= 0)" and param "bb":
10:54:11,041 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:11,041 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:11,041 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:11,041 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:11,043 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,043 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,050 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:11,054 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches: found 4 Element2MapOwners for query-filter "this.map.containsValue(variable) && !(variable.name.indexOf(:queryParam) >= 0)" and param "4":
10:54:11,054 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:11,055 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:11,055 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:11,055 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:11,058 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,059 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,066 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:11,070 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches: found 4 Element2MapOwners for query-filter "this.map.containsValue(variable) && variable.name.indexOf(:queryParam) < 0" and param "4":
10:54:11,071 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:11,071 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:11,071 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:11,071 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:11,073 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,073 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,075 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:54:11,077 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter: found 2 Element2MapOwners for query-filter "this.map.containsKey(:queryParam)" and param "ccc":
10:54:11,077 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:11,077 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:11,078 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,078 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,080 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
10:54:11,081 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,082 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter: found 4 Element2MapOwners for query-filter "!this.map.containsKey(:queryParam)" and param "ccc":
10:54:11,083 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:11,083 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:11,083 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 5: 
10:54:11,083 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:11,084 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,085 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,086 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:11,087 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:11,088 INFO  [main][Element2MapQueryTest] queryContainsValueParameter: found 1 Element2MapOwners for query-filter "this.map.containsValue(:queryParam)" and param "Element2[key="b", name="Element 3.2"]":
10:54:11,088 INFO  [main][Element2MapQueryTest] queryContainsValueParameter:   * Owner 3: a=Element2[key="a", name="Element 3.1"], b=Element2[key="b", name="Element 3.2"], c=Element2[key="c", name="Element 3.3"]
10:54:11,089 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,089 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
10:54:11,091 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:11,092 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:11,093 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:11,095 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter: found 5 Element2MapOwners for query-filter "!this.map.containsValue(:queryParam)" and param "Element2[key="b", name="Element 3.2"]":
10:54:11,096 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 2: aa=Element2[key="aa", name="Element 2.1"], bb=Element2[key="bb", name="Element 2.2"], cc=Element2[key="cc", name="Element 2.3"], dd=Element2[key="dd", name="Element 2.4"]
10:54:11,096 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
10:54:11,096 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 1: aaa=Element2[key="aaa", name="Element 1.1"], ccc=Element2[key="ccc", name="Element 1.3"], bbb=Element2[key="bbb", name="Element 1.2"], ddd=Element2[key="ddd", name="Element 1.4"]
10:54:11,096 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 5: 
10:54:11,096 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
10:54:11,096 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 20, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 11.936 sec
Running org.cumulus4j.store.test.collection.mappedby.Element1SetQueryTest
10:54:11,876 INFO  [main][JDOTransactionalRunner] run: Shutting down Derby (in case it was used before).
10:54:12,255 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:54:12,383 INFO  [main][AbstractJDOTransactionalTestClearingDatabase] clearDatabase: Clearing database (dropping all tables).
10:54:12,384 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:12,395 INFO  [main][CleanupUtil] cleanoutRDBMS: derbyDatabaseDir="/tmp/derby/cumulus4j" was deleted successfully.
10:54:12,395 WARN  [main][CleanupUtil] dropAllTables: 'ConnectionURL' property is not set for index datastore! Skipping!
10:54:12,396 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:54:12,396 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:12,409 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:54:17,955 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:54:17,956 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:54:17,956 INFO  [main][Cumulus4jStoreManager] =======================================================
10:54:17,957 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:54:17,957 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:54:18,110 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:18,218 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:18,320 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element1SetOwner" not found !
10:54:18,323 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element1" not found !
10:54:18,440 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:18,453 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID != :notThisObjectID" since the connection used is closing
10:54:18,456 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "Element1[name="Element 4.3"]":
10:54:18,457 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 1: Element 1.3, Element 1.1, Element 1.2, Element 1.4
10:54:18,457 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 2: Element 2.3, Element 2.2, Element 2.4, Element 2.1
10:54:18,457 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 3: Element 3.3, Element 3.1, Element 3.2
10:54:18,458 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,458 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,469 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:54:18,476 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,476 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf: found 2 Element1SetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
10:54:18,477 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf:   * Owner 5: 
10:54:18,477 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf:   * Owner 3: Element 3.3, Element 3.1, Element 3.2
10:54:18,478 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,478 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,479 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:18,484 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:18,485 INFO  [main][Element1SetQueryTest] queryContainsParameter: found 1 Element1SetOwners for query-filter "this.set.contains(:element)" and param "Element1[name="Element 3.2"]":
10:54:18,485 INFO  [main][Element1SetQueryTest] queryContainsParameter:   * Owner 3: Element 3.3, Element 3.1, Element 3.2
10:54:18,486 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,486 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,492 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:54:18,494 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
10:54:18,494 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 1: Element 1.1, Element 1.4, Element 1.3, Element 1.2
10:54:18,494 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 2: Element 2.2, Element 2.1, Element 2.3, Element 2.4
10:54:18,494 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 4: Element 4.3
10:54:18,495 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,495 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,496 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:18,500 INFO  [main][Query] Reading in results for query "SELECT UNIQUE this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:18,500 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableEquals: found 1 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable == :element" and param "Element1[name="Element 3.2"]":
10:54:18,501 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableEquals:   * Owner 3: Element 3.1, Element 3.2, Element 3.3
10:54:18,502 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,502 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,503 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:18,504 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:18,505 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,506 INFO  [main][Element1SetQueryTest] queryNotContainsParameter: found 4 Element1SetOwners for query-filter "!this.set.contains(:element)" and param "Element1[name="Element 3.2"]":
10:54:18,507 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 4: Element 4.3
10:54:18,507 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 1: Element 1.2, Element 1.1, Element 1.3, Element 1.4
10:54:18,507 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 5: 
10:54:18,507 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 2: Element 2.3, Element 2.1, Element 2.4, Element 2.2
10:54:18,508 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,508 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,520 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:18,523 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) < 0" and param "4":
10:54:18,523 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 1: Element 1.1, Element 1.3, Element 1.2, Element 1.4
10:54:18,524 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 2: Element 2.3, Element 2.1, Element 2.2, Element 2.4
10:54:18,524 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 3: Element 3.3, Element 3.2, Element 3.1
10:54:18,525 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,525 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,531 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:18,535 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable.name.indexOf(:elementPart) >= 0)" and param "4":
10:54:18,535 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 1: Element 1.4, Element 1.3, Element 1.2, Element 1.1
10:54:18,535 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 2: Element 2.2, Element 2.3, Element 2.4, Element 2.1
10:54:18,535 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 3: Element 3.3, Element 3.2, Element 3.1
10:54:18,537 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,537 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,538 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:18,541 INFO  [main][Query] Reading in results for query "SELECT UNIQUE this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:18,542 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,543 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals: found 4 Element1SetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable == :element" and param "Element1[name="Element 3.2"]":
10:54:18,543 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 4: Element 4.3
10:54:18,543 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 1: Element 1.2, Element 1.1, Element 1.3, Element 1.4
10:54:18,543 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 5: 
10:54:18,544 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 2: Element 2.4, Element 2.2, Element 2.1, Element 2.3
10:54:18,545 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:18,545 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:18,546 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:18,547 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID != :notThisObjectID" since the connection used is closing
10:54:18,551 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1: found 4 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "Element1[name="Element 3.2"]":
10:54:18,551 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 1: Element 1.1, Element 1.4, Element 1.3, Element 1.2
10:54:18,551 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 2: Element 2.1, Element 2.2, Element 2.3, Element 2.4
10:54:18,551 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 3: Element 3.1, Element 3.2, Element 3.3
10:54:18,551 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 4: Element 4.3
10:54:19,396 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:54:19,397 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:54:19,398 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:19,414 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:54:22,108 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:54:22,108 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:54:22,108 INFO  [main][Cumulus4jStoreManager] =======================================================
10:54:22,109 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:54:22,109 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:54:22,142 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:22,143 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:22,153 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element1SetOwner" not found !
10:54:22,155 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element1" not found !
10:54:22,278 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:22,284 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID != :notThisObjectID" since the connection used is closing
10:54:22,287 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "Element1[name="Element 4.3"]":
10:54:22,287 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 1: Element 1.2, Element 1.4, Element 1.3, Element 1.1
10:54:22,288 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 2: Element 2.2, Element 2.1, Element 2.3, Element 2.4
10:54:22,288 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 3: Element 3.1, Element 3.3, Element 3.2
10:54:22,289 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,290 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,296 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:54:22,298 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,304 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf: found 2 Element1SetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
10:54:22,304 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf:   * Owner 3: Element 3.1, Element 3.2, Element 3.3
10:54:22,304 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf:   * Owner 5: 
10:54:22,306 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,306 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,307 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:22,309 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:22,310 INFO  [main][Element1SetQueryTest] queryContainsParameter: found 1 Element1SetOwners for query-filter "this.set.contains(:element)" and param "Element1[name="Element 3.2"]":
10:54:22,310 INFO  [main][Element1SetQueryTest] queryContainsParameter:   * Owner 3: Element 3.2, Element 3.1, Element 3.3
10:54:22,311 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,311 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,318 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) >= :compareToArgument" since the connection used is closing
10:54:22,320 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
10:54:22,320 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 1: Element 1.4, Element 1.3, Element 1.2, Element 1.1
10:54:22,321 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 2: Element 2.4, Element 2.1, Element 2.2, Element 2.3
10:54:22,321 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 4: Element 4.3
10:54:22,322 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,322 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,324 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:22,328 INFO  [main][Query] Reading in results for query "SELECT UNIQUE this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:22,328 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableEquals: found 1 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable == :element" and param "Element1[name="Element 3.2"]":
10:54:22,329 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableEquals:   * Owner 3: Element 3.3, Element 3.1, Element 3.2
10:54:22,331 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,332 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,333 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:22,334 INFO  [main][Query] Reading in results for query "SELECT UNIQUE FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:22,335 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,337 INFO  [main][Element1SetQueryTest] queryNotContainsParameter: found 4 Element1SetOwners for query-filter "!this.set.contains(:element)" and param "Element1[name="Element 3.2"]":
10:54:22,337 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 4: Element 4.3
10:54:22,337 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 1: Element 1.1, Element 1.4, Element 1.3, Element 1.2
10:54:22,337 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 5: 
10:54:22,337 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 2: Element 2.1, Element 2.3, Element 2.2, Element 2.4
10:54:22,339 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,339 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,346 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:22,349 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) < 0" and param "4":
10:54:22,350 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 1: Element 1.2, Element 1.1, Element 1.4, Element 1.3
10:54:22,350 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 2: Element 2.1, Element 2.2, Element 2.4, Element 2.3
10:54:22,350 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 3: Element 3.3, Element 3.2, Element 3.1
10:54:22,351 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,352 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,359 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.indexKey.indexOf(:invokeArg) < :compareToArgument" since the connection used is closing
10:54:22,363 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable.name.indexOf(:elementPart) >= 0)" and param "4":
10:54:22,363 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 1: Element 1.4, Element 1.3, Element 1.1, Element 1.2
10:54:22,363 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 2: Element 2.2, Element 2.1, Element 2.4, Element 2.3
10:54:22,364 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 3: Element 3.3, Element 3.1, Element 3.2
10:54:22,365 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,365 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,367 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:22,371 INFO  [main][Query] Reading in results for query "SELECT UNIQUE this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID == :objectID" since the connection used is closing
10:54:22,372 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,373 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals: found 4 Element1SetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable == :element" and param "Element1[name="Element 3.2"]":
10:54:22,373 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 4: Element 4.3
10:54:22,373 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 1: Element 1.3, Element 1.2, Element 1.4, Element 1.1
10:54:22,373 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 5: 
10:54:22,373 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 2: Element 2.4, Element 2.3, Element 2.2, Element 2.1
10:54:22,375 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:22,375 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
10:54:22,376 INFO  [main][Query] Reading in results for query "SELECT FROM org.cumulus4j.store.model.IndexEntryStringShort WHERE this.keyStoreRefID == :keyStoreRefID && this.fieldMeta_fieldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID0 && this.indexKey == :value" since the connection used is closing
10:54:22,378 INFO  [main][Query] Reading in results for query "SELECT this.dataEntryID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID && this.objectID != :notThisObjectID" since the connection used is closing
10:54:22,382 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1: found 4 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "Element1[name="Element 3.2"]":
10:54:22,382 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 1: Element 1.3, Element 1.2, Element 1.1, Element 1.4
10:54:22,382 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 2: Element 2.4, Element 2.1, Element 2.2, Element 2.3
10:54:22,382 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 3: Element 3.2, Element 3.3, Element 3.1
10:54:22,382 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 4: Element 4.3
10:54:22,383 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 20, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 11.233 sec
Running org.cumulus4j.store.test.datatype.StandardOneToOneTypesTest
10:54:23,121 INFO  [main][JDOTransactionalRunner] run: Shutting down Derby (in case it was used before).
10:54:23,207 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:54:23,883 INFO  [main][AbstractJDOTransactionalTestClearingDatabase] clearDatabase: Clearing database (dropping all tables).
10:54:23,885 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:23,893 INFO  [main][CleanupUtil] cleanoutRDBMS: derbyDatabaseDir="/tmp/derby/cumulus4j" was deleted successfully.
10:54:23,893 WARN  [main][CleanupUtil] dropAllTables: 'ConnectionURL' property is not set for index datastore! Skipping!
10:54:23,894 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:54:23,894 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:23,908 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:54:29,634 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:54:29,635 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:54:29,635 INFO  [main][Cumulus4jStoreManager] =======================================================
10:54:29,682 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:54:29,682 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:54:29,781 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:29,913 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:31,112 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:54:31,351 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 05869d85-927a-442e-8a69-b6da408a2be3
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 18340b8c-6758-40bd-831d-491df7d6ac4b
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 19519458-a886-491a-9cdc-eb874e4ca4f3
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 22328b0f-f980-40d0-ac13-2fb69fb4d6e9
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 229dbd5d-55e0-483a-80a0-aabc25ab5722
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 2ed2bbb3-9e70-4d35-8c80-f285ed69735c
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 31da5282-84cc-4bbd-b76b-9f1527f37110
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 32807abd-ebc9-4a0a-a3b8-fc1a9dbcae35
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 3475e5f8-1719-4f72-9ec7-d25082708df7
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 45d1d03f-924e-4682-88c5-d770e8c87839
10:54:31,356 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 5516d54e-ef3e-497b-951e-6983e22b1913
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 5517853a-afe2-4fa2-8cce-7c3b18a78cd1
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 58555f85-8b42-4d39-8e11-7b9d4590efd2
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 6120c244-ef2c-4f5b-a2b5-5a25f9521256
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 614ca3dc-6c6e-4240-b72d-0fd250435b86
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 6636dacd-d4d8-45df-99fb-f76fdb957b35
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = b80572c7-a050-4ac2-a530-d6f73265f644
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = be1b6f6a-f3e5-413f-9616-80431d154567
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = be3e9891-119c-4fe9-af8d-1a5927c8273c
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = c68dbd49-b16a-4255-8139-3764404e397c
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = ce5c5c44-0a90-47f0-9073-71685ac439c0
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = cfd8552e-c579-4bce-b13a-001700ac0700
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = d46cd4dc-786a-4138-8167-0bfb2b095501
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = e594434d-9370-460c-bcd4-40f7a5883a8c
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = e9dbc3eb-0d31-4f2b-9945-5df4255da630
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = f362522d-9c09-40d3-8ec5-c55ad95b07a4
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = f79a5985-56ff-4122-8246-69a716914529
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = f8410039-e107-4da9-b0c0-1989a6f08f18
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = fa1faa26-569a-43c8-b648-e03023aaa604
10:54:31,357 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = fd01ffff-ddb2-42b1-8d1b-0bac1248751c
10:54:32,567 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
10:54:32,570 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:54:32,594 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
10:54:35,329 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:54:35,451 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:54:35,451 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:54:35,451 INFO  [main][Cumulus4jStoreManager] =======================================================
10:54:35,453 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:54:35,453 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:54:35,475 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:35,476 INFO  [main][MinimumCumulus4jVersion] version=10100001
10:54:35,960 INFO  [main][Query] Reading in results for query "SELECT this.classMeta_classID, this.objectID FROM org.cumulus4j.store.model.DataEntry WHERE this.keyStoreRefID == :keyStoreRefID && this.classMeta_classID == :classMeta_classID0" since the connection used is closing
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 05869d85-927a-442e-8a69-b6da408a2be3
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 18340b8c-6758-40bd-831d-491df7d6ac4b
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 19519458-a886-491a-9cdc-eb874e4ca4f3
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 22328b0f-f980-40d0-ac13-2fb69fb4d6e9
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 229dbd5d-55e0-483a-80a0-aabc25ab5722
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 2ed2bbb3-9e70-4d35-8c80-f285ed69735c
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 31da5282-84cc-4bbd-b76b-9f1527f37110
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 32807abd-ebc9-4a0a-a3b8-fc1a9dbcae35
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 3475e5f8-1719-4f72-9ec7-d25082708df7
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 45d1d03f-924e-4682-88c5-d770e8c87839
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 5516d54e-ef3e-497b-951e-6983e22b1913
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 5517853a-afe2-4fa2-8cce-7c3b18a78cd1
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 58555f85-8b42-4d39-8e11-7b9d4590efd2
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 6120c244-ef2c-4f5b-a2b5-5a25f9521256
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 614ca3dc-6c6e-4240-b72d-0fd250435b86
10:54:35,964 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 6636dacd-d4d8-45df-99fb-f76fdb957b35
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = b80572c7-a050-4ac2-a530-d6f73265f644
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = be1b6f6a-f3e5-413f-9616-80431d154567
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = be3e9891-119c-4fe9-af8d-1a5927c8273c
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = c68dbd49-b16a-4255-8139-3764404e397c
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = ce5c5c44-0a90-47f0-9073-71685ac439c0
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = cfd8552e-c579-4bce-b13a-001700ac0700
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = d46cd4dc-786a-4138-8167-0bfb2b095501
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = e594434d-9370-460c-bcd4-40f7a5883a8c
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = e9dbc3eb-0d31-4f2b-9945-5df4255da630
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = f362522d-9c09-40d3-8ec5-c55ad95b07a4
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = f79a5985-56ff-4122-8246-69a716914529
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = f8410039-e107-4da9-b0c0-1989a6f08f18
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = fa1faa26-569a-43c8-b648-e03023aaa604
10:54:35,965 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = fd01ffff-ddb2-42b1-8d1b-0bac1248751c
10:54:35,989 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 13.786 sec

Results :

Failed tests: 
  queryQueryableField.0(org.cumulus4j.store.test.metadata.MetaDataTest): Wrong number of result elements! expected:<2> but was:<4>
  queryQueryableField.1(org.cumulus4j.store.test.metadata.MetaDataTest): Wrong number of result elements! expected:<2> but was:<4>

Tests run: 361, Failures: 2, Errors: 0, Skipped: 2

[ERROR] There are test failures.

Please refer to /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.test/target/surefire-reports for the individual test results.
[JENKINS] Recording test results
[INFO] 
[INFO] --- maven-jar-plugin:2.3.1:jar (default-jar) @ org.cumulus4j.store.test ---
[INFO] Building jar: /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.test/target/org.cumulus4j.store.test-1.2.1-SNAPSHOT.jar
[INFO] 
[INFO] --- maven-jar-plugin:2.3.1:test-jar (test-jar) @ org.cumulus4j.store.test ---
[INFO] Building jar: /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.test/target/org.cumulus4j.store.test-1.2.1-SNAPSHOT-tests.jar
[INFO] 
[INFO] --- maven-source-plugin:2.1.2:jar-no-fork (attach-sources) @ org.cumulus4j.store.test ---
[INFO] META-INF already added, skipping
[INFO] org already added, skipping
[INFO] org/cumulus4j already added, skipping
[INFO] org/cumulus4j/store already added, skipping
[INFO] org/cumulus4j/store/test already added, skipping
[INFO] org/cumulus4j/store/test/movie already added, skipping
[INFO] org/cumulus4j/store/test/embedded already added, skipping
[INFO] org/cumulus4j/store/test/embedded/onetoone already added, skipping
[INFO] org/cumulus4j/store/test/embedded/onetoone/nested already added, skipping
[INFO] org/cumulus4j/store/test/embedded/onetomany already added, skipping
[INFO] org/cumulus4j/store/test/inheritance already added, skipping
[INFO] org/cumulus4j/store/test/inheritance/sources already added, skipping
[INFO] org/cumulus4j/store/test/account already added, skipping
[INFO] org/cumulus4j/store/test/account/id already added, skipping
[INFO] org/cumulus4j/store/test/onetoone already added, skipping
[INFO] org/cumulus4j/store/test/onetoone/mappedby already added, skipping
[INFO] org/cumulus4j/store/test/metadata already added, skipping
[INFO] org/cumulus4j/store/test/valuestrategy already added, skipping
[INFO] org/cumulus4j/store/test/framework already added, skipping
[INFO] org/cumulus4j/store/test/collection already added, skipping
[INFO] org/cumulus4j/store/test/collection/join already added, skipping
[INFO] org/cumulus4j/store/test/collection/mappedby already added, skipping
[INFO] org/cumulus4j/store/test/datatype already added, skipping
[INFO] LICENCE.txt already added, skipping
[INFO] META-INF/MANIFEST.MF already added, skipping
[INFO] Building jar: /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.test/target/org.cumulus4j.store.test-1.2.1-SNAPSHOT-sources.jar
[INFO] META-INF already added, skipping
[INFO] org already added, skipping
[INFO] org/cumulus4j already added, skipping
[INFO] org/cumulus4j/store already added, skipping
[INFO] org/cumulus4j/store/test already added, skipping
[INFO] org/cumulus4j/store/test/movie already added, skipping
[INFO] org/cumulus4j/store/test/embedded already added, skipping
[INFO] org/cumulus4j/store/test/embedded/onetoone already added, skipping
[INFO] org/cumulus4j/store/test/embedded/onetoone/nested already added, skipping
[INFO] org/cumulus4j/store/test/embedded/onetomany already added, skipping
[INFO] org/cumulus4j/store/test/inheritance already added, skipping
[INFO] org/cumulus4j/store/test/inheritance/sources already added, skipping
[INFO] org/cumulus4j/store/test/account already added, skipping
[INFO] org/cumulus4j/store/test/account/id already added, skipping
[INFO] org/cumulus4j/store/test/onetoone already added, skipping
[INFO] org/cumulus4j/store/test/onetoone/mappedby already added, skipping
[INFO] org/cumulus4j/store/test/metadata already added, skipping
[INFO] org/cumulus4j/store/test/valuestrategy already added, skipping
[INFO] org/cumulus4j/store/test/framework already added, skipping
[INFO] org/cumulus4j/store/test/collection already added, skipping
[INFO] org/cumulus4j/store/test/collection/join already added, skipping
[INFO] org/cumulus4j/store/test/collection/mappedby already added, skipping
[INFO] org/cumulus4j/store/test/datatype already added, skipping
[INFO] LICENCE.txt already added, skipping
[INFO] META-INF/MANIFEST.MF already added, skipping
[INFO] 
[INFO] --- maven-install-plugin:2.4:install (default-install) @ org.cumulus4j.store.test ---
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.test/target/org.cumulus4j.store.test-1.2.1-SNAPSHOT.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.store.test/1.2.1-SNAPSHOT/org.cumulus4j.store.test-1.2.1-SNAPSHOT.jar
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.test/pom.xml to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.store.test/1.2.1-SNAPSHOT/org.cumulus4j.store.test-1.2.1-SNAPSHOT.pom
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.test/target/org.cumulus4j.store.test-1.2.1-SNAPSHOT-tests.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.store.test/1.2.1-SNAPSHOT/org.cumulus4j.store.test-1.2.1-SNAPSHOT-tests.jar
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.test/target/org.cumulus4j.store.test-1.2.1-SNAPSHOT-sources.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.store.test/1.2.1-SNAPSHOT/org.cumulus4j.store.test-1.2.1-SNAPSHOT-sources.jar