|  Console Output
Skipping 823 KB.. Full Log06,550 DEBUG [qtp626069067-2496][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth5vyu-1hl8d25m6pbh0_5fdemy7e]: Returning request: null
05:49:06,561 DEBUG [Thread-3][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:49:06,564 DEBUG [qtp626069067-2496][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:49:06,565 DEBUG [qtp626069067-2496][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth5vyu-1hl8d25m6pbh0_5fdemy7e]: Entered.
05:49:06,583 DEBUG [qtp626069067-2492][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth5vyu-1hl8d25m6pbh0_5fdemy7e]: Returning request: null
05:49:06,585 DEBUG [Thread-6][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:49:06,587 DEBUG [qtp626069067-2533][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:49:06,590 DEBUG [qtp626069067-2533][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth5vyu-1hl8d25m6pbh0_5fdemy7e]: Entered.
05:49:06,596 DEBUG [qtp626069067-2497][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth5vyu-1hl8d25m6pbh0_5fdemy7e]: Returning request: null
05:49:06,599 DEBUG [Thread-2][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:49:06,605 DEBUG [qtp626069067-2492][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:49:06,607 DEBUG [qtp626069067-2492][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth5vyu-1hl8d25m6pbh0_5fdemy7e]: Entered.
05:49:06,621 DEBUG [qtp626069067-2495][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth5vyu-1hl8d25m6pbh0_5fdemy7e]: Returning request: null
05:49:06,622 DEBUG [Thread-5][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
05:49:06,624 DEBUG [qtp626069067-2497][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:49:06,627 DEBUG [qtp626069067-2497][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth5vyu-1hl8d25m6pbh0_5fdemy7e]: Entered.
05:49:08,624 INFO [qtp626069067-2527][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
05:49:08,624 DEBUG [qtp626069067-2527][MessageBrokerPMF] [shxvzt] _query[requestID=kefx2y9pe1fzjyaoo7xjz1elq]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@56d06c12[kefx2y9pe1fzjyaoo7xjz1elq,test-ioth6seb-1319kbm8xb8j1_0kp42wvv*1*014t6u]
05:49:08,712 DEBUG [qtp626069067-2527][MessageBrokerPMF] [shxvzt] _query[requestID=kefx2y9pe1fzjyaoo7xjz1elq]: Request persisted.
05:49:08,722 DEBUG [qtp626069067-2525][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@56d06c12[kefx2y9pe1fzjyaoo7xjz1elq,test-ioth6seb-1319kbm8xb8j1_0kp42wvv*1*014t6u]
05:49:08,722 ERROR [qtp626069067-2523][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@40dff18c" (id="kefx2y9pe1fzjyaoo7xjz1elq") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:49:08,723 DEBUG [qtp626069067-2525][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
05:49:08,723 WARN [qtp626069067-2523][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@40dff18c" (id="kefx2y9pe1fzjyaoo7xjz1elq") 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@56d06c12
05:49:08,723 ERROR [qtp626069067-2524][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@74370565" (id="kefx2y9pe1fzjyaoo7xjz1elq") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:49:08,723 WARN [qtp626069067-2524][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@74370565" (id="kefx2y9pe1fzjyaoo7xjz1elq") 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@56d06c12
05:49:08,724 ERROR [qtp626069067-2526][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@3c0d165b" (id="kefx2y9pe1fzjyaoo7xjz1elq") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:49:08,724 WARN [qtp626069067-2526][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@3c0d165b" (id="kefx2y9pe1fzjyaoo7xjz1elq") 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@56d06c12
05:49:08,724 ERROR [qtp626069067-2493][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@62c5e64f" (id="kefx2y9pe1fzjyaoo7xjz1elq") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
05:49:08,725 WARN [qtp626069067-2493][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@62c5e64f" (id="kefx2y9pe1fzjyaoo7xjz1elq") 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@56d06c12
05:49:08,725 DEBUG [Thread-14][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
05:49:08,735 DEBUG [Thread-14][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
05:49:08,741 DEBUG [qtp626069067-2495][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:49:08,743 DEBUG [qtp626069067-2495][MessageBrokerPMF] [shxvzt] _pushResponse[requestID=kefx2y9pe1fzjyaoo7xjz1elq]: Entered.
05:49:08,748 DEBUG [qtp626069067-2495][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: Entered.
05:49:08,929 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Created new Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
05:49:08,929 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,936 TRACE [qtp626069067-2527][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
05:49:08,937 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:08,937 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:08,937 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ead19d1[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:08,941 TRACE [qtp626069067-2527][CryptoCache] getKeyData: Found cached key with keyID=1.
05:49:08,941 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Created new Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
05:49:08,941 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,942 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,942 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,942 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1929aa26[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:08,945 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,945 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,945 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,946 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,948 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,949 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,957 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,957 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,964 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5adb9d8d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:08,966 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,966 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,966 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,966 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,966 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f933287[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:08,970 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,970 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,970 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,970 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,971 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b84060[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:08,973 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,973 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,973 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,973 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,976 DEBUG [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
05:49:08,976 DEBUG [qtp626069067-2527][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
05:49:08,978 DEBUG [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@1cbd54ee[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,979 DEBUG [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@78c7a1bb[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,980 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@78c7a1bb[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,980 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cbd54ee[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,980 DEBUG [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3ac070a0[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:08,980 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3ac070a0[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:08,980 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cbd54ee[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,980 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@78c7a1bb[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,981 DEBUG [qtp626069067-2527][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@78c7a1bb[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,982 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3ac070a0[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:08,983 DEBUG [qtp626069067-2527][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@1cbd54ee[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,983 DEBUG [qtp626069067-2527][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@1cbd54ee[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,983 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1cbd54ee[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,983 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3ac070a0[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:08,983 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3ac070a0[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:08,984 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3ac070a0[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:08,984 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3ac070a0[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:08,984 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@78c7a1bb[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,984 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@78c7a1bb[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,984 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@78c7a1bb[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,984 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@78c7a1bb[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,988 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@27f9e2f9[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,988 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7af23129[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:08,988 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7fd564aa[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:08,988 DEBUG [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 12 ms). class=org.cumulus4j.store.test.movie.Rating
05:49:08,988 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@27f9e2f9[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,988 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@27f9e2f9[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,988 TRACE [qtp626069067-2527][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
05:49:08,988 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,989 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,991 TRACE [qtp626069067-2527][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
05:49:08,991 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@27f9e2f9[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,991 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@27f9e2f9[2,org.cumulus4j.store.test.movie.Rating]
05:49:08,994 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,994 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,997 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:08,997 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:08,999 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:08,999 TRACE [qtp626069067-2527][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
05:49:08,999 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:08,999 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b84060[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:08,999 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:08,999 TRACE [qtp626069067-2527][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
05:49:08,999 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:08,999 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f933287[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:08,999 TRACE [qtp626069067-2527][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
05:49:08,999 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:08,999 TRACE [qtp626069067-2527][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
05:49:09,000 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,000 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5adb9d8d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:09,000 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,000 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,000 TRACE [qtp626069067-2527][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
05:49:09,000 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,000 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1929aa26[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:09,000 TRACE [qtp626069067-2527][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
05:49:09,000 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,000 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ead19d1[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:09,000 TRACE [qtp626069067-2527][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 7
05:49:09,000 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,001 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,002 TRACE [qtp626069067-2527][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 7
05:49:09,002 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ead19d1[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:09,005 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,006 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,006 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,006 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,006 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1929aa26[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:09,009 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,009 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,010 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,010 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,012 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,013 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,016 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,016 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,019 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5adb9d8d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:09,021 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,021 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,021 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,022 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,022 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f933287[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:09,024 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,025 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,025 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,025 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,025 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b84060[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:09,028 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,028 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,029 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,029 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,032 DEBUG [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
05:49:09,033 DEBUG [qtp626069067-2527][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
05:49:09,034 DEBUG [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@7730c6b8[3,org.cumulus4j.store.test.movie.Person]
05:49:09,036 DEBUG [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1e869e7c[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,036 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1e869e7c[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,037 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7730c6b8[3,org.cumulus4j.store.test.movie.Person]
05:49:09,037 DEBUG [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@61518ce2[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:09,037 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@61518ce2[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:09,037 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7730c6b8[3,org.cumulus4j.store.test.movie.Person]
05:49:09,037 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1e869e7c[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,037 DEBUG [qtp626069067-2527][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@1e869e7c[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,038 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@61518ce2[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:09,039 DEBUG [qtp626069067-2527][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@7730c6b8[3,org.cumulus4j.store.test.movie.Person]
05:49:09,039 DEBUG [qtp626069067-2527][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@7730c6b8[3,org.cumulus4j.store.test.movie.Person]
05:49:09,039 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7730c6b8[3,org.cumulus4j.store.test.movie.Person]
05:49:09,040 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1e869e7c[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,040 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1e869e7c[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,040 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1e869e7c[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,040 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1e869e7c[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,040 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@61518ce2[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:09,040 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@61518ce2[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:09,040 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@61518ce2[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:09,040 DEBUG [qtp626069067-2527][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@61518ce2[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:09,040 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5e770aa2[3,org.cumulus4j.store.test.movie.Person]
05:49:09,040 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@470d1f9e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:09,040 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6eae7ec4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:09,040 DEBUG [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 8 ms). class=org.cumulus4j.store.test.movie.Person
05:49:09,040 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5e770aa2[3,org.cumulus4j.store.test.movie.Person]
05:49:09,040 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5e770aa2[3,org.cumulus4j.store.test.movie.Person]
05:49:09,040 TRACE [qtp626069067-2527][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
05:49:09,041 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,041 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,043 TRACE [qtp626069067-2527][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
05:49:09,043 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5e770aa2[3,org.cumulus4j.store.test.movie.Person]
05:49:09,043 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5e770aa2[3,org.cumulus4j.store.test.movie.Person]
05:49:09,045 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,045 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,048 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,049 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,050 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:09,053 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,054 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,054 TRACE [qtp626069067-2527][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@6
05:49:09,054 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,054 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
05:49:09,057 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,057 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,057 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,062 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,062 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,063 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:09,066 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,066 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,067 TRACE [qtp626069067-2527][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@6]
05:49:09,067 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,067 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f933287[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:09,067 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
05:49:09,069 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,069 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,070 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,070 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f933287[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:09,073 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,073 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,074 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,074 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,074 TRACE [qtp626069067-2527][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@f933287[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:09,077 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,077 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,081 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,081 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,081 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,081 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@1644417937 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,099 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:09,100 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:09,110 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:09,113 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:09,124 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,124 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,125 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,125 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,125 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,125 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:09,126 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:09,128 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,129 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,129 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,129 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,129 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,129 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:09,130 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:09,132 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,132 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,132 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,132 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,132 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,132 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:09,133 TRACE [qtp626069067-2527][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:09,135 TRACE [qtp626069067-2527][CryptoCache] acquireCipherEntry: Found cached Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:09,135 TRACE [qtp626069067-2527][CryptoCache] releaseCipherEntry: Releasing Cipher@913269346 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:09,135 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,135 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,135 TRACE [qtp626069067-2527][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5fecd260[1,org.cumulus4j.store.test.movie.Movie]
05:49:09,784 INFO [qtp626069067-2525][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
05:49:10,248 WARN [qtp626069067-2525][MetaData] MetaData Parser encountered an error in file "jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/org/cumulus4j/store/model/package.jdo" at line 10, column 6 : cvc-elt.1: Cannot find the declaration of element 'jdo'. - Please check your specification of DTD and the validity of the MetaData XML that you have specified.
05:49:10,250 WARN [qtp626069067-2525][MetaData] MetaData Parser encountered an error in file "jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/org/cumulus4j/store/model/package.jdo" at line 48, column 7 : The content of element type "jdo" is incomplete, it must match "(extension*,(package|query|fetch-plan)+,extension*)". - Please check your specification of DTD and the validity of the MetaData XML that you have specified.
05:49:12,549 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
05:49:12,549 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
05:49:14,335 INFO [qtp626069067-2525][Cumulus4jStoreManager] ====================== Cumulus4j ======================
05:49:14,335 INFO [qtp626069067-2525][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
05:49:14,335 INFO [qtp626069067-2525][Cumulus4jStoreManager] =======================================================
05:49:14,337 ERROR [qtp626069067-2525][Persistence] java.lang.reflect.InvocationTargetException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at org.datanucleus.plugin.NonManagedPluginRegistry.createExecutableExtension(NonManagedPluginRegistry.java:631)
at org.datanucleus.plugin.PluginManager.createExecutableExtension(PluginManager.java:301)
at org.datanucleus.NucleusContext.initialiseAutoStart(NucleusContext.java:432)
at org.datanucleus.NucleusContext.initialise(NucleusContext.java:384)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.freezeConfiguration(JDOPersistenceManagerFactory.java:768)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.createPersistenceManagerFactory(JDOPersistenceManagerFactory.java:326)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.getPersistenceManagerFactory(JDOPersistenceManagerFactory.java:195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1970)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1965)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1171)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:813)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManagerFactory(TestService.java:59)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManager(TestService.java:72)
at org.cumulus4j.integrationtest.webapp.TestService.testPost(TestService.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:546)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1283)
at org.cumulus4j.keymanager.back.shared.AjaxHeadersFilter.doFilter(AjaxHeadersFilter.java:33)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1254)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:481)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:516)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:230)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:956)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:411)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:188)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:891)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:247)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:151)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:114)
at org.eclipse.jetty.server.Server.handle(Server.java:353)
at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:598)
at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:1059)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:590)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212)
at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:427)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:510)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:450)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassCastException: org.cumulus4j.store.Cumulus4jStoreManager cannot be cast to org.datanucleus.store.rdbms.RDBMSStoreManager
at org.datanucleus.store.rdbms.autostart.SchemaAutoStarter.<init>(SchemaAutoStarter.java:68)
... 70 more
Reading Movies before writing:
05:49:14,353 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Movie
05:49:14,354 INFO [qtp626069067-2525][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
05:49:14,354 TRACE [qtp626069067-2525][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=test-ioth6seb-1319kbm8xb8j1_0kp42wvv*1*014t6u
05:49:14,354 INFO [qtp626069067-2525][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
05:49:14,386 INFO [qtp626069067-2525][MinimumCumulus4jVersion] version=10100001
05:49:14,387 INFO [qtp626069067-2525][MinimumCumulus4jVersion] version=10100001
05:49:14,388 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Movie
05:49:14,390 DEBUG [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,396 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@66256634[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,398 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@7907c2a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:49:14,398 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@66256634[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,398 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@66256634[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,398 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,398 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@516796e6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,399 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@4b216c57[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:49:14,399 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@516796e6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,399 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@516796e6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,399 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,399 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@204b2ec5[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:49:14,400 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@204b2ec5[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:49:14,400 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,400 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@266475f9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,400 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@266475f9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,400 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,400 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5ff1cbd9[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,401 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5b1040fd[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:49:14,401 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ff1cbd9[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,401 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ff1cbd9[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,401 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,401 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2d9c4ed1[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:49:14,401 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d9c4ed1[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:49:14,401 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,401 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@92ac66c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,402 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@143a3216[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:49:14,402 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@92ac66c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,402 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@92ac66c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,402 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,402 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@72ee5355[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,403 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@72ee5355[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,403 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,403 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@18772b90[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,403 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@22bec651[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:49:14,404 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@18772b90[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,404 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@18772b90[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,404 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,404 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@66256634[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,404 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@516796e6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,404 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@204b2ec5[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:49:14,404 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@266475f9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,404 DEBUG [qtp626069067-2525][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@266475f9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,406 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ff1cbd9[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,406 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d9c4ed1[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:49:14,406 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@92ac66c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,406 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@72ee5355[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,406 DEBUG [qtp626069067-2525][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@72ee5355[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,407 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@18772b90[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,408 DEBUG [qtp626069067-2525][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,408 DEBUG [qtp626069067-2525][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,408 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7204661e[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,409 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@66256634[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,409 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@66256634[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,409 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@66256634[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,409 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@7907c2a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:49:14,409 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@7907c2a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:49:14,409 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7907c2a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:49:14,409 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@7907c2a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:49:14,409 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@66256634[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,409 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@516796e6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@516796e6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,410 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@516796e6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@4b216c57[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@4b216c57[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:49:14,410 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4b216c57[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@4b216c57[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@516796e6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@72ee5355[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@72ee5355[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,410 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@72ee5355[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@72ee5355[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,410 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@18772b90[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,411 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@18772b90[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,411 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@18772b90[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,411 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@22bec651[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:49:14,411 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@22bec651[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:49:14,411 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@22bec651[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:49:14,411 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@22bec651[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:49:14,411 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@18772b90[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,411 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@266475f9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,411 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@266475f9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,411 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@266475f9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,411 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@266475f9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2d9c4ed1[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2d9c4ed1[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:49:14,412 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d9c4ed1[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2d9c4ed1[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@92ac66c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@92ac66c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,412 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@92ac66c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@143a3216[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@143a3216[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:49:14,412 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@143a3216[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@143a3216[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:49:14,412 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@92ac66c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@204b2ec5[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@204b2ec5[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:49:14,413 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@204b2ec5[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@204b2ec5[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5ff1cbd9[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5ff1cbd9[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,413 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ff1cbd9[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5b1040fd[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5b1040fd[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:49:14,413 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5b1040fd[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5b1040fd[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:49:14,413 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5ff1cbd9[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,414 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@301d57a[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@719bfbe9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5967e942[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@76d3dccc[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7bf47d69[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@551e954d[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@33d54b55[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5b08d45f[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@34ff562[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@225abcbb[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3bccc446[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@267b554c[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ae34004[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:14,414 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d2b8087[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
05:49:14,414 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 61 ms). class=org.cumulus4j.store.test.movie.Movie
05:49:14,415 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:14,417 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:14,418 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:14,430 TRACE [qtp626069067-2525][CryptoCache] getKeyData: No cached key with keyID=1 found.
05:49:14,430 INFO [qtp626069067-2525][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
05:49:17,689 DEBUG [qtp626069067-2525][MessageBrokerPMF] [shxvzt] _query[requestID=g4en4j4bqqjj5xw9x6h6jsntd]: Entered with request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@b8ba32aa[g4en4j4bqqjj5xw9x6h6jsntd,test-ioth6seb-1319kbm8xb8j1_0kp42wvv*1*014t6u]
05:49:17,702 DEBUG [qtp626069067-2525][MessageBrokerPMF] [shxvzt] _query[requestID=g4en4j4bqqjj5xw9x6h6jsntd]: Request persisted.
05:49:17,710 DEBUG [qtp626069067-2526][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: Returning request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@b8ba32aa[g4en4j4bqqjj5xw9x6h6jsntd,test-ioth6seb-1319kbm8xb8j1_0kp42wvv*1*014t6u]
05:49:17,710 DEBUG [qtp626069067-2526][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyRequest matching=true
05:49:17,713 DEBUG [Thread-16][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
05:49:17,729 DEBUG [Thread-16][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyResponse matching=true
05:49:17,733 DEBUG [qtp626069067-2526][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:49:17,735 DEBUG [qtp626069067-2526][MessageBrokerPMF] [shxvzt] _pushResponse[requestID=g4en4j4bqqjj5xw9x6h6jsntd]: Entered.
05:49:17,738 DEBUG [qtp626069067-2526][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: Entered.
05:49:17,909 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Created new Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
05:49:17,909 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:17,910 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,910 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,910 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,910 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:17,910 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:17,912 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:17,912 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:17,913 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,913 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,913 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,913 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:17,913 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:17,915 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:17,915 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:17,915 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,915 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,915 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,915 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:17,915 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:17,917 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:17,917 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:17,918 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,918 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,918 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
* MMM 1464580127663
* MMM 1464580130790
* MMM 1464580137159
* MMM 1464580148998
05:49:17,918 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:17,919 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:17,919 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
05:49:17,919 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,919 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@551e954d[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:17,920 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,920 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
05:49:17,920 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,920 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@225abcbb[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:17,920 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
05:49:17,920 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,920 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
05:49:17,920 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,920 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ae34004[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:17,920 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,920 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,920 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
05:49:17,920 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,920 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5967e942[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:17,920 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
05:49:17,920 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:17,920 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@301d57a[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:17,920 TRACE [qtp626069067-2525][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
05:49:17,920 INFO [qtp626069067-2525][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is not set. Using default algorithm 'Twofish/GCM/NoPadding'.
05:49:17,920 INFO [qtp626069067-2525][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is not set. Using default MAC algorithm 'NONE'.
05:49:17,921 DEBUG [qtp626069067-2525][MessageBrokerPMF] [shxvzt] _query[requestID=y0s4rae4stv7vz0jey95d1f1d]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@a51eba06[y0s4rae4stv7vz0jey95d1f1d,test-ioth6seb-1319kbm8xb8j1_0kp42wvv*1*014t6u]
05:49:17,926 DEBUG [qtp626069067-2525][MessageBrokerPMF] [shxvzt] _query[requestID=y0s4rae4stv7vz0jey95d1f1d]: Request persisted.
05:49:17,936 DEBUG [qtp626069067-2526][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@a51eba06[y0s4rae4stv7vz0jey95d1f1d,test-ioth6seb-1319kbm8xb8j1_0kp42wvv*1*014t6u]
05:49:17,937 DEBUG [qtp626069067-2526][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
05:49:17,940 DEBUG [Thread-16][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
05:49:17,952 DEBUG [Thread-16][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
05:49:17,959 DEBUG [qtp626069067-2527][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
05:49:17,968 DEBUG [qtp626069067-2527][MessageBrokerPMF] [shxvzt] _pushResponse[requestID=y0s4rae4stv7vz0jey95d1f1d]: Entered.
05:49:17,973 DEBUG [qtp626069067-2527][MessageBrokerPMF] [shxvzt] _pollRequest[cryptoSessionIDPrefix=test-ioth6seb-1319kbm8xb8j1_0kp42wvv]: Entered.
05:49:18,143 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Created new Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
05:49:18,143 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,148 TRACE [qtp626069067-2525][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
05:49:18,148 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,148 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,148 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@301d57a[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:18,151 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,151 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,151 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,151 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,151 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5967e942[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:18,153 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,154 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,154 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,154 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,156 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,156 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,165 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,165 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,171 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ae34004[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:18,173 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,174 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,174 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,174 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,174 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@225abcbb[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:18,177 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,177 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,177 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,177 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,178 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@551e954d[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:18,181 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,181 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,181 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,181 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,183 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
05:49:18,183 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
05:49:18,184 DEBUG [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@235bd0b0[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,186 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1ff57e9f[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,186 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1ff57e9f[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,186 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@235bd0b0[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,186 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@4c97925a[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:18,187 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4c97925a[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:18,187 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@235bd0b0[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,187 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1ff57e9f[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,187 DEBUG [qtp626069067-2525][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@1ff57e9f[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,189 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4c97925a[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:18,189 DEBUG [qtp626069067-2525][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@235bd0b0[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,190 DEBUG [qtp626069067-2525][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@235bd0b0[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,190 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@235bd0b0[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,190 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@4c97925a[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:18,190 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@4c97925a[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:18,190 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4c97925a[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:18,190 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@4c97925a[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:18,190 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1ff57e9f[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,190 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1ff57e9f[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,190 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1ff57e9f[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,190 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1ff57e9f[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,191 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d77690[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,191 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5eb8b263[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
05:49:18,191 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@33417b98[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
05:49:18,191 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 8 ms). class=org.cumulus4j.store.test.movie.Rating
05:49:18,191 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d77690[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,191 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d77690[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,191 TRACE [qtp626069067-2525][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
05:49:18,191 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,192 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,193 TRACE [qtp626069067-2525][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
05:49:18,193 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d77690[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,193 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@69d77690[2,org.cumulus4j.store.test.movie.Rating]
05:49:18,196 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,196 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,199 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,199 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,201 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,201 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
05:49:18,201 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,201 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@551e954d[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:18,201 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,201 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
05:49:18,201 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,201 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@225abcbb[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:18,201 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
05:49:18,201 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,201 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
05:49:18,201 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,202 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ae34004[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:18,202 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,202 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,202 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
05:49:18,202 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,202 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5967e942[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:18,202 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
05:49:18,202 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,202 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@301d57a[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:18,202 TRACE [qtp626069067-2525][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 12
05:49:18,202 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,202 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,204 TRACE [qtp626069067-2525][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 12
05:49:18,204 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@301d57a[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
05:49:18,206 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,206 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,206 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,207 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,207 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5967e942[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
05:49:18,210 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,210 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,210 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,211 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,214 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,214 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,217 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,217 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,219 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ae34004[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
05:49:18,220 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,220 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,221 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,221 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,221 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@225abcbb[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:18,224 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,224 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,224 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,224 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,224 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@551e954d[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
05:49:18,227 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,227 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,227 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,227 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,229 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
05:49:18,229 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
05:49:18,230 DEBUG [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@54300f29[3,org.cumulus4j.store.test.movie.Person]
05:49:18,231 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@209120f7[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,231 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@209120f7[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,231 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@54300f29[3,org.cumulus4j.store.test.movie.Person]
05:49:18,232 DEBUG [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2d48597e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:18,232 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d48597e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:18,232 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@54300f29[3,org.cumulus4j.store.test.movie.Person]
05:49:18,232 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@209120f7[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,232 DEBUG [qtp626069067-2525][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@209120f7[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,234 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d48597e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:18,234 DEBUG [qtp626069067-2525][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@54300f29[3,org.cumulus4j.store.test.movie.Person]
05:49:18,234 DEBUG [qtp626069067-2525][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@54300f29[3,org.cumulus4j.store.test.movie.Person]
05:49:18,234 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@54300f29[3,org.cumulus4j.store.test.movie.Person]
05:49:18,235 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@209120f7[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,235 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@209120f7[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,235 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@209120f7[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,235 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@209120f7[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,235 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2d48597e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:18,235 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2d48597e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:18,235 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d48597e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:18,235 DEBUG [qtp626069067-2525][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2d48597e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:18,235 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7616992d[3,org.cumulus4j.store.test.movie.Person]
05:49:18,236 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@25b1cf3a[17,org.cumulus4j.store.test.movie.Person#name[primary]]
05:49:18,236 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@78ea3adf[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
05:49:18,236 DEBUG [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 7 ms). class=org.cumulus4j.store.test.movie.Person
05:49:18,236 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7616992d[3,org.cumulus4j.store.test.movie.Person]
05:49:18,236 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7616992d[3,org.cumulus4j.store.test.movie.Person]
05:49:18,236 TRACE [qtp626069067-2525][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
05:49:18,236 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,236 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,238 TRACE [qtp626069067-2525][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
05:49:18,238 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7616992d[3,org.cumulus4j.store.test.movie.Person]
05:49:18,238 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7616992d[3,org.cumulus4j.store.test.movie.Person]
05:49:18,240 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,240 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,243 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,243 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,244 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,246 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,246 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,246 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@b
05:49:18,246 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,246 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
05:49:18,248 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,248 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,249 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,252 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,252 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,254 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,255 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,255 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,256 TRACE [qtp626069067-2525][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@b]
05:49:18,256 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,256 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@225abcbb[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:18,256 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
05:49:18,257 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,258 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,258 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,258 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@225abcbb[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:18,260 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,260 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,260 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,260 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,260 TRACE [qtp626069067-2525][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@225abcbb[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
05:49:18,262 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,262 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,265 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,266 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,266 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,266 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@343469076 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,282 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,282 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,283 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:18,284 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,286 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,286 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,286 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,286 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,286 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,286 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:18,287 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,289 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,289 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,289 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,289 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,289 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,289 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:18,290 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,291 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,292 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,292 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,292 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,292 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,292 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:18,292 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,294 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,294 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,294 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,294 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,294 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,294 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:18,295 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,296 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,296 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,296 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,296 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,296 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,296 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
05:49:18,297 TRACE [qtp626069067-2525][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
05:49:18,298 TRACE [qtp626069067-2525][CryptoCache] acquireCipherEntry: Found cached Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
05:49:18,298 TRACE [qtp626069067-2525][CryptoCache] releaseCipherEntry: Releasing Cipher@946214605 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
05:49:18,298 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,298 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
05:49:18,299 TRACE [qtp626069067-2525][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@13778d97[1,org.cumulus4j.store.test.movie.Movie]
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 81.491 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.webapp ---
[INFO] org already added, skipping
[INFO] org/cumulus4j already added, skipping
[INFO] org/cumulus4j/integrationtest already added, skipping
[INFO] org/cumulus4j/integrationtest/webapp already added, skipping
[INFO] LICENCE.txt already added, skipping
[INFO] cumulus4j-test-datanucleus.properties already added, skipping
[INFO] Building jar: /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.webapp/target/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT-sources.jar
[INFO] org already added, skipping
[INFO] org/cumulus4j already added, skipping
[INFO] org/cumulus4j/integrationtest already added, skipping
[INFO] org/cumulus4j/integrationtest/webapp already added, skipping
[INFO] LICENCE.txt already added, skipping
[INFO] cumulus4j-test-datanucleus.properties already added, skipping
[INFO]
[INFO] --- maven-install-plugin:2.4:install (default-install) @ org.cumulus4j.integrationtest.webapp ---
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.webapp/target/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT.war to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.webapp/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT.war
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.webapp/pom.xml to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.webapp/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT.pom
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.webapp/target/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT-sources.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.webapp/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT-sources.jar
|
Help us localize this page