Console Output

Skipping 1,138 KB.. Full Log
.crypto.keymanager.messagebroker.pmf.PendingRequest@655ae489" (id="ssjv7po9epgtkwv4c9047hmve") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:51:20,444 WARN  [qtp626069067-2526][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@655ae489" (id="ssjv7po9epgtkwv4c9047hmve") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
FailedObject:org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@939c40e0
05:51:20,448 DEBUG [Thread-512][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
05:51:20,459 DEBUG [Thread-512][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
05:51:20,462 DEBUG [qtp626069067-2533][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:51:20,464 DEBUG [qtp626069067-2533][MessageBrokerPMF] [shxvzt] _pushResponse[requestID=ssjv7po9epgtkwv4c9047hmve]: Entered.
05:51:20,468 DEBUG [qtp626069067-2533][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: Entered.
05:51:20,650 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Created new Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
05:51:20,650 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,657 TRACE [qtp626069067-2514][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
05:51:20,657 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,657 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,657 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@48f14221[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:20,660 TRACE [qtp626069067-2514][CryptoCache] getKeyData: Found cached key with keyID=1.
05:51:20,660 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Created new Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
05:51:20,661 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,661 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,661 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,661 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@547a8502[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:20,664 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,664 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,664 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,664 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,666 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,666 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,673 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,673 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,679 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@45a02da2[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:20,681 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,681 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,681 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,682 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,682 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f24a657[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:20,685 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,685 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,685 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,685 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,685 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5dfb1432[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:20,687 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,687 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,688 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,688 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,689 DEBUG [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
05:51:20,689 DEBUG [qtp626069067-2514][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
05:51:20,690 DEBUG [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@42f07226[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,691 DEBUG [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@b750651[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,691 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b750651[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,691 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@42f07226[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,691 DEBUG [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1f3c72d9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:20,691 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1f3c72d9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:20,691 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@42f07226[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,691 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b750651[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,691 DEBUG [qtp626069067-2514][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@b750651[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,692 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1f3c72d9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:20,693 DEBUG [qtp626069067-2514][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@42f07226[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,693 DEBUG [qtp626069067-2514][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@42f07226[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,693 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@42f07226[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,693 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1f3c72d9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:20,693 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1f3c72d9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:20,693 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1f3c72d9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:20,693 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1f3c72d9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:20,693 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@b750651[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,693 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@b750651[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,693 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b750651[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,693 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@b750651[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,698 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4444c2dd[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,698 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3491caf3[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:20,698 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@860e35a[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:20,698 DEBUG [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 9 ms). class=org.cumulus4j.store.test.movie.Rating
05:51:20,699 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4444c2dd[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,699 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4444c2dd[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,699 TRACE [qtp626069067-2514][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
05:51:20,699 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,699 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,701 TRACE [qtp626069067-2514][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
05:51:20,701 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4444c2dd[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,701 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4444c2dd[2,org.cumulus4j.store.test.movie.Rating]
05:51:20,703 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,703 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,706 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,706 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,708 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,708 TRACE [qtp626069067-2514][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,708 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5dfb1432[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,708 TRACE [qtp626069067-2514][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,708 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f24a657[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:20,708 TRACE [qtp626069067-2514][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,708 TRACE [qtp626069067-2514][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,708 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@45a02da2[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,708 TRACE [qtp626069067-2514][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,708 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@547a8502[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:20,708 TRACE [qtp626069067-2514][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
05:51:20,708 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,709 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@48f14221[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:20,709 TRACE [qtp626069067-2514][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 7
05:51:20,709 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,709 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,710 TRACE [qtp626069067-2514][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 7
05:51:20,710 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@48f14221[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:20,711 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,711 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,712 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,712 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,712 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@547a8502[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:20,714 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,714 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,715 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,715 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,717 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,717 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,719 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,719 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,720 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@45a02da2[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:20,721 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,721 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,722 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,722 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,722 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f24a657[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:20,724 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,724 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,724 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,724 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,724 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5dfb1432[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:20,726 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,726 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,726 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,726 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,728 DEBUG [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
05:51:20,729 DEBUG [qtp626069067-2514][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
05:51:20,729 DEBUG [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@171f7a1a[3,org.cumulus4j.store.test.movie.Person]
05:51:20,731 DEBUG [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@747e1fda[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,731 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@747e1fda[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,731 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@171f7a1a[3,org.cumulus4j.store.test.movie.Person]
05:51:20,731 DEBUG [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@435ec1a4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:20,731 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@435ec1a4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:20,731 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@171f7a1a[3,org.cumulus4j.store.test.movie.Person]
05:51:20,731 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@747e1fda[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,731 DEBUG [qtp626069067-2514][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@747e1fda[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,733 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@435ec1a4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:20,733 DEBUG [qtp626069067-2514][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@171f7a1a[3,org.cumulus4j.store.test.movie.Person]
05:51:20,733 DEBUG [qtp626069067-2514][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@171f7a1a[3,org.cumulus4j.store.test.movie.Person]
05:51:20,733 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@171f7a1a[3,org.cumulus4j.store.test.movie.Person]
05:51:20,733 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@747e1fda[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,733 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@747e1fda[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,733 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@747e1fda[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,733 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@747e1fda[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,734 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@435ec1a4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:20,734 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@435ec1a4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:20,734 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@435ec1a4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:20,734 DEBUG [qtp626069067-2514][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@435ec1a4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:20,734 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7ee081cf[3,org.cumulus4j.store.test.movie.Person]
05:51:20,734 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6fd55105[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:20,734 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7e79a534[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:20,734 DEBUG [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 5 ms). class=org.cumulus4j.store.test.movie.Person
05:51:20,734 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7ee081cf[3,org.cumulus4j.store.test.movie.Person]
05:51:20,734 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7ee081cf[3,org.cumulus4j.store.test.movie.Person]
05:51:20,734 TRACE [qtp626069067-2514][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
05:51:20,734 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,735 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,736 TRACE [qtp626069067-2514][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
05:51:20,736 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7ee081cf[3,org.cumulus4j.store.test.movie.Person]
05:51:20,736 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7ee081cf[3,org.cumulus4j.store.test.movie.Person]
05:51:20,737 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,737 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,739 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,739 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,740 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,742 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,742 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,743 TRACE [qtp626069067-2514][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@6
05:51:20,743 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,743 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
05:51:20,744 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,745 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,745 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,748 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,749 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,750 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,751 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,751 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,752 TRACE [qtp626069067-2514][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@6]
05:51:20,752 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,752 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f24a657[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:20,752 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
05:51:20,753 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,753 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,753 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,753 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f24a657[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:20,755 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,756 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,756 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,756 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,756 TRACE [qtp626069067-2514][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f24a657[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:20,758 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,758 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,760 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,760 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,760 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,760 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@1205974954 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,784 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,785 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,789 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:20,791 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,798 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,798 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,798 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,798 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,798 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,798 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:20,799 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,801 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,801 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,801 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,801 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,801 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,801 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:20,801 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,802 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,802 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,803 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,803 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,803 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,803 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:20,803 TRACE [qtp626069067-2514][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:20,804 TRACE [qtp626069067-2514][CryptoCache] acquireCipherEntry: Found cached Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:20,804 TRACE [qtp626069067-2514][CryptoCache] releaseCipherEntry: Releasing Cipher@282914179 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:20,804 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,804 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,804 TRACE [qtp626069067-2514][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d928aa[1,org.cumulus4j.store.test.movie.Movie]
05:51:20,824 DEBUG [qtp1483487407-2664][AbstractService] getAuth: 'Authorization' header: Basic ZGV2aWw6dGVzdHRlc3R0ZXN0
05:51:20,825 DEBUG [qtp1483487407-2664][CryptoSessionService] open: authUserName='devil' cryptoSessionID='test-ioth9kls-1clru2x7ozgex_2dtaxi08*1*0mriks'
05:51:21,518 INFO  [qtp626069067-2495][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
05:51:22,151 WARN  [qtp626069067-2495][MetaData] MetaData Parser encountered an error in file "jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/org/cumulus4j/store/model/package.jdo" at line 10, column 6 : cvc-elt.1: Cannot find the declaration of element 'jdo'. - Please check your specification of DTD and the validity of the MetaData XML that you have specified.
05:51:22,153 WARN  [qtp626069067-2495][MetaData] MetaData Parser encountered an error in file "jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/org/cumulus4j/store/model/package.jdo" at line 48, column 7 : The content of element type "jdo" is incomplete, it must match "(extension*,(package|query|fetch-plan)+,extension*)". - Please check your specification of DTD and the validity of the MetaData XML that you have specified.
05:51:24,927 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
05:51:24,927 INFO  [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
05:51:25,296 DEBUG [qtp626069067-2525][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth8aup-1ac9kizpp8w2o_2opfa063]: Returning request: null
05:51:25,298 DEBUG [Thread-502][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:51:25,304 DEBUG [qtp626069067-2514][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:51:25,305 DEBUG [qtp626069067-2514][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth8aup-1ac9kizpp8w2o_2opfa063]: Entered.
05:51:25,798 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 1 users left in cache.
05:51:25,840 INFO  [qtp626069067-2495][Cumulus4jStoreManager] ====================== Cumulus4j ======================
05:51:25,840 INFO  [qtp626069067-2495][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
05:51:25,840 INFO  [qtp626069067-2495][Cumulus4jStoreManager] =======================================================
05:51:25,841 ERROR [qtp626069067-2495][Persistence] java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at org.datanucleus.plugin.NonManagedPluginRegistry.createExecutableExtension(NonManagedPluginRegistry.java:631)
	at org.datanucleus.plugin.PluginManager.createExecutableExtension(PluginManager.java:301)
	at org.datanucleus.NucleusContext.initialiseAutoStart(NucleusContext.java:432)
	at org.datanucleus.NucleusContext.initialise(NucleusContext.java:384)
	at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.freezeConfiguration(JDOPersistenceManagerFactory.java:768)
	at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.createPersistenceManagerFactory(JDOPersistenceManagerFactory.java:326)
	at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.getPersistenceManagerFactory(JDOPersistenceManagerFactory.java:195)
	at sun.reflect.GeneratedMethodAccessor420.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at javax.jdo.JDOHelper$16.run(JDOHelper.java:1970)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.jdo.JDOHelper.invoke(JDOHelper.java:1965)
	at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1171)
	at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:813)
	at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
	at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManagerFactory(TestService.java:59)
	at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManager(TestService.java:72)
	at org.cumulus4j.integrationtest.webapp.TestService.testPost(TestService.java:93)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
	at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
	at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
	at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
	at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
	at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
	at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
	at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469)
	at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400)
	at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349)
	at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339)
	at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
	at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
	at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:546)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1283)
	at org.cumulus4j.keymanager.back.shared.AjaxHeadersFilter.doFilter(AjaxHeadersFilter.java:33)
	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1254)
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:481)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:516)
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:230)
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:956)
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:411)
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:188)
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:891)
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:247)
	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:151)
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:114)
	at org.eclipse.jetty.server.Server.handle(Server.java:353)
	at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:598)
	at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:1059)
	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:590)
	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212)
	at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:427)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:510)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34)
	at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:450)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassCastException: org.cumulus4j.store.Cumulus4jStoreManager cannot be cast to org.datanucleus.store.rdbms.RDBMSStoreManager
	at org.datanucleus.store.rdbms.autostart.SchemaAutoStarter.<init>(SchemaAutoStarter.java:68)
	... 69 more

Reading Movies before writing:
05:51:25,841 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Movie
05:51:25,842 INFO  [qtp626069067-2495][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
05:51:25,842 TRACE [qtp626069067-2495][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=test-ioth9kls-1clru2x7ozgex_2dtaxi08*1*0mriks
05:51:25,842 INFO  [qtp626069067-2495][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
05:51:25,863 INFO  [qtp626069067-2495][MinimumCumulus4jVersion] version=10100001
05:51:25,864 INFO  [qtp626069067-2495][MinimumCumulus4jVersion] version=10100001
05:51:25,864 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Movie
05:51:25,865 DEBUG [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,867 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2032990c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,870 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@4c4dbbe9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:51:25,870 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2032990c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,870 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2032990c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,870 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,870 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@400541ec[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,870 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3f236d5c[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:51:25,871 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@400541ec[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,871 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@400541ec[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,871 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,871 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5070191[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:51:25,871 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5070191[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:51:25,871 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,871 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6e076a10[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,871 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e076a10[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,871 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,872 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@7cbfcd6a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,872 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3f9ac6be[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:51:25,872 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7cbfcd6a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,872 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7cbfcd6a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,872 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,872 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@7fd4438c[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:51:25,873 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7fd4438c[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:51:25,873 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,873 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@4fc05246[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,873 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@27243670[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:51:25,873 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc05246[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,873 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc05246[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,873 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,874 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@55b90a36[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,874 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55b90a36[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,874 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,874 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@61f9cdaa[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,874 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6d79a0f1[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:51:25,875 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@61f9cdaa[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,875 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@61f9cdaa[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,875 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,875 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2032990c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,875 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@400541ec[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,875 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5070191[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:51:25,875 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e076a10[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,875 DEBUG [qtp626069067-2495][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@6e076a10[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,876 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7cbfcd6a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,876 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7fd4438c[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:51:25,876 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc05246[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,876 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55b90a36[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,876 DEBUG [qtp626069067-2495][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@55b90a36[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,877 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@61f9cdaa[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,878 DEBUG [qtp626069067-2495][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,878 DEBUG [qtp626069067-2495][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,878 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ad47441[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2032990c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2032990c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,878 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2032990c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@4c4dbbe9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@4c4dbbe9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:51:25,878 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4c4dbbe9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@4c4dbbe9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2032990c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@400541ec[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@400541ec[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,878 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@400541ec[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3f236d5c[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3f236d5c[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:51:25,878 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f236d5c[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:51:25,878 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3f236d5c[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:51:25,879 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@400541ec[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,879 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@55b90a36[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,879 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@55b90a36[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,879 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55b90a36[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,879 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@55b90a36[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,879 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@61f9cdaa[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,879 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@61f9cdaa[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,879 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@61f9cdaa[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6d79a0f1[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6d79a0f1[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:51:25,880 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d79a0f1[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6d79a0f1[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@61f9cdaa[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6e076a10[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6e076a10[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,880 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e076a10[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6e076a10[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@7fd4438c[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@7fd4438c[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:51:25,880 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7fd4438c[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@7fd4438c[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@4fc05246[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@4fc05246[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,880 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc05246[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,880 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@27243670[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@27243670[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:51:25,881 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@27243670[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@27243670[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@4fc05246[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5070191[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5070191[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:51:25,881 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5070191[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5070191[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@7cbfcd6a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@7cbfcd6a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,881 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7cbfcd6a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3f9ac6be[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3f9ac6be[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:51:25,881 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f9ac6be[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3f9ac6be[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:51:25,881 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@7cbfcd6a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,882 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@191a9989[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@445bc77f[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2fcdf111[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7399a9e5[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3e02b0ce[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f8f84e[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@64fdc0b9[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5a159b42[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@713ad40e[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@12e378ef[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@18918a02[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6ea8ddd9[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4915eea6[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:25,882 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4038c36b[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:51:25,882 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 41 ms). class=org.cumulus4j.store.test.movie.Movie
05:51:25,882 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 1 sessions left.
05:51:25,883 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:25,884 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:25,884 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:25,895 TRACE [qtp626069067-2495][CryptoCache] getKeyData: No cached key with keyID=1 found.
05:51:25,895 INFO  [qtp626069067-2495][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
05:51:26,927 DEBUG [qtp626069067-2524][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth92lk--xbrab1cpyura_r0q9sz62]: Returning request: null
05:51:26,929 DEBUG [Thread-508][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:51:26,933 DEBUG [qtp626069067-2524][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:51:26,934 DEBUG [qtp626069067-2524][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth92lk--xbrab1cpyura_r0q9sz62]: Entered.
05:51:26,988 DEBUG [qtp626069067-2517][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth92lk--xbrab1cpyura_r0q9sz62]: Returning request: null
05:51:26,994 DEBUG [Thread-507][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:51:26,997 DEBUG [qtp626069067-2525][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:51:26,998 DEBUG [qtp626069067-2525][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth92lk--xbrab1cpyura_r0q9sz62]: Entered.
05:51:27,012 DEBUG [qtp626069067-2497][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth92lk--xbrab1cpyura_r0q9sz62]: Returning request: null
05:51:27,014 DEBUG [Thread-509][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:51:27,018 DEBUG [qtp626069067-2517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:51:27,019 DEBUG [qtp626069067-2517][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth92lk--xbrab1cpyura_r0q9sz62]: Entered.
05:51:27,029 DEBUG [qtp626069067-2527][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth92lk--xbrab1cpyura_r0q9sz62]: Returning request: null
05:51:27,031 DEBUG [Thread-510][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:51:27,033 DEBUG [qtp626069067-2497][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:51:27,033 DEBUG [qtp626069067-2497][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth92lk--xbrab1cpyura_r0q9sz62]: Entered.
05:51:33,579 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
05:51:33,579 INFO  [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
05:51:39,636 DEBUG [qtp626069067-2495][MessageBrokerPMF] [shxvzt] _query[requestID=jvzzclvh99zjhazh7misp9ylm]: Entered with request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@b7e5feb3[jvzzclvh99zjhazh7misp9ylm,test-ioth9kls-1clru2x7ozgex_2dtaxi08*1*0mriks]
05:51:39,698 DEBUG [qtp626069067-2495][MessageBrokerPMF] [shxvzt] _query[requestID=jvzzclvh99zjhazh7misp9ylm]: Request persisted.
05:51:39,703 DEBUG [qtp626069067-2526][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: Returning request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@b7e5feb3[jvzzclvh99zjhazh7misp9ylm,test-ioth9kls-1clru2x7ozgex_2dtaxi08*1*0mriks]
05:51:39,704 DEBUG [qtp626069067-2526][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyRequest matching=true
05:51:39,706 DEBUG [Thread-513][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
05:51:39,707 ERROR [qtp626069067-2492][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@29e71d92" (id="jvzzclvh99zjhazh7misp9ylm") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:51:39,708 WARN  [qtp626069067-2492][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@29e71d92" (id="jvzzclvh99zjhazh7misp9ylm") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
FailedObject:org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@b7e5feb3
05:51:39,710 ERROR [qtp626069067-2523][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@7a595c0d" (id="jvzzclvh99zjhazh7misp9ylm") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:51:39,711 WARN  [qtp626069067-2523][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@7a595c0d" (id="jvzzclvh99zjhazh7misp9ylm") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
FailedObject:org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@b7e5feb3
05:51:39,711 ERROR [qtp626069067-2533][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@5a889083" (id="jvzzclvh99zjhazh7misp9ylm") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:51:39,712 WARN  [qtp626069067-2533][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@5a889083" (id="jvzzclvh99zjhazh7misp9ylm") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
FailedObject:org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@b7e5feb3
05:51:39,713 ERROR [qtp626069067-2703][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@5688b896" (id="jvzzclvh99zjhazh7misp9ylm") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:51:39,714 WARN  [qtp626069067-2703][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@5688b896" (id="jvzzclvh99zjhazh7misp9ylm") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
FailedObject:org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@b7e5feb3
05:51:39,717 DEBUG [Thread-513][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyResponse matching=true
05:51:39,722 DEBUG [qtp626069067-2527][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:51:39,726 DEBUG [qtp626069067-2527][MessageBrokerPMF] [shxvzt] _pushResponse[requestID=jvzzclvh99zjhazh7misp9ylm]: Entered.
05:51:39,730 DEBUG [qtp626069067-2527][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: Entered.
05:51:39,911 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Created new Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
05:51:39,912 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:39,912 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,912 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,912 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,912 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:39,912 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:39,914 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:39,914 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:39,914 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,914 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,914 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,915 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:39,915 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:39,916 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:39,916 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:39,917 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,917 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,917 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,917 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:39,917 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:39,918 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:39,918 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:39,918 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,918 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,918 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
 * MMM 1464580257873
 * MMM 1464580268838
 * MMM 1464580274806
 * MMM 1464580280708
05:51:39,919 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:39,921 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:39,921 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f8f84e[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@12e378ef[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:39,921 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4915eea6[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2fcdf111[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:39,921 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
05:51:39,921 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:39,921 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@191a9989[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:39,922 TRACE [qtp626069067-2495][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
05:51:39,922 INFO  [qtp626069067-2495][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is not set. Using default algorithm 'Twofish/GCM/NoPadding'.
05:51:39,922 INFO  [qtp626069067-2495][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is not set. Using default MAC algorithm 'NONE'.
05:51:39,922 DEBUG [qtp626069067-2495][MessageBrokerPMF] [shxvzt] _query[requestID=tmvodwt20ace8vdf3go3sij63]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@354c0d03[tmvodwt20ace8vdf3go3sij63,test-ioth9kls-1clru2x7ozgex_2dtaxi08*1*0mriks]
05:51:39,926 DEBUG [qtp626069067-2495][MessageBrokerPMF] [shxvzt] _query[requestID=tmvodwt20ace8vdf3go3sij63]: Request persisted.
05:51:39,952 DEBUG [qtp626069067-2703][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@354c0d03[tmvodwt20ace8vdf3go3sij63,test-ioth9kls-1clru2x7ozgex_2dtaxi08*1*0mriks]
05:51:39,953 DEBUG [qtp626069067-2703][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
05:51:39,958 DEBUG [Thread-516][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
05:51:39,970 DEBUG [Thread-516][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
05:51:39,973 DEBUG [qtp626069067-2703][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:51:39,974 DEBUG [qtp626069067-2703][MessageBrokerPMF] [shxvzt] _pushResponse[requestID=tmvodwt20ace8vdf3go3sij63]: Entered.
05:51:39,978 DEBUG [qtp626069067-2703][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth9kls-1clru2x7ozgex_2dtaxi08]: Entered.
05:51:40,138 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Created new Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
05:51:40,138 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,144 TRACE [qtp626069067-2495][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
05:51:40,144 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,144 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,145 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@191a9989[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:40,148 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,148 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,148 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,148 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,148 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2fcdf111[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:40,150 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,150 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,150 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,151 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,153 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,153 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,161 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,161 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,167 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4915eea6[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:40,169 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,169 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,169 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,169 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,169 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@12e378ef[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:40,172 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,172 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,172 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,172 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,173 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f8f84e[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:40,174 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,175 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,175 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,175 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,176 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
05:51:40,176 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
05:51:40,177 DEBUG [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@3d7c61a7[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,178 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@41d9c42e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,178 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41d9c42e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,178 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3d7c61a7[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,178 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6e937253[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:40,179 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e937253[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:40,179 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3d7c61a7[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,179 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41d9c42e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,179 DEBUG [qtp626069067-2495][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@41d9c42e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,180 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e937253[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:40,181 DEBUG [qtp626069067-2495][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@3d7c61a7[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,181 DEBUG [qtp626069067-2495][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@3d7c61a7[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,181 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3d7c61a7[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,181 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6e937253[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:40,181 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6e937253[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:40,181 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e937253[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:40,181 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6e937253[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:40,181 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@41d9c42e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,181 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@41d9c42e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,181 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41d9c42e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,181 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@41d9c42e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,182 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@31f885ac[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,182 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@403a14c1[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:51:40,182 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@63f27eb2[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:51:40,182 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 6 ms). class=org.cumulus4j.store.test.movie.Rating
05:51:40,182 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@31f885ac[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,182 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@31f885ac[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,182 TRACE [qtp626069067-2495][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
05:51:40,182 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,182 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,184 TRACE [qtp626069067-2495][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
05:51:40,184 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@31f885ac[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,184 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@31f885ac[2,org.cumulus4j.store.test.movie.Rating]
05:51:40,185 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,185 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,187 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,188 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,189 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,189 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
05:51:40,189 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,189 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f8f84e[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:40,189 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,189 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
05:51:40,189 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,189 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@12e378ef[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:40,189 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
05:51:40,189 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,189 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
05:51:40,189 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,189 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4915eea6[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:40,189 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,189 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,189 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
05:51:40,189 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,190 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2fcdf111[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:40,190 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
05:51:40,190 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,190 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@191a9989[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:40,190 TRACE [qtp626069067-2495][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 12
05:51:40,190 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,190 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,191 TRACE [qtp626069067-2495][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 12
05:51:40,191 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@191a9989[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:51:40,193 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,193 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,193 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,194 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,194 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2fcdf111[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:51:40,196 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,196 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,196 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,196 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,198 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,198 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,201 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,201 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,202 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4915eea6[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:51:40,204 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,204 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,204 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,204 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,205 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@12e378ef[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:40,208 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,208 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,208 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,208 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,208 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f8f84e[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:51:40,210 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,210 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,211 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,211 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,212 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
05:51:40,213 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
05:51:40,214 DEBUG [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@5c03ff57[3,org.cumulus4j.store.test.movie.Person]
05:51:40,214 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@88c67a6[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,215 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@88c67a6[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,215 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5c03ff57[3,org.cumulus4j.store.test.movie.Person]
05:51:40,215 DEBUG [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@75557ffb[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:40,215 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@75557ffb[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:40,215 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5c03ff57[3,org.cumulus4j.store.test.movie.Person]
05:51:40,215 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@88c67a6[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,215 DEBUG [qtp626069067-2495][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@88c67a6[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,216 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@75557ffb[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:40,217 DEBUG [qtp626069067-2495][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@5c03ff57[3,org.cumulus4j.store.test.movie.Person]
05:51:40,217 DEBUG [qtp626069067-2495][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@5c03ff57[3,org.cumulus4j.store.test.movie.Person]
05:51:40,217 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5c03ff57[3,org.cumulus4j.store.test.movie.Person]
05:51:40,217 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@88c67a6[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,217 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@88c67a6[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,217 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@88c67a6[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,217 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@88c67a6[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,217 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@75557ffb[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:40,217 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@75557ffb[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:40,217 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@75557ffb[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:40,217 DEBUG [qtp626069067-2495][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@75557ffb[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:40,218 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2069646c[3,org.cumulus4j.store.test.movie.Person]
05:51:40,218 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2e95cfd5[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:51:40,218 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5e4b9489[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:51:40,218 DEBUG [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 6 ms). class=org.cumulus4j.store.test.movie.Person
05:51:40,218 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2069646c[3,org.cumulus4j.store.test.movie.Person]
05:51:40,218 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2069646c[3,org.cumulus4j.store.test.movie.Person]
05:51:40,218 TRACE [qtp626069067-2495][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
05:51:40,218 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,218 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,219 TRACE [qtp626069067-2495][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
05:51:40,220 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2069646c[3,org.cumulus4j.store.test.movie.Person]
05:51:40,220 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2069646c[3,org.cumulus4j.store.test.movie.Person]
05:51:40,221 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,221 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,225 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,225 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,226 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,228 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,228 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,228 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@b
05:51:40,228 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,229 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
05:51:40,230 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,230 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,231 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,234 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,234 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,235 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,237 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,237 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,237 TRACE [qtp626069067-2495][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@b]
05:51:40,237 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,237 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@12e378ef[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:40,237 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
05:51:40,238 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,239 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,239 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,239 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@12e378ef[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:40,241 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,241 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,241 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,241 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,241 TRACE [qtp626069067-2495][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@12e378ef[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:51:40,243 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,243 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,245 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,245 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,245 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,246 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@564793662 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,273 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,275 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,278 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:40,279 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,281 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,281 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,281 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,282 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,282 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,282 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:40,282 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,284 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,284 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,284 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,284 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,284 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,284 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:40,285 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,286 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,286 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,286 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,286 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,287 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,287 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:40,287 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,288 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,289 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,289 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,289 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,289 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,289 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:40,289 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,291 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,291 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,291 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,291 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,291 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,291 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:51:40,292 TRACE [qtp626069067-2495][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:51:40,293 TRACE [qtp626069067-2495][CryptoCache] acquireCipherEntry: Found cached Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:51:40,293 TRACE [qtp626069067-2495][CryptoCache] releaseCipherEntry: Releasing Cipher@1798399426 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:51:40,293 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,293 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
05:51:40,293 TRACE [qtp626069067-2495][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@6c2615d8[1,org.cumulus4j.store.test.movie.Movie]
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 110.918 sec

Results :

Tests run: 3, Failures: 0, Errors: 0, Skipped: 0

[JENKINS] Recording test results
[INFO] 
[INFO] --- maven-source-plugin:2.1.2:jar-no-fork (attach-sources) @ org.cumulus4j.integrationtest.withkeyserver ---
[INFO] No sources in project. Archive not created.
[INFO] 
[INFO] --- maven-install-plugin:2.4:install (default-install) @ org.cumulus4j.integrationtest.withkeyserver ---
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.withkeyserver/target/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.withkeyserver/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.jar
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.withkeyserver/pom.xml to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.withkeyserver/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.pom