|  Console Output
Skipping 1,682 KB.. Full Log:54,821 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@166c244c[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:10:54,821 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,821 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
16:10:54,821 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,821 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a23f12[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:10:54,821 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
16:10:54,822 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,822 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
16:10:54,822 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,822 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1db1f2bc[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:10:54,822 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,822 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,822 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
16:10:54,822 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,822 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@25d4e9fb[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:10:54,822 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
16:10:54,822 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,822 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@72940c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:10:54,822 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 7
16:10:54,822 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,823 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,825 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 7
16:10:54,825 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@72940c81[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:10:54,829 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,829 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,830 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,830 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,830 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@25d4e9fb[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:10:54,835 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,835 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,835 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,836 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,840 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,840 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,846 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,846 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,848 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1db1f2bc[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:10:54,852 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,852 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,853 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,853 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,854 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a23f12[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:10:54,858 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,859 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,859 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,859 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,860 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@166c244c[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:10:54,864 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,865 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,865 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,865 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,869 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
16:10:54,869 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
16:10:54,871 DEBUG [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@50df67ad[3,org.cumulus4j.store.test.movie.Person]
16:10:54,873 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3247a871[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,874 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3247a871[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,874 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@50df67ad[3,org.cumulus4j.store.test.movie.Person]
16:10:54,874 DEBUG [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@76b24863[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:10:54,874 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@76b24863[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:10:54,874 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@50df67ad[3,org.cumulus4j.store.test.movie.Person]
16:10:54,875 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3247a871[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,875 DEBUG [qtp849731105-1273][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@3247a871[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,877 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@76b24863[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:10:54,878 DEBUG [qtp849731105-1273][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@50df67ad[3,org.cumulus4j.store.test.movie.Person]
16:10:54,878 DEBUG [qtp849731105-1273][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@50df67ad[3,org.cumulus4j.store.test.movie.Person]
16:10:54,878 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@50df67ad[3,org.cumulus4j.store.test.movie.Person]
16:10:54,878 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3247a871[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,878 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3247a871[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,878 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3247a871[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,878 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3247a871[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,879 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@76b24863[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:10:54,879 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@76b24863[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:10:54,879 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@76b24863[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:10:54,879 DEBUG [qtp849731105-1273][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@76b24863[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:10:54,879 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2d3c366a[3,org.cumulus4j.store.test.movie.Person]
16:10:54,879 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4c188059[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:10:54,879 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5c927a16[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:10:54,880 DEBUG [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 11 ms). class=org.cumulus4j.store.test.movie.Person
16:10:54,880 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2d3c366a[3,org.cumulus4j.store.test.movie.Person]
16:10:54,880 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2d3c366a[3,org.cumulus4j.store.test.movie.Person]
16:10:54,880 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 6
16:10:54,880 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,880 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,883 TRACE [qtp849731105-1273][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 6
16:10:54,883 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2d3c366a[3,org.cumulus4j.store.test.movie.Person]
16:10:54,883 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2d3c366a[3,org.cumulus4j.store.test.movie.Person]
16:10:54,886 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,887 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,892 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,892 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,895 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:10:54,899 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,900 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,900 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@6]
16:10:54,900 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,900 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a23f12[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:10:54,901 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
16:10:54,904 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,904 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,905 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,905 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a23f12[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:10:54,910 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,910 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,910 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,910 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,911 TRACE [qtp849731105-1273][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2a23f12[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:10:54,915 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,915 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,921 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,921 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,922 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,922 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,922 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:10:54,927 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,927 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,928 TRACE [qtp849731105-1273][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@6
16:10:54,928 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,928 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
16:10:54,931 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,931 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:54,932 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:54,939 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:54,939 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@1022783521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:55,011 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:10:55,012 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:10:55,015 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:10:55,015 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:10:55,028 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:55,028 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:55,030 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,030 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,030 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,031 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:10:55,031 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:10:55,035 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:55,036 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:55,037 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,037 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,037 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,037 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:10:55,038 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:10:55,042 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:55,042 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:55,043 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,043 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,043 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,043 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:10:55,044 TRACE [qtp849731105-1273][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:10:55,048 TRACE [qtp849731105-1273][CryptoCache] acquireCipherEntry: Found cached Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:10:55,049 TRACE [qtp849731105-1273][CryptoCache] releaseCipherEntry: Releasing Cipher@310569039 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:10:55,051 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,052 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,052 TRACE [qtp849731105-1273][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@4f55e1d3[1,org.cumulus4j.store.test.movie.Movie]
16:10:55,066 DEBUG [qtp2140698269-1413][AbstractService] getAuth: 'Authorization' header: Basic ZGV2aWw6dGVzdHRlc3R0ZXN0
16:10:55,066 DEBUG [qtp2140698269-1413][CryptoSessionService] open: authUserName='devil' cryptoSessionID='test-i2j40yco-1chsgcgwhuf9t_ybrpnzle*1*0j7eqy'
16:10:56,156 INFO [qtp849731105-1276][TestUtil] loadProperties: File /home/tomcat/cumulus4j-test-datanucleus.properties does not exist. Thus not overriding any settings with user-specific ones.
16:10:57,639 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
16:10:57,640 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
16:10:57,757 WARN [qtp849731105-1276][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:10:57,758 WARN [qtp849731105-1276][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:10:58,857 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 0 users left in cache.
16:10:58,967 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 1 users left in cache.
16:10:59,148 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 1 sessions left.
16:11:00,880 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 0 sessions left.
16:11:00,995 DEBUG [qtp849731105-1241][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:11:00,997 DEBUG [Thread-507][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,000 DEBUG [qtp849731105-1273][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,002 DEBUG [qtp849731105-1273][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:11:01,038 DEBUG [qtp849731105-1242][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Returning request: null
16:11:01,048 DEBUG [Thread-513][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,048 DEBUG [qtp849731105-1239][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: null
16:11:01,050 DEBUG [Thread-517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,054 DEBUG [qtp849731105-1261][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:11:01,056 DEBUG [qtp849731105-1261][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,057 DEBUG [Thread-505][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,060 DEBUG [qtp849731105-1241][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,062 DEBUG [qtp849731105-1241][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Entered.
16:11:01,064 DEBUG [qtp849731105-1239][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,069 DEBUG [qtp849731105-1278][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:11:01,070 DEBUG [Thread-508][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,071 DEBUG [qtp849731105-1239][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:11:01,072 DEBUG [qtp849731105-1261][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:11:01,073 DEBUG [qtp849731105-1242][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,075 DEBUG [qtp849731105-1275][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:11:01,075 DEBUG [qtp849731105-1242][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:11:01,078 DEBUG [Thread-509][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,080 DEBUG [qtp849731105-1278][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,082 DEBUG [qtp849731105-1278][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:11:01,084 DEBUG [qtp849731105-1277][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Returning request: null
16:11:01,086 DEBUG [Thread-512][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,089 DEBUG [qtp849731105-1275][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,092 DEBUG [qtp849731105-1275][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Entered.
16:11:01,107 DEBUG [qtp849731105-1243][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Returning request: null
16:11:01,108 DEBUG [Thread-511][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,111 DEBUG [qtp849731105-1277][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,113 DEBUG [qtp849731105-1277][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Entered.
16:11:01,171 DEBUG [qtp849731105-1453][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: null
16:11:01,172 DEBUG [Thread-520][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,175 DEBUG [qtp849731105-1243][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,177 DEBUG [qtp849731105-1274][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: null
16:11:01,178 DEBUG [Thread-519][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,180 DEBUG [qtp849731105-1243][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:11:01,182 DEBUG [qtp849731105-1453][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,185 DEBUG [qtp849731105-1453][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:11:01,223 DEBUG [qtp849731105-1284][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: null
16:11:01,225 DEBUG [Thread-521][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:01,228 DEBUG [qtp849731105-1274][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:01,231 DEBUG [qtp849731105-1274][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:11:02,154 DEBUG [qtp849731105-1454][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:11:02,155 DEBUG [Thread-506][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:02,158 DEBUG [qtp849731105-1454][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:02,160 DEBUG [qtp849731105-1454][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:11:04,363 INFO [qtp849731105-1276][Cumulus4jStoreManager] ====================== Cumulus4j ======================
16:11:04,363 INFO [qtp849731105-1276][Cumulus4jStoreManager] Bundle: org.cumulus4j.store - Version: 1.2.1.SNAPSHOT
16:11:04,363 INFO [qtp849731105-1276][Cumulus4jStoreManager] =======================================================
16:11:04,364 ERROR [qtp849731105-1276][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.GeneratedMethodAccessor417.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at javax.jdo.JDOHelper$16.run(JDOHelper.java:1970)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1965)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1171)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:813)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:702)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManagerFactory(TestService.java:59)
at org.cumulus4j.integrationtest.webapp.TestService.getPersistenceManager(TestService.java:72)
at org.cumulus4j.integrationtest.webapp.TestService.testPost(TestService.java:93)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$TypeOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:185)
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288)
at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108)
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469)
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349)
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339)
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537)
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:546)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1283)
at org.cumulus4j.keymanager.back.shared.AjaxHeadersFilter.doFilter(AjaxHeadersFilter.java:33)
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1254)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:481)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:119)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:516)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:230)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:956)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:411)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:188)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:891)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:117)
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:247)
at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:151)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:114)
at org.eclipse.jetty.server.Server.handle(Server.java:353)
at org.eclipse.jetty.server.HttpConnection.handleRequest(HttpConnection.java:598)
at org.eclipse.jetty.server.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:1059)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:590)
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212)
at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:427)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:510)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34)
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:450)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.ClassCastException: org.cumulus4j.store.Cumulus4jStoreManager cannot be cast to org.datanucleus.store.rdbms.RDBMSStoreManager
at org.datanucleus.store.rdbms.autostart.SchemaAutoStarter.<init>(SchemaAutoStarter.java:68)
... 69 more
Reading Movies before writing:
16:11:04,366 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Movie
16:11:04,367 INFO [qtp849731105-1276][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
16:11:04,368 TRACE [qtp849731105-1276][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle*1*0j7eqy
16:11:04,368 INFO [qtp849731105-1276][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
16:11:04,429 INFO [qtp849731105-1276][MinimumCumulus4jVersion] version=10100001
16:11:04,431 INFO [qtp849731105-1276][MinimumCumulus4jVersion] version=10100001
16:11:04,431 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Movie
16:11:04,436 DEBUG [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,445 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@34e2589b[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,455 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@31476b05[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:11:04,463 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@34e2589b[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,463 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@34e2589b[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,463 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,463 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5f24492d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,465 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@69d620e4[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:11:04,466 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f24492d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,466 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f24492d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,466 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,466 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@728c857b[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:11:04,467 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@728c857b[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:11:04,472 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,472 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@6acf29[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,473 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6acf29[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,473 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,474 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@53d05c41[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,475 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1ee82511[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:11:04,476 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@53d05c41[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,476 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@53d05c41[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,476 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,476 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@41377dfc[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:11:04,477 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41377dfc[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:11:04,481 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,481 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@1104c8ca[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,483 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@46d2a681[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:11:04,483 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1104c8ca[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,484 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1104c8ca[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,484 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,484 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@2f2ed70c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,485 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2f2ed70c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,489 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,489 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@17cb6249[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,491 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@5783c24a[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:11:04,492 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@17cb6249[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,494 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@17cb6249[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,495 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,496 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@34e2589b[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,496 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f24492d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,496 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@728c857b[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:11:04,496 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6acf29[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,496 DEBUG [qtp849731105-1276][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@6acf29[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,499 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@53d05c41[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,504 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41377dfc[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:11:04,504 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1104c8ca[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,505 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2f2ed70c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,506 DEBUG [qtp849731105-1276][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@2f2ed70c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,508 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@17cb6249[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,511 DEBUG [qtp849731105-1276][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,515 DEBUG [qtp849731105-1276][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,515 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@260623ce[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,516 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@728c857b[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:11:04,516 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@728c857b[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:11:04,516 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@728c857b[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:11:04,516 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@728c857b[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:11:04,516 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@2f2ed70c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,517 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@2f2ed70c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,521 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@2f2ed70c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,521 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@2f2ed70c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,522 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5f24492d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,522 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5f24492d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,522 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5f24492d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,522 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@69d620e4[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:11:04,522 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@69d620e4[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:11:04,523 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@69d620e4[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:11:04,523 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@69d620e4[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:11:04,523 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5f24492d[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,523 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@53d05c41[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,523 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@53d05c41[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,523 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@53d05c41[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,524 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1ee82511[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:11:04,524 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1ee82511[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:11:04,524 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1ee82511[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:11:04,524 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1ee82511[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:11:04,524 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@53d05c41[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,525 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@6acf29[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,531 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@6acf29[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,531 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6acf29[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,531 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@6acf29[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,532 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@34e2589b[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,532 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@34e2589b[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,532 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@34e2589b[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,532 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@31476b05[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:11:04,532 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@31476b05[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:11:04,533 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@31476b05[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:11:04,533 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@31476b05[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:11:04,533 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@34e2589b[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,533 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@41377dfc[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:11:04,533 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@41377dfc[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:11:04,534 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@41377dfc[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:11:04,534 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@41377dfc[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:11:04,534 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@1104c8ca[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,534 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@1104c8ca[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,534 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@1104c8ca[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,535 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@46d2a681[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:11:04,535 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@46d2a681[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:11:04,535 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@46d2a681[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:11:04,535 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@46d2a681[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:11:04,535 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@1104c8ca[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,536 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@17cb6249[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,536 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@17cb6249[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,536 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@17cb6249[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,537 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@5783c24a[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:11:04,537 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@5783c24a[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:11:04,537 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@5783c24a[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:11:04,537 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@5783c24a[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:11:04,537 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@17cb6249[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,541 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:11:04,542 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4e78b054[5,org.cumulus4j.store.test.movie.Movie#movieID[primary]]
16:11:04,542 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@621d05f6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:11:04,542 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7797e3fa[4,org.cumulus4j.store.test.movie.Movie#languages[collectionElement]]
16:11:04,542 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7effbe8c[12,org.cumulus4j.store.test.movie.Movie#tagLine[primary]]
16:11:04,542 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@48371a77[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:11:04,542 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@19aa9fab[8,org.cumulus4j.store.test.movie.Movie#producedBy[collectionElement]]
16:11:04,542 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10d8a0b7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:11:04,542 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@7e1f5704[2,org.cumulus4j.store.test.movie.Movie#directedBy[collectionElement]]
16:11:04,543 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3b8a084c[6,org.cumulus4j.store.test.movie.Movie#name[primary]]
16:11:04,543 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6326d41d[9,org.cumulus4j.store.test.movie.Movie#rating[primary]]
16:11:04,543 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a2feec6[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:11:04,543 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@50e50e63[11,org.cumulus4j.store.test.movie.Movie#starring[collectionElement]]
16:11:04,543 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e13af12[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:11:04,543 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@4e4aff33[14,org.cumulus4j.store.test.movie.Movie#writtenBy[collectionElement]]
16:11:04,543 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 176 ms). class=org.cumulus4j.store.test.movie.Movie
16:11:04,544 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:11:04,547 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:11:04,548 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:11:04,564 TRACE [qtp849731105-1276][CryptoCache] getKeyData: No cached key with keyID=1 found.
16:11:04,564 INFO [qtp849731105-1276][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
16:11:15,926 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
16:11:15,926 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
16:11:23,165 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
16:11:23,165 INFO [CryptoCache][CryptoCache] getCryptoCacheEntryExpiryAgeMSec: Property 'cumulus4j.CryptoCache.entryExpiryAge' cannot be read, because NucleusContext was garbage-collected. Using fallback value 300000.
16:11:23,165 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyEncryptionKeyEntry (1 left).
16:11:23,165 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyDecrypterEntry (1 left).
16:11:23,165 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyEntry (1 left).
16:11:23,165 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheCipherEntry (2 left).
16:11:23,165 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of empty List<CryptoCacheCipherEntry> (2 non-empty lists left).
16:11:33,834 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
16:11:39,443 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
16:11:39,443 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
16:11:49,534 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 1 users left in cache.
16:11:49,714 INFO [SessionManager][SessionManager$ExpireSessionTimerTask] run: Expiring session: userName='devil' cryptoSessionID='test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug*1*0qlzab'.
16:11:49,714 DEBUG [SessionManager][CachedMasterKey] clear: Clearing for userName='devil'.
16:11:49,715 DEBUG [SessionManager][MasterKey] clear: Clearing org.cumulus4j.keystore.MasterKey@66f12209
16:11:49,715 DEBUG [SessionManager][Session] destroy: Destroying session for userName='devil' cryptoSessionID='test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug*1*0qlzab'.
16:11:49,715 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 0 sessions left.
16:11:51,015 DEBUG [qtp849731105-1240][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Returning request: null
16:11:51,017 DEBUG [Thread-515][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:51,020 DEBUG [qtp849731105-1468][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:51,025 DEBUG [qtp849731105-1468][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Entered.
16:11:51,215 DEBUG [qtp849731105-1464][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Returning request: null
16:11:51,227 DEBUG [Thread-514][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:51,231 DEBUG [qtp849731105-1240][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:51,233 DEBUG [qtp849731105-1240][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Entered.
16:11:54,024 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
16:11:54,139 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
16:11:54,140 INFO [CryptoCache][CryptoCache] getCryptoCacheEntryExpiryAgeMSec: Property 'cumulus4j.CryptoCache.entryExpiryAge' is not set. Using default value 1800000.
16:11:54,140 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyEncryptionKeyEntry (1 left).
16:11:54,140 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyDecrypterEntry (1 left).
16:11:54,140 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheKeyEntry (1 left).
16:11:54,140 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of CryptoCacheCipherEntry (2 left).
16:11:54,140 DEBUG [CryptoCache][CryptoCache] removeExpiredEntries: Removed 0 instances of empty List<CryptoCacheCipherEntry> (2 non-empty lists left).
16:11:54,372 DEBUG [qtp849731105-1460][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: null
16:11:54,374 DEBUG [Thread-518][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:11:54,376 DEBUG [qtp849731105-1460][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:11:54,378 DEBUG [qtp849731105-1460][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:11:58,858 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 0 users left in cache.
16:11:58,967 DEBUG [KeyStore][KeyStore$ExipreCacheEntryTimerTask] run: 1 users left in cache.
16:11:59,148 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 1 sessions left.
16:11:59,928 DEBUG [qtp849731105-1276][MessageBrokerPMF] [artt1z] _query[requestID=esnmfgsg315m9wzror4sgqzzz]: Entered with request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@bb316220[esnmfgsg315m9wzror4sgqzzz,test-i2j40yco-1chsgcgwhuf9t_ybrpnzle*1*0j7eqy]
16:11:59,979 DEBUG [qtp849731105-1276][MessageBrokerPMF] [artt1z] _query[requestID=esnmfgsg315m9wzror4sgqzzz]: Request persisted.
16:11:59,997 DEBUG [qtp849731105-1453][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: org.cumulus4j.keymanager.back.shared.GetKeyRequest@bb316220[esnmfgsg315m9wzror4sgqzzz,test-i2j40yco-1chsgcgwhuf9t_ybrpnzle*1*0j7eqy]
16:11:59,999 DEBUG [qtp849731105-1453][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyRequest matching=true
16:11:59,999 ERROR [qtp849731105-1460][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@57d41e7a" (id="esnmfgsg315m9wzror4sgqzzz") 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:12:00,001 DEBUG [Thread-519][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
16:12:00,002 WARN [qtp849731105-1460][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@57d41e7a" (id="esnmfgsg315m9wzror4sgqzzz") 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@bb316220
16:12:00,003 ERROR [qtp849731105-1261][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@27a57d43" (id="esnmfgsg315m9wzror4sgqzzz") 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:12:00,004 WARN [qtp849731105-1261][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@27a57d43" (id="esnmfgsg315m9wzror4sgqzzz") 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@bb316220
16:12:00,011 DEBUG [Thread-519][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetKeyResponse matching=true
16:12:00,014 DEBUG [qtp849731105-1464][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:00,016 DEBUG [qtp849731105-1464][MessageBrokerPMF] [artt1z] _pushResponse[requestID=esnmfgsg315m9wzror4sgqzzz]: Entered.
16:12:00,108 DEBUG [qtp849731105-1464][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:12:00,473 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Created new Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
16:12:00,475 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,476 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,476 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,476 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,476 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:00,477 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:00,483 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,484 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,485 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,485 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,485 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,485 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:00,486 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:00,489 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,490 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,491 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,491 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,491 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,491 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:00,491 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:00,495 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,495 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,496 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,496 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,496 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
* MMM 1416064196159
* MMM 1416064224160
* MMM 1416064233936
* MMM 1416064254820
16:12:00,497 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:00,499 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:00,499 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
16:12:00,499 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,499 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e13af12[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:12:00,499 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,499 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
16:12:00,499 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,500 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a2feec6[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:12:00,500 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
16:12:00,500 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,500 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
16:12:00,500 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,500 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@48371a77[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:12:00,500 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,500 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,500 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
16:12:00,500 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,500 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@621d05f6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:12:00,500 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
16:12:00,500 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,500 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10d8a0b7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:12:00,500 TRACE [qtp849731105-1276][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
16:12:00,501 INFO [qtp849731105-1276][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is not set. Using default algorithm 'Twofish/GCM/NoPadding'.
16:12:00,501 INFO [qtp849731105-1276][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is not set. Using default MAC algorithm 'NONE'.
16:12:00,501 DEBUG [qtp849731105-1276][MessageBrokerPMF] [artt1z] _query[requestID=b66o2cww0izi0c91hz8n31iae]: Entered with request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@8546e936[b66o2cww0izi0c91hz8n31iae,test-i2j40yco-1chsgcgwhuf9t_ybrpnzle*1*0j7eqy]
16:12:00,563 DEBUG [qtp849731105-1276][MessageBrokerPMF] [artt1z] _query[requestID=b66o2cww0izi0c91hz8n31iae]: Request persisted.
16:12:00,586 DEBUG [qtp849731105-1261][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest@8546e936[b66o2cww0izi0c91hz8n31iae,test-i2j40yco-1chsgcgwhuf9t_ybrpnzle*1*0j7eqy]
16:12:00,586 ERROR [qtp849731105-1464][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@1353cd76" (id="b66o2cww0izi0c91hz8n31iae") 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:12:00,586 WARN [qtp849731105-1464][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@1353cd76" (id="b66o2cww0izi0c91hz8n31iae") 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@8546e936
16:12:00,587 DEBUG [qtp849731105-1261][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyRequest matching=true
16:12:00,587 ERROR [qtp849731105-1460][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@5e090707" (id="b66o2cww0izi0c91hz8n31iae") 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:12:00,588 WARN [qtp849731105-1460][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@5e090707" (id="b66o2cww0izi0c91hz8n31iae") 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@8546e936
16:12:00,588 ERROR [qtp849731105-1243][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@1b0be48f" (id="b66o2cww0izi0c91hz8n31iae") 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:12:00,589 WARN [qtp849731105-1243][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@1b0be48f" (id="b66o2cww0izi0c91hz8n31iae") 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@8546e936
16:12:00,589 DEBUG [Thread-517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Request matching=true
16:12:00,590 ERROR [qtp849731105-1274][Persistence] Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@a2cd86a" (id="b66o2cww0izi0c91hz8n31iae") 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:12:00,590 WARN [qtp849731105-1274][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: javax.jdo.JDOOptimisticVerificationException: Transaction failed to commit
NestedThrowables:
javax.jdo.JDOOptimisticVerificationException: Object "org.cumulus4j.store.crypto.keymanager.messagebroker.pmf.PendingRequest@a2cd86a" (id="b66o2cww0izi0c91hz8n31iae") 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@8546e936
16:12:00,603 DEBUG [Thread-517][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.GetActiveEncryptionKeyResponse matching=true
16:12:00,607 DEBUG [qtp849731105-1453][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:00,613 DEBUG [qtp849731105-1453][MessageBrokerPMF] [artt1z] _pushResponse[requestID=b66o2cww0izi0c91hz8n31iae]: Entered.
16:12:00,657 DEBUG [qtp849731105-1453][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:12:00,880 DEBUG [SessionManager][SessionManager$ExpireSessionTimerTask] run: 0 sessions left.
16:12:00,940 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Created new Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with key and IV.
16:12:00,941 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,950 TRACE [qtp849731105-1276][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
16:12:00,950 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,950 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:00,950 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10d8a0b7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:12:00,956 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,956 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,956 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,957 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,957 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@621d05f6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:12:00,962 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,962 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,962 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,963 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,968 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,968 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,981 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,981 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,991 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@48371a77[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:12:00,995 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,995 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,995 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:00,995 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:00,996 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a2feec6[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:12:01,000 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,001 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,001 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,001 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,001 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e13af12[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:12:01,006 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,007 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,007 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,007 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,010 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Rating
16:12:01,010 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Rating
16:12:01,012 DEBUG [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@1b6b0b13[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,014 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@722b4714[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,015 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@722b4714[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,015 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1b6b0b13[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,015 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@3fefb189[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:12:01,016 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3fefb189[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:12:01,016 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1b6b0b13[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,016 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@722b4714[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,016 DEBUG [qtp849731105-1276][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@722b4714[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,019 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3fefb189[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:12:01,020 DEBUG [qtp849731105-1276][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@1b6b0b13[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,020 DEBUG [qtp849731105-1276][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@1b6b0b13[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,020 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1b6b0b13[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,020 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@3fefb189[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:12:01,020 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@3fefb189[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:12:01,020 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@3fefb189[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:12:01,020 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@3fefb189[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:12:01,021 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@722b4714[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,021 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@722b4714[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,021 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@722b4714[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,021 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@722b4714[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,021 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1a8a5f96[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,021 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@72897e76[16,org.cumulus4j.store.test.movie.Rating#ratingID[primary]]
16:12:01,021 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@20cdafb9[15,org.cumulus4j.store.test.movie.Rating#name[primary]]
16:12:01,021 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 11 ms). class=org.cumulus4j.store.test.movie.Rating
16:12:01,022 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1a8a5f96[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,022 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1a8a5f96[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,022 TRACE [qtp849731105-1276][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
16:12:01,022 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,022 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,025 TRACE [qtp849731105-1276][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
16:12:01,025 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1a8a5f96[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,025 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@1a8a5f96[2,org.cumulus4j.store.test.movie.Rating]
16:12:01,028 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,028 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,030 DEBUG [qtp849731105-1273][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:12:01,031 DEBUG [Thread-507][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,034 DEBUG [qtp849731105-1261][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,037 DEBUG [qtp849731105-1261][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:12:01,038 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,038 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,041 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,041 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=8 value=[]
16:12:01,041 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,041 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e13af12[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:12:01,041 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,041 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[]
16:12:01,041 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,041 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a2feec6[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:12:01,041 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=null
16:12:01,041 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,041 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=4 value=[]
16:12:01,042 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,042 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@48371a77[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:12:01,042 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,042 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,042 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=1 value=[]
16:12:01,042 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,054 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@621d05f6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:12:01,054 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=0 value=[]
16:12:01,054 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,055 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10d8a0b7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:12:01,056 TRACE [qtp849731105-1276][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 12
16:12:01,056 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,056 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,059 TRACE [qtp849731105-1276][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 12
16:12:01,059 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@10d8a0b7[1,org.cumulus4j.store.test.movie.Movie#directedBy[primary]]
16:12:01,063 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,063 DEBUG [qtp849731105-1241][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Returning request: null
16:12:01,063 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,064 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,064 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,064 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@621d05f6[3,org.cumulus4j.store.test.movie.Movie#languages[primary]]
16:12:01,065 DEBUG [Thread-513][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,068 DEBUG [qtp849731105-1273][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,070 DEBUG [qtp849731105-1273][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Entered.
16:12:01,071 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,071 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,071 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,072 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,076 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,076 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,082 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,082 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,085 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@48371a77[7,org.cumulus4j.store.test.movie.Movie#producedBy[primary]]
16:12:01,088 DEBUG [qtp849731105-1242][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:12:01,089 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,089 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,090 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,090 DEBUG [Thread-508][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,090 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,090 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a2feec6[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:12:01,093 DEBUG [qtp849731105-1241][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,095 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,095 DEBUG [qtp849731105-1241][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:12:01,096 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,097 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,097 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,097 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6e13af12[13,org.cumulus4j.store.test.movie.Movie#writtenBy[primary]]
16:12:01,102 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,103 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,103 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,103 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,105 DEBUG [qtp849731105-1278][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:12:01,106 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: begin loading. class=org.cumulus4j.store.test.movie.Person
16:12:01,106 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] registerClass: clazz=org.cumulus4j.store.test.movie.Person
16:12:01,107 DEBUG [Thread-509][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,110 DEBUG [qtp849731105-1242][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,112 DEBUG [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta == null => populating. this=org.cumulus4j.store.model.ClassMeta@68dd7816[3,org.cumulus4j.store.test.movie.Person]
16:12:01,113 DEBUG [qtp849731105-1242][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:12:01,114 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@54c29d13[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,115 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@54c29d13[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,115 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@68dd7816[3,org.cumulus4j.store.test.movie.Person]
16:12:01,115 DEBUG [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta == null => populating. this=org.cumulus4j.store.model.FieldMeta@e26f02e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:12:01,116 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@e26f02e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:12:01,116 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@68dd7816[3,org.cumulus4j.store.test.movie.Person]
16:12:01,116 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@54c29d13[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,116 DEBUG [qtp849731105-1276][FieldMeta] getEmbeddedClassMeta: this.embeddedClassMetaLoaded == false => loading. this=org.cumulus4j.store.model.FieldMeta@54c29d13[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,118 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@e26f02e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:12:01,119 DEBUG [qtp849731105-1276][ClassMeta] jdoPostDetach: attached=org.cumulus4j.store.model.ClassMeta@68dd7816[3,org.cumulus4j.store.test.movie.Person]
16:12:01,119 DEBUG [qtp849731105-1276][ClassMeta] jdoPostDetach: Detaching this.fieldName2FieldMeta: attached=org.cumulus4j.store.model.ClassMeta@68dd7816[3,org.cumulus4j.store.test.movie.Person]
16:12:01,119 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@68dd7816[3,org.cumulus4j.store.test.movie.Person]
16:12:01,120 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@54c29d13[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,121 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@54c29d13[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,121 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@54c29d13[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,121 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@54c29d13[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,121 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: attached=org.cumulus4j.store.model.FieldMeta@e26f02e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:12:01,121 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.role2SubFieldMeta: attached=org.cumulus4j.store.model.FieldMeta@e26f02e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:12:01,121 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@e26f02e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:12:01,121 DEBUG [qtp849731105-1276][FieldMeta] jdoPostDetach: Detaching this.embeddedClassMeta: attached=org.cumulus4j.store.model.FieldMeta@e26f02e[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:12:01,121 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52a71e65[3,org.cumulus4j.store.test.movie.Person]
16:12:01,122 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@59bca347[17,org.cumulus4j.store.test.movie.Person#name[primary]]
16:12:01,122 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@6f83b857[18,org.cumulus4j.store.test.movie.Person#personID[primary]]
16:12:01,122 DEBUG [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: end loading (took 16 ms). class=org.cumulus4j.store.test.movie.Person
16:12:01,122 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52a71e65[3,org.cumulus4j.store.test.movie.Person]
16:12:01,122 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52a71e65[3,org.cumulus4j.store.test.movie.Person]
16:12:01,122 TRACE [qtp849731105-1276][Cumulus4jPersistenceHandler] insertObject: Created new DataEntry for: 11
16:12:01,122 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,122 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,125 TRACE [qtp849731105-1276][Cumulus4jPersistenceHandler] insertObject: Persisted new non-embedded DataEntry for: 11
16:12:01,125 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52a71e65[3,org.cumulus4j.store.test.movie.Person]
16:12:01,125 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@52a71e65[3,org.cumulus4j.store.test.movie.Person]
16:12:01,128 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,128 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,135 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,135 DEBUG [qtp849731105-1239][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Returning request: null
16:12:01,135 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,136 DEBUG [Thread-505][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,138 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,139 DEBUG [qtp849731105-1278][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,142 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,142 DEBUG [qtp849731105-1278][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3x0m4--1h1u20pua6vte_ihxxt811]: Entered.
16:12:01,142 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,143 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=5 value=org.cumulus4j.store.test.movie.Rating@b
16:12:01,143 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,143 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Rating
16:12:01,144 DEBUG [qtp849731105-1275][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Returning request: null
16:12:01,145 DEBUG [Thread-512][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,148 DEBUG [qtp849731105-1239][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,148 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,149 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,149 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,150 DEBUG [qtp849731105-1239][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Entered.
16:12:01,157 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,157 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,161 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,163 DEBUG [qtp849731105-1277][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Returning request: null
16:12:01,165 DEBUG [Thread-511][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,167 DEBUG [qtp849731105-1275][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,170 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,170 DEBUG [qtp849731105-1275][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j3zgq8--1nw7kl06hq0it_qzgef4ug]: Entered.
16:12:01,170 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,171 TRACE [qtp849731105-1276][StoreFieldManager] storeObjectField: classMeta.className=org.cumulus4j.store.test.movie.Movie fieldNumber=6 value=[org.cumulus4j.store.test.movie.Person@b]
16:12:01,171 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,171 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a2feec6[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:12:01,171 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Person
16:12:01,174 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,175 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,175 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,175 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a2feec6[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:12:01,180 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,181 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,181 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,182 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,182 TRACE [qtp849731105-1276][FieldMeta] getRole2SubFieldMeta: this.role2SubFieldMeta != null (already populated). this=org.cumulus4j.store.model.FieldMeta@a2feec6[10,org.cumulus4j.store.test.movie.Movie#starring[primary]]
16:12:01,186 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,186 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,192 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,193 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,193 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,193 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@162551998 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,218 DEBUG [qtp849731105-1243][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: null
16:12:01,219 DEBUG [Thread-520][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,221 DEBUG [qtp849731105-1277][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,223 DEBUG [qtp849731105-1277][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:12:01,266 DEBUG [qtp849731105-1274][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Returning request: null
16:12:01,267 DEBUG [Thread-521][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.NullResponse matching=true
16:12:01,271 DEBUG [qtp849731105-1243][JAXBContextResolver] getContext: objectType=org.cumulus4j.keymanager.back.shared.Response matching=true
16:12:01,275 DEBUG [qtp849731105-1243][MessageBrokerPMF] [artt1z] _pollRequest[cryptoSessionIDPrefix=test-i2j40yco-1chsgcgwhuf9t_ybrpnzle]: Entered.
16:12:01,289 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,290 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,293 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:01,294 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,300 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,301 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,302 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,303 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,303 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,303 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:01,304 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,309 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,310 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,311 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,311 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,311 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,311 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:01,312 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,317 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,320 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,321 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,321 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,321 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,322 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:01,322 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,327 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,328 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,329 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,329 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,329 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,330 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:01,330 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,337 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,338 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,339 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,340 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,340 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,340 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClassID: found cache entry. classID=1
16:12:01,341 TRACE [qtp849731105-1276][Cumulus4jStoreManager] getClassMetaByClass: found cache entry. class=org.cumulus4j.store.test.movie.Movie
16:12:01,346 TRACE [qtp849731105-1276][CryptoCache] acquireCipherEntry: Found cached Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING and keyID=1. Initialising it with new IV (without key).
16:12:01,347 TRACE [qtp849731105-1276][CryptoCache] releaseCipherEntry: Releasing Cipher@1995040332 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/GCM/NOPADDING keyID=1.
16:12:01,348 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,348 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
16:12:01,348 TRACE [qtp849731105-1276][ClassMeta] getFieldName2FieldMeta: this.fieldName2FieldMeta != null (already populated). this=org.cumulus4j.store.model.ClassMeta@2ba30555[1,org.cumulus4j.store.test.movie.Movie]
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 366.662 sec
Results :
Tests run: 3, Failures: 0, Errors: 0, Skipped: 0
[JENKINS] Recording test results
[INFO]
[INFO] --- maven-source-plugin:2.1.2:jar-no-fork (attach-sources) @ org.cumulus4j.integrationtest.withkeyserver ---
[INFO] No sources in project. Archive not created.
[INFO]
[INFO] --- maven-install-plugin:2.4:install (default-install) @ org.cumulus4j.integrationtest.withkeyserver ---
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.withkeyserver/target/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.withkeyserver/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.jar
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.integrationtest.withkeyserver/pom.xml to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.integrationtest.withkeyserver/1.2.1-SNAPSHOT/org.cumulus4j.integrationtest.withkeyserver-1.2.1-SNAPSHOT.pom
|
Help us localize this page