|  Console Output
Skipping 1,266 KB.. Full Log9isyle0a7ooyrxis0vn9h1") 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@5fb42622
10:11:12,935 DEBUG [Thread-516][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:11:12,951 DEBUG [Thread-516][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
10:11:12,954 DEBUG [qtp307046058-2511][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:12,957 DEBUG [qtp307046058-2511][MessageBrokerPMF] [eof9fu] _pushResponse[requestID=8xv9isyle0a7ooyrxis0vn9h1]: Entered.
10:11:12,974 DEBUG [qtp307046058-2511][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Entered.
10:11:12,987 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
10:11:12,987 INFO [CryptoCache][CryptoCache] getCryptoCacheEntryExpiryAgeMSec: Property 'cumulus4j.CryptoCache.entryExpiryAge' cannot be read, because NucleusContext was garbage-collected. Using fallback value 300000.
10:11:12,987 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyEncryptionKeyEntry (1 left).
10:11:12,987 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyDecrypterEntry (1 left).
10:11:12,987 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyEntry (1 left).
10:11:12,987 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheCipherEntry (2 left).
10:11:12,987 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of empty List<CryptoCacheCipherEntry> (2 non-empty lists left).
10:11:13,156 DEBUG [qtp307046058-2509][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18ywes0-u5k33xyz6nsa_ro3y4yt8]: Returning request: null
10:11:13,163 DEBUG [Thread-505][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:11:13,161 DEBUG [qtp307046058-2476][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18ywes0-u5k33xyz6nsa_ro3y4yt8]: Returning request: null
10:11:13,159 DEBUG [qtp307046058-2474][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18ywes0-u5k33xyz6nsa_ro3y4yt8]: Returning request: null
10:11:13,169 DEBUG [qtp307046058-2682][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:13,169 DEBUG [Thread-506][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:11:13,173 DEBUG [qtp307046058-2682][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18ywes0-u5k33xyz6nsa_ro3y4yt8]: Entered.
10:11:13,183 DEBUG [Thread-503][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:11:13,190 DEBUG [qtp307046058-2509][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:13,191 DEBUG [qtp307046058-2474][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:13,196 DEBUG [qtp307046058-2474][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18ywes0-u5k33xyz6nsa_ro3y4yt8]: Entered.
10:11:13,202 DEBUG [qtp307046058-2509][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18ywes0-u5k33xyz6nsa_ro3y4yt8]: Entered.
10:11:13,218 DEBUG [qtp307046058-2510][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18ywes0-u5k33xyz6nsa_ro3y4yt8]: Returning request: null
10:11:13,220 DEBUG [Thread-507][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:11:13,228 DEBUG [qtp307046058-2476][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:13,234 DEBUG [qtp307046058-2476][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18ywes0-u5k33xyz6nsa_ro3y4yt8]: Entered.
10:11:13,312 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Created new Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:11:13,313 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,322 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:11:13,323 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,323 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,323 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@13fc3e7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:13,327 TRACE [qtp307046058-2517][CryptoCache] getKeyData: Found cached key with keyID=1.
10:11:13,329 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Created new Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:11:13,330 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,330 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,330 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,331 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7f5f6af8[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:13,337 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,338 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,338 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,338 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,339 DEBUG [qtp307046058-2498][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yxn08-118gtbd3w9gy1_py888r49]: Returning request: null
10:11:13,340 DEBUG [Thread-513][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:11:13,343 DEBUG [qtp307046058-2510][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:13,346 DEBUG [qtp307046058-2510][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yxn08-118gtbd3w9gy1_py888r49]: Entered.
10:11:13,346 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,347 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,360 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,360 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,398 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6b46a2dd[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:13,403 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,403 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,403 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,403 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,404 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a8aa0f4[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:13,409 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,410 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,410 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,410 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,410 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2253c672[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:13,415 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,416 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,416 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,416 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,419 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
10:11:13,419 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
10:11:13,421 DEBUG [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@5e7694cd[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,423 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@469c4831[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,424 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@469c4831[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,424 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5e7694cd[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,424 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@562f7ba1[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:13,425 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@562f7ba1[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:13,425 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5e7694cd[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,425 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@469c4831[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,426 DEBUG [qtp307046058-2517][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@469c4831[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,428 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@562f7ba1[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:13,429 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@5e7694cd[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,429 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@5e7694cd[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,429 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5e7694cd[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,431 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@562f7ba1[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:13,431 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@562f7ba1[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:13,431 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@562f7ba1[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:13,431 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@562f7ba1[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:13,431 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@469c4831[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,431 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@469c4831[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,432 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@469c4831[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,432 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@469c4831[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,432 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@412ae993[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,432 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@684cd351[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:13,432 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@bc5a056[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:13,432 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 13 ms). class=org.cumulus4j.store.test.movie.Rating
10:11:13,432 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@412ae993[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,432 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@412ae993[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,432 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
10:11:13,432 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,433 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,435 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:11:13,436 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@412ae993[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,436 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@412ae993[2,org.cumulus4j.store.test.movie.Rating]
10:11:13,439 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,439 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,444 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,445 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,448 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,448 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:11:13,448 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,448 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2253c672[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:13,448 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,448 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:11:13,448 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,448 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a8aa0f4[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:13,448 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:11:13,448 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,448 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:11:13,448 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,449 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6b46a2dd[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:13,449 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,449 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,449 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:11:13,449 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,449 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7f5f6af8[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:13,449 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:11:13,449 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,450 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@13fc3e7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:13,450 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 7
10:11:13,450 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,450 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,453 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 7
10:11:13,453 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@13fc3e7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:13,457 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,457 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,457 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,458 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,458 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7f5f6af8[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:13,465 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,467 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,467 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,467 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,474 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,474 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,480 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,480 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,483 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6b46a2dd[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:13,487 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,488 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,488 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,488 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,488 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a8aa0f4[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:13,493 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,493 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,494 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,494 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,494 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2253c672[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:13,499 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,499 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,499 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,500 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,504 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
10:11:13,504 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
10:11:13,506 DEBUG [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@77e7379b[3,org.cumulus4j.store.test.movie.Person]
10:11:13,508 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3cb671aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,509 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3cb671aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,509 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@77e7379b[3,org.cumulus4j.store.test.movie.Person]
10:11:13,509 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2999f03a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:13,509 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2999f03a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:13,510 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@77e7379b[3,org.cumulus4j.store.test.movie.Person]
10:11:13,510 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3cb671aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,510 DEBUG [qtp307046058-2517][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@3cb671aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,512 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2999f03a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:13,513 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@77e7379b[3,org.cumulus4j.store.test.movie.Person]
10:11:13,513 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@77e7379b[3,org.cumulus4j.store.test.movie.Person]
10:11:13,513 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@77e7379b[3,org.cumulus4j.store.test.movie.Person]
10:11:13,514 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3cb671aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,514 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3cb671aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,514 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3cb671aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,514 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3cb671aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,514 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2999f03a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:13,514 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2999f03a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:13,514 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2999f03a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:13,514 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2999f03a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:13,515 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1ef73aa7[3,org.cumulus4j.store.test.movie.Person]
10:11:13,515 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@792bb9d2[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:13,515 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@25b4c824[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:13,515 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 11 ms). class=org.cumulus4j.store.test.movie.Person
10:11:13,515 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1ef73aa7[3,org.cumulus4j.store.test.movie.Person]
10:11:13,515 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1ef73aa7[3,org.cumulus4j.store.test.movie.Person]
10:11:13,515 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
10:11:13,515 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,516 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,518 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:11:13,518 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1ef73aa7[3,org.cumulus4j.store.test.movie.Person]
10:11:13,518 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1ef73aa7[3,org.cumulus4j.store.test.movie.Person]
10:11:13,522 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,522 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,527 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,528 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,530 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,535 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,535 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,536 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@6]
10:11:13,536 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,536 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a8aa0f4[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:13,536 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
10:11:13,539 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,540 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,540 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,540 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a8aa0f4[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:13,545 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,546 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,546 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,546 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,546 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a8aa0f4[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:13,550 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,551 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,557 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,557 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,557 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,558 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,558 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,562 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,563 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,563 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@6
10:11:13,563 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,563 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
10:11:13,566 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,567 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,567 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,574 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,574 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2039714058 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,606 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,606 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,609 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:13,610 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,622 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,623 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,625 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,625 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,625 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,625 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:13,625 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,629 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,630 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,630 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,631 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,631 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,631 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:13,631 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,634 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,635 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,635 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,635 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,635 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,635 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:13,636 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:13,639 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:13,639 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@1118039982 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:13,640 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,640 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,640 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3c01abee[1,org.cumulus4j.store.test.movie.Movie]
10:11:13,654 DEBUG [qtp56413367-2648][AbstractService] getAuth: 'Authorization' header: Basic ZGV2aWw6dGVzdHRlc3R0ZXN0
10:11:13,654 DEBUG [qtp56413367-2648][CryptoSessionService] open: authUserName='devil' cryptoSessionID='test-i18yz6qb-rsnbou3zwaoc_h5tbnte1*1*03ea10'
10:11:14,714 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 1 sessions left.
10:11:14,715 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 1 users left in cache.
10:11:14,716 INFO [qtp307046058-2517][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:11:15,188 DEBUG [qtp307046058-2497][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Returning request: null
10:11:15,191 DEBUG [Thread-517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:11:15,196 DEBUG [qtp307046058-2498][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:15,200 DEBUG [qtp307046058-2498][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Entered.
10:11:15,671 WARN [qtp307046058-2517][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.
10:11:15,672 WARN [qtp307046058-2517][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.
10:11:16,430 DEBUG [qtp307046058-2496][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Returning request: null
10:11:16,432 DEBUG [Thread-515][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:11:16,436 DEBUG [qtp307046058-2496][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:16,439 DEBUG [qtp307046058-2496][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Entered.
10:11:16,445 DEBUG [qtp307046058-2472][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Returning request: null
10:11:16,447 DEBUG [Thread-518][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:11:16,450 DEBUG [qtp307046058-2497][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:16,452 DEBUG [qtp307046058-2497][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Entered.
10:11:20,908 INFO [qtp307046058-2517][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:11:20,908 INFO [qtp307046058-2517][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:11:20,909 INFO [qtp307046058-2517][Cumulus4jStoreManager] =======================================================
10:11:20,910 ERROR [qtp307046058-2517][Persistence] java.lang.reflect.InvocationTargetException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
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.GeneratedMethodAccessor413.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
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:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
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:
10:11:20,915 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Movie
10:11:20,916 INFO [qtp307046058-2517][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:11:20,916 TRACE [qtp307046058-2517][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1*1*03ea10
10:11:20,916 INFO [qtp307046058-2517][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:11:20,975 INFO [qtp307046058-2517][MinimumCumulus4jVersion] version=10100001
10:11:20,977 INFO [qtp307046058-2517][MinimumCumulus4jVersion] version=10100001
10:11:20,977 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Movie
10:11:20,981 DEBUG [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:20,988 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3aacdd79[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:20,991 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@56345439[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:11:20,992 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3aacdd79[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:20,992 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3aacdd79[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:20,992 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:20,992 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@365f21b4[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:20,994 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3a90fc67[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:11:20,996 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@365f21b4[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:20,996 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@365f21b4[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:20,996 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:20,996 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@49d6a669[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:11:20,997 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@49d6a669[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:11:20,997 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:20,997 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5a42dc84[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:20,998 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5a42dc84[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:20,998 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:20,998 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@411eed2d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:20,999 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@22e024c6[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:11:21,000 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@411eed2d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:21,000 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@411eed2d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:21,000 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,000 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3f71ddcb[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:11:21,001 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f71ddcb[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:11:21,001 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,001 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@267c356a[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,003 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@7c7a72e3[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:11:21,004 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@267c356a[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,004 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@267c356a[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,004 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,004 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@376f3a19[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,005 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@376f3a19[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,005 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,005 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@b100a48[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,006 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2b17fa34[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:11:21,007 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b100a48[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,007 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b100a48[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,007 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,007 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3aacdd79[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:21,008 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@365f21b4[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:21,008 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@49d6a669[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:11:21,008 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5a42dc84[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:21,008 DEBUG [qtp307046058-2517][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@5a42dc84[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:21,010 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@411eed2d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:21,011 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f71ddcb[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:11:21,011 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@267c356a[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,011 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@376f3a19[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,011 DEBUG [qtp307046058-2517][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@376f3a19[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,014 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b100a48[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,017 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,017 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,017 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4bd78fb4[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,018 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@49d6a669[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:11:21,018 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@49d6a669[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:11:21,019 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@49d6a669[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:11:21,019 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@49d6a669[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:11:21,020 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@376f3a19[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,020 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@376f3a19[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,020 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@376f3a19[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,020 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@376f3a19[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,021 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@365f21b4[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:21,021 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@365f21b4[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:21,021 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@365f21b4[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:21,021 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3a90fc67[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:11:21,021 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3a90fc67[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:11:21,021 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3a90fc67[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:11:21,021 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3a90fc67[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:11:21,022 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@365f21b4[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:21,022 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@411eed2d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:21,022 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@411eed2d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:21,022 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@411eed2d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:21,022 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@22e024c6[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:11:21,023 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@22e024c6[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:11:21,023 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@22e024c6[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:11:21,023 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@22e024c6[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:11:21,023 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@411eed2d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:21,023 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5a42dc84[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:21,023 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5a42dc84[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:21,023 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5a42dc84[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:21,023 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5a42dc84[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:21,024 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3aacdd79[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:21,024 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3aacdd79[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:21,024 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3aacdd79[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:21,024 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@56345439[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:11:21,025 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@56345439[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:11:21,025 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@56345439[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:11:21,025 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@56345439[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:11:21,025 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3aacdd79[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:21,025 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3f71ddcb[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:11:21,026 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3f71ddcb[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:11:21,026 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f71ddcb[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:11:21,026 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3f71ddcb[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:11:21,026 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@267c356a[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,026 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@267c356a[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,026 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@267c356a[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,027 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@7c7a72e3[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:11:21,027 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@7c7a72e3[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:11:21,027 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7c7a72e3[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:11:21,027 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@7c7a72e3[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:11:21,027 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@267c356a[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,027 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@b100a48[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,027 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@b100a48[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,027 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b100a48[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,028 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2b17fa34[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:11:21,028 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2b17fa34[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:11:21,028 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2b17fa34[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:11:21,028 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2b17fa34[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:11:21,028 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@b100a48[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,028 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:21,028 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@67cd0b7b[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:11:21,028 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@46aced7a[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:21,028 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@31b08d6[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@63e11b31[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc06131[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f2d00de[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3941fa3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@71a9082a[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@105737b2[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4e098f7f[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55ac02df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@ff0aa6a[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1441d53[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:21,029 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1ee134cb[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:11:21,029 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 114 ms). class=org.cumulus4j.store.test.movie.Movie
10:11:21,030 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:21,033 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:21,034 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:21,048 TRACE [qtp307046058-2517][CryptoCache] getKeyData: No cached key with keyID=1 found.
10:11:21,048 INFO [qtp307046058-2517][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
10:11:33,896 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
10:11:33,896 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:11:37,650 DEBUG [qtp307046058-2517][MessageBrokerPMF] [eof9fu] _query[requestID=rvkji4o17pwwihpwrmib3ayi0]: Entered with request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@cc3e430f[rvkji4o17pwwihpwrmib3ayi0,test-i18yz6qb-rsnbou3zwaoc_h5tbnte1*1*03ea10]
10:11:37,682 DEBUG [qtp307046058-2517][MessageBrokerPMF] [eof9fu] _query[requestID=rvkji4o17pwwihpwrmib3ayi0]: Request persisted.
10:11:37,693 DEBUG [qtp307046058-2497][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Returning request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@cc3e430f[rvkji4o17pwwihpwrmib3ayi0,test-i18yz6qb-rsnbou3zwaoc_h5tbnte1*1*03ea10]
10:11:37,694 ERROR [qtp307046058-2688][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@26e13a59" (id="rvkji4o17pwwihpwrmib3ayi0") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
10:11:37,694 DEBUG [qtp307046058-2497][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyRequest matching=true
10:11:37,694 WARN [qtp307046058-2688][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@26e13a59" (id="rvkji4o17pwwihpwrmib3ayi0") 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@cc3e430f
10:11:37,696 DEBUG [Thread-518][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:11:37,698 ERROR [qtp307046058-2511][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@7bc31a26" (id="rvkji4o17pwwihpwrmib3ayi0") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
10:11:37,698 WARN [qtp307046058-2511][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@7bc31a26" (id="rvkji4o17pwwihpwrmib3ayi0") 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@cc3e430f
10:11:37,705 DEBUG [Thread-518][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyResponse matching=true
10:11:37,708 DEBUG [qtp307046058-2691][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:37,713 DEBUG [qtp307046058-2691][MessageBrokerPMF] [eof9fu] _pushResponse[requestID=rvkji4o17pwwihpwrmib3ayi0]: Entered.
10:11:37,727 DEBUG [qtp307046058-2691][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Entered.
10:11:38,004 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Created new Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:11:38,005 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,005 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,006 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,006 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,006 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,006 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,010 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,011 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,011 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,011 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,012 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,012 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,012 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,016 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,016 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,017 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,017 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,017 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,017 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,017 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,021 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,021 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,022 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,022 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,022 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
* MMM 1413274247387
* MMM 1413274258479
* MMM 1413274267326
* MMM 1413274273447
10:11:38,022 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,024 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,024 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:11:38,024 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,025 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1441d53[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:38,025 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,025 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:11:38,025 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,025 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55ac02df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:38,025 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:11:38,025 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,025 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:11:38,025 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,025 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc06131[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:38,025 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,025 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,025 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:11:38,025 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,026 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@46aced7a[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:38,026 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:11:38,026 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,026 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3941fa3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:38,026 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:11:38,026 INFO [qtp307046058-2517][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is not set. Using default algorithm 'Twofish/GCM/NoPadding'.
10:11:38,026 INFO [qtp307046058-2517][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is not set. Using default MAC algorithm 'NONE'.
10:11:38,026 DEBUG [qtp307046058-2517][MessageBrokerPMF] [eof9fu] _query[requestID=f46w0ao5duone1wk8rlxzidof]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@6179e950[f46w0ao5duone1wk8rlxzidof,test-i18yz6qb-rsnbou3zwaoc_h5tbnte1*1*03ea10]
10:11:38,049 DEBUG [qtp307046058-2517][MessageBrokerPMF] [eof9fu] _query[requestID=f46w0ao5duone1wk8rlxzidof]: Request persisted.
10:11:38,060 DEBUG [qtp307046058-2498][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@6179e950[f46w0ao5duone1wk8rlxzidof,test-i18yz6qb-rsnbou3zwaoc_h5tbnte1*1*03ea10]
10:11:38,061 DEBUG [qtp307046058-2498][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
10:11:38,063 DEBUG [Thread-517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:11:38,072 DEBUG [Thread-517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
10:11:38,075 DEBUG [qtp307046058-2497][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:11:38,078 DEBUG [qtp307046058-2497][MessageBrokerPMF] [eof9fu] _pushResponse[requestID=f46w0ao5duone1wk8rlxzidof]: Entered.
10:11:38,094 DEBUG [qtp307046058-2497][MessageBrokerPMF] [eof9fu] _pollRequest[cryptoSessionIDPrefix=test-i18yz6qb-rsnbou3zwaoc_h5tbnte1]: Entered.
10:11:38,421 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Created new Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:11:38,421 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,431 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:11:38,431 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,431 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,431 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3941fa3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:38,437 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,437 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,437 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,437 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,438 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@46aced7a[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:38,443 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,443 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,443 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,443 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,448 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,449 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,462 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,462 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,471 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc06131[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:38,475 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,476 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,476 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,476 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,477 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55ac02df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:38,482 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,482 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,482 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,483 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,483 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1441d53[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:38,488 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,488 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,488 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,488 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,491 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
10:11:38,491 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
10:11:38,494 DEBUG [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@162557ba[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,496 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@79d7e738[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,496 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@79d7e738[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,497 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@162557ba[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,497 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6a3f907e[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:38,498 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6a3f907e[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:38,498 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@162557ba[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,498 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@79d7e738[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,498 DEBUG [qtp307046058-2517][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@79d7e738[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,500 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6a3f907e[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:38,501 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@162557ba[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,501 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@162557ba[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,501 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@162557ba[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,502 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6a3f907e[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:38,502 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6a3f907e[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:38,502 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6a3f907e[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:38,502 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6a3f907e[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:38,502 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@79d7e738[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,502 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@79d7e738[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,503 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@79d7e738[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,503 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@79d7e738[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,503 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3fc9e1d[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,503 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3df083f6[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:11:38,503 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7967ab3e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:11:38,503 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 12 ms). class=org.cumulus4j.store.test.movie.Rating
10:11:38,503 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3fc9e1d[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,503 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3fc9e1d[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,503 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:11:38,504 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,504 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,507 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:11:38,507 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3fc9e1d[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,507 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3fc9e1d[2,org.cumulus4j.store.test.movie.Rating]
10:11:38,510 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,510 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,516 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,516 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,519 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,519 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:11:38,519 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,519 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1441d53[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:38,519 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,519 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:11:38,519 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,519 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55ac02df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:38,519 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:11:38,519 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,519 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:11:38,519 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,520 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc06131[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:38,520 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,520 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,520 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:11:38,520 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,520 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@46aced7a[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:38,520 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:11:38,520 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,520 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3941fa3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:38,520 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 12
10:11:38,520 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,521 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,523 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 12
10:11:38,523 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3941fa3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:11:38,527 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,527 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,528 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,528 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,528 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@46aced7a[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:11:38,533 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,533 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,534 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,534 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,539 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,539 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,544 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,545 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,547 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4fc06131[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:11:38,551 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,551 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,551 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,551 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,552 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55ac02df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:38,556 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,557 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,557 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,557 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,557 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1441d53[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:11:38,562 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,562 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,563 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,563 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,566 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
10:11:38,566 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
10:11:38,568 DEBUG [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@3130e8e9[3,org.cumulus4j.store.test.movie.Person]
10:11:38,570 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@483ce806[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,571 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@483ce806[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,571 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3130e8e9[3,org.cumulus4j.store.test.movie.Person]
10:11:38,571 DEBUG [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2c6c4dbe[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:38,572 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2c6c4dbe[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:38,572 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3130e8e9[3,org.cumulus4j.store.test.movie.Person]
10:11:38,572 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@483ce806[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,572 DEBUG [qtp307046058-2517][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@483ce806[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,575 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2c6c4dbe[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:38,576 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@3130e8e9[3,org.cumulus4j.store.test.movie.Person]
10:11:38,576 DEBUG [qtp307046058-2517][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@3130e8e9[3,org.cumulus4j.store.test.movie.Person]
10:11:38,576 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3130e8e9[3,org.cumulus4j.store.test.movie.Person]
10:11:38,576 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@483ce806[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,576 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@483ce806[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,576 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@483ce806[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,576 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@483ce806[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,577 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2c6c4dbe[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:38,577 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2c6c4dbe[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:38,577 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2c6c4dbe[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:38,577 DEBUG [qtp307046058-2517][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2c6c4dbe[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:38,577 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@77a1dd69[3,org.cumulus4j.store.test.movie.Person]
10:11:38,578 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@23cf55db[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:11:38,578 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10daf3b[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:11:38,578 DEBUG [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 12 ms). class=org.cumulus4j.store.test.movie.Person
10:11:38,578 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@77a1dd69[3,org.cumulus4j.store.test.movie.Person]
10:11:38,578 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@77a1dd69[3,org.cumulus4j.store.test.movie.Person]
10:11:38,578 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:11:38,578 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,579 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,581 TRACE [qtp307046058-2517][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:11:38,581 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@77a1dd69[3,org.cumulus4j.store.test.movie.Person]
10:11:38,581 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@77a1dd69[3,org.cumulus4j.store.test.movie.Person]
10:11:38,584 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,585 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,591 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,591 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,594 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,597 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,598 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,598 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@b
10:11:38,598 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,598 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
10:11:38,602 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,602 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,602 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,610 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,610 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,613 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,616 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,617 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,617 TRACE [qtp307046058-2517][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@b]
10:11:38,617 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,617 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55ac02df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:38,618 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
10:11:38,620 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,621 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,621 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,621 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55ac02df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:38,626 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,627 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,627 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,627 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,627 TRACE [qtp307046058-2517][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55ac02df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:11:38,632 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,632 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,638 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,639 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,639 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,639 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@979463003 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,678 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,679 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,682 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,682 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,685 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,686 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,686 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,686 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,686 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,686 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,687 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,690 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,690 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,691 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,691 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,691 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,691 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,691 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,694 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,695 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,695 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,695 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,695 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,696 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,696 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,699 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,699 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,700 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,700 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,700 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,700 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,700 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,703 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,704 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,704 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,704 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,704 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,704 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:11:38,705 TRACE [qtp307046058-2517][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:11:38,708 TRACE [qtp307046058-2517][CryptoCache] acquireCipherEntry: Found cached Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:11:38,708 TRACE [qtp307046058-2517][CryptoCache] releaseCipherEntry: Releasing Cipher@2050730232 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:11:38,709 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,709 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
10:11:38,709 TRACE [qtp307046058-2517][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cfa6c2[1,org.cumulus4j.store.test.movie.Movie]
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 214.489 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
|
Help us localize this page