using org.datanucleus.store.types.converters.SqlDateStringConverter
09:57:27,751 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimeLongConverter
09:57:27,751 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.String using org.datanucleus.store.types.converters.SqlTimeStringConverter
09:57:27,752 DEBUG [main][Persistence] Added converter for java.sql.Timestamp<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimestampLongConverter
09:57:27,752 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
09:57:27,752 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
09:57:27,752 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
09:57:27,753 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
09:57:27,753 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
09:57:27,754 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
09:57:27,755 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
09:57:27,756 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
09:57:27,757 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
09:57:27,758 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
09:57:27,758 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
09:57:27,758 DEBUG [main][Persistence] Type converter support loaded
09:57:27,758 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
09:57:27,758 DEBUG [main][MetaData] Registering listener for metadata initialisation
09:57:27,759 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
09:57:27,761 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
09:57:27,762 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
09:57:27,763 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
09:57:27,764 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
09:57:27,765 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
09:57:27,766 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
09:57:27,767 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
09:57:27,768 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
09:57:27,769 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
09:57:27,770 DEBUG [main][MetaData] Parsing MetaData 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" using handler "jdo" (validation="false")
09:57:27,776 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
09:57:28,440 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
09:57:28,441 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
09:57:28,441 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
09:57:28,469 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
09:57:28,475 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
09:57:28,476 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
09:57:28,477 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
09:57:28,478 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
09:57:28,479 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
09:57:28,480 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
09:57:28,481 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
09:57:28,482 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
09:57:28,483 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
09:57:28,483 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
09:57:28,484 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
09:57:28,485 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
09:57:28,486 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
09:57:28,486 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
09:57:28,487 DEBUG [main][Datastore] Creating StoreManager for datastore
09:57:28,499 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
09:57:28,500 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
09:57:28,501 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
09:57:28,520 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
09:57:37,155 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
09:57:37,156 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
09:57:39,529 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4780223c" opened
09:57:39,537 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:57:39,538 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=BOOLEAN, sql-type=BOOLEAN, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BooleanRDBMSMapping, default=false)
09:57:39,538 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:57:39,539 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Byte (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:57:39,539 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=true)
09:57:39,539 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:57:39,540 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:57:39,540 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Double (jdbc-type=DOUBLE, sql-type=DOUBLE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DoubleRDBMSMapping, default=true)
09:57:39,540 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Double (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=false)
09:57:39,541 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=FLOAT, sql-type=FLOAT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.FloatRDBMSMapping, default=true)
09:57:39,541 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=DOUBLE, sql-type=DOUBLE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DoubleRDBMSMapping, default=false)
09:57:39,541 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=REAL, sql-type=REAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.RealRDBMSMapping, default=false)
09:57:39,541 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=false)
09:57:39,542 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=true)
09:57:39,542 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:57:39,542 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:57:39,543 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=true)
09:57:39,543 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:57:39,543 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=true)
09:57:39,544 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:57:39,544 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:57:39,544 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:57:39,545 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=true)
09:57:39,545 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:57:39,545 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:57:39,546 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=true)
09:57:39,546 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:57:39,546 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:57:39,546 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=LONGVARCHAR, sql-type=LONGVARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.LongVarcharRDBMSMapping, default=false)
09:57:39,547 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=CLOB, sql-type=CLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.ClobRDBMSMapping, default=false)
09:57:39,547 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=BLOB, sql-type=BLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BlobRDBMSMapping, default=false)
09:57:39,548 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NVarcharRDBMSMapping, default=false)
09:57:39,548 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NCharRDBMSMapping, default=false)
09:57:39,548 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigDecimal (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=true)
09:57:39,549 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigDecimal (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:57:39,549 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigInteger (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=true)
09:57:39,550 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=DATE, sql-type=DATE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DateRDBMSMapping, default=true)
09:57:39,550 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=false)
09:57:39,550 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:57:39,550 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:57:39,551 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:57:39,551 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=TIME, sql-type=TIME, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimeRDBMSMapping, default=true)
09:57:39,551 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=false)
09:57:39,551 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:57:39,552 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:57:39,552 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:57:39,552 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=true)
09:57:39,552 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:57:39,553 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:57:39,553 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=true)
09:57:39,553 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=DATE, sql-type=DATE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DateRDBMSMapping, default=false)
09:57:39,553 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:57:39,554 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:57:39,554 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:57:39,554 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=TIME, sql-type=TIME, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimeRDBMSMapping, default=false)
09:57:39,554 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=LONGVARBINARY, sql-type=LONGVARBINARY, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.LongVarBinaryRDBMSMapping, default=true)
09:57:39,555 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=BLOB, sql-type=BLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BlobRDBMSMapping, default=false)
09:57:39,555 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=VARBINARY, sql-type=VARBINARY, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarBinaryRDBMSMapping, default=false)
09:57:39,555 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=true)
09:57:39,556 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:57:39,556 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:57:39,556 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:57:39,556 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:57:39,785 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
09:57:39,785 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
09:57:39,796 DEBUG [main][Datastore] ======================= Datastore =========================
09:57:39,796 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
09:57:39,796 DEBUG [main][Datastore] Datastore : read-write
09:57:39,796 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
09:57:39,797 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
09:57:39,797 DEBUG [main][Datastore] Queries : Timeout=0
09:57:39,797 DEBUG [main][Datastore] ===========================================================
09:57:39,797 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
09:57:39,797 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
09:57:39,797 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
09:57:39,797 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.0l17hehl/derby/cumulus4j;create=true]
09:57:39,797 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.0l17hehl/derby/cumulus4j;create=true]
09:57:39,797 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
09:57:39,797 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
09:57:39,797 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
09:57:39,798 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
09:57:39,798 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
09:57:39,798 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
09:57:39,798 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
09:57:39,798 DEBUG [main][Datastore] Java-Types : string-default-length=255
09:57:39,798 DEBUG [main][Datastore] JDBC-Types : [id=2009], BLOB, CLOB, TIMESTAMP, TIME, DATE, BOOLEAN, VARCHAR, DECIMAL, NUMERIC, CHAR, BINARY, REAL, LONGVARCHAR, FLOAT, LONGVARBINARY, SMALLINT, VARBINARY, INTEGER, BIGINT, DOUBLE, JAVA_OBJECT
09:57:39,798 DEBUG [main][Datastore] ===========================================================
09:57:39,842 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4780223c" non enlisted to a transaction is being committed.
09:57:39,842 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4780223c" closed
09:57:39,843 DEBUG [main][Datastore] StoreManager now created
09:57:39,843 DEBUG [main][Persistence] ================= NucleusContext ===============
09:57:39,843 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
09:57:39,843 DEBUG [main][Persistence] Persistence API : JDO
09:57:39,843 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
09:57:39,843 DEBUG [main][Persistence] ClassLoading : datanucleus
09:57:39,843 DEBUG [main][Persistence] Persistence : pm-singlethreaded, nontransactional-read, nontransactional-write, reachability-at-commit, copy-on-attach, managed-relations(checked), deletion-policy=JDO2, serverTimeZone=Europe/Berlin
09:57:39,843 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
09:57:39,843 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
09:57:39,844 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
09:57:39,844 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
09:57:39,844 DEBUG [main][Persistence] ================================================
09:57:39,844 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
09:57:39,844 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:57:39,844 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=2e57c092-2a7f-4b32-925c-22ce5847dbd4
09:57:39,845 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:57:39,845 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
09:57:39,846 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@20062487" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@73482b7d" with txn="org.datanucleus.TransactionImpl@71f56ac"
09:57:39,846 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
09:57:39,877 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CBC/PKCS5Padding'. Using this encryption algorithm.
09:57:39,877 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'RC2'. Using this MAC algorithm.
09:57:39,877 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
09:57:39,877 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
09:57:39,877 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
09:57:39,878 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
09:57:39,878 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
09:57:39,879 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
09:57:39,879 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
09:57:39,879 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.encryptionCoordinateSetID] -> Column(s) [ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID] using mapping of type "org.datanucleus.store.rdbms.mapping.java.LongMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
09:57:39,880 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
09:57:39,880 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
09:57:39,880 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.cipherTransformation] -> Column(s) [ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION] using mapping of type "org.datanucleus.store.rdbms.mapping.java.StringMapping" (org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping)
09:57:39,881 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
09:57:39,881 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.macAlgorithm] -> Column(s) [ENCRYPTIONCOORDINATESET.MACALGORITHM] using mapping of type "org.datanucleus.store.rdbms.mapping.java.StringMapping" (org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping)
09:57:39,882 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
09:57:39,883 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
09:57:39,884 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@7c13dd72" opened with isolation level "serializable" and auto-commit=false
09:57:39,884 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@7c13dd72" with isolation "serializable"
09:57:39,953 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
09:57:39,953 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
09:57:39,954 DEBUG [main][Schema] CREATE TABLE ENCRYPTIONCOORDINATESET
(
ENCRYPTIONCOORDINATESETID BIGINT NOT NULL generated always as identity (start with 1),
CIPHERTRANSFORMATION VARCHAR(255) NOT NULL,
MACALGORITHM VARCHAR(255) NOT NULL,
VERSION BIGINT NOT NULL
)
09:57:40,032 DEBUG [main][Schema] Execution Time = 78 ms
09:57:40,032 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
09:57:40,188 DEBUG [main][Schema] Execution Time = 156 ms
09:57:40,226 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@7c13dd72"
09:57:40,250 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@7c13dd72"
09:57:40,250 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@7c13dd72" non enlisted to a transaction is being committed.
09:57:40,251 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@7c13dd72" closed
09:57:40,251 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
09:57:40,254 DEBUG [main][Query] JDOQL Query : Compile Time = 3 ms
09:57:40,254 DEBUG [main][Query] QueryCompilation:
[filter:DyadicExpression{DyadicExpression{PrimaryExpression{this.cipherTransformation} = ParameterExpression{cipherTransformation}} AND DyadicExpression{PrimaryExpression{this.macAlgorithm} = ParameterExpression{macAlgorithm}}}]
[symbols: cipherTransformation type=java.lang.String, this type=org.cumulus4j.store.model.EncryptionCoordinateSet, macAlgorithm type=java.lang.String]
09:57:40,254 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
09:57:40,261 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 7 ms
09:57:40,261 DEBUG [main][Query] SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm Query compiled to datastore query "SELECT 'org.cumulus4j.store.model.EncryptionCoordinateSet' AS NUCLEUS_TYPE,A0.CIPHERTRANSFORMATION,A0.ENCRYPTIONCOORDINATESETID,A0.MACALGORITHM,A0.VERSION FROM ENCRYPTIONCOORDINATESET A0 WHERE A0.CIPHERTRANSFORMATION = ? AND A0.MACALGORITHM = ?"
09:57:40,262 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@66ee0080 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@20062487 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@1363084b]
09:57:40,262 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
09:57:40,263 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4ab57dde" opened with isolation level "read-committed" and auto-commit=false
09:57:40,285 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@689ac9d6"
09:57:40,285 DEBUG [main][Native] SELECT 'org.cumulus4j.store.model.EncryptionCoordinateSet' AS NUCLEUS_TYPE,A0.CIPHERTRANSFORMATION,A0.ENCRYPTIONCOORDINATESETID,A0.MACALGORITHM,A0.VERSION FROM ENCRYPTIONCOORDINATESET A0 WHERE A0.CIPHERTRANSFORMATION = <'TWOFISH/CBC/PKCS5PADDING'> AND A0.MACALGORITHM = <'RC2'>
09:57:40,286 DEBUG [main][Retrieve] Execution Time = 1 ms
09:57:40,287 DEBUG [main][Query] JDOQL Query : Execution Time = 25 ms
09:57:40,288 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4ab57dde" non enlisted to a transaction is being committed.
09:57:40,288 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4ab57dde" closed
09:57:40,288 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@66ee0080 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4ab57dde, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@20062487 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@1363084b]
09:57:40,289 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5"
09:57:40,289 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
09:57:40,291 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" being inserted into table "ENCRYPTIONCOORDINATESET"
09:57:40,291 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1d51055 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@20062487 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@1363084b]
09:57:40,292 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b233d63" opened with isolation level "read-committed" and auto-commit=false
09:57:40,308 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@a93feda" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b233d63"
09:57:40,309 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (MACALGORITHM,CIPHERTRANSFORMATION,VERSION) VALUES (<'RC2'>,<'TWOFISH/CBC/PKCS5PADDING'>,<1>)
09:57:40,314 DEBUG [main][Persist] Execution Time = 4 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@a93feda"
09:57:40,322 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" was inserted in the datastore and was given strategy value of "1"
09:57:40,323 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
09:57:40,323 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@a93feda"
09:57:40,349 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b233d63" non enlisted to a transaction is being committed.
09:57:40,349 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b233d63" closed
09:57:40,349 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1d51055 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b233d63, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@20062487 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@1363084b]
09:57:40,350 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
09:57:40,350 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
09:57:40,351 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
09:57:40,351 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
09:57:40,351 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
09:57:40,352 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@220a347a" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
09:57:40,352 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
09:57:40,353 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
09:57:50,581 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
09:57:50,716 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1976387597 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
09:57:50,830 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1976387597 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
09:57:50,830 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@1976387597 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with new IV (without key).
09:57:50,844 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1976387597 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
09:57:50,844 TRACE [main][CryptoCache] clear: entered
09:57:50,917 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
09:57:50,917 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:57:50,978 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@2016774630 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
09:57:50,989 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@2016774630 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
09:57:50,997 TRACE [main][CryptoCache] clear: entered
09:57:50,997 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
09:57:51,132 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@28888992 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
09:57:51,136 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=114752 actual=114750
09:57:51,143 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@28888992 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
09:57:51,219 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@28888992 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with new IV (without key).
09:57:51,223 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=114752 actual=114750
09:57:51,230 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@28888992 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
09:57:51,230 TRACE [main][CryptoCache] clear: entered
09:57:51,230 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
09:57:51,364 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@205984322 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
09:57:51,368 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=114752 actual=114750
09:57:51,375 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@205984322 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
09:57:51,381 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5 from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@3218eaa5, lifecycle=P_NONTRANS]
09:57:51,381 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
09:57:51,381 DEBUG [main][Cache] Level 1 Cache cleared
09:57:51,381 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@20062487" closed
09:57:51,539 DEBUG [main][Persistence] Unmanaging Persistence of all classes
09:57:51,540 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
09:57:51,540 DEBUG [main][Cache] Level 2 Cache cleared
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 49.98 sec
Running org.cumulus4j.store.crypto.keymanager.test.TestKeyManagerCryptoSession_Twofish_CFB_NoPadding_HMACSHA256
09:57:52,547 WARN [main][MessageBrokerRegistry] setActiveMessageBroker: java.lang.IllegalStateException: An active MessageBroker already exists! Changing the active MessageBroker now is highly discouraged as it may cause errors!
java.lang.IllegalStateException: An active MessageBroker already exists! Changing the active MessageBroker now is highly discouraged as it may cause errors!
at org.cumulus4j.store.crypto.keymanager.messagebroker.MessageBrokerRegistry.setActiveMessageBroker(MessageBrokerRegistry.java:117)
at org.cumulus4j.store.crypto.keymanager.test.MockMessageBroker.setMockSharedInstance(MockMessageBroker.java:41)
at org.cumulus4j.store.crypto.keymanager.test.AbstractKeyManagerCryptoSessionTest.beforeClass(AbstractKeyManagerCryptoSessionTest.java:74)
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 org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:27)
at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:119)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:101)
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 org.apache.maven.surefire.booter.ProviderFactory$ClassLoaderProxy.invoke(ProviderFactory.java:103)
at com.sun.proxy.$Proxy0.invoke(Unknown Source)
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:150)
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcess(SurefireStarter.java:91)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:69)
09:57:52,550 INFO [main][MessageBrokerRegistry] setActiveMessageBroker: New activeMessageBroker=org.cumulus4j.store.crypto.keymanager.test.MockMessageBroker@6b80ce58
09:57:52,555 DEBUG [main][General] Plugin Registry "org.datanucleus.plugin.EclipsePluginRegistry" not found. Falling back to DataNucleus registry. Reason : Class "org.eclipse.core.runtime.RegistryFactory" was not found in the CLASSPATH. Please check your specification and your CLASSPATH..
09:57:52,556 DEBUG [main][General] Using PluginRegistry org.datanucleus.plugin.NonManagedPluginRegistry
09:57:52,563 DEBUG [main][General] Registering bundle org.cumulus4j.store version 1.2.1.SNAPSHOT at URL file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar.
09:57:52,567 DEBUG [main][General] Loading extension points from plug-in file jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/plugin.xml.
09:57:52,569 DEBUG [main][General] Loading extensions from plug-in file jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/plugin.xml.
09:57:52,571 WARN [main][General] Could not find MANIFEST.MF file for plugin file "file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.crypto.keymanager/target/classes/plugin.xml" so ignoring it
09:57:52,573 DEBUG [main][General] Registering bundle org.datanucleus.api.jdo version 3.2.3 at URL file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-api-jdo/3.2.3/datanucleus-api-jdo-3.2.3.jar.
09:57:52,577 DEBUG [main][General] Loading extension points from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-api-jdo/3.2.3/datanucleus-api-jdo-3.2.3.jar!/plugin.xml.
09:57:52,578 DEBUG [main][General] Loading extensions from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-api-jdo/3.2.3/datanucleus-api-jdo-3.2.3.jar!/plugin.xml.
09:57:52,581 DEBUG [main][General] Registering bundle org.datanucleus.store.rdbms version 3.2.3 at URL file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-rdbms/3.2.3/datanucleus-rdbms-3.2.3.jar.
09:57:52,595 DEBUG [main][General] Loading extension points from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-rdbms/3.2.3/datanucleus-rdbms-3.2.3.jar!/plugin.xml.
09:57:52,601 DEBUG [main][General] Loading extensions from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-rdbms/3.2.3/datanucleus-rdbms-3.2.3.jar!/plugin.xml.
09:57:52,607 DEBUG [main][General] Registering bundle org.datanucleus version 3.2.4 at URL file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-core/3.2.4/datanucleus-core-3.2.4.jar.
09:57:52,615 DEBUG [main][General] Loading extension points from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-core/3.2.4/datanucleus-core-3.2.4.jar!/plugin.xml.
09:57:52,628 DEBUG [main][General] Loading extensions from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-core/3.2.4/datanucleus-core-3.2.4.jar!/plugin.xml.
09:57:52,634 INFO [main][Persistence] Property cumulus4j.macAlgorithm unknown - will be ignored
09:57:52,634 INFO [main][Persistence] Property cumulus4j.encryptionAlgorithm unknown - will be ignored
09:57:52,635 DEBUG [main][Persistence] Java types support initialising ...
09:57:52,643 DEBUG [main][Persistence] Java types support loaded : supported java types=java.util.TimeZone, [Ljava.lang.Byte;, [Ljava.lang.Integer;, java.util.SortedMap, char, java.lang.Boolean, [Ljava.lang.Boolean;, java.lang.Long, java.sql.Timestamp, [Ljava.lang.Double;, java.lang.Float, long, float, java.util.BitSet, java.util.Stack, java.math.BigInteger, java.lang.Double, java.util.Vector, byte, java.util.Locale, java.lang.Class, [Ljava.lang.Long;, java.sql.Time, boolean, [Ljava.lang.Short;, java.util.LinkedList, java.util.PriorityQueue, [Ljava.lang.Enum;, int, java.util.List, java.util.TreeMap, java.lang.Integer, java.lang.Short, double, java.lang.Number, java.util.LinkedHashMap, java.sql.Date, [Ljava.util.Locale;, java.util.Arrays$ArrayList, java.lang.Byte, java.util.UUID, [Ljava.lang.String;, [Ljava.util.Date;, java.util.Currency, java.util.Properties, java.util.Calendar, java.util.Map, java.awt.Color, java.util.HashMap, [Ljava.lang.Character;, short, java.util.GregorianCalendar, java.util.TreeSet, java.lang.Character, java.util.SortedSet, java.util.Set, java.util.Collection, java.util.ArrayList, java.lang.StringBuffer, [Ljava.math.BigDecimal;, [B, java.util.Hashtable, [F, java.lang.String, java.net.URI, [C, java.awt.image.BufferedImage, [D, java.util.Date, [I, [J, [Ljava.lang.Number;, [Ljava.lang.Float;, [Ljava.math.BigInteger;, java.net.URL, java.util.HashSet, java.math.BigDecimal, [S, [Z, java.util.Queue, java.lang.Enum, java.util.LinkedHashSet
09:57:52,644 DEBUG [main][Persistence] Type converter support initialising ...
09:57:52,645 DEBUG [main][Persistence] Added converter for java.math.BigDecimal<->java.lang.String using org.datanucleus.store.types.converters.BigDecimalStringConverter
09:57:52,645 DEBUG [main][Persistence] Added converter for java.math.BigInteger<->java.lang.String using org.datanucleus.store.types.converters.BigIntegerStringConverter
09:57:52,645 DEBUG [main][Persistence] Added converter for java.util.BitSet<->java.lang.String using org.datanucleus.store.types.converters.BitSetStringConverter
09:57:52,645 DEBUG [main][Persistence] Added converter for java.util.Calendar<->java.lang.String using org.datanucleus.store.types.converters.CalendarStringConverter
09:57:52,646 DEBUG [main][Persistence] Added converter for java.lang.Class<->java.lang.String using org.datanucleus.store.types.converters.ClassStringConverter
09:57:52,646 DEBUG [main][Persistence] Added converter for java.awt.Color<->java.lang.String using org.datanucleus.store.types.converters.ColorStringConverter
09:57:52,646 DEBUG [main][Persistence] Added converter for java.lang.Integer<->java.lang.String using org.datanucleus.store.types.converters.IntegerStringConverter
09:57:52,646 DEBUG [main][Persistence] Added converter for java.lang.Long<->java.lang.String using org.datanucleus.store.types.converters.LongStringConverter
09:57:52,647 DEBUG [main][Persistence] Added converter for java.util.Currency<->java.lang.String using org.datanucleus.store.types.converters.CurrencyStringConverter
09:57:52,647 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.Long using org.datanucleus.store.types.converters.DateLongConverter
09:57:52,647 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.String using org.datanucleus.store.types.converters.DateStringConverter
09:57:52,648 DEBUG [main][Persistence] Added converter for java.util.Locale<->java.lang.String using org.datanucleus.store.types.converters.LocaleStringConverter
09:57:52,648 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.Long using org.datanucleus.store.types.converters.SqlDateLongConverter
09:57:52,648 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.String using org.datanucleus.store.types.converters.SqlDateStringConverter
09:57:52,649 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimeLongConverter
09:57:52,649 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.String using org.datanucleus.store.types.converters.SqlTimeStringConverter
09:57:52,649 DEBUG [main][Persistence] Added converter for java.sql.Timestamp<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimestampLongConverter
09:57:52,649 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
09:57:52,650 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
09:57:52,650 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
09:57:52,650 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
09:57:52,650 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
09:57:52,651 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
09:57:52,652 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
09:57:52,653 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
09:57:52,654 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
09:57:52,655 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
09:57:52,655 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
09:57:52,655 DEBUG [main][Persistence] Type converter support loaded
09:57:52,656 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
09:57:52,656 DEBUG [main][MetaData] Registering listener for metadata initialisation
09:57:52,656 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
09:57:52,657 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
09:57:52,658 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
09:57:52,659 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
09:57:52,660 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
09:57:52,661 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
09:57:52,662 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
09:57:52,663 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
09:57:52,663 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
09:57:52,664 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
09:57:52,666 DEBUG [main][MetaData] Parsing MetaData 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" using handler "jdo" (validation="false")
09:57:52,670 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
09:57:53,560 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
09:57:53,562 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
09:57:53,562 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
09:57:53,566 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
09:57:53,572 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
09:57:53,573 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
09:57:53,574 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
09:57:53,575 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
09:57:53,576 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
09:57:53,576 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
09:57:53,577 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
09:57:53,578 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
09:57:53,579 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
09:57:53,580 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
09:57:53,581 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
09:57:53,582 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
09:57:53,583 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
09:57:53,583 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
09:57:53,584 DEBUG [main][Datastore] Creating StoreManager for datastore
09:57:53,597 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
09:57:53,597 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
09:57:53,598 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
09:57:53,614 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
09:57:59,799 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
09:57:59,800 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
09:58:04,465 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6785b361" opened
09:58:04,475 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:04,475 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=BOOLEAN, sql-type=BOOLEAN, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BooleanRDBMSMapping, default=false)
09:58:04,476 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:58:04,477 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Byte (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:58:04,477 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=true)
09:58:04,478 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:04,479 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:04,479 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Double (jdbc-type=DOUBLE, sql-type=DOUBLE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DoubleRDBMSMapping, default=true)
09:58:04,480 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Double (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=false)
09:58:04,480 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=FLOAT, sql-type=FLOAT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.FloatRDBMSMapping, default=true)
09:58:04,481 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=DOUBLE, sql-type=DOUBLE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DoubleRDBMSMapping, default=false)
09:58:04,481 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=REAL, sql-type=REAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.RealRDBMSMapping, default=false)
09:58:04,482 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=false)
09:58:04,483 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=true)
09:58:04,483 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:04,484 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:58:04,484 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=true)
09:58:04,485 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:58:04,485 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=true)
09:58:04,486 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:04,486 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:58:04,487 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:58:04,488 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=true)
09:58:04,488 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:04,489 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:04,489 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=true)
09:58:04,490 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:04,490 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:04,491 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=LONGVARCHAR, sql-type=LONGVARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.LongVarcharRDBMSMapping, default=false)
09:58:04,491 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=CLOB, sql-type=CLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.ClobRDBMSMapping, default=false)
09:58:04,492 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=BLOB, sql-type=BLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BlobRDBMSMapping, default=false)
09:58:04,493 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NVarcharRDBMSMapping, default=false)
09:58:04,494 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NCharRDBMSMapping, default=false)
09:58:04,494 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigDecimal (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=true)
09:58:04,495 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigDecimal (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:58:04,495 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigInteger (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=true)
09:58:04,496 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=DATE, sql-type=DATE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DateRDBMSMapping, default=true)
09:58:04,497 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=false)
09:58:04,497 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:04,497 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:04,498 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:04,499 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=TIME, sql-type=TIME, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimeRDBMSMapping, default=true)
09:58:04,499 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=false)
09:58:04,500 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:04,500 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:04,500 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:04,501 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=true)
09:58:04,501 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:04,501 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:04,501 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=true)
09:58:04,502 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=DATE, sql-type=DATE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DateRDBMSMapping, default=false)
09:58:04,502 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:04,502 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:04,502 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:04,503 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=TIME, sql-type=TIME, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimeRDBMSMapping, default=false)
09:58:04,503 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=LONGVARBINARY, sql-type=LONGVARBINARY, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.LongVarBinaryRDBMSMapping, default=true)
09:58:04,503 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=BLOB, sql-type=BLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BlobRDBMSMapping, default=false)
09:58:04,504 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=VARBINARY, sql-type=VARBINARY, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarBinaryRDBMSMapping, default=false)
09:58:04,504 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=true)
09:58:04,504 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:04,504 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:58:04,505 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:04,505 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:04,742 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
09:58:04,742 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
09:58:04,751 DEBUG [main][Datastore] ======================= Datastore =========================
09:58:04,751 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
09:58:04,751 DEBUG [main][Datastore] Datastore : read-write
09:58:04,751 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
09:58:04,751 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
09:58:04,751 DEBUG [main][Datastore] Queries : Timeout=0
09:58:04,752 DEBUG [main][Datastore] ===========================================================
09:58:04,752 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
09:58:04,752 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
09:58:04,752 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
09:58:04,752 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.2a1c00tz/derby/cumulus4j;create=true]
09:58:04,752 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.2a1c00tz/derby/cumulus4j;create=true]
09:58:04,752 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
09:58:04,752 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
09:58:04,752 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
09:58:04,752 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
09:58:04,752 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
09:58:04,752 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
09:58:04,753 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
09:58:04,753 DEBUG [main][Datastore] Java-Types : string-default-length=255
09:58:04,753 DEBUG [main][Datastore] JDBC-Types : [id=2009], BLOB, CLOB, TIMESTAMP, TIME, DATE, BOOLEAN, VARCHAR, DECIMAL, NUMERIC, CHAR, BINARY, REAL, LONGVARCHAR, FLOAT, LONGVARBINARY, SMALLINT, VARBINARY, INTEGER, BIGINT, DOUBLE, JAVA_OBJECT
09:58:04,753 DEBUG [main][Datastore] ===========================================================
09:58:04,803 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6785b361" non enlisted to a transaction is being committed.
09:58:04,804 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6785b361" closed
09:58:04,804 DEBUG [main][Datastore] StoreManager now created
09:58:04,804 DEBUG [main][Persistence] ================= NucleusContext ===============
09:58:04,804 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
09:58:04,804 DEBUG [main][Persistence] Persistence API : JDO
09:58:04,804 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
09:58:04,804 DEBUG [main][Persistence] ClassLoading : datanucleus
09:58:04,804 DEBUG [main][Persistence] Persistence : pm-singlethreaded, nontransactional-read, nontransactional-write, reachability-at-commit, copy-on-attach, managed-relations(checked), deletion-policy=JDO2, serverTimeZone=Europe/Berlin
09:58:04,804 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
09:58:04,805 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
09:58:04,805 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
09:58:04,805 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
09:58:04,805 DEBUG [main][Persistence] ================================================
09:58:04,805 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
09:58:04,805 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:04,806 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=5a7ba22d-04ba-4547-92a9-37a00babcbcf
09:58:04,806 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:04,806 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
09:58:04,807 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@21b63266" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@40a6d7d4" with txn="org.datanucleus.TransactionImpl@9a3c075"
09:58:04,807 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
09:58:04,807 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CFB/NoPadding'. Using this encryption algorithm.
09:58:04,807 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'HMAC-SHA256'. Using this MAC algorithm.
09:58:04,807 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
09:58:04,808 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
09:58:04,808 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
09:58:04,808 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
09:58:04,809 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
09:58:04,809 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
09:58:04,810 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
09:58:04,810 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.encryptionCoordinateSetID] -> Column(s) [ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID] using mapping of type "org.datanucleus.store.rdbms.mapping.java.LongMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
09:58:04,811 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
09:58:04,811 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
09:58:04,811 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.cipherTransformation] -> Column(s) [ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION] using mapping of type "org.datanucleus.store.rdbms.mapping.java.StringMapping" (org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping)
09:58:04,812 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
09:58:04,812 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.macAlgorithm] -> Column(s) [ENCRYPTIONCOORDINATESET.MACALGORITHM] using mapping of type "org.datanucleus.store.rdbms.mapping.java.StringMapping" (org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping)
09:58:04,812 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
09:58:04,813 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
09:58:04,813 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4fb93f90" opened with isolation level "serializable" and auto-commit=false
09:58:04,814 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4fb93f90" with isolation "serializable"
09:58:04,876 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
09:58:04,876 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
09:58:04,876 DEBUG [main][Schema] CREATE TABLE ENCRYPTIONCOORDINATESET
(
ENCRYPTIONCOORDINATESETID BIGINT NOT NULL generated always as identity (start with 1),
CIPHERTRANSFORMATION VARCHAR(255) NOT NULL,
MACALGORITHM VARCHAR(255) NOT NULL,
VERSION BIGINT NOT NULL
)
09:58:04,970 DEBUG [main][Schema] Execution Time = 94 ms
09:58:04,971 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
09:58:05,146 DEBUG [main][Schema] Execution Time = 175 ms
09:58:05,181 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4fb93f90"
09:58:05,205 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4fb93f90"
09:58:05,205 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4fb93f90" non enlisted to a transaction is being committed.
09:58:05,206 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4fb93f90" closed
09:58:05,206 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
09:58:05,209 DEBUG [main][Query] JDOQL Query : Compile Time = 3 ms
09:58:05,209 DEBUG [main][Query] QueryCompilation:
[filter:DyadicExpression{DyadicExpression{PrimaryExpression{this.cipherTransformation} = ParameterExpression{cipherTransformation}} AND DyadicExpression{PrimaryExpression{this.macAlgorithm} = ParameterExpression{macAlgorithm}}}]
[symbols: cipherTransformation type=java.lang.String, this type=org.cumulus4j.store.model.EncryptionCoordinateSet, macAlgorithm type=java.lang.String]
09:58:05,210 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
09:58:05,214 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 4 ms
09:58:05,214 DEBUG [main][Query] SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm Query compiled to datastore query "SELECT 'org.cumulus4j.store.model.EncryptionCoordinateSet' AS NUCLEUS_TYPE,A0.CIPHERTRANSFORMATION,A0.ENCRYPTIONCOORDINATESETID,A0.MACALGORITHM,A0.VERSION FROM ENCRYPTIONCOORDINATESET A0 WHERE A0.CIPHERTRANSFORMATION = ? AND A0.MACALGORITHM = ?"
09:58:05,215 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@6419a8b5 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@21b63266 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@5093366a]
09:58:05,215 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
09:58:05,216 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@70d99279" opened with isolation level "read-committed" and auto-commit=false
09:58:05,237 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@55b9d320"
09:58:05,238 DEBUG [main][Native] SELECT 'org.cumulus4j.store.model.EncryptionCoordinateSet' AS NUCLEUS_TYPE,A0.CIPHERTRANSFORMATION,A0.ENCRYPTIONCOORDINATESETID,A0.MACALGORITHM,A0.VERSION FROM ENCRYPTIONCOORDINATESET A0 WHERE A0.CIPHERTRANSFORMATION = <'TWOFISH/CFB/NOPADDING'> AND A0.MACALGORITHM = <'HMAC-SHA256'>
09:58:05,239 DEBUG [main][Retrieve] Execution Time = 1 ms
09:58:05,240 DEBUG [main][Query] JDOQL Query : Execution Time = 25 ms
09:58:05,240 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@70d99279" non enlisted to a transaction is being committed.
09:58:05,240 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@70d99279" closed
09:58:05,241 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@6419a8b5 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@70d99279, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@21b63266 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@5093366a]
09:58:05,241 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa"
09:58:05,241 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
09:58:05,243 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" being inserted into table "ENCRYPTIONCOORDINATESET"
09:58:05,243 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@3103d7e7 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@21b63266 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@5093366a]
09:58:05,244 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@735397d4" opened with isolation level "read-committed" and auto-commit=false
09:58:05,260 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@20d19be0" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@735397d4"
09:58:05,260 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (MACALGORITHM,CIPHERTRANSFORMATION,VERSION) VALUES (<'HMAC-SHA256'>,<'TWOFISH/CFB/NOPADDING'>,<1>)
09:58:05,264 DEBUG [main][Persist] Execution Time = 4 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@20d19be0"
09:58:05,272 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" was inserted in the datastore and was given strategy value of "1"
09:58:05,273 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
09:58:05,273 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@20d19be0"
09:58:05,310 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@735397d4" non enlisted to a transaction is being committed.
09:58:05,311 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@735397d4" closed
09:58:05,311 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@3103d7e7 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@735397d4, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@21b63266 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@5093366a]
09:58:05,311 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
09:58:05,312 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
09:58:05,312 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
09:58:05,313 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
09:58:05,313 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
09:58:05,314 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@5e651a66" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
09:58:05,314 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
09:58:05,314 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
09:58:08,720 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
09:58:08,856 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@608704088 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
09:58:08,861 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@608704088 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
09:58:08,861 TRACE [main][CryptoCache] getKeyData: Found cached key with keyID=123.
09:58:08,862 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@19013001 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
09:58:08,863 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@19013001 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
09:58:08,864 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@55cbb5aa, lifecycle=P_NONTRANS]
09:58:08,864 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
09:58:08,864 DEBUG [main][Cache] Level 1 Cache cleared
09:58:08,864 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@21b63266" closed
09:58:09,003 DEBUG [main][Persistence] Unmanaging Persistence of all classes
09:58:09,004 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
09:58:09,004 DEBUG [main][Cache] Level 2 Cache cleared
09:58:09,950 DEBUG [main][General] Plugin Registry "org.datanucleus.plugin.EclipsePluginRegistry" not found. Falling back to DataNucleus registry. Reason : Class "org.eclipse.core.runtime.RegistryFactory" was not found in the CLASSPATH. Please check your specification and your CLASSPATH..
09:58:09,951 DEBUG [main][General] Using PluginRegistry org.datanucleus.plugin.NonManagedPluginRegistry
09:58:09,957 DEBUG [main][General] Registering bundle org.cumulus4j.store version 1.2.1.SNAPSHOT at URL file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar.
09:58:09,961 DEBUG [main][General] Loading extension points from plug-in file jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/plugin.xml.
09:58:09,963 DEBUG [main][General] Loading extensions from plug-in file jar:file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store/target/org.cumulus4j.store-1.2.1-SNAPSHOT.jar!/plugin.xml.
09:58:09,964 WARN [main][General] Could not find MANIFEST.MF file for plugin file "file:/home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.crypto.keymanager/target/classes/plugin.xml" so ignoring it
09:58:09,966 DEBUG [main][General] Registering bundle org.datanucleus.api.jdo version 3.2.3 at URL file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-api-jdo/3.2.3/datanucleus-api-jdo-3.2.3.jar.
09:58:09,970 DEBUG [main][General] Loading extension points from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-api-jdo/3.2.3/datanucleus-api-jdo-3.2.3.jar!/plugin.xml.
09:58:09,970 DEBUG [main][General] Loading extensions from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-api-jdo/3.2.3/datanucleus-api-jdo-3.2.3.jar!/plugin.xml.
09:58:09,973 DEBUG [main][General] Registering bundle org.datanucleus.store.rdbms version 3.2.3 at URL file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-rdbms/3.2.3/datanucleus-rdbms-3.2.3.jar.
09:58:09,987 DEBUG [main][General] Loading extension points from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-rdbms/3.2.3/datanucleus-rdbms-3.2.3.jar!/plugin.xml.
09:58:09,993 DEBUG [main][General] Loading extensions from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-rdbms/3.2.3/datanucleus-rdbms-3.2.3.jar!/plugin.xml.
09:58:09,999 DEBUG [main][General] Registering bundle org.datanucleus version 3.2.4 at URL file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-core/3.2.4/datanucleus-core-3.2.4.jar.
09:58:10,007 DEBUG [main][General] Loading extension points from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-core/3.2.4/datanucleus-core-3.2.4.jar!/plugin.xml.
09:58:10,020 DEBUG [main][General] Loading extensions from plug-in file jar:file:/home/tomcat/.m2/repository/org/datanucleus/datanucleus-core/3.2.4/datanucleus-core-3.2.4.jar!/plugin.xml.
09:58:10,026 INFO [main][Persistence] Property cumulus4j.macAlgorithm unknown - will be ignored
09:58:10,027 INFO [main][Persistence] Property cumulus4j.encryptionAlgorithm unknown - will be ignored
09:58:10,028 DEBUG [main][Persistence] Java types support initialising ...
09:58:10,036 DEBUG [main][Persistence] Java types support loaded : supported java types=java.util.TimeZone, [Ljava.lang.Byte;, [Ljava.lang.Integer;, java.util.SortedMap, char, java.lang.Boolean, [Ljava.lang.Boolean;, java.lang.Long, java.sql.Timestamp, [Ljava.lang.Double;, java.lang.Float, long, float, java.util.BitSet, java.util.Stack, java.math.BigInteger, java.lang.Double, java.util.Vector, byte, java.util.Locale, java.lang.Class, [Ljava.lang.Long;, java.sql.Time, boolean, [Ljava.lang.Short;, java.util.LinkedList, java.util.PriorityQueue, [Ljava.lang.Enum;, int, java.util.List, java.util.TreeMap, java.lang.Integer, java.lang.Short, double, java.lang.Number, java.util.LinkedHashMap, java.sql.Date, [Ljava.util.Locale;, java.util.Arrays$ArrayList, java.lang.Byte, java.util.UUID, [Ljava.lang.String;, [Ljava.util.Date;, java.util.Currency, java.util.Properties, java.util.Calendar, java.util.Map, java.awt.Color, java.util.HashMap, [Ljava.lang.Character;, short, java.util.GregorianCalendar, java.util.TreeSet, java.lang.Character, java.util.SortedSet, java.util.Set, java.util.Collection, java.util.ArrayList, java.lang.StringBuffer, [Ljava.math.BigDecimal;, [B, java.util.Hashtable, [F, java.lang.String, java.net.URI, [C, java.awt.image.BufferedImage, [D, java.util.Date, [I, [J, [Ljava.lang.Number;, [Ljava.lang.Float;, [Ljava.math.BigInteger;, java.net.URL, java.util.HashSet, java.math.BigDecimal, [S, [Z, java.util.Queue, java.lang.Enum, java.util.LinkedHashSet
09:58:10,037 DEBUG [main][Persistence] Type converter support initialising ...
09:58:10,038 DEBUG [main][Persistence] Added converter for java.math.BigDecimal<->java.lang.String using org.datanucleus.store.types.converters.BigDecimalStringConverter
09:58:10,038 DEBUG [main][Persistence] Added converter for java.math.BigInteger<->java.lang.String using org.datanucleus.store.types.converters.BigIntegerStringConverter
09:58:10,039 DEBUG [main][Persistence] Added converter for java.util.BitSet<->java.lang.String using org.datanucleus.store.types.converters.BitSetStringConverter
09:58:10,039 DEBUG [main][Persistence] Added converter for java.util.Calendar<->java.lang.String using org.datanucleus.store.types.converters.CalendarStringConverter
09:58:10,040 DEBUG [main][Persistence] Added converter for java.lang.Class<->java.lang.String using org.datanucleus.store.types.converters.ClassStringConverter
09:58:10,040 DEBUG [main][Persistence] Added converter for java.awt.Color<->java.lang.String using org.datanucleus.store.types.converters.ColorStringConverter
09:58:10,041 DEBUG [main][Persistence] Added converter for java.lang.Integer<->java.lang.String using org.datanucleus.store.types.converters.IntegerStringConverter
09:58:10,041 DEBUG [main][Persistence] Added converter for java.lang.Long<->java.lang.String using org.datanucleus.store.types.converters.LongStringConverter
09:58:10,042 DEBUG [main][Persistence] Added converter for java.util.Currency<->java.lang.String using org.datanucleus.store.types.converters.CurrencyStringConverter
09:58:10,042 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.Long using org.datanucleus.store.types.converters.DateLongConverter
09:58:10,043 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.String using org.datanucleus.store.types.converters.DateStringConverter
09:58:10,043 DEBUG [main][Persistence] Added converter for java.util.Locale<->java.lang.String using org.datanucleus.store.types.converters.LocaleStringConverter
09:58:10,044 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.Long using org.datanucleus.store.types.converters.SqlDateLongConverter
09:58:10,044 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.String using org.datanucleus.store.types.converters.SqlDateStringConverter
09:58:10,044 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimeLongConverter
09:58:10,045 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.String using org.datanucleus.store.types.converters.SqlTimeStringConverter
09:58:10,045 DEBUG [main][Persistence] Added converter for java.sql.Timestamp<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimestampLongConverter
09:58:10,045 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
09:58:10,045 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
09:58:10,046 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
09:58:10,046 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
09:58:10,046 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
09:58:10,047 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
09:58:10,049 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
09:58:10,050 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
09:58:10,051 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
09:58:10,051 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
09:58:10,051 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
09:58:10,051 DEBUG [main][Persistence] Type converter support loaded
09:58:10,052 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
09:58:10,052 DEBUG [main][MetaData] Registering listener for metadata initialisation
09:58:10,052 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
09:58:10,053 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
09:58:10,054 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
09:58:10,055 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
09:58:10,056 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
09:58:10,057 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
09:58:10,058 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
09:58:10,059 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
09:58:10,060 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
09:58:10,061 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
09:58:10,062 DEBUG [main][MetaData] Parsing MetaData 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" using handler "jdo" (validation="false")
09:58:10,067 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
09:58:10,766 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
09:58:10,767 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
09:58:10,767 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
09:58:10,770 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
09:58:10,776 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
09:58:10,777 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
09:58:10,778 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
09:58:10,779 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
09:58:10,779 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
09:58:10,780 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
09:58:10,781 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
09:58:10,782 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
09:58:10,783 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
09:58:10,784 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
09:58:10,785 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
09:58:10,785 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
09:58:10,786 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
09:58:10,787 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
09:58:10,788 DEBUG [main][Datastore] Creating StoreManager for datastore
09:58:10,800 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
09:58:10,800 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
09:58:10,801 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
09:58:10,811 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
09:58:14,644 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
09:58:14,645 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
09:58:20,809 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@5006f966" opened
09:58:20,823 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:20,824 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=BOOLEAN, sql-type=BOOLEAN, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BooleanRDBMSMapping, default=false)
09:58:20,824 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Boolean (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:58:20,825 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Byte (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:58:20,826 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=true)
09:58:20,826 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:20,827 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Character (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:20,827 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Double (jdbc-type=DOUBLE, sql-type=DOUBLE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DoubleRDBMSMapping, default=true)
09:58:20,828 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Double (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=false)
09:58:20,828 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=FLOAT, sql-type=FLOAT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.FloatRDBMSMapping, default=true)
09:58:20,829 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=DOUBLE, sql-type=DOUBLE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DoubleRDBMSMapping, default=false)
09:58:20,830 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=REAL, sql-type=REAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.RealRDBMSMapping, default=false)
09:58:20,830 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Float (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=false)
09:58:20,831 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=true)
09:58:20,831 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:20,832 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:58:20,832 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=true)
09:58:20,833 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Integer (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:58:20,833 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=true)
09:58:20,834 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:20,834 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:58:20,835 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Long (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=false)
09:58:20,836 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=SMALLINT, sql-type=SMALLINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.SmallIntRDBMSMapping, default=true)
09:58:20,836 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:20,836 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:20,837 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=true)
09:58:20,838 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:20,838 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:20,839 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=LONGVARCHAR, sql-type=LONGVARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.LongVarcharRDBMSMapping, default=false)
09:58:20,839 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=CLOB, sql-type=CLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.ClobRDBMSMapping, default=false)
09:58:20,840 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=BLOB, sql-type=BLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BlobRDBMSMapping, default=false)
09:58:20,841 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NVarcharRDBMSMapping, default=false)
09:58:20,841 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NCharRDBMSMapping, default=false)
09:58:20,842 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigDecimal (jdbc-type=DECIMAL, sql-type=DECIMAL, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DecimalRDBMSMapping, default=true)
09:58:20,842 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigDecimal (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:58:20,851 DEBUG [main][Datastore] Adding RDBMS support for Java type java.math.BigInteger (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=true)
09:58:20,851 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=DATE, sql-type=DATE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DateRDBMSMapping, default=true)
09:58:20,852 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=false)
09:58:20,858 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:20,859 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:20,859 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Date (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:20,860 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=TIME, sql-type=TIME, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimeRDBMSMapping, default=true)
09:58:20,860 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=false)
09:58:20,867 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:20,868 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:20,869 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Time (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:20,869 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=true)
09:58:20,870 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:20,870 DEBUG [main][Datastore] Adding RDBMS support for Java type java.sql.Timestamp (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:20,877 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=TIMESTAMP, sql-type=TIMESTAMP, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimestampRDBMSMapping, default=true)
09:58:20,878 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=DATE, sql-type=DATE, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.DateRDBMSMapping, default=false)
09:58:20,878 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:20,879 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:20,879 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
09:58:20,880 DEBUG [main][Datastore] Adding RDBMS support for Java type java.util.Date (jdbc-type=TIME, sql-type=TIME, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.TimeRDBMSMapping, default=false)
09:58:20,880 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=LONGVARBINARY, sql-type=LONGVARBINARY, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.LongVarBinaryRDBMSMapping, default=true)
09:58:20,885 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=BLOB, sql-type=BLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BlobRDBMSMapping, default=false)
09:58:20,885 DEBUG [main][Datastore] Adding RDBMS support for Java type java.io.Serializable (jdbc-type=VARBINARY, sql-type=VARBINARY, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarBinaryRDBMSMapping, default=false)
09:58:20,886 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=true)
09:58:20,887 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=INTEGER, sql-type=INTEGER, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
09:58:20,887 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=NUMERIC, sql-type=NUMERIC, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.NumericRDBMSMapping, default=false)
09:58:20,887 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
09:58:20,888 DEBUG [main][Datastore] Adding RDBMS support for Java type org.datanucleus.identity.OID (jdbc-type=VARCHAR, sql-type=VARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping, default=false)
09:58:21,109 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
09:58:21,109 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
09:58:21,118 DEBUG [main][Datastore] ======================= Datastore =========================
09:58:21,118 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
09:58:21,118 DEBUG [main][Datastore] Datastore : read-write
09:58:21,118 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
09:58:21,118 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
09:58:21,119 DEBUG [main][Datastore] Queries : Timeout=0
09:58:21,119 DEBUG [main][Datastore] ===========================================================
09:58:21,119 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
09:58:21,119 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
09:58:21,119 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
09:58:21,119 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.whhmllbz/derby/cumulus4j;create=true]
09:58:21,119 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.whhmllbz/derby/cumulus4j;create=true]
09:58:21,119 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
09:58:21,119 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
09:58:21,119 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
09:58:21,119 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
09:58:21,120 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
09:58:21,120 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
09:58:21,120 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
09:58:21,120 DEBUG [main][Datastore] Java-Types : string-default-length=255
09:58:21,120 DEBUG [main][Datastore] JDBC-Types : [id=2009], BLOB, CLOB, TIMESTAMP, TIME, DATE, BOOLEAN, VARCHAR, DECIMAL, NUMERIC, CHAR, BINARY, REAL, LONGVARCHAR, FLOAT, LONGVARBINARY, SMALLINT, VARBINARY, INTEGER, BIGINT, DOUBLE, JAVA_OBJECT
09:58:21,120 DEBUG [main][Datastore] ===========================================================
09:58:21,173 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@5006f966" non enlisted to a transaction is being committed.
09:58:21,173 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@5006f966" closed
09:58:21,173 DEBUG [main][Datastore] StoreManager now created
09:58:21,173 DEBUG [main][Persistence] ================= NucleusContext ===============
09:58:21,174 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
09:58:21,174 DEBUG [main][Persistence] Persistence API : JDO
09:58:21,174 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
09:58:21,174 DEBUG [main][Persistence] ClassLoading : datanucleus
09:58:21,174 DEBUG [main][Persistence] Persistence : pm-singlethreaded, nontransactional-read, nontransactional-write, reachability-at-commit, copy-on-attach, managed-relations(checked), deletion-policy=JDO2, serverTimeZone=Europe/Berlin
09:58:21,174 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
09:58:21,174 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
09:58:21,174 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
09:58:21,174 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
09:58:21,174 DEBUG [main][Persistence] ================================================
09:58:21,175 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
09:58:21,175 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
09:58:21,175 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=da9bb57f-38c8-42db-85ee-44be96c9592e
09:58:21,175 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
09:58:21,175 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
09:58:21,176 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@64cbd575" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@22b2806" with txn="org.datanucleus.TransactionImpl@5f50a306"
09:58:21,176 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
09:58:21,261 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CFB/NoPadding'. Using this encryption algorithm.
09:58:21,261 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'HMAC-SHA256'. Using this MAC algorithm.
09:58:21,262 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
09:58:21,262 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
09:58:21,262 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
09:58:21,262 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
09:58:21,263 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
09:58:21,264 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
09:58:21,264 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
09:58:21,264 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.encryptionCoordinateSetID] -> Column(s) [ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID] using mapping of type "org.datanucleus.store.rdbms.mapping.java.LongMapping" (org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping)
09:58:21,265 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
09:58:21,265 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
09:58:21,265 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.cipherTransformation] -> Column(s) [ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION] using mapping of type "org.datanucleus.store.rdbms.mapping.java.StringMapping" (org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping)
09:58:21,265 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
09:58:21,266 DEBUG [main][Schema] Field [org.cumulus4j.store.model.EncryptionCoordinateSet.macAlgorithm] -> Column(s) [ENCRYPTIONCOORDINATESET.MACALGORITHM] using mapping of type "org.datanucleus.store.rdbms.mapping.java.StringMapping" (org.datanucleus.store.rdbms.mapping.datastore.VarCharRDBMSMapping)
09:58:21,266 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
09:58:21,266 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
09:58:21,266 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@30b6c3c3" opened with isolation level "serializable" and auto-commit=false
09:58:21,267 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@30b6c3c3" with isolation "serializable"
09:58:21,327 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
09:58:21,328 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
09:58:21,328 DEBUG [main][Schema] CREATE TABLE ENCRYPTIONCOORDINATESET
(
ENCRYPTIONCOORDINATESETID BIGINT NOT NULL generated always as identity (start with 1),
CIPHERTRANSFORMATION VARCHAR(255) NOT NULL,
MACALGORITHM VARCHAR(255) NOT NULL,
VERSION BIGINT NOT NULL
)
09:58:21,448 DEBUG [main][Schema] Execution Time = 120 ms
09:58:21,448 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
09:58:21,586 DEBUG [main][Schema] Execution Time = 138 ms
09:58:21,622 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@30b6c3c3"
09:58:21,641 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@30b6c3c3"
09:58:21,642 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@30b6c3c3" non enlisted to a transaction is being committed.
09:58:21,642 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@30b6c3c3" closed
09:58:21,643 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
09:58:21,645 DEBUG [main][Query] JDOQL Query : Compile Time = 2 ms
09:58:21,646 DEBUG [main][Query] QueryCompilation:
[filter:DyadicExpression{DyadicExpression{PrimaryExpression{this.cipherTransformation} = ParameterExpression{cipherTransformation}} AND DyadicExpression{PrimaryExpression{this.macAlgorithm} = ParameterExpression{macAlgorithm}}}]
[symbols: cipherTransformation type=java.lang.String, this type=org.cumulus4j.store.model.EncryptionCoordinateSet, macAlgorithm type=java.lang.String]
09:58:21,646 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
09:58:21,650 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 4 ms
09:58:21,651 DEBUG [main][Query] SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm Query compiled to datastore query "SELECT 'org.cumulus4j.store.model.EncryptionCoordinateSet' AS NUCLEUS_TYPE,A0.CIPHERTRANSFORMATION,A0.ENCRYPTIONCOORDINATESETID,A0.MACALGORITHM,A0.VERSION FROM ENCRYPTIONCOORDINATESET A0 WHERE A0.CIPHERTRANSFORMATION = ? AND A0.MACALGORITHM = ?"
09:58:21,651 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@645b5be2 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@64cbd575 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@29ed85e7]
09:58:21,652 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
09:58:21,652 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@28f21632" opened with isolation level "read-committed" and auto-commit=false
09:58:21,674 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@3576fd39"
09:58:21,674 DEBUG [main][Native] SELECT 'org.cumulus4j.store.model.EncryptionCoordinateSet' AS NUCLEUS_TYPE,A0.CIPHERTRANSFORMATION,A0.ENCRYPTIONCOORDINATESETID,A0.MACALGORITHM,A0.VERSION FROM ENCRYPTIONCOORDINATESET A0 WHERE A0.CIPHERTRANSFORMATION = <'TWOFISH/CFB/NOPADDING'> AND A0.MACALGORITHM = <'HMAC-SHA256'>
09:58:21,676 DEBUG [main][Retrieve] Execution Time = 1 ms
09:58:21,676 DEBUG [main][Query] JDOQL Query : Execution Time = 24 ms
09:58:21,677 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@28f21632" non enlisted to a transaction is being committed.
09:58:21,677 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@28f21632" closed
09:58:21,677 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@645b5be2 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@28f21632, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@64cbd575 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@29ed85e7]
09:58:21,678 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de"
09:58:21,678 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
09:58:21,679 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" being inserted into table "ENCRYPTIONCOORDINATESET"
09:58:21,680 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@5023e78c [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@64cbd575 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@29ed85e7]
09:58:21,680 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6536c16e" opened with isolation level "read-committed" and auto-commit=false
09:58:21,696 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5a3c2fd0" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6536c16e"
09:58:21,697 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (MACALGORITHM,CIPHERTRANSFORMATION,VERSION) VALUES (<'HMAC-SHA256'>,<'TWOFISH/CFB/NOPADDING'>,<1>)
09:58:21,700 DEBUG [main][Persist] Execution Time = 3 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5a3c2fd0"
09:58:21,709 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" was inserted in the datastore and was given strategy value of "1"
09:58:21,709 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
09:58:21,709 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5a3c2fd0"
09:58:21,718 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6536c16e" non enlisted to a transaction is being committed.
09:58:21,719 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6536c16e" closed
09:58:21,719 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@5023e78c [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6536c16e, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@64cbd575 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@29ed85e7]
09:58:21,719 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
09:58:21,720 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
09:58:21,720 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
09:58:21,720 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
09:58:21,721 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
09:58:21,721 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@2a439324" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
09:58:21,722 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
09:58:21,722 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
09:58:26,393 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
09:58:26,393 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
09:58:26,413 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
09:58:26,548 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1738100390 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
09:58:26,680 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1738100390 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
09:58:26,680 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@1738100390 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with new IV (without key).
09:58:26,701 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1738100390 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
09:58:26,702 TRACE [main][CryptoCache] clear: entered
09:58:26,836 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@33204589 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
09:58:26,856 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@33204589 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
09:58:26,878 TRACE [main][CryptoCache] clear: entered
09:58:26,878 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
09:58:27,012 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1871262750 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
09:58:27,051 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1871262750 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
09:58:27,255 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@1871262750 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with new IV (without key).
09:58:27,282 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1871262750 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
09:58:27,282 TRACE [main][CryptoCache] clear: entered
09:58:27,282 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
09:58:27,416 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@364425089 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
09:58:27,443 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@364425089 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
09:58:27,458 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@f11a7de, lifecycle=P_NONTRANS]
09:58:27,458 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
09:58:27,458 DEBUG [main][Cache] Level 1 Cache cleared
09:58:27,458 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@64cbd575" closed
09:58:27,590 DEBUG [main][Persistence] Unmanaging Persistence of all classes
09:58:27,590 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
09:58:27,590 DEBUG [main][Cache] Level 2 Cache cleared
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 36.033 sec
Results :
Tests run: 10, Failures: 0, Errors: 0, Skipped: 0
[JENKINS] Recording test results
[INFO]
[INFO] --- maven-bundle-plugin:2.3.4:bundle (default-bundle) @ org.cumulus4j.store.crypto.keymanager ---
[INFO]
[INFO] --- maven-source-plugin:2.1.2:jar-no-fork (attach-sources) @ org.cumulus4j.store.crypto.keymanager ---
[INFO] org already added, skipping
[INFO] org/cumulus4j already added, skipping
[INFO] org/cumulus4j/store already added, skipping
[INFO] org/cumulus4j/store/crypto already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/httppmf already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/pmf already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/inmemory already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/rest already added, skipping
[INFO] LICENCE.txt already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/httppmf/messagebroker-datanucleus.properties already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/pmf/messagebroker-datanucleus.properties already added, skipping
[INFO] Building jar: /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.crypto.keymanager/target/org.cumulus4j.store.crypto.keymanager-1.2.1-SNAPSHOT-sources.jar
[INFO] org already added, skipping
[INFO] org/cumulus4j already added, skipping
[INFO] org/cumulus4j/store already added, skipping
[INFO] org/cumulus4j/store/crypto already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/httppmf already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/pmf already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/inmemory already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/rest already added, skipping
[INFO] LICENCE.txt already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/httppmf/messagebroker-datanucleus.properties already added, skipping
[INFO] org/cumulus4j/store/crypto/keymanager/messagebroker/pmf/messagebroker-datanucleus.properties already added, skipping
[INFO]
[INFO] --- maven-install-plugin:2.4:install (default-install) @ org.cumulus4j.store.crypto.keymanager ---
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.crypto.keymanager/target/org.cumulus4j.store.crypto.keymanager-1.2.1-SNAPSHOT.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.store.crypto.keymanager/1.2.1-SNAPSHOT/org.cumulus4j.store.crypto.keymanager-1.2.1-SNAPSHOT.jar
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.crypto.keymanager/pom.xml to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.store.crypto.keymanager/1.2.1-SNAPSHOT/org.cumulus4j.store.crypto.keymanager-1.2.1-SNAPSHOT.pom
[INFO] Installing /home/tomcat/.jenkins/workspace/org.cumulus4j/org.cumulus4j/org.cumulus4j.store.crypto.keymanager/target/org.cumulus4j.store.crypto.keymanager-1.2.1-SNAPSHOT-sources.jar to /home/tomcat/.m2/repository/org/cumulus4j/org.cumulus4j.store.crypto.keymanager/1.2.1-SNAPSHOT/org.cumulus4j.store.crypto.keymanager-1.2.1-SNAPSHOT-sources.jar
[INFO]
[INFO] --- maven-bundle-plugin:2.3.4:install (default-install) @ org.cumulus4j.store.crypto.keymanager ---
[WARNING] Ignoring project type bundle - supportedProjectTypes = []
Console Output
Help us localize this page