|  Console Output
Skipping 1,195 KB.. Full Log[qtp1954195322-410][MessageBrokerPMF] [hoco9j] _query[requestID=kqlt2bxj3f0vil9z7akqdduv0]: Request persisted.
10:08:20,876 DEBUG [qtp1954195322-573][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@523334b2[kqlt2bxj3f0vil9z7akqdduv0,test-iotqg0jh--109cexsd8xiff_g085tgup*1*0w5nh8]
10:08:20,877 DEBUG [qtp1954195322-573][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
10:08:20,877 ERROR [qtp1954195322-446][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@428e1409" (id="kqlt2bxj3f0vil9z7akqdduv0") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
10:08:20,879 WARN [qtp1954195322-446][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@428e1409" (id="kqlt2bxj3f0vil9z7akqdduv0") 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@523334b2
10:08:20,879 DEBUG [Thread-518][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:08:20,881 ERROR [qtp1954195322-439][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@a39db6e" (id="kqlt2bxj3f0vil9z7akqdduv0") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
10:08:20,881 WARN [qtp1954195322-439][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@a39db6e" (id="kqlt2bxj3f0vil9z7akqdduv0") 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@523334b2
10:08:20,882 ERROR [qtp1954195322-553][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@6265d22a" (id="kqlt2bxj3f0vil9z7akqdduv0") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
10:08:20,882 WARN [qtp1954195322-553][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@6265d22a" (id="kqlt2bxj3f0vil9z7akqdduv0") 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@523334b2
10:08:20,889 DEBUG [Thread-518][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
10:08:20,892 DEBUG [qtp1954195322-429][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:08:20,895 DEBUG [qtp1954195322-429][MessageBrokerPMF] [hoco9j] _pushResponse[requestID=kqlt2bxj3f0vil9z7akqdduv0]: Entered.
10:08:20,900 DEBUG [qtp1954195322-429][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: Entered.
10:08:21,051 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Created new Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:08:21,051 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,057 TRACE [qtp1954195322-410][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:08:21,057 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,057 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,058 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@11f3923a[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:21,060 TRACE [qtp1954195322-410][CryptoCache] getKeyData: Found cached key with keyID=1.
10:08:21,061 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Created new Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:08:21,061 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,061 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,061 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,061 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7d25db1d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:21,064 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,064 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,064 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,064 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,067 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,067 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,073 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,074 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,080 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2ca6c203[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:21,082 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,082 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,082 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,082 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,082 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a9e1d07[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:21,086 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,086 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,086 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,086 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,086 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f91a53e[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:21,088 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,088 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,089 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,089 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,090 DEBUG [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
10:08:21,090 DEBUG [qtp1954195322-410][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
10:08:21,091 DEBUG [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@7be716e8[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,092 DEBUG [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@7235491e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,092 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7235491e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,092 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7be716e8[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,092 DEBUG [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5e5bc18[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:21,092 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5e5bc18[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:21,093 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7be716e8[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,093 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7235491e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,093 DEBUG [qtp1954195322-410][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@7235491e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,093 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5e5bc18[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:21,094 DEBUG [qtp1954195322-410][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@7be716e8[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,094 DEBUG [qtp1954195322-410][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@7be716e8[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,094 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@7be716e8[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,094 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5e5bc18[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:21,094 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5e5bc18[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:21,094 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5e5bc18[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:21,094 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5e5bc18[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:21,094 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@7235491e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,094 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@7235491e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,094 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7235491e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,094 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@7235491e[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,097 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1e4c57be[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,097 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@55223322[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:21,097 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5da94998[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:21,097 DEBUG [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 7 ms). class=org.cumulus4j.store.test.movie.Rating
10:08:21,097 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1e4c57be[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,097 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1e4c57be[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,097 TRACE [qtp1954195322-410][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
10:08:21,097 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,098 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,099 TRACE [qtp1954195322-410][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:08:21,099 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1e4c57be[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,099 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1e4c57be[2,org.cumulus4j.store.test.movie.Rating]
10:08:21,100 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,100 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,103 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,103 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,105 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,105 TRACE [qtp1954195322-410][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:08:21,105 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,105 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f91a53e[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:21,105 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,105 TRACE [qtp1954195322-410][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:08:21,105 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,106 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a9e1d07[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:21,106 TRACE [qtp1954195322-410][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:08:21,106 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,106 TRACE [qtp1954195322-410][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:08:21,106 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,106 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2ca6c203[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:21,106 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,106 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,106 TRACE [qtp1954195322-410][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:08:21,106 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,106 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7d25db1d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:21,106 TRACE [qtp1954195322-410][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:08:21,106 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,106 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@11f3923a[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:21,106 TRACE [qtp1954195322-410][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 7
10:08:21,107 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,107 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,108 TRACE [qtp1954195322-410][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 7
10:08:21,108 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@11f3923a[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:21,110 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,111 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,111 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,111 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,111 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7d25db1d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:21,115 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,115 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,115 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,115 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,117 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,117 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,120 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,121 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,122 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2ca6c203[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:21,123 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,124 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,124 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,124 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,124 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a9e1d07[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:21,126 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,126 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,126 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,126 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,127 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f91a53e[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:21,129 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,129 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,129 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,129 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,131 DEBUG [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
10:08:21,132 DEBUG [qtp1954195322-410][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
10:08:21,133 DEBUG [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@53c15ece[3,org.cumulus4j.store.test.movie.Person]
10:08:21,133 DEBUG [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@117666ca[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,134 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@117666ca[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,134 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@53c15ece[3,org.cumulus4j.store.test.movie.Person]
10:08:21,134 DEBUG [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@41894680[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:21,134 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41894680[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:21,134 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@53c15ece[3,org.cumulus4j.store.test.movie.Person]
10:08:21,134 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@117666ca[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,134 DEBUG [qtp1954195322-410][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@117666ca[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,135 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41894680[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:21,136 DEBUG [qtp1954195322-410][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@53c15ece[3,org.cumulus4j.store.test.movie.Person]
10:08:21,136 DEBUG [qtp1954195322-410][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@53c15ece[3,org.cumulus4j.store.test.movie.Person]
10:08:21,136 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@53c15ece[3,org.cumulus4j.store.test.movie.Person]
10:08:21,136 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@117666ca[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,136 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@117666ca[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,136 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@117666ca[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,136 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@117666ca[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,136 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@41894680[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:21,136 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@41894680[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:21,136 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41894680[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:21,136 DEBUG [qtp1954195322-410][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@41894680[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:21,136 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@375d46fa[3,org.cumulus4j.store.test.movie.Person]
10:08:21,136 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10274659[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:21,137 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@b84ad61[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:21,137 DEBUG [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 6 ms). class=org.cumulus4j.store.test.movie.Person
10:08:21,137 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@375d46fa[3,org.cumulus4j.store.test.movie.Person]
10:08:21,137 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@375d46fa[3,org.cumulus4j.store.test.movie.Person]
10:08:21,137 TRACE [qtp1954195322-410][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
10:08:21,137 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,137 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,138 TRACE [qtp1954195322-410][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:08:21,138 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@375d46fa[3,org.cumulus4j.store.test.movie.Person]
10:08:21,138 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@375d46fa[3,org.cumulus4j.store.test.movie.Person]
10:08:21,140 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,140 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,142 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,142 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,143 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,145 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,145 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,146 TRACE [qtp1954195322-410][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@6
10:08:21,146 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,146 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
10:08:21,147 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,148 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,148 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,151 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,151 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,152 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,154 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,154 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,154 TRACE [qtp1954195322-410][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@6]
10:08:21,154 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,154 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a9e1d07[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:21,154 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
10:08:21,155 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,155 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,156 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,156 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a9e1d07[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:21,158 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,158 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,158 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,158 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,158 TRACE [qtp1954195322-410][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a9e1d07[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:21,160 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,160 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,162 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,163 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,163 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,163 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@442915307 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,218 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,220 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,223 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:21,224 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,234 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,234 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,234 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,234 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,234 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,234 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:21,235 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,236 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,236 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,237 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,237 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,237 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,237 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:21,237 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,239 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,239 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,239 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,239 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,240 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,240 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:21,240 TRACE [qtp1954195322-410][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:21,241 TRACE [qtp1954195322-410][CryptoCache] acquireCipherEntry: Found cached Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:21,241 TRACE [qtp1954195322-410][CryptoCache] releaseCipherEntry: Releasing Cipher@1171783843 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:21,241 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,241 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,241 TRACE [qtp1954195322-410][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4940e369[1,org.cumulus4j.store.test.movie.Movie]
10:08:21,259 DEBUG [qtp2010162204-535][AbstractService] getAuth: 'Authorization' header: Basic ZGV2aWw6dGVzdHRlc3R0ZXN0
10:08:21,260 DEBUG [qtp2010162204-535][CryptoSessionService] open: authUserName='devil' cryptoSessionID='test-iotqg0jh--109cexsd8xiff_g085tgup*1*0w5nh8'
10:08:22,077 INFO [qtp1954195322-411][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
10:08:22,559 WARN [qtp1954195322-411][MetaData] MetaData Parser encountered an error in file "jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/org/cumulus4j/store/model/package.jdo" at line 10, column 6 : cvc-elt.1: Cannot find the declaration of element 'jdo'. - Please check your specification of DTD and the validity of the MetaData XML that you have specified.
10:08:22,561 WARN [qtp1954195322-411][MetaData] MetaData Parser encountered an error in file "jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/org/cumulus4j/store/model/package.jdo" at line 48, column 7 : The content of element type "jdo" is incomplete, it must match "(extension*,(package|query|fetch-plan)+,extension*)". - Please check your specification of DTD and the validity of the MetaData XML that you have specified.
10:08:24,969 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
10:08:24,969 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:08:26,171 INFO [qtp1954195322-411][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:08:26,171 INFO [qtp1954195322-411][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:08:26,171 INFO [qtp1954195322-411][Cumulus4jStoreManager] =======================================================
10:08:26,172 ERROR [qtp1954195322-411][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.GeneratedMethodAccessor419.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1970)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1965)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1171)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:813)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManagerFactory(TestService.java:59)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManager(TestService.java:72)
at org.cumulus4j.integrationtest.webapp.TestService.testPost(TestService.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:546)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1283)
at org.cumulus4j.keymanager.back.shared.AjaxHeadersFilter.doFilter(AjaxHeadersFilter.java:33)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1254)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:481)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:516)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:230)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:956)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:411)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:188)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:891)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:247)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:151)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:114)
at org.eclipse.jetty.server.Server.handle(Server.java:353)
at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:598)
at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:1059)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:590)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212)
at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:427)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:510)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:450)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassCastException: org.cumulus4j.store.Cumulus4jStoreManager cannot be cast to org.datanucleus.store.rdbms.RDBMSStoreManager
at org.datanucleus.store.rdbms.autostart.SchemaAutoStarter.<init>(SchemaAutoStarter.java:68)
... 69 more
Reading Movies before writing:
10:08:26,173 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Movie
10:08:26,173 INFO [qtp1954195322-411][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:08:26,174 TRACE [qtp1954195322-411][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=test-iotqg0jh--109cexsd8xiff_g085tgup*1*0w5nh8
10:08:26,174 INFO [qtp1954195322-411][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:08:26,209 INFO [qtp1954195322-411][MinimumCumulus4jVersion] version=10100001
10:08:26,210 INFO [qtp1954195322-411][MinimumCumulus4jVersion] version=10100001
10:08:26,210 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Movie
10:08:26,212 DEBUG [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,215 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@4315cc0d[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,216 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@18af73c8[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:08:26,216 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4315cc0d[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,217 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4315cc0d[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,217 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,217 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2d9317e5[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,217 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1e30b2c7[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:08:26,217 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d9317e5[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,217 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d9317e5[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,217 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,217 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6de34aa3[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:08:26,218 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6de34aa3[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:08:26,218 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,218 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@10b204bf[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,218 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10b204bf[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,218 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,218 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@65e3960a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,219 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6f49bbe2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:08:26,219 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@65e3960a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,219 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@65e3960a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,219 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,219 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@54285078[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:08:26,219 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@54285078[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:08:26,219 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,219 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@7917d41e[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,220 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5881f399[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:08:26,220 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7917d41e[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,220 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7917d41e[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,220 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,220 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2751053a[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,220 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2751053a[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,220 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,220 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6464d151[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,221 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@30fc0e6c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:08:26,221 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6464d151[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,221 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6464d151[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,221 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,221 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4315cc0d[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,221 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d9317e5[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,221 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6de34aa3[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:08:26,221 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10b204bf[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,221 DEBUG [qtp1954195322-411][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@10b204bf[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,222 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@65e3960a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,222 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@54285078[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:08:26,222 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7917d41e[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,222 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2751053a[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,223 DEBUG [qtp1954195322-411][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@2751053a[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,224 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6464d151[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,224 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,224 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,224 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4285f20f[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@4315cc0d[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@4315cc0d[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,225 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4315cc0d[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@18af73c8[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@18af73c8[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:08:26,225 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@18af73c8[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@18af73c8[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@4315cc0d[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2d9317e5[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2d9317e5[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,225 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d9317e5[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1e30b2c7[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1e30b2c7[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:08:26,225 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1e30b2c7[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1e30b2c7[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2d9317e5[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2751053a[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,225 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2751053a[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,225 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2751053a[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,226 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2751053a[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,226 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6464d151[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,226 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6464d151[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,226 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6464d151[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,226 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@30fc0e6c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:08:26,226 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@30fc0e6c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:08:26,226 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30fc0e6c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:08:26,226 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@30fc0e6c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6464d151[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@10b204bf[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@10b204bf[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,227 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10b204bf[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@10b204bf[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@54285078[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@54285078[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:08:26,227 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@54285078[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@54285078[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@7917d41e[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,227 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@7917d41e[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,227 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7917d41e[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5881f399[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5881f399[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:08:26,228 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5881f399[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5881f399[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@7917d41e[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6de34aa3[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6de34aa3[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:08:26,228 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6de34aa3[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6de34aa3[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@65e3960a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@65e3960a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,228 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@65e3960a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6f49bbe2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6f49bbe2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:08:26,228 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6f49bbe2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6f49bbe2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:08:26,228 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@65e3960a[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,229 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6bc812aa[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@14f32f85[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7ed57f6c[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1c07e1fc[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@37f1ed94[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3a7363e8[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6f0855d5[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4ca351c9[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@74869884[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@554bd9df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@78c0985e[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2e3bb396[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e394c6d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:26,229 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6537e554[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:08:26,229 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 56 ms). class=org.cumulus4j.store.test.movie.Movie
10:08:26,229 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:26,231 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:26,231 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:26,241 TRACE [qtp1954195322-411][CryptoCache] getKeyData: No cached key with keyID=1 found.
10:08:26,241 INFO [qtp1954195322-411][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
10:08:29,588 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
10:08:29,588 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
10:08:29,900 DEBUG [qtp1954195322-432][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfb33--1kziadlnyqsv6_0xmbvyde]: Returning request: null
10:08:29,904 DEBUG [Thread-503][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:08:29,910 DEBUG [qtp1954195322-573][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:08:29,911 DEBUG [qtp1954195322-573][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfb33--1kziadlnyqsv6_0xmbvyde]: Entered.
10:08:30,405 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 1 users left in cache.
10:08:30,486 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 1 sessions left.
10:08:31,481 DEBUG [qtp1954195322-419][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfoay-lbqcd0piojx1_8vcesbfb]: Returning request: null
10:08:31,485 DEBUG [Thread-512][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:08:31,490 DEBUG [qtp1954195322-574][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:08:31,495 DEBUG [qtp1954195322-574][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfoay-lbqcd0piojx1_8vcesbfb]: Entered.
10:08:31,506 DEBUG [qtp1954195322-550][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfoay-lbqcd0piojx1_8vcesbfb]: Returning request: null
10:08:31,510 DEBUG [Thread-511][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:08:31,512 DEBUG [qtp1954195322-438][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:08:31,513 DEBUG [qtp1954195322-438][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfoay-lbqcd0piojx1_8vcesbfb]: Entered.
10:08:31,539 DEBUG [qtp1954195322-440][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfoay-lbqcd0piojx1_8vcesbfb]: Returning request: null
10:08:31,541 DEBUG [Thread-514][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:08:31,544 DEBUG [qtp1954195322-549][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:08:31,546 DEBUG [qtp1954195322-549][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfoay-lbqcd0piojx1_8vcesbfb]: Entered.
10:08:31,598 DEBUG [qtp1954195322-552][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfoay-lbqcd0piojx1_8vcesbfb]: Returning request: null
10:08:31,600 DEBUG [Thread-515][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:08:31,602 DEBUG [qtp1954195322-551][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:08:31,603 DEBUG [qtp1954195322-551][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqfoay-lbqcd0piojx1_8vcesbfb]: Entered.
10:08:39,187 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _query[requestID=ciepo4h91clr9j8lsla1miswb]: Entered with request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@58106295[ciepo4h91clr9j8lsla1miswb,test-iotqg0jh--109cexsd8xiff_g085tgup*1*0w5nh8]
10:08:39,226 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _query[requestID=ciepo4h91clr9j8lsla1miswb]: Request persisted.
10:08:39,236 DEBUG [qtp1954195322-553][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: Returning request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@58106295[ciepo4h91clr9j8lsla1miswb,test-iotqg0jh--109cexsd8xiff_g085tgup*1*0w5nh8]
10:08:39,236 DEBUG [qtp1954195322-553][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyRequest matching=true
10:08:39,238 ERROR [qtp1954195322-439][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@556ba3be" (id="ciepo4h91clr9j8lsla1miswb") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
10:08:39,239 WARN [qtp1954195322-439][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@556ba3be" (id="ciepo4h91clr9j8lsla1miswb") 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@58106295
10:08:39,240 DEBUG [Thread-517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:08:39,252 DEBUG [Thread-517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyResponse matching=true
10:08:39,254 DEBUG [qtp1954195322-408][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:08:39,255 DEBUG [qtp1954195322-408][MessageBrokerPMF] [hoco9j] _pushResponse[requestID=ciepo4h91clr9j8lsla1miswb]: Entered.
10:08:39,261 DEBUG [qtp1954195322-408][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: Entered.
10:08:39,435 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Created new Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:08:39,436 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,436 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,436 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,436 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,436 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,437 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,439 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,439 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,439 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,439 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,440 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,440 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,440 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,441 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,441 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,441 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,442 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,442 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,442 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,442 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,443 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,443 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,444 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,444 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,444 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
* MMM 1464595675630
* MMM 1464595687914
* MMM 1464595693626
* MMM 1464595701105
10:08:39,444 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,445 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,446 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3a7363e8[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@554bd9df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:39,446 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e394c6d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7ed57f6c[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:39,446 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:08:39,446 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,446 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6bc812aa[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:39,446 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:08:39,446 INFO [qtp1954195322-411][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is not set. Using default algorithm 'Twofish/GCM/NoPadding'.
10:08:39,446 INFO [qtp1954195322-411][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is not set. Using default MAC algorithm 'NONE'.
10:08:39,447 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _query[requestID=n8zu0amotv09ezhqy8me6xsum]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@743b6c71[n8zu0amotv09ezhqy8me6xsum,test-iotqg0jh--109cexsd8xiff_g085tgup*1*0w5nh8]
10:08:39,450 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _query[requestID=n8zu0amotv09ezhqy8me6xsum]: Request persisted.
10:08:39,462 DEBUG [qtp1954195322-412][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@743b6c71[n8zu0amotv09ezhqy8me6xsum,test-iotqg0jh--109cexsd8xiff_g085tgup*1*0w5nh8]
10:08:39,463 DEBUG [qtp1954195322-412][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
10:08:39,465 DEBUG [Thread-520][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:08:39,480 DEBUG [Thread-520][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
10:08:39,483 DEBUG [qtp1954195322-419][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:08:39,487 DEBUG [qtp1954195322-419][MessageBrokerPMF] [hoco9j] _pushResponse[requestID=n8zu0amotv09ezhqy8me6xsum]: Entered.
10:08:39,491 DEBUG [qtp1954195322-419][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqg0jh--109cexsd8xiff_g085tgup]: Entered.
10:08:39,663 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Created new Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:08:39,663 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,669 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:08:39,669 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,669 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,670 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6bc812aa[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:39,672 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,672 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,672 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,672 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,672 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7ed57f6c[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:39,674 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,674 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,675 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,675 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,677 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,677 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,685 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,686 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,690 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e394c6d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:39,692 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,692 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,692 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,693 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,693 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@554bd9df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:39,695 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,695 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,695 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,695 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,696 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3a7363e8[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:39,698 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,698 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,698 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,698 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,700 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
10:08:39,700 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
10:08:39,701 DEBUG [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@1130e52a[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,701 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@498f5518[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,702 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@498f5518[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,702 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1130e52a[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,702 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@64b0d653[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:39,702 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@64b0d653[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:39,702 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1130e52a[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,702 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@498f5518[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,702 DEBUG [qtp1954195322-411][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@498f5518[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,703 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@64b0d653[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:39,704 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@1130e52a[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,704 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@1130e52a[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,704 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1130e52a[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,704 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@64b0d653[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:39,704 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@64b0d653[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:39,704 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@64b0d653[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:39,704 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@64b0d653[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:39,704 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@498f5518[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,704 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@498f5518[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,704 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@498f5518[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,704 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@498f5518[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,705 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@56d7ea1[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,705 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7aaf45[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:08:39,705 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@657c2d0d[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:08:39,705 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 5 ms). class=org.cumulus4j.store.test.movie.Rating
10:08:39,705 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@56d7ea1[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,705 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@56d7ea1[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,705 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:08:39,705 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,705 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,706 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:08:39,706 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@56d7ea1[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,706 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@56d7ea1[2,org.cumulus4j.store.test.movie.Rating]
10:08:39,708 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,708 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,709 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,710 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,711 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,711 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:08:39,711 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,711 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3a7363e8[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:39,711 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,711 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:08:39,711 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,711 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@554bd9df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:39,711 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:08:39,711 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,711 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:08:39,711 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,711 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e394c6d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:39,712 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,712 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,712 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:08:39,712 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,712 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7ed57f6c[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:39,712 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:08:39,712 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,712 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6bc812aa[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:39,712 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 12
10:08:39,712 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,712 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,713 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 12
10:08:39,713 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6bc812aa[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:08:39,715 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,715 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,715 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,716 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,716 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7ed57f6c[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:08:39,718 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,718 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,719 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,719 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,720 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,720 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,722 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,722 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,723 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e394c6d[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:08:39,725 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,725 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,725 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,725 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,725 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@554bd9df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:39,727 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,727 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,727 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,728 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,728 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3a7363e8[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:08:39,729 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,730 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,730 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,730 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,731 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
10:08:39,731 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
10:08:39,732 DEBUG [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@5a792ce8[3,org.cumulus4j.store.test.movie.Person]
10:08:39,733 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@435e9136[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,733 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@435e9136[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,733 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5a792ce8[3,org.cumulus4j.store.test.movie.Person]
10:08:39,733 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2e8ddbf0[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:39,733 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2e8ddbf0[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:39,733 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5a792ce8[3,org.cumulus4j.store.test.movie.Person]
10:08:39,733 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@435e9136[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,733 DEBUG [qtp1954195322-411][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@435e9136[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,734 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2e8ddbf0[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:39,735 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@5a792ce8[3,org.cumulus4j.store.test.movie.Person]
10:08:39,735 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@5a792ce8[3,org.cumulus4j.store.test.movie.Person]
10:08:39,735 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5a792ce8[3,org.cumulus4j.store.test.movie.Person]
10:08:39,735 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@435e9136[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,735 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@435e9136[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,735 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@435e9136[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,735 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@435e9136[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,735 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2e8ddbf0[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:39,735 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2e8ddbf0[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:39,735 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2e8ddbf0[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:39,735 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2e8ddbf0[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:39,736 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5c8b1641[3,org.cumulus4j.store.test.movie.Person]
10:08:39,736 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3aa274aa[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:08:39,736 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@c28551c[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:08:39,736 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 5 ms). class=org.cumulus4j.store.test.movie.Person
10:08:39,736 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5c8b1641[3,org.cumulus4j.store.test.movie.Person]
10:08:39,736 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5c8b1641[3,org.cumulus4j.store.test.movie.Person]
10:08:39,736 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:08:39,736 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,736 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,737 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:08:39,737 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5c8b1641[3,org.cumulus4j.store.test.movie.Person]
10:08:39,737 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@5c8b1641[3,org.cumulus4j.store.test.movie.Person]
10:08:39,739 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,739 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,742 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,742 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,743 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,745 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,745 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,745 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@b
10:08:39,745 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,745 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
10:08:39,747 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,747 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,747 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,750 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,750 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,751 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,753 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,753 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,753 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@b]
10:08:39,753 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,753 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@554bd9df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:39,753 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
10:08:39,754 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,754 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,754 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,755 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@554bd9df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:39,756 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,756 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,757 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,757 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,757 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@554bd9df[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:08:39,758 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,758 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,761 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,761 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,761 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,761 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1804547830 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,777 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
10:08:39,777 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
10:08:39,798 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,799 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,801 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,801 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,803 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,803 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,803 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,804 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,804 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,804 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,804 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,805 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,805 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,806 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,806 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,806 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,806 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,806 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,807 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,807 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,808 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,808 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,808 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,808 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,808 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,809 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,809 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,810 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,810 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,810 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,810 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,810 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,812 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,812 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,812 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,812 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,812 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,812 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:08:39,812 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:08:39,814 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:08:39,814 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@689660483 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:08:39,814 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,814 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
10:08:39,814 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@3dfbe97b[1,org.cumulus4j.store.test.movie.Movie]
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 86.984 sec
Results :
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0
[JENKINS] Recording test results
[INFO]
[INFO] --- maven-source-plugin:2.1.2:jar-no-fork (attach-sources) @ org.cumulus4j.integrationtest.withkeyserver ---
[INFO] No sources in project. Archive not created.
[INFO]
[INFO] --- maven-install-plugin:2.4:install (default-install) @ org.cumulus4j.integrationtest.withkeyserver ---
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.withkeyserver/target/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.withkeyserver/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.jar
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.withkeyserver/pom.xml to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.withkeyserver/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.pom
|
Help us localize this page