SuccessConsole Output

Skipping 3,138 KB.. Full Log
eldID == :fieldMeta_fieldID && this.classMeta_classID == :classMeta_classID && this.indexKey == :indexKey" since the connection used is closing
09:57:50,580 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
09:57:50,581 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
09:57:50,582 INFO  [main][ElementASetQueryTest] invoke: found 2 ElementASetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
09:57:50,582 INFO  [main][General] >> result=Owner 5
09:57:50,582 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
09:57:50,582 INFO  [main][General] >> result=Owner 3
09:57:50,582 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.1, S.Element 3.2, S.Element 3.3
09:57:50,584 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
09:57:50,584 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:50,592 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
09:57:51,358 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:57:51,360 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:57:51,375 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:57:53,854 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:57:53,854 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:57:53,854 INFO  [main][Cumulus4jStoreManager] =======================================================
09:57:53,855 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:57:53,855 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:57:53,880 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:57:53,880 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:57:53,887 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.join.ElementASetOwner" not found !
09:57:53,888 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.join.ElementA" not found !
09:57:54,013 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
09:57:54,014 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
09:57:54,015 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
09:57:54,016 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
09:57:54,017 INFO  [main][ElementASetQueryTest] invoke: found 3 ElementASetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
09:57:54,018 INFO  [main][General] >> result=Owner 1
09:57:54,018 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.1, S.Element 1.4, S.Element 1.3, S.Element 1.2
09:57:54,018 INFO  [main][General] >> result=Owner 2
09:57:54,018 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.1, S.Element 2.4, S.Element 2.3, S.Element 2.2
09:57:54,018 INFO  [main][General] >> result=Owner 4
09:57:54,018 INFO  [main][ElementASetQueryTest] invoke:   * Owner 4: S.Element 4.3
09:57:54,020 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
09:57:54,020 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,022 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
09:57:54,026 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
09:57:54,027 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
09:57:54,028 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.contains(elementVariable) && elementVariable == :element" and param "ElementA[name="S.Element 3.2"]":
09:57:54,028 INFO  [main][General] >> result=Owner 3
09:57:54,028 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.2, S.Element 3.3, S.Element 3.1
09:57:54,031 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
09:57:54,031 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,032 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
09:57:54,034 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
09:57:54,035 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
09:57:54,036 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
09:57:54,038 INFO  [main][ElementASetQueryTest] invoke: found 4 ElementASetOwners for query-filter "!this.set.contains(:element)" and param "ElementA[name="S.Element 3.2"]":
09:57:54,038 INFO  [main][General] >> result=Owner 4
09:57:54,038 INFO  [main][ElementASetQueryTest] invoke:   * Owner 4: S.Element 4.3
09:57:54,038 INFO  [main][General] >> result=Owner 5
09:57:54,038 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
09:57:54,038 INFO  [main][General] >> result=Owner 1
09:57:54,038 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.4, S.Element 1.2, S.Element 1.1, S.Element 1.3
09:57:54,038 INFO  [main][General] >> result=Owner 2
09:57:54,038 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.1, S.Element 2.3, S.Element 2.4, S.Element 2.2
09:57:54,040 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
09:57:54,040 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,047 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
09:57:54,049 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
09:57:54,050 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
09:57:54,050 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
09:57:54,051 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
09:57:54,052 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
09:57:54,053 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
09:57:54,054 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
09:57:54,055 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
09:57:54,056 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
09:57:54,057 INFO  [main][ElementASetQueryTest] invoke: found 3 ElementASetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) < 0" and param "4":
09:57:54,057 INFO  [main][General] >> result=Owner 1
09:57:54,057 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.4, S.Element 1.3, S.Element 1.2, S.Element 1.1
09:57:54,058 INFO  [main][General] >> result=Owner 2
09:57:54,058 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.2, S.Element 2.1, S.Element 2.3, S.Element 2.4
09:57:54,058 INFO  [main][General] >> result=Owner 3
09:57:54,058 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.2, S.Element 3.1, S.Element 3.3
09:57:54,059 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
09:57:54,059 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,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
09:57:54,068 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
09:57:54,069 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
09:57:54,070 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
09:57:54,071 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
09:57:54,072 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
09:57:54,072 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
09:57:54,073 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
09:57:54,074 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
09:57:54,075 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
09:57:54,076 INFO  [main][ElementASetQueryTest] invoke: found 3 ElementASetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable.name.indexOf(:elementPart) >= 0)" and param "4":
09:57:54,077 INFO  [main][General] >> result=Owner 1
09:57:54,077 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.4, S.Element 1.2, S.Element 1.3, S.Element 1.1
09:57:54,077 INFO  [main][General] >> result=Owner 2
09:57:54,077 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.3, S.Element 2.1, S.Element 2.2, S.Element 2.4
09:57:54,077 INFO  [main][General] >> result=Owner 3
09:57:54,077 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.1, S.Element 3.2, S.Element 3.3
09:57:54,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
09:57:54,079 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,080 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
09:57:54,084 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
09:57:54,085 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
09:57:54,086 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
09:57:54,088 INFO  [main][ElementASetQueryTest] invoke: found 4 ElementASetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable == :element" and param "ElementA[name="S.Element 3.2"]":
09:57:54,088 INFO  [main][General] >> result=Owner 4
09:57:54,088 INFO  [main][ElementASetQueryTest] invoke:   * Owner 4: S.Element 4.3
09:57:54,088 INFO  [main][General] >> result=Owner 5
09:57:54,088 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
09:57:54,088 INFO  [main][General] >> result=Owner 1
09:57:54,088 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.3, S.Element 1.4, S.Element 1.2, S.Element 1.1
09:57:54,088 INFO  [main][General] >> result=Owner 2
09:57:54,088 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.3, S.Element 2.2, S.Element 2.1, S.Element 2.4
09:57:54,090 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
09:57:54,090 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,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
09:57:54,093 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
09:57:54,094 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.isEmpty()" and param "ElementA[name="S.Element 3.2"]":
09:57:54,094 INFO  [main][General] >> result=Owner 5
09:57:54,094 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
09:57:54,095 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
09:57:54,095 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,097 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
09:57:54,098 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
09:57:54,099 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.size() == 3" and param "ElementA[name="S.Element 3.2"]":
09:57:54,099 INFO  [main][General] >> result=Owner 3
09:57:54,099 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.2, S.Element 3.3, S.Element 3.1
09:57:54,100 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
09:57:54,101 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,102 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
09:57:54,104 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
09:57:54,106 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
09:57:54,106 INFO  [main][ElementASetQueryTest] invoke: found 1 ElementASetOwners for query-filter "this.set.contains(:element)" and param "ElementA[name="S.Element 3.2"]":
09:57:54,107 INFO  [main][General] >> result=Owner 3
09:57:54,107 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.3, S.Element 3.2, S.Element 3.1
09:57:54,109 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
09:57:54,109 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,111 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
09:57:54,116 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
09:57:54,118 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
09:57:54,119 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
09:57:54,120 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
09:57:54,121 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
09:57:54,122 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
09:57:54,124 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
09:57:54,125 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
09:57:54,126 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
09:57:54,127 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
09:57:54,128 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
09:57:54,128 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
09:57:54,130 INFO  [main][ElementASetQueryTest] invoke: found 4 ElementASetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "ElementA[name="S.Element 3.2"]":
09:57:54,130 INFO  [main][General] >> result=Owner 1
09:57:54,131 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.2, S.Element 1.4, S.Element 1.1, S.Element 1.3
09:57:54,131 INFO  [main][General] >> result=Owner 2
09:57:54,131 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.3, S.Element 2.2, S.Element 2.4, S.Element 2.1
09:57:54,131 INFO  [main][General] >> result=Owner 3
09:57:54,131 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.3, S.Element 3.1, S.Element 3.2
09:57:54,131 INFO  [main][General] >> result=Owner 4
09:57:54,131 INFO  [main][ElementASetQueryTest] invoke:   * Owner 4: S.Element 4.3
09:57:54,132 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
09:57:54,133 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,135 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
09:57:54,137 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
09:57:54,138 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
09:57:54,138 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
09:57:54,139 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
09:57:54,140 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
09:57:54,141 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
09:57:54,142 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
09:57:54,143 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
09:57:54,144 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
09:57:54,145 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
09:57:54,145 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
09:57:54,146 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
09:57:54,147 INFO  [main][ElementASetQueryTest] invoke: found 3 ElementASetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "ElementA[name="S.Element 4.3"]":
09:57:54,148 INFO  [main][General] >> result=Owner 1
09:57:54,148 INFO  [main][ElementASetQueryTest] invoke:   * Owner 1: S.Element 1.3, S.Element 1.4, S.Element 1.2, S.Element 1.1
09:57:54,148 INFO  [main][General] >> result=Owner 2
09:57:54,148 INFO  [main][ElementASetQueryTest] invoke:   * Owner 2: S.Element 2.4, S.Element 2.3, S.Element 2.1, S.Element 2.2
09:57:54,148 INFO  [main][General] >> result=Owner 3
09:57:54,148 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.3, S.Element 3.2, S.Element 3.1
09:57:54,149 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
09:57:54,150 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,157 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
09:57:54,158 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
09:57:54,159 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
09:57:54,160 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
09:57:54,160 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
09:57:54,161 INFO  [main][ElementASetQueryTest] invoke: found 2 ElementASetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
09:57:54,161 INFO  [main][General] >> result=Owner 3
09:57:54,161 INFO  [main][ElementASetQueryTest] invoke:   * Owner 3: S.Element 3.3, S.Element 3.2, S.Element 3.1
09:57:54,161 INFO  [main][General] >> result=Owner 5
09:57:54,161 INFO  [main][ElementASetQueryTest] invoke:   * Owner 5: 
09:57:54,163 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
09:57:54,163 INFO  [main][ElementASetQueryTest] createTestData: There is already test data. Skipping creation.
09:57:54,165 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
09:57:54,166 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 26, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.737 sec
Running org.cumulus4j.store.test.collection.mappedby.Element3MapQueryTest
09:57:54,999 INFO  [main][JDOTransactionalRunner] run: Shutting down Derby (in case it was used before).
09:57:55,431 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:57:55,438 INFO  [main][AbstractJDOTransactionalTestClearingDatabase] clearDatabase: Clearing database (dropping all tables).
09:57:55,438 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:57:55,446 INFO  [main][CleanupUtil] cleanoutRDBMS: derbyDatabaseDir="/tmp/derby/cumulus4j" was deleted successfully.
09:57:55,446 WARN  [main][CleanupUtil] dropAllTables: 'ConnectionURL' property is not set for index datastore! Skipping!
09:57:55,446 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:57:55,447 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:57:55,461 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:57:59,524 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:57:59,524 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:57:59,525 INFO  [main][Cumulus4jStoreManager] =======================================================
09:57:59,527 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:57:59,527 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:57:59,595 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:57:59,697 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:57:59,810 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element3MapOwner" not found !
09:57:59,814 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element3" not found !
09:57:59,986 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
09:57:59,996 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches: found 3 Element3MapOwners for query-filter "this.map.containsKey(variable) && variable.name.indexOf(:queryParam) >= 0" and param "4":
09:57:59,996 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 1: Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="ddd", name="Element 1.4"]=ddd, Element3[value="ccc", name="Element 1.3"]=ccc
09:57:59,996 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 2: Element3[value="aa", name="Element 2.1"]=aa, Element3[value="dd", name="Element 2.4"]=dd, Element3[value="bb", name="Element 2.2"]=bb, Element3[value="cc", name="Element 2.3"]=cc
09:57:59,996 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
09:57:59,998 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
09:57:59,999 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:00,003 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
09:58:00,005 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches: found 3 Element3MapOwners for query-filter "this.map.containsValue(variable) && variable.indexOf(:queryParam) >= 0" and param "bb":
09:58:00,005 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 1: Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="ddd", name="Element 1.4"]=ddd, Element3[value="ccc", name="Element 1.3"]=ccc
09:58:00,006 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 2: Element3[value="dd", name="Element 2.4"]=dd, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="aa", name="Element 2.1"]=aa, Element3[value="bb", name="Element 2.2"]=bb
09:58:00,006 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
09:58:00,008 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
09:58:00,008 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:00,015 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
09:58:00,022 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
09:58:00,023 INFO  [main][Element3MapQueryTest] queryContainsKeyParameter: found 1 Element3MapOwners for query-filter "this.map.containsKey(:queryParam)" and param "Element3[value="b", name="Element 3.2"]":
09:58:00,023 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
09:58:00,025 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
09:58:00,025 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:00,026 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
09:58:00,028 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
09:58:00,034 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
09:58:00,037 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter: found 5 Element3MapOwners for query-filter "!this.map.containsKey(:queryParam)" and param "Element3[value="b", name="Element 3.2"]":
09:58:00,037 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
09:58:00,037 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 1: Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="ddd", name="Element 1.4"]=ddd, Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="ccc", name="Element 1.3"]=ccc
09:58:00,038 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 5: 
09:58:00,038 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
09:58:00,038 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 2: Element3[value="aa", name="Element 2.1"]=aa, Element3[value="dd", name="Element 2.4"]=dd, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="bb", name="Element 2.2"]=bb
09:58:00,039 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
09:58:00,040 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:00,042 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
09:58:00,045 INFO  [main][Element3MapQueryTest] queryContainsValueParameter: found 2 Element3MapOwners for query-filter "this.map.containsValue(:queryParam)" and param "ccc":
09:58:00,045 INFO  [main][Element3MapQueryTest] queryContainsValueParameter:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
09:58:00,046 INFO  [main][Element3MapQueryTest] queryContainsValueParameter:   * 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
09:58:00,048 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
09:58:00,048 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:00,050 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
09:58:00,051 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
09:58:00,053 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter: found 4 Element3MapOwners for query-filter "!this.map.containsValue(:queryParam)" and param "ccc":
09:58:00,053 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 5: 
09:58:00,053 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
09:58:00,053 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 2: Element3[value="dd", name="Element 2.4"]=dd, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="bb", name="Element 2.2"]=bb, Element3[value="aa", name="Element 2.1"]=aa
09:58:00,053 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
09:58:00,960 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:58:00,963 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:00,979 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:58:03,648 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:58:03,649 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:58:03,649 INFO  [main][Cumulus4jStoreManager] =======================================================
09:58:03,650 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:03,650 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:03,679 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:03,680 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:03,687 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element3MapOwner" not found !
09:58:03,689 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element3" not found !
09:58:03,829 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
09:58:03,832 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches: found 3 Element3MapOwners for query-filter "this.map.containsKey(variable) && variable.name.indexOf(:queryParam) >= 0" and param "4":
09:58:03,832 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 1: Element3[value="ddd", name="Element 1.4"]=ddd, Element3[value="ccc", name="Element 1.3"]=ccc, Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="bbb", name="Element 1.2"]=bbb
09:58:03,832 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 2: Element3[value="aa", name="Element 2.1"]=aa, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="dd", name="Element 2.4"]=dd, Element3[value="bb", name="Element 2.2"]=bb
09:58:03,833 INFO  [main][Element3MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
09:58:03,834 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
09:58:03,834 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:03,839 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
09:58:03,841 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches: found 3 Element3MapOwners for query-filter "this.map.containsValue(variable) && variable.indexOf(:queryParam) >= 0" and param "bb":
09:58:03,841 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
09:58:03,841 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 2: Element3[value="cc", name="Element 2.3"]=cc, Element3[value="dd", name="Element 2.4"]=dd, Element3[value="bb", name="Element 2.2"]=bb, Element3[value="aa", name="Element 2.1"]=aa
09:58:03,841 INFO  [main][Element3MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
09:58:03,843 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
09:58:03,843 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:03,844 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
09:58:03,846 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
09:58:03,847 INFO  [main][Element3MapQueryTest] queryContainsKeyParameter: found 1 Element3MapOwners for query-filter "this.map.containsKey(:queryParam)" and param "Element3[value="b", name="Element 3.2"]":
09:58:03,847 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
09:58:03,848 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
09:58:03,848 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:03,849 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
09:58:03,851 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
09:58:03,852 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
09:58:03,854 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter: found 5 Element3MapOwners for query-filter "!this.map.containsKey(:queryParam)" and param "Element3[value="b", name="Element 3.2"]":
09:58:03,854 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 2: Element3[value="dd", name="Element 2.4"]=dd, Element3[value="cc", name="Element 2.3"]=cc, Element3[value="aa", name="Element 2.1"]=aa, Element3[value="bb", name="Element 2.2"]=bb
09:58:03,854 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
09:58:03,855 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
09:58:03,855 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 5: 
09:58:03,855 INFO  [main][Element3MapQueryTest] queryNotContainsKeyParameter:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
09:58:03,856 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
09:58:03,856 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:03,858 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
09:58:03,859 INFO  [main][Element3MapQueryTest] queryContainsValueParameter: found 2 Element3MapOwners for query-filter "this.map.containsValue(:queryParam)" and param "ccc":
09:58:03,860 INFO  [main][Element3MapQueryTest] queryContainsValueParameter:   * Owner 1: Element3[value="ccc", name="Element 1.3"]=ccc, Element3[value="aaa", name="Element 1.1"]=aaa, Element3[value="bbb", name="Element 1.2"]=bbb, Element3[value="ddd", name="Element 1.4"]=ddd
09:58:03,860 INFO  [main][Element3MapQueryTest] queryContainsValueParameter:   * Owner 4: Element3[value="ccc", name="Element 4.3"]=ccc
09:58:03,861 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
09:58:03,861 INFO  [main][Element3MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:03,863 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
09:58:03,864 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
09:58:03,866 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter: found 4 Element3MapOwners for query-filter "!this.map.containsValue(:queryParam)" and param "ccc":
09:58:03,866 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * 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
09:58:03,866 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
09:58:03,866 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 5: 
09:58:03,866 INFO  [main][Element3MapQueryTest] queryNotContainsValueParameter:   * Owner 6: Element3[value="bb", name="Element 6.2"]=bb
09:58:03,866 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 12, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.607 sec
Running org.cumulus4j.store.test.collection.mappedby.Element2MapQueryTest
09:58:04,615 INFO  [main][JDOTransactionalRunner] run: Shutting down Derby (in case it was used before).
09:58:04,728 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:05,097 INFO  [main][AbstractJDOTransactionalTestClearingDatabase] clearDatabase: Clearing database (dropping all tables).
09:58:05,098 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:05,112 INFO  [main][CleanupUtil] cleanoutRDBMS: derbyDatabaseDir="/tmp/derby/cumulus4j" was deleted successfully.
09:58:05,112 WARN  [main][CleanupUtil] dropAllTables: 'ConnectionURL' property is not set for index datastore! Skipping!
09:58:05,113 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:58:05,113 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:05,128 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:58:09,185 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:58:09,185 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:58:09,185 INFO  [main][Cumulus4jStoreManager] =======================================================
09:58:09,187 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:09,188 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:09,256 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:09,355 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:09,464 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element2MapOwner" not found !
09:58:09,469 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element2" not found !
09:58:09,625 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
09:58:09,634 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches: found 3 Element2MapOwners for query-filter "this.map.containsKey(variable) && variable.indexOf(:queryParam) >= 0" and param "bb":
09:58:09,635 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"]
09:58:09,635 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"]
09:58:09,635 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:09,637 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
09:58:09,637 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,646 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
09:58:09,651 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches: found 4 Element2MapOwners for query-filter "this.map.containsKey(variable) && variable.indexOf(:queryParam) < 0" and param "bb":
09:58:09,651 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"]
09:58:09,651 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"]
09:58:09,651 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"]
09:58:09,651 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:09,653 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
09:58:09,653 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,659 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
09:58:09,661 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches: found 3 Element2MapOwners for query-filter "this.map.containsValue(variable) && variable.name.indexOf(:queryParam) >= 0" and param "4":
09:58:09,662 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"]
09:58:09,662 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"]
09:58:09,662 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:09,663 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
09:58:09,663 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,667 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
09:58:09,672 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches: found 4 Element2MapOwners for query-filter "this.map.containsKey(variable) && !(variable.indexOf(:queryParam) >= 0)" and param "bb":
09:58:09,672 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"]
09:58:09,672 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"]
09:58:09,672 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"]
09:58:09,672 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:09,674 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
09:58:09,674 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,680 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
09:58:09,686 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches: found 4 Element2MapOwners for query-filter "this.map.containsValue(variable) && !(variable.name.indexOf(:queryParam) >= 0)" and param "4":
09:58:09,686 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"]
09:58:09,686 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"]
09:58:09,686 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"]
09:58:09,686 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:09,688 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
09:58:09,688 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,694 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
09:58:09,699 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches: found 4 Element2MapOwners for query-filter "this.map.containsValue(variable) && variable.name.indexOf(:queryParam) < 0" and param "4":
09:58:09,699 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"]
09:58:09,699 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"]
09:58:09,699 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"]
09:58:09,700 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:09,701 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
09:58:09,701 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,708 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
09:58:09,709 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter: found 2 Element2MapOwners for query-filter "this.map.containsKey(:queryParam)" and param "ccc":
09:58:09,709 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:09,710 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"]
09:58:09,711 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
09:58:09,711 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,713 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
09:58:09,719 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
09:58:09,720 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter: found 4 Element2MapOwners for query-filter "!this.map.containsKey(:queryParam)" and param "ccc":
09:58:09,720 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 5: 
09:58:09,720 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:09,721 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"]
09:58:09,721 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"]
09:58:09,722 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
09:58:09,722 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,724 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
09:58:09,731 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
09:58:09,732 INFO  [main][Element2MapQueryTest] queryContainsValueParameter: found 1 Element2MapOwners for query-filter "this.map.containsValue(:queryParam)" and param "Element2[key="b", name="Element 3.2"]":
09:58:09,732 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"]
09:58:09,733 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
09:58:09,734 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:09,735 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
09:58:09,737 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
09:58:09,737 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
09:58:09,739 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter: found 5 Element2MapOwners for query-filter "!this.map.containsValue(:queryParam)" and param "Element2[key="b", name="Element 3.2"]":
09:58:09,739 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:09,740 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"]
09:58:09,740 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 5: 
09:58:09,740 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:09,740 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"]
09:58:10,563 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:58:10,564 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:10,580 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:58:10,782 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:13,088 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:58:13,088 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:58:13,088 INFO  [main][Cumulus4jStoreManager] =======================================================
09:58:13,089 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:13,089 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:13,112 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:13,113 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:13,123 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element2MapOwner" not found !
09:58:13,124 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element2" not found !
09:58:13,320 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
09:58:13,322 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches: found 3 Element2MapOwners for query-filter "this.map.containsKey(variable) && variable.indexOf(:queryParam) >= 0" and param "bb":
09:58:13,323 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"]
09:58:13,323 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"]
09:58:13,323 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:13,324 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
09:58:13,325 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,328 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
09:58:13,338 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches: found 4 Element2MapOwners for query-filter "this.map.containsKey(variable) && variable.indexOf(:queryParam) < 0" and param "bb":
09:58:13,338 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"]
09:58:13,338 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"]
09:58:13,338 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"]
09:58:13,338 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndIndexOfNotMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:13,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
09:58:13,340 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,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
09:58:13,350 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches: found 3 Element2MapOwners for query-filter "this.map.containsValue(variable) && variable.name.indexOf(:queryParam) >= 0" and param "4":
09:58:13,350 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"]
09:58:13,350 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"]
09:58:13,351 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:13,352 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
09:58:13,353 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,357 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
09:58:13,363 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches: found 4 Element2MapOwners for query-filter "this.map.containsKey(variable) && !(variable.indexOf(:queryParam) >= 0)" and param "bb":
09:58:13,363 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"]
09:58:13,363 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"]
09:58:13,364 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"]
09:58:13,364 INFO  [main][Element2MapQueryTest] queryContainsKeyVariableAndNotIndexOfMatches:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:13,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
09:58:13,366 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,373 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
09:58:13,377 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches: found 4 Element2MapOwners for query-filter "this.map.containsValue(variable) && !(variable.name.indexOf(:queryParam) >= 0)" and param "4":
09:58:13,378 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"]
09:58:13,378 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"]
09:58:13,378 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"]
09:58:13,378 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndNotIndexOfMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:13,382 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
09:58:13,383 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,391 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
09:58:13,396 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches: found 4 Element2MapOwners for query-filter "this.map.containsValue(variable) && variable.name.indexOf(:queryParam) < 0" and param "4":
09:58:13,396 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"]
09:58:13,396 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"]
09:58:13,396 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"]
09:58:13,396 INFO  [main][Element2MapQueryTest] queryContainsValueVariableAndIndexOfNotMatches:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:13,398 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
09:58:13,398 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,400 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
09:58:13,401 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter: found 2 Element2MapOwners for query-filter "this.map.containsKey(:queryParam)" and param "ccc":
09:58:13,402 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"]
09:58:13,402 INFO  [main][Element2MapQueryTest] queryContainsKeyParameter:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:13,403 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
09:58:13,404 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,405 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
09:58:13,407 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
09:58:13,408 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter: found 4 Element2MapOwners for query-filter "!this.map.containsKey(:queryParam)" and param "ccc":
09:58:13,408 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"]
09:58:13,409 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"]
09:58:13,409 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 5: 
09:58:13,409 INFO  [main][Element2MapQueryTest] queryNotContainsKeyParameter:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:13,410 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
09:58:13,410 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,412 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
09:58:13,414 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
09:58:13,415 INFO  [main][Element2MapQueryTest] queryContainsValueParameter: found 1 Element2MapOwners for query-filter "this.map.containsValue(:queryParam)" and param "Element2[key="b", name="Element 3.2"]":
09:58:13,415 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"]
09:58:13,417 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
09:58:13,417 INFO  [main][Element2MapQueryTest] createTestData: There is already test data. Skipping creation.
09:58:13,418 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
09:58:13,420 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
09:58:13,421 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
09:58:13,423 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter: found 5 Element2MapOwners for query-filter "!this.map.containsValue(:queryParam)" and param "Element2[key="b", name="Element 3.2"]":
09:58:13,423 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"]
09:58:13,423 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 4: ccc=Element2[key="ccc", name="Element 4.3"]
09:58:13,423 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"]
09:58:13,424 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 5: 
09:58:13,424 INFO  [main][Element2MapQueryTest] queryNotContainsValueParameter:   * Owner 6: bb=Element2[key="bb", name="Element 6.2"]
09:58:13,424 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 20, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.642 sec
Running org.cumulus4j.store.test.collection.mappedby.Element1SetQueryTest
09:58:14,263 INFO  [main][JDOTransactionalRunner] run: Shutting down Derby (in case it was used before).
09:58:14,700 INFO  [main][AbstractJDOTransactionalTestClearingDatabase] clearDatabase: Clearing database (dropping all tables).
09:58:14,701 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:14,710 INFO  [main][CleanupUtil] cleanoutRDBMS: derbyDatabaseDir="/tmp/derby/cumulus4j" was deleted successfully.
09:58:14,710 WARN  [main][CleanupUtil] dropAllTables: 'ConnectionURL' property is not set for index datastore! Skipping!
09:58:14,711 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:58:14,712 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:14,727 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:58:15,007 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:18,595 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:58:18,596 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:58:18,596 INFO  [main][Cumulus4jStoreManager] =======================================================
09:58:18,597 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:18,598 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:18,677 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:18,782 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:18,898 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element1SetOwner" not found !
09:58:18,901 INFO  [main][Retrieve] Object with id "1.org.cumulus4j.store.test.collection.mappedby.Element1" not found !
09:58:19,032 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
09:58:19,041 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
09:58:19,041 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 1: Element 1.4, Element 1.1, Element 1.3, Element 1.2
09:58:19,042 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 2: Element 2.2, Element 2.3, Element 2.1, Element 2.4
09:58:19,042 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 4: Element 4.3
09:58:19,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
09:58:19,044 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,049 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
09:58:19,053 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
09:58:19,053 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableEquals: found 1 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable == :element" and param "Element1[name="Element 3.2"]":
09:58:19,054 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableEquals:   * Owner 3: Element 3.1, Element 3.2, Element 3.3
09:58:19,055 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
09:58:19,055 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,056 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
09:58:19,063 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
09:58:19,068 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
09:58:19,069 INFO  [main][Element1SetQueryTest] queryNotContainsParameter: found 4 Element1SetOwners for query-filter "!this.set.contains(:element)" and param "Element1[name="Element 3.2"]":
09:58:19,070 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 4: Element 4.3
09:58:19,070 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 1: Element 1.2, Element 1.3, Element 1.4, Element 1.1
09:58:19,070 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 5: 
09:58:19,070 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 2: Element 2.3, Element 2.2, Element 2.1, Element 2.4
09:58:19,071 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
09:58:19,071 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,083 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
09:58:19,087 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) < 0" and param "4":
09:58:19,087 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 1: Element 1.3, Element 1.1, Element 1.4, Element 1.2
09:58:19,087 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 2: Element 2.4, Element 2.2, Element 2.1, Element 2.3
09:58:19,087 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 3: Element 3.2, Element 3.3, Element 3.1
09:58:19,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
09:58:19,089 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,096 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
09:58:19,099 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable.name.indexOf(:elementPart) >= 0)" and param "4":
09:58:19,100 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 1: Element 1.4, Element 1.3, Element 1.2, Element 1.1
09:58:19,100 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 2: Element 2.4, Element 2.2, Element 2.3, Element 2.1
09:58:19,100 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 3: Element 3.2, Element 3.3, Element 3.1
09:58:19,102 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
09:58:19,103 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,104 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
09:58:19,108 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
09:58:19,109 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
09:58:19,110 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals: found 4 Element1SetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable == :element" and param "Element1[name="Element 3.2"]":
09:58:19,110 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 4: Element 4.3
09:58:19,110 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 1: Element 1.3, Element 1.2, Element 1.1, Element 1.4
09:58:19,110 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 5: 
09:58:19,110 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 2: Element 2.1, Element 2.3, Element 2.4, Element 2.2
09:58:19,112 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
09:58:19,112 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,114 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
09:58:19,115 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
09:58:19,116 INFO  [main][Element1SetQueryTest] queryContainsParameter: found 1 Element1SetOwners for query-filter "this.set.contains(:element)" and param "Element1[name="Element 3.2"]":
09:58:19,116 INFO  [main][Element1SetQueryTest] queryContainsParameter:   * Owner 3: Element 3.3, Element 3.1, Element 3.2
09:58:19,117 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
09:58:19,117 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,119 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
09:58:19,127 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
09:58:19,130 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "Element1[name="Element 4.3"]":
09:58:19,131 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 1: Element 1.4, Element 1.3, Element 1.2, Element 1.1
09:58:19,131 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 2: Element 2.3, Element 2.2, Element 2.4, Element 2.1
09:58:19,131 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 3: Element 3.3, Element 3.2, Element 3.1
09:58:19,132 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
09:58:19,133 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,139 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
09:58:19,141 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
09:58:19,142 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf: found 2 Element1SetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
09:58:19,142 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf:   * Owner 5: 
09:58:19,142 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf:   * Owner 3: Element 3.3, Element 3.2, Element 3.1
09:58:19,143 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
09:58:19,143 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:19,144 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
09:58:19,146 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
09:58:19,149 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1: found 4 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "Element1[name="Element 3.2"]":
09:58:19,149 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 1: Element 1.3, Element 1.4, Element 1.2, Element 1.1
09:58:19,149 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 2: Element 2.2, Element 2.3, Element 2.4, Element 2.1
09:58:19,149 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 3: Element 3.3, Element 3.2, Element 3.1
09:58:19,150 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 4: Element 4.3
09:58:19,880 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:58:19,880 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:19,899 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:58:20,815 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:22,199 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:58:22,199 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:58:22,199 INFO  [main][Cumulus4jStoreManager] =======================================================
09:58:22,200 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:22,200 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:22,225 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:22,226 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:22,234 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element1SetOwner" not found !
09:58:22,236 INFO  [main][Retrieve] Object with id "2.org.cumulus4j.store.test.collection.mappedby.Element1" not found !
09:58:22,342 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
09:58:22,344 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
09:58:22,345 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 1: Element 1.2, Element 1.3, Element 1.4, Element 1.1
09:58:22,345 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 2: Element 2.3, Element 2.4, Element 2.1, Element 2.2
09:58:22,345 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableIndexOf:   * Owner 4: Element 4.3
09:58:22,346 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
09:58:22,347 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,348 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
09:58:22,352 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
09:58:22,353 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableEquals: found 1 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable == :element" and param "Element1[name="Element 3.2"]":
09:58:22,353 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableEquals:   * Owner 3: Element 3.3, Element 3.2, Element 3.1
09:58:22,355 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
09:58:22,355 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,356 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
09:58:22,358 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
09:58:22,359 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
09:58:22,361 INFO  [main][Element1SetQueryTest] queryNotContainsParameter: found 4 Element1SetOwners for query-filter "!this.set.contains(:element)" and param "Element1[name="Element 3.2"]":
09:58:22,361 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 4: Element 4.3
09:58:22,361 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 1: Element 1.4, Element 1.2, Element 1.1, Element 1.3
09:58:22,361 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 5: 
09:58:22,361 INFO  [main][Element1SetQueryTest] queryNotContainsParameter:   * Owner 2: Element 2.4, Element 2.3, Element 2.2, Element 2.1
09:58:22,363 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
09:58:22,363 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,370 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
09:58:22,378 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) < 0" and param "4":
09:58:22,378 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 1: Element 1.4, Element 1.2, Element 1.1, Element 1.3
09:58:22,378 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 2: Element 2.3, Element 2.2, Element 2.4, Element 2.1
09:58:22,379 INFO  [main][Element1SetQueryTest] queryContainsVariableAndVariableNotIndexOf:   * Owner 3: Element 3.1, Element 3.2, Element 3.3
09:58:22,380 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
09:58:22,381 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,388 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
09:58:22,392 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable.name.indexOf(:elementPart) >= 0)" and param "4":
09:58:22,393 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 1: Element 1.2, Element 1.4, Element 1.3, Element 1.1
09:58:22,393 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 2: Element 2.2, Element 2.1, Element 2.3, Element 2.4
09:58:22,393 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableIndexOf:   * Owner 3: Element 3.1, Element 3.2, Element 3.3
09:58:22,395 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
09:58:22,396 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,397 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
09:58:22,401 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
09:58:22,402 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
09:58:22,404 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals: found 4 Element1SetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable == :element" and param "Element1[name="Element 3.2"]":
09:58:22,404 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 4: Element 4.3
09:58:22,404 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 1: Element 1.2, Element 1.1, Element 1.4, Element 1.3
09:58:22,404 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 5: 
09:58:22,404 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableEquals:   * Owner 2: Element 2.2, Element 2.3, Element 2.1, Element 2.4
09:58:22,405 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
09:58:22,406 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,407 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
09:58:22,409 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
09:58:22,409 INFO  [main][Element1SetQueryTest] queryContainsParameter: found 1 Element1SetOwners for query-filter "this.set.contains(:element)" and param "Element1[name="Element 3.2"]":
09:58:22,409 INFO  [main][Element1SetQueryTest] queryContainsParameter:   * Owner 3: Element 3.3, Element 3.2, Element 3.1
09:58:22,411 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
09:58:22,411 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,412 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
09:58:22,416 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
09:58:22,420 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2: found 3 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "Element1[name="Element 4.3"]":
09:58:22,420 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 1: Element 1.4, Element 1.3, Element 1.2, Element 1.1
09:58:22,420 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 2: Element 2.3, Element 2.4, Element 2.1, Element 2.2
09:58:22,420 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals2:   * Owner 3: Element 3.1, Element 3.2, Element 3.3
09:58:22,422 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
09:58:22,422 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,429 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
09:58:22,431 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
09:58:22,432 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf: found 2 Element1SetOwners for query-filter "!this.set.contains(elementVariable) && elementVariable.name.indexOf(:elementPart) >= 0" and param "4":
09:58:22,432 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf:   * Owner 3: Element 3.1, Element 3.3, Element 3.2
09:58:22,432 INFO  [main][Element1SetQueryTest] queryNotContainsVariableAndVariableIndexOf:   * Owner 5: 
09:58:22,434 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
09:58:22,434 INFO  [main][Element1SetQueryTest] createTestData: There is already test data. Skipping creation.
09:58:22,435 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
09:58:22,437 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
09:58:22,441 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1: found 4 Element1SetOwners for query-filter "this.set.contains(elementVariable) && !(elementVariable == :element)" and param "Element1[name="Element 3.2"]":
09:58:22,441 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 1: Element 1.3, Element 1.4, Element 1.1, Element 1.2
09:58:22,441 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 2: Element 2.1, Element 2.2, Element 2.4, Element 2.3
09:58:22,441 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 3: Element 3.2, Element 3.3, Element 3.1
09:58:22,441 INFO  [main][Element1SetQueryTest] queryContainsVariableAndNotVariableEquals1:   * Owner 4: Element 4.3
09:58:22,442 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 20, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.04 sec
Running org.cumulus4j.store.test.datatype.StandardOneToOneTypesTest
09:58:23,305 INFO  [main][JDOTransactionalRunner] run: Shutting down Derby (in case it was used before).
09:58:24,023 INFO  [main][AbstractJDOTransactionalTestClearingDatabase] clearDatabase: Clearing database (dropping all tables).
09:58:24,026 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:24,039 INFO  [main][CleanupUtil] cleanoutRDBMS: derbyDatabaseDir="/tmp/derby/cumulus4j" was deleted successfully.
09:58:24,039 WARN  [main][CleanupUtil] dropAllTables: 'ConnectionURL' property is not set for index datastore! Skipping!
09:58:24,040 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:58:24,040 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:24,053 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:58:24,695 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:28,168 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:58:28,168 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:58:28,168 INFO  [main][Cumulus4jStoreManager] =======================================================
09:58:28,202 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:28,202 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:28,270 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:28,449 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:29,931 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
09:58:29,936 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 0cb5a8de-3eca-4236-9925-645eb56e872d
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 14c5808e-8c3d-4251-94c1-76d2131c0454
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 328bc326-96a1-456b-8feb-bb11ae5b7db7
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 3a666e3d-6ddf-4884-834c-a14044836cf2
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 3b7c45ce-4cb3-4fd2-a425-8248a23ba941
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 5174f5cf-6ce1-4164-bf47-571b1cde0968
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 5f47f664-2774-40c6-8d62-d412a9554a22
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 61286336-4575-43b0-ae33-2cacbdcd7a01
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 63849722-ce72-4d75-8050-f7f7f32e28a8
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 686bb206-d1ed-49fd-8063-cceab30629c5
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 6cd93f25-5898-4813-a8af-0a96abd95f9e
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 6ff7b5dc-0574-49a8-ae6d-4f75b4bd29bf
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 77a77b13-0e76-4a3c-a27e-d45d8db95ad3
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 7c793c65-093f-4ef1-abe0-863c3fcc28f6
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 8d1a3850-246f-4def-94b2-e64ff341b06f
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 8fff41bc-37a7-4ba3-84a3-96059b76f29c
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 9294aecc-5ccf-48aa-b630-39da777c9064
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 951271dd-3696-4a1d-8175-77a3edb1b162
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 996fdaa2-7379-4aed-b6af-fa4db0db8f3c
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = a05ac2b0-6fbc-4b0b-81e3-0d70d21d86e2
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = ad78a67c-a8c6-4da7-b295-8fac365a210a
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = b8cb2bac-4d47-4c94-b110-1f1c52d37b47
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = ba782c08-84c8-4a97-9cb4-82c84b34fca2
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = bdadf447-03df-43d0-acd1-390eb057b44a
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = bede00c0-e24e-4e4d-86cc-f6817281e039
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = d563e2cc-5374-4e44-a587-1b6a47029f56
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = d5837e77-592c-483d-af40-af631d0dc2e8
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = d87b82e4-74e3-4704-aaf6-1af2c8d19537
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = e9a5eb96-3810-49c8-9db6-706e20d2a20d
09:58:29,937 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = f2c4fa54-abd0-43d8-95b3-ccdfd98d0ed0
09:58:31,478 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:31,478 INFO  [main][JDOTransactionalRunner] run: Setting up PersistenceManagerFactory.
09:58:31,484 INFO  [main][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
09:58:31,505 INFO  [main][Persistence] Property cumulus4j.index.clob.enabled unknown - will be ignored
09:58:34,158 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:40,106 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:44,325 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:44,359 INFO  [main][Cumulus4jStoreManager] ====================== Cumulus4j ======================
09:58:44,359 INFO  [main][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
09:58:44,359 INFO  [main][Cumulus4jStoreManager] =======================================================
09:58:44,361 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:44,361 INFO  [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:44,388 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:44,389 INFO  [main][MinimumCumulus4jVersion] version=10100001
09:58:44,885 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
09:58:44,890 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 0cb5a8de-3eca-4236-9925-645eb56e872d
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 14c5808e-8c3d-4251-94c1-76d2131c0454
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 328bc326-96a1-456b-8feb-bb11ae5b7db7
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 3a666e3d-6ddf-4884-834c-a14044836cf2
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 3b7c45ce-4cb3-4fd2-a425-8248a23ba941
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 5174f5cf-6ce1-4164-bf47-571b1cde0968
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 5f47f664-2774-40c6-8d62-d412a9554a22
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 61286336-4575-43b0-ae33-2cacbdcd7a01
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 63849722-ce72-4d75-8050-f7f7f32e28a8
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 686bb206-d1ed-49fd-8063-cceab30629c5
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 6cd93f25-5898-4813-a8af-0a96abd95f9e
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 6ff7b5dc-0574-49a8-ae6d-4f75b4bd29bf
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 77a77b13-0e76-4a3c-a27e-d45d8db95ad3
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 7c793c65-093f-4ef1-abe0-863c3fcc28f6
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 8d1a3850-246f-4def-94b2-e64ff341b06f
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 8fff41bc-37a7-4ba3-84a3-96059b76f29c
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 9294aecc-5ccf-48aa-b630-39da777c9064
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 951271dd-3696-4a1d-8175-77a3edb1b162
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = 996fdaa2-7379-4aed-b6af-fa4db0db8f3c
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = a05ac2b0-6fbc-4b0b-81e3-0d70d21d86e2
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = ad78a67c-a8c6-4da7-b295-8fac365a210a
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = b8cb2bac-4d47-4c94-b110-1f1c52d37b47
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = ba782c08-84c8-4a97-9cb4-82c84b34fca2
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = bdadf447-03df-43d0-acd1-390eb057b44a
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = bede00c0-e24e-4e4d-86cc-f6817281e039
09:58:44,891 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = d563e2cc-5374-4e44-a587-1b6a47029f56
09:58:44,892 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = d5837e77-592c-483d-af40-af631d0dc2e8
09:58:44,892 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = d87b82e4-74e3-4704-aaf6-1af2c8d19537
09:58:44,892 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = e9a5eb96-3810-49c8-9db6-706e20d2a20d
09:58:44,892 INFO  [main][StandardOneToOneTypesTest] * foundEntity.uuid = f2c4fa54-abd0-43d8-95b3-ccdfd98d0ed0
09:58:44,915 INFO  [main][JDOTransactionalRunner] run: Shutting down PersistenceManagerFactory.
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 22.41 sec

Results :

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

[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