|  Console Output
Skipping 795 KB.. Full LogE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:06:41,008 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:41,008 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@be40ab7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:41,008 TRACE [qtp1954195322-439][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
10:06:41,009 INFO [qtp1954195322-439][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is not set. Using default algorithm 'Twofish/GCM/NoPadding'.
10:06:41,009 INFO [qtp1954195322-439][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is not set. Using default MAC algorithm 'NONE'.
10:06:49,132 INFO [qtp1954195322-439][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
10:06:49,133 DEBUG [qtp1954195322-439][MessageBrokerPMF] [hoco9j] _query[requestID=9akocff0vxf3sg6z8coz7psa4]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@5f151dd7[9akocff0vxf3sg6z8coz7psa4,test-iotqe4hb--26vpqicafnfd_vklna9lo*1*0yt41d]
10:06:49,147 DEBUG [qtp1954195322-439][MessageBrokerPMF] [hoco9j] _query[requestID=9akocff0vxf3sg6z8coz7psa4]: Request persisted.
10:06:49,161 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqe4hb--26vpqicafnfd_vklna9lo]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@5f151dd7[9akocff0vxf3sg6z8coz7psa4,test-iotqe4hb--26vpqicafnfd_vklna9lo*1*0yt41d]
10:06:49,162 DEBUG [qtp1954195322-411][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
10:06:49,165 DEBUG [Thread-14][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:06:49,177 DEBUG [Thread-14][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
10:06:49,184 DEBUG [qtp1954195322-428][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:06:49,188 DEBUG [qtp1954195322-428][MessageBrokerPMF] [hoco9j] _pushResponse[requestID=9akocff0vxf3sg6z8coz7psa4]: Entered.
10:06:49,195 DEBUG [qtp1954195322-428][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqe4hb--26vpqicafnfd_vklna9lo]: Entered.
10:06:49,362 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Created new Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:06:49,363 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,371 TRACE [qtp1954195322-439][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:06:49,371 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,371 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,371 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@be40ab7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:49,375 TRACE [qtp1954195322-439][CryptoCache] getKeyData: Found cached key with keyID=1.
10:06:49,376 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Created new Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:06:49,376 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,376 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,377 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,377 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1deea0a7[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:49,380 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,380 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,381 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,381 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,385 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,386 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,395 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,395 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,402 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f1e53ce[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:49,404 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,405 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,405 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,405 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,405 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4a7e8ba2[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:49,409 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,409 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,410 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,410 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,410 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@274b2ae0[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:49,413 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,413 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,413 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,414 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,416 DEBUG [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
10:06:49,416 DEBUG [qtp1954195322-439][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
10:06:49,417 DEBUG [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@401ac3b0[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,419 DEBUG [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@66a1806b[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,420 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@66a1806b[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,420 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@401ac3b0[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,420 DEBUG [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5e7f93a9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:06:49,420 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5e7f93a9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:06:49,420 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@401ac3b0[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,420 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@66a1806b[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,420 DEBUG [qtp1954195322-439][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@66a1806b[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,422 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5e7f93a9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:06:49,424 DEBUG [qtp1954195322-439][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@401ac3b0[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,424 DEBUG [qtp1954195322-439][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@401ac3b0[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,424 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@401ac3b0[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,425 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5e7f93a9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:06:49,425 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5e7f93a9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:06:49,425 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5e7f93a9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:06:49,425 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5e7f93a9[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:06:49,425 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@66a1806b[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,425 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@66a1806b[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,425 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@66a1806b[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,425 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@66a1806b[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,429 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@68a3363a[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,429 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@78558a7f[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:06:49,429 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4b68b140[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:06:49,429 DEBUG [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 13 ms). class=org.cumulus4j.store.test.movie.Rating
10:06:49,429 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@68a3363a[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,429 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@68a3363a[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,429 TRACE [qtp1954195322-439][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
10:06:49,429 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,430 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,432 TRACE [qtp1954195322-439][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:06:49,432 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@68a3363a[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,432 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@68a3363a[2,org.cumulus4j.store.test.movie.Rating]
10:06:49,436 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,436 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,440 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,440 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,442 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,442 TRACE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:06:49,442 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,443 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@274b2ae0[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:49,443 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,443 TRACE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:06:49,443 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,443 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4a7e8ba2[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:49,443 TRACE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:06:49,443 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,443 TRACE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:06:49,443 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,443 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f1e53ce[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:49,444 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,444 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,444 TRACE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:06:49,444 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,444 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1deea0a7[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:49,444 TRACE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:06:49,444 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,444 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@be40ab7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:49,444 TRACE [qtp1954195322-439][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 7
10:06:49,444 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,445 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,447 TRACE [qtp1954195322-439][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 7
10:06:49,447 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@be40ab7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:49,449 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,449 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,450 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,450 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,450 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1deea0a7[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:49,453 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,453 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,453 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,453 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,456 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,456 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,460 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,460 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,461 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3f1e53ce[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:49,464 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,464 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,464 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,464 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,465 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4a7e8ba2[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:49,467 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,467 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,467 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,467 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,467 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@274b2ae0[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:49,470 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,470 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,470 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,470 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,472 DEBUG [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
10:06:49,473 DEBUG [qtp1954195322-439][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
10:06:49,474 DEBUG [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@25c8c82[3,org.cumulus4j.store.test.movie.Person]
10:06:49,475 DEBUG [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1e102c49[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,476 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1e102c49[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,476 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@25c8c82[3,org.cumulus4j.store.test.movie.Person]
10:06:49,476 DEBUG [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@768b299a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:06:49,476 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@768b299a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:06:49,476 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@25c8c82[3,org.cumulus4j.store.test.movie.Person]
10:06:49,476 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1e102c49[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,477 DEBUG [qtp1954195322-439][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@1e102c49[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,478 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@768b299a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:06:49,479 DEBUG [qtp1954195322-439][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@25c8c82[3,org.cumulus4j.store.test.movie.Person]
10:06:49,479 DEBUG [qtp1954195322-439][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@25c8c82[3,org.cumulus4j.store.test.movie.Person]
10:06:49,479 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@25c8c82[3,org.cumulus4j.store.test.movie.Person]
10:06:49,480 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1e102c49[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,480 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1e102c49[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,480 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1e102c49[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,480 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1e102c49[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,480 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@768b299a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:06:49,480 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@768b299a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:06:49,480 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@768b299a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:06:49,480 DEBUG [qtp1954195322-439][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@768b299a[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:06:49,481 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@28ad6dfe[3,org.cumulus4j.store.test.movie.Person]
10:06:49,481 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6db7ae45[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:06:49,481 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4628e6cc[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:06:49,481 DEBUG [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 9 ms). class=org.cumulus4j.store.test.movie.Person
10:06:49,481 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@28ad6dfe[3,org.cumulus4j.store.test.movie.Person]
10:06:49,481 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@28ad6dfe[3,org.cumulus4j.store.test.movie.Person]
10:06:49,481 TRACE [qtp1954195322-439][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
10:06:49,481 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,482 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,483 TRACE [qtp1954195322-439][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
10:06:49,483 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@28ad6dfe[3,org.cumulus4j.store.test.movie.Person]
10:06:49,483 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@28ad6dfe[3,org.cumulus4j.store.test.movie.Person]
10:06:49,486 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,486 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,489 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,489 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,491 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,493 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,494 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,494 TRACE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@6
10:06:49,494 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,494 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
10:06:49,496 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,497 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,497 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,502 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,502 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,503 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,506 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,506 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,506 TRACE [qtp1954195322-439][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@6]
10:06:49,506 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,506 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4a7e8ba2[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:49,506 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
10:06:49,508 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,508 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,509 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,509 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4a7e8ba2[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:49,512 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,512 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,512 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,512 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,512 TRACE [qtp1954195322-439][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4a7e8ba2[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:49,515 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,515 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,519 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,519 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,519 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,519 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1996573980 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,537 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,538 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,542 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:06:49,542 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,556 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,557 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,557 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,557 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,557 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,557 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:06:49,558 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,560 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,560 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,561 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,561 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,561 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,561 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:06:49,561 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,563 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,563 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,563 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,563 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,563 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,564 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:06:49,564 TRACE [qtp1954195322-439][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:49,566 TRACE [qtp1954195322-439][CryptoCache] acquireCipherEntry: Found cached Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:06:49,566 TRACE [qtp1954195322-439][CryptoCache] releaseCipherEntry: Releasing Cipher@1147069808 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:06:49,579 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,579 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:49,579 TRACE [qtp1954195322-439][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@575cee1e[1,org.cumulus4j.store.test.movie.Movie]
10:06:50,180 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:06:50,863 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:06:50,864 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:06:54,586 INFO [qtp1954195322-411][Cumulus4jStoreManager] ====================== Cumulus4j ======================
10:06:54,586 INFO [qtp1954195322-411][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
10:06:54,586 INFO [qtp1954195322-411][Cumulus4jStoreManager] =======================================================
10:06:54,587 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.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1970)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1965)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1171)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:813)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManagerFactory(TestService.java:59)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManager(TestService.java:72)
at org.cumulus4j.integrationtest.webapp.TestService.testPost(TestService.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:546)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1283)
at org.cumulus4j.keymanager.back.shared.AjaxHeadersFilter.doFilter(AjaxHeadersFilter.java:33)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1254)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:481)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:516)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:230)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:956)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:411)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:188)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:891)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:247)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:151)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:114)
at org.eclipse.jetty.server.Server.handle(Server.java:353)
at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:598)
at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:1059)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:590)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212)
at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:427)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:510)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:450)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassCastException: org.cumulus4j.store.Cumulus4jStoreManager cannot be cast to org.datanucleus.store.rdbms.RDBMSStoreManager
at org.datanucleus.store.rdbms.autostart.SchemaAutoStarter.<init>(SchemaAutoStarter.java:68)
... 70 more
Reading Movies before writing:
10:06:54,588 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Movie
10:06:54,589 INFO [qtp1954195322-411][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
10:06:54,589 TRACE [qtp1954195322-411][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=test-iotqe4hb--26vpqicafnfd_vklna9lo*1*0yt41d
10:06:54,589 INFO [qtp1954195322-411][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
10:06:54,612 INFO [qtp1954195322-411][MinimumCumulus4jVersion] version=10100001
10:06:54,613 INFO [qtp1954195322-411][MinimumCumulus4jVersion] version=10100001
10:06:54,614 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Movie
10:06:54,616 DEBUG [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,619 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@37871c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,621 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@36b541a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:06:54,621 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@37871c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,621 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@37871c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,621 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,621 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1813ef57[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,622 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@289f7f36[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:06:54,622 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1813ef57[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,622 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1813ef57[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,622 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,622 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1167adb1[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:06:54,622 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1167adb1[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:06:54,623 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,623 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6720433a[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,623 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6720433a[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,623 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,623 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2aa1208e[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,624 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@49505eec[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:06:54,624 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2aa1208e[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,624 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2aa1208e[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,624 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,624 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@49e841c4[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:06:54,625 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@49e841c4[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:06:54,625 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,625 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5dbec07f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,626 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5ba3aafd[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:06:54,626 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5dbec07f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,626 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5dbec07f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,626 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,626 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3cebefff[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,626 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3cebefff[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,626 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,626 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@23383b91[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,627 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5bcf105f[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:06:54,627 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@23383b91[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,628 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@23383b91[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,628 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,628 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@37871c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,628 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1813ef57[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,628 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1167adb1[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:06:54,628 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6720433a[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,628 DEBUG [qtp1954195322-411][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@6720433a[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,630 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2aa1208e[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,630 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@49e841c4[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:06:54,630 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5dbec07f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,630 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3cebefff[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,630 DEBUG [qtp1954195322-411][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@3cebefff[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,632 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@23383b91[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,633 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,633 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,633 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1d8547a9[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,634 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@37871c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,634 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@37871c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,634 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@37871c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,634 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@36b541a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:06:54,634 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@36b541a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:06:54,634 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@36b541a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:06:54,634 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@36b541a9[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:06:54,634 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@37871c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,635 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1813ef57[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,635 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1813ef57[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,635 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1813ef57[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,635 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@289f7f36[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:06:54,635 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@289f7f36[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:06:54,635 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@289f7f36[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:06:54,635 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@289f7f36[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:06:54,635 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1813ef57[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,636 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3cebefff[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,636 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3cebefff[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,636 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3cebefff[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,636 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3cebefff[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,636 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@23383b91[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,636 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@23383b91[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,636 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@23383b91[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,636 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5bcf105f[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:06:54,637 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5bcf105f[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:06:54,637 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5bcf105f[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:06:54,637 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5bcf105f[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:06:54,637 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@23383b91[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,637 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6720433a[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,637 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6720433a[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,637 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6720433a[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,637 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6720433a[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,638 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@49e841c4[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:06:54,638 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@49e841c4[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:06:54,638 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@49e841c4[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:06:54,638 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@49e841c4[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:06:54,638 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5dbec07f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,638 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5dbec07f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,638 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5dbec07f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,638 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5ba3aafd[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:06:54,638 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5ba3aafd[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:06:54,639 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ba3aafd[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:06:54,639 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5ba3aafd[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:06:54,639 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5dbec07f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,639 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1167adb1[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:06:54,639 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1167adb1[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:06:54,639 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1167adb1[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:06:54,639 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1167adb1[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:06:54,639 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2aa1208e[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,640 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2aa1208e[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,640 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2aa1208e[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,640 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@49505eec[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:06:54,640 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@49505eec[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:06:54,640 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@49505eec[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:06:54,640 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@49505eec[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:06:54,640 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2aa1208e[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,640 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@698c53c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@61134afa[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@14d7923d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@38c5e2cb[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@783461ca[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30ba0ac[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2b658c8a[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3c21f097[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6740fce8[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@39903e6c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3e16f408[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@d801e15[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d4704f1[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:06:54,641 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@551c346b[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
10:06:54,641 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 53 ms). class=org.cumulus4j.store.test.movie.Movie
10:06:54,642 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:54,644 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:06:54,645 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:06:54,659 TRACE [qtp1954195322-411][CryptoCache] getKeyData: No cached key with keyID=1 found.
10:06:54,659 INFO [qtp1954195322-411][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
10:06:56,228 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
10:06:56,228 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
10:06:56,750 DEBUG [qtp1954195322-406][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-6300741180062597995_f5s2gbhb]: Returning request: null
10:06:56,756 DEBUG [Thread-6][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:06:56,763 DEBUG [qtp1954195322-439][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:06:56,766 DEBUG [qtp1954195322-439][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-6300741180062597995_f5s2gbhb]: Entered.
10:06:57,959 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 1 users left in cache.
10:06:58,017 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 1 sessions left.
10:06:59,023 DEBUG [qtp1954195322-410][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqdp31-eydlya0k6c5o_av06mltz]: Returning request: null
10:06:59,029 DEBUG [Thread-11][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:06:59,034 DEBUG [qtp1954195322-406][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:06:59,036 DEBUG [qtp1954195322-406][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqdp31-eydlya0k6c5o_av06mltz]: Entered.
10:06:59,045 DEBUG [qtp1954195322-430][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqdp31-eydlya0k6c5o_av06mltz]: Returning request: null
10:06:59,049 DEBUG [Thread-10][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:06:59,053 DEBUG [qtp1954195322-410][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:06:59,055 DEBUG [qtp1954195322-410][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqdp31-eydlya0k6c5o_av06mltz]: Entered.
10:06:59,061 DEBUG [qtp1954195322-429][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqdp31-eydlya0k6c5o_av06mltz]: Returning request: null
10:06:59,064 DEBUG [Thread-12][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:06:59,070 DEBUG [qtp1954195322-430][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:06:59,071 DEBUG [qtp1954195322-430][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqdp31-eydlya0k6c5o_av06mltz]: Entered.
10:06:59,475 DEBUG [qtp1954195322-431][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqdp31-eydlya0k6c5o_av06mltz]: Returning request: null
10:06:59,478 DEBUG [Thread-9][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
10:06:59,485 DEBUG [qtp1954195322-429][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:06:59,488 DEBUG [qtp1954195322-429][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqdp31-eydlya0k6c5o_av06mltz]: Entered.
10:07:03,849 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _query[requestID=kw39k6aq89xzzu673ykb817pc]: Entered with request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@101f3308[kw39k6aq89xzzu673ykb817pc,test-iotqe4hb--26vpqicafnfd_vklna9lo*1*0yt41d]
10:07:03,884 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _query[requestID=kw39k6aq89xzzu673ykb817pc]: Request persisted.
10:07:03,887 DEBUG [qtp1954195322-428][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqe4hb--26vpqicafnfd_vklna9lo]: Returning request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@101f3308[kw39k6aq89xzzu673ykb817pc,test-iotqe4hb--26vpqicafnfd_vklna9lo*1*0yt41d]
10:07:03,888 DEBUG [qtp1954195322-428][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyRequest matching=true
10:07:03,890 ERROR [qtp1954195322-438][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@ed40b52" (id="kw39k6aq89xzzu673ykb817pc") 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:07:03,892 ERROR [qtp1954195322-437][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@19bb1884" (id="kw39k6aq89xzzu673ykb817pc") 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:07:03,893 WARN [qtp1954195322-438][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqe4hb--26vpqicafnfd_vklna9lo]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@ed40b52" (id="kw39k6aq89xzzu673ykb817pc") 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@101f3308
10:07:03,893 WARN [qtp1954195322-437][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqe4hb--26vpqicafnfd_vklna9lo]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@19bb1884" (id="kw39k6aq89xzzu673ykb817pc") 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@101f3308
10:07:03,892 DEBUG [Thread-14][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:07:03,903 DEBUG [Thread-14][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyResponse matching=true
10:07:03,906 DEBUG [qtp1954195322-428][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:07:03,908 DEBUG [qtp1954195322-428][MessageBrokerPMF] [hoco9j] _pushResponse[requestID=kw39k6aq89xzzu673ykb817pc]: Entered.
10:07:03,914 DEBUG [qtp1954195322-428][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqe4hb--26vpqicafnfd_vklna9lo]: Entered.
10:07:04,090 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Created new Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:07:04,090 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,091 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,091 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,091 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,091 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,092 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,094 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,094 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,094 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,094 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,094 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,094 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,094 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,096 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,096 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,096 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,097 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,097 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,097 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,097 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,099 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,099 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,099 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,099 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,099 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
* MMM 1464595587270
* MMM 1464595595078
* MMM 1464595601005
* MMM 1464595609442
10:07:04,099 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,101 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,101 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:07:04,101 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,101 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30ba0ac[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:07:04,101 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,101 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:07:04,101 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,101 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@39903e6c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:07:04,101 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:07:04,101 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,101 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:07:04,101 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,101 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d4704f1[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:07:04,101 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,101 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,101 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:07:04,101 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,101 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@14d7923d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:07:04,102 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:07:04,102 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,102 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@698c53c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:07:04,102 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:07:04,102 INFO [qtp1954195322-411][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is not set. Using default algorithm 'Twofish/GCM/NoPadding'.
10:07:04,102 INFO [qtp1954195322-411][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is not set. Using default MAC algorithm 'NONE'.
10:07:04,102 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _query[requestID=ceav57ij5blpjb6gar8nflhjt]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@b9311c51[ceav57ij5blpjb6gar8nflhjt,test-iotqe4hb--26vpqicafnfd_vklna9lo*1*0yt41d]
10:07:04,105 DEBUG [qtp1954195322-411][MessageBrokerPMF] [hoco9j] _query[requestID=ceav57ij5blpjb6gar8nflhjt]: Request persisted.
10:07:04,127 DEBUG [qtp1954195322-438][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqe4hb--26vpqicafnfd_vklna9lo]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@b9311c51[ceav57ij5blpjb6gar8nflhjt,test-iotqe4hb--26vpqicafnfd_vklna9lo*1*0yt41d]
10:07:04,127 DEBUG [qtp1954195322-438][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
10:07:04,131 DEBUG [Thread-15][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
10:07:04,148 DEBUG [Thread-15][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
10:07:04,151 DEBUG [qtp1954195322-431][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
10:07:04,153 DEBUG [qtp1954195322-431][MessageBrokerPMF] [hoco9j] _pushResponse[requestID=ceav57ij5blpjb6gar8nflhjt]: Entered.
10:07:04,157 DEBUG [qtp1954195322-431][MessageBrokerPMF] [hoco9j] _pollRequest[cryptoSessionIDPrefix=test-iotqe4hb--26vpqicafnfd_vklna9lo]: Entered.
10:07:04,317 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Created new Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
10:07:04,317 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,326 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:07:04,326 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,326 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,326 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@698c53c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:07:04,330 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,330 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,330 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,330 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,330 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@14d7923d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:07:04,333 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,333 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,333 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,334 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,336 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,336 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,345 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,345 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,351 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d4704f1[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:07:04,353 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,353 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,353 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,354 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,354 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@39903e6c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:07:04,356 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,356 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,357 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,357 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,357 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30ba0ac[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:07:04,359 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,359 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,360 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,360 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,361 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
10:07:04,361 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
10:07:04,362 DEBUG [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@54ed500b[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,364 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@63078f82[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,364 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@63078f82[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,364 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@54ed500b[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,364 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1ed55a5b[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:07:04,365 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1ed55a5b[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:07:04,365 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@54ed500b[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,365 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@63078f82[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,365 DEBUG [qtp1954195322-411][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@63078f82[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,366 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1ed55a5b[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:07:04,367 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@54ed500b[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,367 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@54ed500b[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,367 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@54ed500b[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,367 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1ed55a5b[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:07:04,367 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1ed55a5b[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:07:04,367 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1ed55a5b[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:07:04,367 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1ed55a5b[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:07:04,367 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@63078f82[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,368 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@63078f82[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,368 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@63078f82[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,368 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@63078f82[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,368 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@126d52a2[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,368 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@504d4635[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
10:07:04,368 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3a061f71[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
10:07:04,368 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 7 ms). class=org.cumulus4j.store.test.movie.Rating
10:07:04,368 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@126d52a2[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,368 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@126d52a2[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,368 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:07:04,368 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,368 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,370 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:07:04,370 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@126d52a2[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,370 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@126d52a2[2,org.cumulus4j.store.test.movie.Rating]
10:07:04,372 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,372 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,375 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,375 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,376 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,376 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
10:07:04,376 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,376 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30ba0ac[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:07:04,376 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,376 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
10:07:04,376 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,376 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@39903e6c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:07:04,376 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
10:07:04,376 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,376 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
10:07:04,376 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,377 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d4704f1[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:07:04,377 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,377 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,377 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
10:07:04,377 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,377 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@14d7923d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:07:04,377 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
10:07:04,377 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,377 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@698c53c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:07:04,377 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 12
10:07:04,377 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,377 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,378 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 12
10:07:04,378 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@698c53c[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
10:07:04,381 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,381 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,381 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,381 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,381 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@14d7923d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
10:07:04,384 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,384 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,384 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,385 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,387 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,387 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,389 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,390 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,391 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d4704f1[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
10:07:04,393 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,393 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,393 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,393 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,393 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@39903e6c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:07:04,396 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,396 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,396 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,396 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,396 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30ba0ac[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
10:07:04,398 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,398 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,399 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,399 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,400 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
10:07:04,400 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
10:07:04,401 DEBUG [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@2812761d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,402 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@746e9833[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,403 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@746e9833[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,403 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2812761d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,403 DEBUG [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@ed4c88[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:07:04,403 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@ed4c88[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:07:04,403 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2812761d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,403 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@746e9833[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,403 DEBUG [qtp1954195322-411][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@746e9833[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,405 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@ed4c88[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:07:04,405 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@2812761d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,405 DEBUG [qtp1954195322-411][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@2812761d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,405 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2812761d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,406 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@746e9833[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,406 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@746e9833[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,406 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@746e9833[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,406 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@746e9833[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,406 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@ed4c88[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:07:04,406 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@ed4c88[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:07:04,406 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@ed4c88[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:07:04,406 DEBUG [qtp1954195322-411][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@ed4c88[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:07:04,406 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@33e0338d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,406 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@e215c03[17,org.cumulus4j.store.test.movie.Person#name[primary]]
10:07:04,406 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@457dfe82[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
10:07:04,406 DEBUG [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 6 ms). class=org.cumulus4j.store.test.movie.Person
10:07:04,406 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@33e0338d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,406 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@33e0338d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,406 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
10:07:04,407 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,407 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,408 TRACE [qtp1954195322-411][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
10:07:04,408 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@33e0338d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,408 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@33e0338d[3,org.cumulus4j.store.test.movie.Person]
10:07:04,410 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,410 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,413 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,414 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,415 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,417 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,417 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,417 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@b
10:07:04,417 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,417 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
10:07:04,419 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,419 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,420 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,423 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,423 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,424 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,426 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,426 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,426 TRACE [qtp1954195322-411][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@b]
10:07:04,426 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,427 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@39903e6c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:07:04,427 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
10:07:04,428 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,428 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,428 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,428 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@39903e6c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:07:04,431 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,431 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,431 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,431 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,431 TRACE [qtp1954195322-411][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@39903e6c[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
10:07:04,433 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,434 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,436 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,436 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,437 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,437 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@2053159315 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,449 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,449 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,451 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,451 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,454 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,454 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,454 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,454 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,454 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,454 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,456 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,458 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,458 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,458 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,458 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,458 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,458 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,459 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,461 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,461 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,461 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,461 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,461 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,461 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,462 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,463 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,464 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,464 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,464 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,464 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,464 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,464 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,466 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,466 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,466 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,467 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,467 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,467 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
10:07:04,467 TRACE [qtp1954195322-411][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
10:07:04,469 TRACE [qtp1954195322-411][CryptoCache] acquireCipherEntry: Found cached Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
10:07:04,469 TRACE [qtp1954195322-411][CryptoCache] releaseCipherEntry: Releasing Cipher@1512452049 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
10:07:04,470 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,470 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
10:07:04,470 TRACE [qtp1954195322-411][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52dfdc30[1,org.cumulus4j.store.test.movie.Movie]
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 102.549 sec
Results :
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0
[JENKINS] Recording test results
[INFO]
[INFO] --- maven-source-plugin:2.1.2:jar-no-fork (attach-sources) @ org.cumulus4j.integrationtest.webapp ---
[INFO] org already added, skipping
[INFO] org/cumulus4j already added, skipping
[INFO] org/cumulus4j/integrationtest already added, skipping
[INFO] org/cumulus4j/integrationtest/webapp already added, skipping
[INFO] LICENCE.txt already added, skipping
[INFO] cumulus4j-test-datanucleus.properties already added, skipping
[INFO] Building jar: /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.webapp/target/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT-sources.jar
[INFO] org already added, skipping
[INFO] org/cumulus4j already added, skipping
[INFO] org/cumulus4j/integrationtest already added, skipping
[INFO] org/cumulus4j/integrationtest/webapp already added, skipping
[INFO] LICENCE.txt already added, skipping
[INFO] cumulus4j-test-datanucleus.properties already added, skipping
[INFO]
[INFO] --- maven-install-plugin:2.4:install (default-install) @ org.cumulus4j.integrationtest.webapp ---
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.webapp/target/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT.war to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.webapp/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT.war
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.webapp/pom.xml to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.webapp/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT.pom
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.webapp/target/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT-sources.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.webapp/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.webapp-1.2.1-SNAPSHOT-sources.jar
|
Help us localize this page