|  Console Output
Skipping 1,570 KB.. Full Logithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,309 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,310 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,310 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,324 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,328 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,364 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,368 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,393 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@230d8132[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:04:53,398 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,404 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,404 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,405 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,405 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3676bd4f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:04:53,429 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,430 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,431 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,431 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,435 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ec2d739[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:04:53,449 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,452 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,453 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,459 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,466 DEBUG [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
16:04:53,469 DEBUG [qtp849731105-1277][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
16:04:53,483 DEBUG [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@26c34aa[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,490 DEBUG [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@526cb133[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,491 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@526cb133[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,492 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@26c34aa[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,493 DEBUG [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@13f1e8d6[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:04:53,494 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@13f1e8d6[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:04:53,499 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@26c34aa[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,500 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@526cb133[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,500 DEBUG [qtp849731105-1277][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@526cb133[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,510 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@13f1e8d6[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:04:53,512 DEBUG [qtp849731105-1277][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@26c34aa[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,513 DEBUG [qtp849731105-1277][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@26c34aa[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,516 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@26c34aa[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,517 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@13f1e8d6[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:04:53,520 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@13f1e8d6[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:04:53,520 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@13f1e8d6[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:04:53,520 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@13f1e8d6[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:04:53,521 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@526cb133[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,521 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@526cb133[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,521 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@526cb133[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,521 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@526cb133[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,524 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@598e865e[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,525 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1c17b341[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:04:53,525 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@57f97ecf[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:04:53,525 DEBUG [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 56 ms). class=org.cumulus4j.store.test.movie.Rating
16:04:53,525 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@598e865e[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,530 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@598e865e[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,530 TRACE [qtp849731105-1277][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
16:04:53,531 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,532 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,542 TRACE [qtp849731105-1277][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
16:04:53,543 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@598e865e[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,549 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@598e865e[2,org.cumulus4j.store.test.movie.Rating]
16:04:53,559 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,559 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,584 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,585 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,606 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:53,606 TRACE [qtp849731105-1277][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
16:04:53,606 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,606 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ec2d739[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:04:53,607 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,607 TRACE [qtp849731105-1277][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
16:04:53,607 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,607 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3676bd4f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:04:53,607 TRACE [qtp849731105-1277][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
16:04:53,607 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,607 TRACE [qtp849731105-1277][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
16:04:53,607 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,608 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@230d8132[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:04:53,608 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,608 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,608 TRACE [qtp849731105-1277][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
16:04:53,608 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,608 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30625484[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:04:53,608 TRACE [qtp849731105-1277][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
16:04:53,608 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,609 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@33644ef0[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:04:53,609 TRACE [qtp849731105-1277][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 7
16:04:53,609 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,611 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,622 TRACE [qtp849731105-1277][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 7
16:04:53,625 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@33644ef0[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:04:53,629 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,636 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,641 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,642 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,645 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30625484[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:04:53,656 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,667 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,669 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,670 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,687 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,701 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,712 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,714 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,719 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@230d8132[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:04:53,743 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,750 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,751 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,751 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,752 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3676bd4f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:04:53,765 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,773 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,774 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,774 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,774 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5ec2d739[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:04:53,801 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,802 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,803 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,804 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,811 DEBUG [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
16:04:53,820 DEBUG [qtp849731105-1277][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
16:04:53,825 DEBUG [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@528d68d9[3,org.cumulus4j.store.test.movie.Person]
16:04:53,835 DEBUG [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2b956d1e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,836 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2b956d1e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,837 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@528d68d9[3,org.cumulus4j.store.test.movie.Person]
16:04:53,837 DEBUG [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1c3943ef[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:04:53,838 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1c3943ef[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:04:53,838 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@528d68d9[3,org.cumulus4j.store.test.movie.Person]
16:04:53,838 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2b956d1e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,838 DEBUG [qtp849731105-1277][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@2b956d1e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,841 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1c3943ef[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:04:53,846 DEBUG [qtp849731105-1277][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@528d68d9[3,org.cumulus4j.store.test.movie.Person]
16:04:53,846 DEBUG [qtp849731105-1277][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@528d68d9[3,org.cumulus4j.store.test.movie.Person]
16:04:53,847 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@528d68d9[3,org.cumulus4j.store.test.movie.Person]
16:04:53,847 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2b956d1e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,849 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2b956d1e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,849 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2b956d1e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,849 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2b956d1e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,850 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1c3943ef[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:04:53,857 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1c3943ef[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:04:53,857 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1c3943ef[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:04:53,857 DEBUG [qtp849731105-1277][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1c3943ef[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:04:53,858 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@588aa998[3,org.cumulus4j.store.test.movie.Person]
16:04:53,858 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@77846791[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:04:53,858 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@15ab9de4[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:04:53,858 DEBUG [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 38 ms). class=org.cumulus4j.store.test.movie.Person
16:04:53,858 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@588aa998[3,org.cumulus4j.store.test.movie.Person]
16:04:53,858 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@588aa998[3,org.cumulus4j.store.test.movie.Person]
16:04:53,858 TRACE [qtp849731105-1277][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
16:04:53,859 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,860 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,862 TRACE [qtp849731105-1277][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
16:04:53,863 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@588aa998[3,org.cumulus4j.store.test.movie.Person]
16:04:53,863 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@588aa998[3,org.cumulus4j.store.test.movie.Person]
16:04:53,870 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,872 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,897 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,901 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,919 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:53,936 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,940 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,941 TRACE [qtp849731105-1277][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@6
16:04:53,941 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,942 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
16:04:53,960 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,961 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:53,961 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:53,988 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:53,990 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,006 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:54,016 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,016 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,027 TRACE [qtp849731105-1277][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@6]
16:04:54,028 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,028 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3676bd4f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:04:54,028 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
16:04:54,038 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,039 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,039 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,041 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3676bd4f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:04:54,058 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,066 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,067 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,067 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,067 TRACE [qtp849731105-1277][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3676bd4f[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:04:54,080 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,081 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,102 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,102 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,103 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,103 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@628211737 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,149 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:54,151 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:54,156 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:04:54,157 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:54,174 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,175 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,177 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,178 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,178 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,178 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:04:54,180 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:54,184 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,194 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,196 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,196 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,196 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,197 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:04:54,197 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:54,200 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,207 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,208 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,208 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,208 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,208 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:04:54,209 TRACE [qtp849731105-1277][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:04:54,219 TRACE [qtp849731105-1277][CryptoCache] acquireCipherEntry: Found cached Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:04:54,221 TRACE [qtp849731105-1277][CryptoCache] releaseCipherEntry: Releasing Cipher@471839397 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:04:54,222 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,222 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:54,222 TRACE [qtp849731105-1277][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2e305e8a[1,org.cumulus4j.store.test.movie.Movie]
16:04:55,911 INFO [qtp849731105-1273][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
16:04:57,114 WARN [qtp849731105-1273][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.
16:04:57,115 WARN [qtp849731105-1273][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.
16:04:58,316 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
16:04:58,316 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
16:04:59,234 DEBUG [qtp849731105-1243][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-3959044183728920602_kvf2f36d]: Returning request: null
16:04:59,236 DEBUG [Thread-2][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:04:59,240 DEBUG [qtp849731105-1277][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:04:59,242 DEBUG [qtp849731105-1277][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-3959044183728920602_kvf2f36d]: Entered.
16:05:01,787 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 1 users left in cache.
16:05:02,152 INFO [SessionManager][SessionManager$ExpireSessionTimerTask] run: Expiring session: userName='marco' cryptoSessionID='test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj*1*061gf9'.
16:05:02,152 DEBUG [SessionManager][CachedMasterKey] clear: Clearing for userName='marco'.
16:05:02,152 DEBUG [SessionManager][MasterKey] clear: Clearing org.cumulus4j.keystore.MasterKey@184f3e5
16:05:02,153 DEBUG [SessionManager][Session] destroy: Destroying session for userName='marco' cryptoSessionID='test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj*1*061gf9'.
16:05:02,153 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 0 sessions left.
16:05:07,898 DEBUG [qtp849731105-1241][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj]: Returning request: null
16:05:07,904 DEBUG [Thread-9][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:05:07,908 DEBUG [qtp849731105-1243][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:05:07,914 DEBUG [qtp849731105-1243][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj]: Entered.
16:05:07,940 DEBUG [qtp849731105-1238][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj]: Returning request: null
16:05:07,944 DEBUG [Thread-10][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:05:07,947 DEBUG [qtp849731105-1241][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:05:07,950 DEBUG [qtp849731105-1241][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj]: Entered.
16:05:07,979 DEBUG [qtp849731105-1242][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj]: Returning request: null
16:05:07,981 DEBUG [Thread-12][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:05:07,986 DEBUG [qtp849731105-1238][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:05:07,990 DEBUG [qtp849731105-1238][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj]: Entered.
16:05:08,029 DEBUG [qtp849731105-1261][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj]: Returning request: null
16:05:08,035 DEBUG [Thread-11][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:05:08,039 DEBUG [qtp849731105-1242][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:05:08,043 DEBUG [qtp849731105-1242][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3qqau-1jmvar4a7ua3q_4dctz7vj]: Entered.
16:05:08,075 DEBUG [qtp849731105-1258][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-3959044183728920602_kvf2f36d]: Returning request: null
16:05:08,077 DEBUG [Thread-5][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:05:08,081 DEBUG [qtp849731105-1261][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:05:08,084 DEBUG [qtp849731105-1261][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-3959044183728920602_kvf2f36d]: Entered.
16:05:09,829 INFO [qtp849731105-1273][Cumulus4jStoreManager] ====================== Cumulus4j ======================
16:05:09,829 INFO [qtp849731105-1273][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
16:05:09,829 INFO [qtp849731105-1273][Cumulus4jStoreManager] =======================================================
16:05:09,830 ERROR [qtp849731105-1273][Persistence] java.lang.reflect.InvocationTargetException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
at org.datanucleus.plugin.NonManagedPluginRegistry.createExecutableExtension(NonManagedPluginRegistry.java:631)
at org.datanucleus.plugin.PluginManager.createExecutableExtension(PluginManager.java:301)
at org.datanucleus.NucleusContext.initialiseAutoStart(NucleusContext.java:432)
at org.datanucleus.NucleusContext.initialise(NucleusContext.java:384)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.freezeConfiguration(JDOPersistenceManagerFactory.java:768)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.createPersistenceManagerFactory(JDOPersistenceManagerFactory.java:326)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.getPersistenceManagerFactory(JDOPersistenceManagerFactory.java:195)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1970)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1965)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1171)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:813)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManagerFactory(TestService.java:59)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManager(TestService.java:72)
at org.cumulus4j.integrationtest.webapp.TestService.testPost(TestService.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:546)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1283)
at org.cumulus4j.keymanager.back.shared.AjaxHeadersFilter.doFilter(AjaxHeadersFilter.java:33)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1254)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:481)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:516)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:230)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:956)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:411)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:188)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:891)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:247)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:151)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:114)
at org.eclipse.jetty.server.Server.handle(Server.java:353)
at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:598)
at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:1059)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:590)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212)
at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:427)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:510)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:450)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassCastException: org.cumulus4j.store.Cumulus4jStoreManager cannot be cast to org.datanucleus.store.rdbms.RDBMSStoreManager
at org.datanucleus.store.rdbms.autostart.SchemaAutoStarter.<init>(SchemaAutoStarter.java:68)
... 70 more
Reading Movies before writing:
16:05:09,831 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Movie
16:05:09,839 INFO [qtp849731105-1273][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
16:05:09,839 TRACE [qtp849731105-1273][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv*1*0b2rqk
16:05:09,839 INFO [qtp849731105-1273][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
16:05:10,037 INFO [qtp849731105-1273][MinimumCumulus4jVersion] version=10100001
16:05:10,040 INFO [qtp849731105-1273][MinimumCumulus4jVersion] version=10100001
16:05:10,040 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Movie
16:05:10,049 DEBUG [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,056 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@4b5df9e3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,072 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@618af423[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:05:10,079 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4b5df9e3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,079 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4b5df9e3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,079 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,080 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@4bac0000[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,081 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1cecf869[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:05:10,082 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4bac0000[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,086 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4bac0000[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,086 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,086 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@38f175ef[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:05:10,087 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@38f175ef[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:05:10,087 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,088 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5d4fa8a6[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,095 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5d4fa8a6[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,095 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,096 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@24f92f16[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,097 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1699f6d2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:05:10,098 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f92f16[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,099 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f92f16[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,099 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,099 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1f62025d[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:05:10,100 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1f62025d[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:05:10,106 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,108 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2d0fc05b[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,109 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@549bb2a5[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:05:10,110 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d0fc05b[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,111 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d0fc05b[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,111 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,112 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@74a46708[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,113 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@74a46708[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,117 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,117 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3e2493fb[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,120 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@77fbde0c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:05:10,121 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3e2493fb[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,124 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3e2493fb[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,124 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,124 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4b5df9e3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,124 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4bac0000[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,124 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@38f175ef[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:05:10,127 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5d4fa8a6[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,127 DEBUG [qtp849731105-1273][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@5d4fa8a6[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,136 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f92f16[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,138 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1f62025d[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:05:10,138 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d0fc05b[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,138 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@74a46708[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,138 DEBUG [qtp849731105-1273][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@74a46708[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,141 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3e2493fb[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,142 DEBUG [qtp849731105-1273][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,145 DEBUG [qtp849731105-1273][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,145 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@217ff5c8[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,146 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@38f175ef[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:05:10,146 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@38f175ef[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:05:10,147 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@38f175ef[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:05:10,147 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@38f175ef[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:05:10,147 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@74a46708[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,150 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@74a46708[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,150 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@74a46708[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,151 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@74a46708[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,151 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@4bac0000[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,151 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@4bac0000[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,151 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4bac0000[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,152 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1cecf869[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:05:10,152 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1cecf869[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:05:10,152 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1cecf869[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:05:10,152 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1cecf869[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:05:10,152 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@4bac0000[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,153 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@24f92f16[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,153 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@24f92f16[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,154 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@24f92f16[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,160 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1699f6d2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:05:10,160 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1699f6d2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:05:10,160 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1699f6d2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:05:10,160 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1699f6d2[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:05:10,160 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@24f92f16[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,161 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5d4fa8a6[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,161 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5d4fa8a6[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,161 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5d4fa8a6[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,161 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5d4fa8a6[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,162 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@4b5df9e3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,162 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@4b5df9e3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,163 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4b5df9e3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,164 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@618af423[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:05:10,164 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@618af423[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:05:10,164 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@618af423[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:05:10,164 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@618af423[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:05:10,165 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@4b5df9e3[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,165 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1f62025d[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:05:10,165 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1f62025d[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:05:10,165 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1f62025d[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:05:10,166 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1f62025d[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:05:10,166 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2d0fc05b[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,166 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2d0fc05b[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,166 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2d0fc05b[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,167 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@549bb2a5[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:05:10,170 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@549bb2a5[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:05:10,171 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@549bb2a5[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:05:10,171 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@549bb2a5[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:05:10,171 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2d0fc05b[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,172 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3e2493fb[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,172 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3e2493fb[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,172 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3e2493fb[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,172 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@77fbde0c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:05:10,173 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@77fbde0c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:05:10,173 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@77fbde0c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:05:10,173 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@77fbde0c[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:05:10,173 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3e2493fb[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,174 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:10,174 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7ae56fd7[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:05:10,174 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d11cb49[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:10,174 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2b395d90[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:05:10,174 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@432daf1b[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:05:10,174 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6c433811[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:10,174 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@31161b9e[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:05:10,181 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6490a4b4[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:10,182 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@542d5900[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:05:10,182 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d2e3a2c[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:05:10,182 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@75ed56b3[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:05:10,182 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30d73e41[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:10,182 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3383674[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:05:10,182 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f7efb52[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:10,182 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@9a5f579[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:05:10,182 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 351 ms). class=org.cumulus4j.store.test.movie.Movie
16:05:10,183 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:10,197 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:10,198 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:10,235 TRACE [qtp849731105-1273][CryptoCache] getKeyData: No cached key with keyID=1 found.
16:05:10,235 INFO [qtp849731105-1273][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
16:05:16,535 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 0 users left in cache.
16:05:18,396 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 0 sessions left.
16:05:21,072 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
16:05:21,072 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
16:05:23,069 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
16:05:27,761 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
16:05:27,762 INFO [CryptoCache][CryptoCache] getCryptoCacheEntryExpiryAgeMSec: Property 'cumulus4j.CryptoCache.entryExpiryAge' cannot be read, because NucleusContext was garbage-collected. Using fallback value 300000.
16:05:27,762 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyEncryptionKeyEntry (1 left).
16:05:27,762 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyDecrypterEntry (1 left).
16:05:27,762 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyEntry (1 left).
16:05:27,762 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheCipherEntry (2 left).
16:05:27,762 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of empty List<CryptoCacheCipherEntry> (2 non-empty lists left).
16:05:28,351 DEBUG [qtp849731105-1284][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: Returning request: null
16:05:28,354 DEBUG [Thread-15][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:05:28,357 DEBUG [qtp849731105-1287][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:05:28,363 DEBUG [qtp849731105-1287][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: Entered.
16:05:30,346 DEBUG [qtp849731105-1273][MessageBrokerPMF] [artt1z] _query[requestID=vb3e5iil3me20iz9q1st3qqlr]: Entered with request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@ef452004[vb3e5iil3me20iz9q1st3qqlr,test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv*1*0b2rqk]
16:05:30,391 DEBUG [qtp849731105-1273][MessageBrokerPMF] [artt1z] _query[requestID=vb3e5iil3me20iz9q1st3qqlr]: Request persisted.
16:05:30,503 DEBUG [qtp849731105-1287][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: Returning request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@ef452004[vb3e5iil3me20iz9q1st3qqlr,test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv*1*0b2rqk]
16:05:30,503 DEBUG [qtp849731105-1287][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyRequest matching=true
16:05:30,506 DEBUG [Thread-15][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
16:05:30,523 DEBUG [Thread-15][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyResponse matching=true
16:05:30,533 DEBUG [qtp849731105-1284][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:05:30,537 DEBUG [qtp849731105-1284][MessageBrokerPMF] [artt1z] _pushResponse[requestID=vb3e5iil3me20iz9q1st3qqlr]: Entered.
16:05:30,628 DEBUG [qtp849731105-1284][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: Entered.
16:05:31,046 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Created new Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
16:05:31,049 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,050 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,051 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,051 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,051 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:31,052 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:31,058 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,059 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,061 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,061 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,061 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,061 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:31,062 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:31,068 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,069 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,070 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,070 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,070 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,071 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:31,071 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:31,075 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,075 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,076 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,076 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,076 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
* MMM 1416063865597
* MMM 1416063868785
* MMM 1416063884074
* MMM 1416063893602
16:05:31,077 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:31,079 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:31,079 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
16:05:31,079 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,079 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f7efb52[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:31,079 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,080 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
16:05:31,080 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,080 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30d73e41[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:31,080 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
16:05:31,080 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,080 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
16:05:31,080 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,080 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6c433811[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:31,080 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,080 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,080 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
16:05:31,080 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,080 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d11cb49[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:31,080 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
16:05:31,080 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,081 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6490a4b4[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:31,081 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
16:05:31,081 INFO [qtp849731105-1273][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is not set. Using default algorithm 'Twofish/GCM/NoPadding'.
16:05:31,081 INFO [qtp849731105-1273][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is not set. Using default MAC algorithm 'NONE'.
16:05:31,081 DEBUG [qtp849731105-1273][MessageBrokerPMF] [artt1z] _query[requestID=6os16awboex8biaor37jeresu]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@9de9004e[6os16awboex8biaor37jeresu,test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv*1*0b2rqk]
16:05:31,158 DEBUG [qtp849731105-1273][MessageBrokerPMF] [artt1z] _query[requestID=6os16awboex8biaor37jeresu]: Request persisted.
16:05:31,248 DEBUG [qtp849731105-1284][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@9de9004e[6os16awboex8biaor37jeresu,test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv*1*0b2rqk]
16:05:31,249 DEBUG [qtp849731105-1284][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
16:05:31,256 ERROR [qtp849731105-1274][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@4d3ff31b" (id="6os16awboex8biaor37jeresu") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
16:05:31,258 ERROR [qtp849731105-1276][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@4e88fbaa" (id="6os16awboex8biaor37jeresu") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
16:05:31,259 WARN [qtp849731105-1276][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@4e88fbaa" (id="6os16awboex8biaor37jeresu") 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@9de9004e
16:05:31,257 DEBUG [Thread-15][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
16:05:31,260 WARN [qtp849731105-1274][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@4d3ff31b" (id="6os16awboex8biaor37jeresu") 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@9de9004e
16:05:31,263 ERROR [qtp849731105-1275][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@2930783a" (id="6os16awboex8biaor37jeresu") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
16:05:31,264 WARN [qtp849731105-1275][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@2930783a" (id="6os16awboex8biaor37jeresu") 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@9de9004e
16:05:31,265 ERROR [qtp849731105-1240][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@4b725640" (id="6os16awboex8biaor37jeresu") has been changed in the datastore since your last read. Your transaction is using version "1" but this doesnt exist in the datastore now
16:05:31,266 WARN [qtp849731105-1240][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@4b725640" (id="6os16awboex8biaor37jeresu") 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@9de9004e
16:05:31,276 DEBUG [Thread-15][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
16:05:31,282 DEBUG [qtp849731105-1287][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:05:31,287 DEBUG [qtp849731105-1287][MessageBrokerPMF] [artt1z] _pushResponse[requestID=6os16awboex8biaor37jeresu]: Entered.
16:05:31,326 DEBUG [qtp849731105-1287][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3u0vl-12pv47hwhgtfi_q3v1p6uv]: Entered.
16:05:31,719 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Created new Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
16:05:31,720 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,730 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
16:05:31,730 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,730 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,731 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6490a4b4[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:31,737 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,738 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,738 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,738 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,739 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d11cb49[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:31,744 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,744 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,745 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,745 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,751 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,752 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,766 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,767 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,777 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6c433811[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:31,781 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,781 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,782 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,782 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,782 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30d73e41[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:31,787 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,788 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,788 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,788 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,789 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f7efb52[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:31,794 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,794 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,794 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,795 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,797 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
16:05:31,798 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
16:05:31,800 DEBUG [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@45ef7650[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,802 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3bbfa569[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,802 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3bbfa569[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,803 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@45ef7650[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,803 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@8867672[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:05:31,803 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@8867672[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:05:31,803 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@45ef7650[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,804 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3bbfa569[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,804 DEBUG [qtp849731105-1273][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@3bbfa569[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,806 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@8867672[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:05:31,807 DEBUG [qtp849731105-1273][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@45ef7650[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,807 DEBUG [qtp849731105-1273][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@45ef7650[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,807 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@45ef7650[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,808 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@8867672[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:05:31,808 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@8867672[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:05:31,808 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@8867672[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:05:31,808 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@8867672[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:05:31,808 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3bbfa569[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,808 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3bbfa569[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,808 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3bbfa569[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,809 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3bbfa569[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,809 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@67b340dc[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,809 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@296760b4[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:05:31,809 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41fddea8[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:05:31,809 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 12 ms). class=org.cumulus4j.store.test.movie.Rating
16:05:31,809 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@67b340dc[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,809 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@67b340dc[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,809 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
16:05:31,810 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,810 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,812 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
16:05:31,813 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@67b340dc[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,813 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@67b340dc[2,org.cumulus4j.store.test.movie.Rating]
16:05:31,816 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,816 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,833 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,834 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,837 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:31,837 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
16:05:31,837 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,837 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f7efb52[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:31,837 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,837 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
16:05:31,837 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,837 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30d73e41[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:31,838 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
16:05:31,838 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,838 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
16:05:31,838 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,838 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6c433811[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:31,838 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,838 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,838 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
16:05:31,838 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,838 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d11cb49[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:31,838 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
16:05:31,838 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,838 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6490a4b4[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:31,838 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 12
16:05:31,839 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,839 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,842 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 12
16:05:31,842 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6490a4b4[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:05:31,846 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,846 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,846 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,846 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,847 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6d11cb49[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:05:31,852 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,852 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,852 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,853 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,857 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,858 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,863 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,863 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,866 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6c433811[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:05:31,870 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,870 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,871 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,871 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,871 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30d73e41[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:31,876 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,877 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,877 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,877 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,877 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f7efb52[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:05:31,882 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,883 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,883 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,883 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,886 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
16:05:31,886 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
16:05:31,888 DEBUG [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@71ef4c89[3,org.cumulus4j.store.test.movie.Person]
16:05:31,890 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@32272e2e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,891 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@32272e2e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,891 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@71ef4c89[3,org.cumulus4j.store.test.movie.Person]
16:05:31,891 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1865bbad[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:05:31,892 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1865bbad[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:05:31,892 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@71ef4c89[3,org.cumulus4j.store.test.movie.Person]
16:05:31,892 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@32272e2e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,892 DEBUG [qtp849731105-1273][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@32272e2e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,894 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1865bbad[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:05:31,895 DEBUG [qtp849731105-1273][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@71ef4c89[3,org.cumulus4j.store.test.movie.Person]
16:05:31,895 DEBUG [qtp849731105-1273][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@71ef4c89[3,org.cumulus4j.store.test.movie.Person]
16:05:31,896 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@71ef4c89[3,org.cumulus4j.store.test.movie.Person]
16:05:31,896 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@32272e2e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,896 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@32272e2e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,896 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@32272e2e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,896 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@32272e2e[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,897 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1865bbad[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:05:31,897 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1865bbad[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:05:31,897 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1865bbad[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:05:31,897 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1865bbad[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:05:31,897 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@62f3c97a[3,org.cumulus4j.store.test.movie.Person]
16:05:31,897 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@73309b56[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:05:31,897 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7c26662e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:05:31,897 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 11 ms). class=org.cumulus4j.store.test.movie.Person
16:05:31,897 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@62f3c97a[3,org.cumulus4j.store.test.movie.Person]
16:05:31,898 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@62f3c97a[3,org.cumulus4j.store.test.movie.Person]
16:05:31,898 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
16:05:31,898 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,898 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,901 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
16:05:31,901 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@62f3c97a[3,org.cumulus4j.store.test.movie.Person]
16:05:31,901 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@62f3c97a[3,org.cumulus4j.store.test.movie.Person]
16:05:31,904 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,905 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,911 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,911 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,914 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:31,918 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,918 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,919 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@b
16:05:31,919 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,919 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
16:05:31,924 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,924 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,925 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,933 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,933 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,936 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:31,940 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,940 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,941 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@b]
16:05:31,941 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,941 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30d73e41[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:31,941 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
16:05:31,944 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,944 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,945 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:31,945 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30d73e41[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:31,950 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,950 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,950 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,951 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,951 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@30d73e41[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:05:31,955 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,956 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,962 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,962 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:31,962 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:31,963 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1051524604 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:32,028 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:32,029 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:32,031 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:32,032 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:32,035 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:32,036 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:32,037 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,037 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,037 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,037 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:32,038 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:32,041 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:32,042 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:32,043 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,043 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,043 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,043 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:32,043 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:32,047 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:32,047 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:32,048 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,048 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,048 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,048 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:32,049 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:32,052 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:32,053 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:32,053 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,053 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,053 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,054 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:32,054 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:32,058 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:32,059 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:32,059 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,060 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,060 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,060 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:05:32,060 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:05:32,063 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:05:32,064 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@411695484 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:05:32,065 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,065 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
16:05:32,065 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ce530c7[1,org.cumulus4j.store.test.movie.Movie]
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 376.944 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
16:05:34,216 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
16:05:34,216 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
|
Help us localize this page