n][Persistence] Added converter for java.sql.Timestamp<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimestampLongConverter
15:53:36,208 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
15:53:36,208 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
15:53:36,209 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
15:53:36,209 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
15:53:36,209 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
15:53:36,210 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
15:53:36,212 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
15:53:36,213 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
15:53:36,215 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
15:53:36,215 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
15:53:36,215 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
15:53:36,215 DEBUG [main][Persistence] Type converter support loaded
15:53:36,216 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
15:53:36,216 DEBUG [main][MetaData] Registering listener for metadata initialisation
15:53:36,216 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
15:53:36,219 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
15:53:36,220 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
15:53:36,221 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
15:53:36,222 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
15:53:36,223 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
15:53:36,224 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
15:53:36,225 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
15:53:36,226 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
15:53:36,227 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
15:53:36,229 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")
15:53:36,234 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
15:53:37,092 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
15:53:37,094 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
15:53:37,094 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
15:53:37,123 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
15:53:37,130 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
15:53:37,131 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
15:53:37,132 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
15:53:37,133 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
15:53:37,134 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
15:53:37,135 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
15:53:37,136 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
15:53:37,137 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
15:53:37,138 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
15:53:37,139 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
15:53:37,140 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
15:53:37,141 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
15:53:37,142 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
15:53:37,143 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
15:53:37,144 DEBUG [main][Datastore] Creating StoreManager for datastore
15:53:37,157 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
15:53:37,157 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
15:53:37,159 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
15:53:37,178 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
15:53:41,598 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
15:53:41,599 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
15:53:52,877 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@61880847" opened
15:53:52,884 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)
15:53:52,884 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)
15:53:52,885 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)
15:53:52,885 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)
15:53:52,885 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)
15:53:52,886 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)
15:53:52,886 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)
15:53:52,886 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)
15:53:52,887 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)
15:53:52,887 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)
15:53:52,887 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)
15:53:52,888 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)
15:53:52,888 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)
15:53:52,888 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)
15:53:52,889 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)
15:53:52,889 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)
15:53:52,889 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)
15:53:52,890 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)
15:53:52,890 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)
15:53:52,890 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)
15:53:52,890 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)
15:53:52,891 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)
15:53:52,891 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)
15:53:52,892 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)
15:53:52,892 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)
15:53:52,892 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)
15:53:52,892 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)
15:53:52,893 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)
15:53:52,893 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)
15:53:52,893 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)
15:53:52,894 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)
15:53:52,894 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)
15:53:52,895 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)
15:53:52,895 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)
15:53:52,895 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)
15:53:52,896 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)
15:53:52,896 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)
15:53:52,897 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)
15:53:52,897 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)
15:53:52,898 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)
15:53:52,898 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)
15:53:52,898 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)
15:53:52,899 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)
15:53:52,899 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)
15:53:52,899 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)
15:53:52,900 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)
15:53:52,900 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)
15:53:52,901 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)
15:53:52,901 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)
15:53:52,901 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)
15:53:52,902 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)
15:53:52,902 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)
15:53:52,902 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)
15:53:52,902 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)
15:53:52,902 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)
15:53:52,903 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)
15:53:52,903 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)
15:53:52,903 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)
15:53:52,904 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)
15:53:52,904 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)
15:53:52,904 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)
15:53:52,904 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)
15:53:52,905 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)
15:53:53,153 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
15:53:53,153 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
15:53:53,164 DEBUG [main][Datastore] ======================= Datastore =========================
15:53:53,164 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
15:53:53,164 DEBUG [main][Datastore] Datastore : read-write
15:53:53,165 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
15:53:53,165 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
15:53:53,165 DEBUG [main][Datastore] Queries : Timeout=0
15:53:53,165 DEBUG [main][Datastore] ===========================================================
15:53:53,165 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
15:53:53,165 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
15:53:53,165 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
15:53:53,166 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.0xybo8bl/derby/cumulus4j;create=true]
15:53:53,166 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.0xybo8bl/derby/cumulus4j;create=true]
15:53:53,166 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
15:53:53,166 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
15:53:53,166 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
15:53:53,166 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
15:53:53,167 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
15:53:53,167 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
15:53:53,167 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
15:53:53,167 DEBUG [main][Datastore] Java-Types : string-default-length=255
15:53:53,167 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
15:53:53,167 DEBUG [main][Datastore] ===========================================================
15:53:53,413 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@61880847" non enlisted to a transaction is being committed.
15:53:53,414 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@61880847" closed
15:53:53,414 DEBUG [main][Datastore] StoreManager now created
15:53:53,414 DEBUG [main][Persistence] ================= NucleusContext ===============
15:53:53,414 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
15:53:53,414 DEBUG [main][Persistence] Persistence API : JDO
15:53:53,415 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
15:53:53,415 DEBUG [main][Persistence] ClassLoading : datanucleus
15:53:53,415 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
15:53:53,415 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
15:53:53,415 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
15:53:53,415 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
15:53:53,416 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
15:53:53,416 DEBUG [main][Persistence] ================================================
15:53:53,416 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
15:53:53,417 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
15:53:53,417 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=c9a830c3-48ab-4614-ad20-636dd4e6971b
15:53:53,417 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
15:53:53,417 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
15:53:53,419 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@2db666e" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@1221c139" with txn="org.datanucleus.TransactionImpl@66148e7b"
15:53:53,419 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
15:53:53,467 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CBC/PKCS5Padding'. Using this encryption algorithm.
15:53:53,467 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'RC2'. Using this MAC algorithm.
15:53:53,468 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
15:53:53,468 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
15:53:53,468 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
15:53:53,469 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
15:53:53,470 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
15:53:53,471 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
15:53:53,472 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
15:53:53,472 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)
15:53:53,473 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
15:53:53,474 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
15:53:53,474 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)
15:53:53,475 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
15:53:53,475 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)
15:53:53,476 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
15:53:53,478 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
15:53:53,479 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@68262ced" opened with isolation level "serializable" and auto-commit=false
15:53:53,479 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@68262ced" with isolation "serializable"
15:53:53,569 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
15:53:53,569 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
15:53:53,570 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
)
15:53:53,743 DEBUG [main][Schema] Execution Time = 172 ms
15:53:53,743 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
15:53:54,059 DEBUG [main][Schema] Execution Time = 316 ms
15:53:54,097 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@68262ced"
15:53:54,123 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@68262ced"
15:53:54,123 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@68262ced" non enlisted to a transaction is being committed.
15:53:54,123 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@68262ced" closed
15:53:54,124 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
15:53:54,127 DEBUG [main][Query] JDOQL Query : Compile Time = 3 ms
15:53:54,127 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]
15:53:54,127 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
15:53:54,134 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 7 ms
15:53:54,134 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 = ?"
15:53:54,135 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@368e2bf1 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@2db666e in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@2fe6f732]
15:53:54,135 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
15:53:54,136 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@646f0c2f" opened with isolation level "read-committed" and auto-commit=false
15:53:54,157 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@7693551e"
15:53:54,157 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'>
15:53:54,159 DEBUG [main][Retrieve] Execution Time = 2 ms
15:53:54,159 DEBUG [main][Query] JDOQL Query : Execution Time = 24 ms
15:53:54,160 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@646f0c2f" non enlisted to a transaction is being committed.
15:53:54,160 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@646f0c2f" closed
15:53:54,160 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@368e2bf1 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@646f0c2f, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@2db666e in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@2fe6f732]
15:53:54,161 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce"
15:53:54,161 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
15:53:54,162 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" being inserted into table "ENCRYPTIONCOORDINATESET"
15:53:54,163 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@721df507 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@2db666e in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@2fe6f732]
15:53:54,163 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@cc1d919" opened with isolation level "read-committed" and auto-commit=false
15:53:54,181 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5fb1fbe9" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@cc1d919"
15:53:54,182 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (CIPHERTRANSFORMATION,MACALGORITHM,VERSION) VALUES (<'TWOFISH/CBC/PKCS5PADDING'>,<'RC2'>,<1>)
15:53:54,186 DEBUG [main][Persist] Execution Time = 3 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5fb1fbe9"
15:53:54,194 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" was inserted in the datastore and was given strategy value of "1"
15:53:54,194 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
15:53:54,194 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@5fb1fbe9"
15:53:54,233 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@cc1d919" non enlisted to a transaction is being committed.
15:53:54,234 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@cc1d919" closed
15:53:54,234 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@721df507 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@cc1d919, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@2db666e in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@2fe6f732]
15:53:54,234 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
15:53:54,235 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
15:53:54,235 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
15:53:54,235 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
15:53:54,236 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
15:53:54,237 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@1a2e808a" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
15:53:54,237 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
15:53:54,237 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
15:54:05,002 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
15:54:05,002 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
15:54:10,761 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
15:54:10,761 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
15:54:19,971 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
15:54:20,106 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@2130165203 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
15:54:20,226 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@2130165203 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
15:54:20,227 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@2130165203 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with new IV (without key).
15:54:20,242 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@2130165203 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
15:54:20,242 TRACE [main][CryptoCache] clear: entered
15:54:20,376 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@986687684 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
15:54:20,386 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@986687684 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
15:54:20,393 TRACE [main][CryptoCache] clear: entered
15:54:20,393 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
15:54:20,527 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@391182854 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
15:54:20,531 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=98960 actual=98951
15:54:20,537 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@391182854 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
15:54:20,602 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@391182854 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with new IV (without key).
15:54:20,606 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=98960 actual=98951
15:54:20,612 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@391182854 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
15:54:20,612 TRACE [main][CryptoCache] clear: entered
15:54:20,612 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
15:54:20,745 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1162783711 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
15:54:20,749 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=98960 actual=98951
15:54:20,755 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1162783711 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
15:54:20,760 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@18a8ccce, lifecycle=P_NONTRANS]
15:54:20,760 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
15:54:20,760 DEBUG [main][Cache] Level 1 Cache cleared
15:54:20,761 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@2db666e" closed
15:54:20,951 DEBUG [main][Persistence] Unmanaging Persistence of all classes
15:54:20,951 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
15:54:20,951 DEBUG [main][Cache] Level 2 Cache cleared
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 68.774 sec
Running org.cumulus4j.store.crypto.keymanager.test.TestKeyManagerCryptoSession_Twofish_CFB_NoPadding_HMACSHA256
15:54:22,385 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)
15:54:22,389 INFO [main][MessageBrokerRegistry] setActiveMessageBroker: New activeMessageBroker=org.cumulus4j.store.crypto.keymanager.test.MockMessageBroker@3254664b
15:54:22,396 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..
15:54:22,402 DEBUG [main][General] Using PluginRegistry org.datanucleus.plugin.NonManagedPluginRegistry
15:54:22,425 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.
15:54:22,433 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.
15:54:22,436 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.
15:54:22,437 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
15:54:22,440 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.
15:54:22,444 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.
15:54:22,445 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.
15:54:22,448 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.
15:54:22,463 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.
15:54:22,469 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.
15:54:22,475 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.
15:54:22,491 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.
15:54:22,511 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.
15:54:22,518 INFO [main][Persistence] Property cumulus4j.macAlgorithm unknown - will be ignored
15:54:22,519 INFO [main][Persistence] Property cumulus4j.encryptionAlgorithm unknown - will be ignored
15:54:22,520 DEBUG [main][Persistence] Java types support initialising ...
15:54:22,532 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
15:54:22,533 DEBUG [main][Persistence] Type converter support initialising ...
15:54:22,534 DEBUG [main][Persistence] Added converter for java.math.BigDecimal<->java.lang.String using org.datanucleus.store.types.converters.BigDecimalStringConverter
15:54:22,534 DEBUG [main][Persistence] Added converter for java.math.BigInteger<->java.lang.String using org.datanucleus.store.types.converters.BigIntegerStringConverter
15:54:22,535 DEBUG [main][Persistence] Added converter for java.util.BitSet<->java.lang.String using org.datanucleus.store.types.converters.BitSetStringConverter
15:54:22,535 DEBUG [main][Persistence] Added converter for java.util.Calendar<->java.lang.String using org.datanucleus.store.types.converters.CalendarStringConverter
15:54:22,536 DEBUG [main][Persistence] Added converter for java.lang.Class<->java.lang.String using org.datanucleus.store.types.converters.ClassStringConverter
15:54:22,536 DEBUG [main][Persistence] Added converter for java.awt.Color<->java.lang.String using org.datanucleus.store.types.converters.ColorStringConverter
15:54:22,537 DEBUG [main][Persistence] Added converter for java.lang.Integer<->java.lang.String using org.datanucleus.store.types.converters.IntegerStringConverter
15:54:22,537 DEBUG [main][Persistence] Added converter for java.lang.Long<->java.lang.String using org.datanucleus.store.types.converters.LongStringConverter
15:54:22,538 DEBUG [main][Persistence] Added converter for java.util.Currency<->java.lang.String using org.datanucleus.store.types.converters.CurrencyStringConverter
15:54:22,538 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.Long using org.datanucleus.store.types.converters.DateLongConverter
15:54:22,539 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.String using org.datanucleus.store.types.converters.DateStringConverter
15:54:22,539 DEBUG [main][Persistence] Added converter for java.util.Locale<->java.lang.String using org.datanucleus.store.types.converters.LocaleStringConverter
15:54:22,540 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.Long using org.datanucleus.store.types.converters.SqlDateLongConverter
15:54:22,540 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.String using org.datanucleus.store.types.converters.SqlDateStringConverter
15:54:22,541 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimeLongConverter
15:54:22,541 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.String using org.datanucleus.store.types.converters.SqlTimeStringConverter
15:54:22,542 DEBUG [main][Persistence] Added converter for java.sql.Timestamp<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimestampLongConverter
15:54:22,542 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
15:54:22,542 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
15:54:22,543 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
15:54:22,543 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
15:54:22,544 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
15:54:22,546 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
15:54:22,547 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
15:54:22,549 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
15:54:22,550 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
15:54:22,551 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
15:54:22,552 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
15:54:22,552 DEBUG [main][Persistence] Type converter support loaded
15:54:22,552 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
15:54:22,553 DEBUG [main][MetaData] Registering listener for metadata initialisation
15:54:22,553 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
15:54:22,559 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
15:54:22,567 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
15:54:22,568 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
15:54:22,570 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
15:54:22,571 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
15:54:22,580 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
15:54:22,586 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
15:54:22,587 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
15:54:22,589 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
15:54:22,591 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")
15:54:22,602 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
15:54:23,491 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
15:54:23,492 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
15:54:23,493 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
15:54:23,496 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
15:54:23,508 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
15:54:23,515 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
15:54:23,519 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
15:54:23,520 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
15:54:23,522 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
15:54:23,523 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
15:54:23,524 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
15:54:23,526 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
15:54:23,527 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
15:54:23,529 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
15:54:23,530 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
15:54:23,532 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
15:54:23,533 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
15:54:23,534 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
15:54:23,535 DEBUG [main][Datastore] Creating StoreManager for datastore
15:54:23,553 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
15:54:23,554 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
15:54:23,554 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
15:54:23,570 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
15:54:30,799 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
15:54:30,800 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
15:54:34,310 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
15:54:34,311 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
15:54:41,682 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3d67fc18" opened
15:54:41,693 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)
15:54:41,699 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)
15:54:41,701 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)
15:54:41,702 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)
15:54:41,702 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)
15:54:41,702 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)
15:54:41,702 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)
15:54:41,711 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)
15:54:41,712 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)
15:54:41,712 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)
15:54:41,712 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)
15:54:41,712 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)
15:54:41,713 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)
15:54:41,713 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)
15:54:41,713 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)
15:54:41,714 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)
15:54:41,718 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)
15:54:41,719 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)
15:54:41,719 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)
15:54:41,719 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)
15:54:41,721 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)
15:54:41,722 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)
15:54:41,723 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)
15:54:41,724 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)
15:54:41,724 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)
15:54:41,724 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)
15:54:41,725 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)
15:54:41,725 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)
15:54:41,726 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)
15:54:41,727 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)
15:54:41,727 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)
15:54:41,728 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)
15:54:41,729 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)
15:54:41,730 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)
15:54:41,730 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)
15:54:41,738 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)
15:54:41,738 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)
15:54:41,739 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)
15:54:41,739 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)
15:54:41,739 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)
15:54:41,740 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)
15:54:41,740 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)
15:54:41,740 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)
15:54:41,741 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)
15:54:41,741 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)
15:54:41,741 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)
15:54:41,741 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)
15:54:41,742 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)
15:54:41,742 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)
15:54:41,742 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)
15:54:41,742 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)
15:54:41,743 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)
15:54:41,743 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)
15:54:41,743 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)
15:54:41,743 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)
15:54:41,744 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)
15:54:41,744 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)
15:54:41,744 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)
15:54:41,744 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)
15:54:41,745 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)
15:54:41,745 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)
15:54:41,745 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)
15:54:41,746 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)
15:54:41,936 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
15:54:41,936 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
15:54:41,946 DEBUG [main][Datastore] ======================= Datastore =========================
15:54:41,946 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
15:54:41,946 DEBUG [main][Datastore] Datastore : read-write
15:54:41,946 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
15:54:41,947 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
15:54:41,947 DEBUG [main][Datastore] Queries : Timeout=0
15:54:41,947 DEBUG [main][Datastore] ===========================================================
15:54:41,947 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
15:54:41,947 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
15:54:41,947 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
15:54:41,948 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.bsee81jt/derby/cumulus4j;create=true]
15:54:41,948 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.bsee81jt/derby/cumulus4j;create=true]
15:54:41,948 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
15:54:41,948 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
15:54:41,948 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
15:54:41,948 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
15:54:41,949 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
15:54:41,949 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
15:54:41,949 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
15:54:41,949 DEBUG [main][Datastore] Java-Types : string-default-length=255
15:54:41,949 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
15:54:41,950 DEBUG [main][Datastore] ===========================================================
15:54:42,068 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3d67fc18" non enlisted to a transaction is being committed.
15:54:42,068 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3d67fc18" closed
15:54:42,068 DEBUG [main][Datastore] StoreManager now created
15:54:42,069 DEBUG [main][Persistence] ================= NucleusContext ===============
15:54:42,069 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
15:54:42,069 DEBUG [main][Persistence] Persistence API : JDO
15:54:42,069 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
15:54:42,069 DEBUG [main][Persistence] ClassLoading : datanucleus
15:54:42,069 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
15:54:42,069 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
15:54:42,069 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
15:54:42,069 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
15:54:42,069 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
15:54:42,069 DEBUG [main][Persistence] ================================================
15:54:42,070 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
15:54:42,070 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
15:54:42,070 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=2a2b056f-2dc2-490b-89ab-5a4f42383a54
15:54:42,070 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
15:54:42,070 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
15:54:42,071 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@5fd54a69" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@2c0864a6" with txn="org.datanucleus.TransactionImpl@5b07e4df"
15:54:42,071 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
15:54:42,072 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CFB/NoPadding'. Using this encryption algorithm.
15:54:42,072 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'HMAC-SHA256'. Using this MAC algorithm.
15:54:42,073 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
15:54:42,073 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
15:54:42,073 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
15:54:42,074 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
15:54:42,075 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
15:54:42,075 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
15:54:42,076 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
15:54:42,076 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)
15:54:42,085 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
15:54:42,086 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
15:54:42,086 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)
15:54:42,088 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
15:54:42,088 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)
15:54:42,089 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
15:54:42,089 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
15:54:42,090 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@78bfe1f4" opened with isolation level "serializable" and auto-commit=false
15:54:42,090 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@78bfe1f4" with isolation "serializable"
15:54:42,152 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
15:54:42,153 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
15:54:42,153 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
)
15:54:42,321 DEBUG [main][Schema] Execution Time = 158 ms
15:54:42,321 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
15:54:42,655 DEBUG [main][Schema] Execution Time = 334 ms
15:54:42,693 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@78bfe1f4"
15:54:42,759 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@78bfe1f4"
15:54:42,759 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@78bfe1f4" non enlisted to a transaction is being committed.
15:54:42,760 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@78bfe1f4" closed
15:54:42,760 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
15:54:42,763 DEBUG [main][Query] JDOQL Query : Compile Time = 3 ms
15:54:42,763 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]
15:54:42,764 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
15:54:42,768 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 4 ms
15:54:42,768 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 = ?"
15:54:42,769 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@18005ff0 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@5fd54a69 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@409a91df]
15:54:42,769 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
15:54:42,770 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@63dee89b" opened with isolation level "read-committed" and auto-commit=false
15:54:42,792 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@735397d4"
15:54:42,792 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'>
15:54:42,794 DEBUG [main][Retrieve] Execution Time = 2 ms
15:54:42,795 DEBUG [main][Query] JDOQL Query : Execution Time = 26 ms
15:54:42,795 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@63dee89b" non enlisted to a transaction is being committed.
15:54:42,796 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@63dee89b" closed
15:54:42,796 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@18005ff0 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@63dee89b, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@5fd54a69 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@409a91df]
15:54:42,796 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b"
15:54:42,797 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
15:54:42,798 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" being inserted into table "ENCRYPTIONCOORDINATESET"
15:54:42,798 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4b8e51d2 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@5fd54a69 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@409a91df]
15:54:42,799 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6c9dd8be" opened with isolation level "read-committed" and auto-commit=false
15:54:42,815 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@3a1f78e6" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6c9dd8be"
15:54:42,816 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (MACALGORITHM,CIPHERTRANSFORMATION,VERSION) VALUES (<'HMAC-SHA256'>,<'TWOFISH/CFB/NOPADDING'>,<1>)
15:54:42,819 DEBUG [main][Persist] Execution Time = 3 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@3a1f78e6"
15:54:42,827 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" was inserted in the datastore and was given strategy value of "1"
15:54:42,828 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
15:54:42,828 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@3a1f78e6"
15:54:42,888 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6c9dd8be" non enlisted to a transaction is being committed.
15:54:42,888 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6c9dd8be" closed
15:54:42,889 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4b8e51d2 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6c9dd8be, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@5fd54a69 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@409a91df]
15:54:42,889 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
15:54:42,889 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
15:54:42,890 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
15:54:42,890 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
15:54:42,891 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
15:54:42,891 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@2b3c70a2" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
15:54:42,892 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
15:54:42,892 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
15:54:53,417 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
15:54:57,488 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
15:54:57,638 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@766025248 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
15:54:57,644 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@766025248 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
15:54:57,644 TRACE [main][CryptoCache] getKeyData: Found cached key with keyID=123.
15:54:57,645 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1161105893 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
15:54:57,646 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1161105893 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
15:54:57,647 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@3c7b6e6b, lifecycle=P_NONTRANS]
15:54:57,647 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
15:54:57,647 DEBUG [main][Cache] Level 1 Cache cleared
15:54:57,647 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@5fd54a69" closed
15:54:57,802 DEBUG [main][Persistence] Unmanaging Persistence of all classes
15:54:57,803 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
15:54:57,804 DEBUG [main][Cache] Level 2 Cache cleared
15:54:59,434 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..
15:54:59,441 DEBUG [main][General] Using PluginRegistry org.datanucleus.plugin.NonManagedPluginRegistry
15:54:59,444 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.
15:54:59,457 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.
15:54:59,460 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.
15:54:59,461 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
15:54:59,463 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.
15:54:59,465 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.
15:54:59,466 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.
15:54:59,478 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.
15:54:59,491 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.
15:54:59,495 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.
15:54:59,498 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.
15:54:59,503 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.
15:54:59,512 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.
15:54:59,516 INFO [main][Persistence] Property cumulus4j.macAlgorithm unknown - will be ignored
15:54:59,516 INFO [main][Persistence] Property cumulus4j.encryptionAlgorithm unknown - will be ignored
15:54:59,517 DEBUG [main][Persistence] Java types support initialising ...
15:54:59,522 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
15:54:59,522 DEBUG [main][Persistence] Type converter support initialising ...
15:54:59,522 DEBUG [main][Persistence] Added converter for java.math.BigDecimal<->java.lang.String using org.datanucleus.store.types.converters.BigDecimalStringConverter
15:54:59,523 DEBUG [main][Persistence] Added converter for java.math.BigInteger<->java.lang.String using org.datanucleus.store.types.converters.BigIntegerStringConverter
15:54:59,523 DEBUG [main][Persistence] Added converter for java.util.BitSet<->java.lang.String using org.datanucleus.store.types.converters.BitSetStringConverter
15:54:59,523 DEBUG [main][Persistence] Added converter for java.util.Calendar<->java.lang.String using org.datanucleus.store.types.converters.CalendarStringConverter
15:54:59,523 DEBUG [main][Persistence] Added converter for java.lang.Class<->java.lang.String using org.datanucleus.store.types.converters.ClassStringConverter
15:54:59,524 DEBUG [main][Persistence] Added converter for java.awt.Color<->java.lang.String using org.datanucleus.store.types.converters.ColorStringConverter
15:54:59,524 DEBUG [main][Persistence] Added converter for java.lang.Integer<->java.lang.String using org.datanucleus.store.types.converters.IntegerStringConverter
15:54:59,524 DEBUG [main][Persistence] Added converter for java.lang.Long<->java.lang.String using org.datanucleus.store.types.converters.LongStringConverter
15:54:59,525 DEBUG [main][Persistence] Added converter for java.util.Currency<->java.lang.String using org.datanucleus.store.types.converters.CurrencyStringConverter
15:54:59,525 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.Long using org.datanucleus.store.types.converters.DateLongConverter
15:54:59,525 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.String using org.datanucleus.store.types.converters.DateStringConverter
15:54:59,525 DEBUG [main][Persistence] Added converter for java.util.Locale<->java.lang.String using org.datanucleus.store.types.converters.LocaleStringConverter
15:54:59,526 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.Long using org.datanucleus.store.types.converters.SqlDateLongConverter
15:54:59,526 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.String using org.datanucleus.store.types.converters.SqlDateStringConverter
15:54:59,526 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimeLongConverter
15:54:59,526 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.String using org.datanucleus.store.types.converters.SqlTimeStringConverter
15:54:59,527 DEBUG [main][Persistence] Added converter for java.sql.Timestamp<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimestampLongConverter
15:54:59,527 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
15:54:59,527 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
15:54:59,527 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
15:54:59,528 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
15:54:59,528 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
15:54:59,529 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
15:54:59,530 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
15:54:59,531 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
15:54:59,532 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
15:54:59,532 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
15:54:59,532 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
15:54:59,532 DEBUG [main][Persistence] Type converter support loaded
15:54:59,533 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
15:54:59,533 DEBUG [main][MetaData] Registering listener for metadata initialisation
15:54:59,533 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
15:54:59,534 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
15:54:59,535 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
15:54:59,536 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
15:54:59,536 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
15:54:59,537 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
15:54:59,538 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
15:54:59,539 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
15:54:59,540 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
15:54:59,540 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
15:54:59,542 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")
15:54:59,561 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
15:55:00,461 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
15:55:00,464 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
15:55:00,464 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
15:55:00,465 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
15:55:00,475 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
15:55:00,476 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
15:55:00,484 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
15:55:00,485 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
15:55:00,486 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
15:55:00,486 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
15:55:00,487 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
15:55:00,488 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
15:55:00,488 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
15:55:00,489 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
15:55:00,490 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
15:55:00,499 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
15:55:00,499 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
15:55:00,499 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
15:55:00,500 DEBUG [main][Datastore] Creating StoreManager for datastore
15:55:00,515 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
15:55:00,515 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
15:55:00,515 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
15:55:00,534 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
15:55:18,393 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@2823a32b" opened
15:55:18,397 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)
15:55:18,398 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)
15:55:18,398 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)
15:55:18,399 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)
15:55:18,399 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)
15:55:18,399 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)
15:55:18,400 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)
15:55:18,400 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)
15:55:18,400 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)
15:55:18,401 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)
15:55:18,401 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)
15:55:18,401 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)
15:55:18,402 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)
15:55:18,403 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)
15:55:18,403 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)
15:55:18,403 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)
15:55:18,404 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)
15:55:18,404 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)
15:55:18,404 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)
15:55:18,404 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)
15:55:18,405 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)
15:55:18,405 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)
15:55:18,405 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)
15:55:18,406 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)
15:55:18,406 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)
15:55:18,406 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)
15:55:18,407 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)
15:55:18,407 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)
15:55:18,407 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)
15:55:18,407 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)
15:55:18,408 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)
15:55:18,409 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)
15:55:18,411 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)
15:55:18,411 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)
15:55:18,411 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)
15:55:18,412 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)
15:55:18,413 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)
15:55:18,413 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)
15:55:18,414 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)
15:55:18,414 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)
15:55:18,414 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)
15:55:18,414 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)
15:55:18,415 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)
15:55:18,415 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)
15:55:18,415 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)
15:55:18,415 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)
15:55:18,416 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)
15:55:18,416 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)
15:55:18,416 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)
15:55:18,416 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)
15:55:18,417 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)
15:55:18,417 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)
15:55:18,417 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)
15:55:18,417 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)
15:55:18,418 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)
15:55:18,418 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)
15:55:18,418 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)
15:55:18,418 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)
15:55:18,419 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)
15:55:18,419 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)
15:55:18,419 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)
15:55:18,419 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)
15:55:18,420 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)
15:55:18,851 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
15:55:18,857 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
15:55:18,890 DEBUG [main][Datastore] ======================= Datastore =========================
15:55:18,890 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
15:55:18,890 DEBUG [main][Datastore] Datastore : read-write
15:55:18,891 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
15:55:18,891 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
15:55:18,891 DEBUG [main][Datastore] Queries : Timeout=0
15:55:18,891 DEBUG [main][Datastore] ===========================================================
15:55:18,891 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
15:55:18,894 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
15:55:18,895 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
15:55:18,895 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.0m3b9hta/derby/cumulus4j;create=true]
15:55:18,895 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.0m3b9hta/derby/cumulus4j;create=true]
15:55:18,895 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
15:55:18,896 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
15:55:18,896 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
15:55:18,896 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
15:55:18,896 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
15:55:18,896 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
15:55:18,896 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
15:55:18,896 DEBUG [main][Datastore] Java-Types : string-default-length=255
15:55:18,897 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
15:55:18,897 DEBUG [main][Datastore] ===========================================================
15:55:19,111 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@2823a32b" non enlisted to a transaction is being committed.
15:55:19,112 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@2823a32b" closed
15:55:19,112 DEBUG [main][Datastore] StoreManager now created
15:55:19,112 DEBUG [main][Persistence] ================= NucleusContext ===============
15:55:19,112 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
15:55:19,112 DEBUG [main][Persistence] Persistence API : JDO
15:55:19,112 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
15:55:19,112 DEBUG [main][Persistence] ClassLoading : datanucleus
15:55:19,112 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
15:55:19,113 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
15:55:19,113 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
15:55:19,113 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
15:55:19,113 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
15:55:19,113 DEBUG [main][Persistence] ================================================
15:55:19,113 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
15:55:19,113 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
15:55:19,113 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=0dd3f41f-eb08-4cd9-904b-422139ee78ad
15:55:19,114 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
15:55:19,114 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
15:55:19,114 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@7e10cc38" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@cfb131" with txn="org.datanucleus.TransactionImpl@437a0861"
15:55:19,115 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
15:55:19,272 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CFB/NoPadding'. Using this encryption algorithm.
15:55:19,272 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'HMAC-SHA256'. Using this MAC algorithm.
15:55:19,272 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
15:55:19,273 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
15:55:19,273 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
15:55:19,274 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
15:55:19,275 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
15:55:19,275 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
15:55:19,284 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
15:55:19,285 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)
15:55:19,285 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
15:55:19,286 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
15:55:19,286 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)
15:55:19,288 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
15:55:19,289 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)
15:55:19,290 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
15:55:19,291 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
15:55:19,293 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@42f66184" opened with isolation level "serializable" and auto-commit=false
15:55:19,294 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@42f66184" with isolation "serializable"
15:55:19,358 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
15:55:19,358 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
15:55:19,359 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
)
15:55:19,555 DEBUG [main][Schema] Execution Time = 196 ms
15:55:19,556 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
15:55:19,973 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
15:55:19,973 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
15:55:20,011 DEBUG [main][Schema] Execution Time = 455 ms
15:55:20,067 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@42f66184"
15:55:20,102 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@42f66184"
15:55:20,102 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@42f66184" non enlisted to a transaction is being committed.
15:55:20,102 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@42f66184" closed
15:55:20,102 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
15:55:20,104 DEBUG [main][Query] JDOQL Query : Compile Time = 2 ms
15:55:20,104 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]
15:55:20,104 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
15:55:20,108 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 4 ms
15:55:20,108 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 = ?"
15:55:20,109 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@3576fd39 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@7e10cc38 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@16eac49b]
15:55:20,109 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
15:55:20,110 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@f11a7de" opened with isolation level "read-committed" and auto-commit=false
15:55:20,124 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@193caef7"
15:55:20,124 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'>
15:55:20,125 DEBUG [main][Retrieve] Execution Time = 1 ms
15:55:20,126 DEBUG [main][Query] JDOQL Query : Execution Time = 17 ms
15:55:20,126 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@f11a7de" non enlisted to a transaction is being committed.
15:55:20,126 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@f11a7de" closed
15:55:20,127 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@3576fd39 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@f11a7de, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@7e10cc38 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@16eac49b]
15:55:20,127 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79"
15:55:20,127 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
15:55:20,128 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" being inserted into table "ENCRYPTIONCOORDINATESET"
15:55:20,129 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@6fa0fd6e [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@7e10cc38 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@16eac49b]
15:55:20,138 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@325e7a03" opened with isolation level "read-committed" and auto-commit=false
15:55:20,153 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@8cf3d8e" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@325e7a03"
15:55:20,155 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (CIPHERTRANSFORMATION,MACALGORITHM,VERSION) VALUES (<'TWOFISH/CFB/NOPADDING'>,<'HMAC-SHA256'>,<1>)
15:55:20,159 DEBUG [main][Persist] Execution Time = 4 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@8cf3d8e"
15:55:20,164 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" was inserted in the datastore and was given strategy value of "1"
15:55:20,164 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
15:55:20,165 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@8cf3d8e"
15:55:20,201 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@325e7a03" non enlisted to a transaction is being committed.
15:55:20,202 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@325e7a03" closed
15:55:20,202 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@6fa0fd6e [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@325e7a03, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@7e10cc38 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@16eac49b]
15:55:20,203 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
15:55:20,203 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
15:55:20,203 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
15:55:20,204 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
15:55:20,204 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
15:55:20,204 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@2502835" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
15:55:20,205 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
15:55:20,205 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
15:55:42,070 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
15:55:49,019 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
15:55:49,252 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@331544656 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
15:55:49,424 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@331544656 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
15:55:49,424 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@331544656 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with new IV (without key).
15:55:49,448 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@331544656 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
15:55:49,449 TRACE [main][CryptoCache] clear: entered
15:55:49,593 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1548178794 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
15:55:49,609 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1548178794 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
15:55:49,626 TRACE [main][CryptoCache] clear: entered
15:55:49,627 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
15:55:49,774 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1329123706 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
15:55:49,807 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1329123706 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
15:55:49,969 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@1329123706 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with new IV (without key).
15:55:49,990 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1329123706 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
15:55:49,990 TRACE [main][CryptoCache] clear: entered
15:55:49,990 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
15:55:50,124 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@979011970 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
15:55:50,145 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@979011970 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
15:55:50,157 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79 from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@37907f79, lifecycle=P_NONTRANS]
15:55:50,158 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
15:55:50,158 DEBUG [main][Cache] Level 1 Cache cleared
15:55:50,158 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@7e10cc38" closed
15:55:50,352 DEBUG [main][Persistence] Unmanaging Persistence of all classes
15:55:50,352 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
15:55:50,352 DEBUG [main][Cache] Level 2 Cache cleared
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 88.697 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