er
18:22:44,456 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
18:22:44,457 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
18:22:44,457 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
18:22:44,457 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
18:22:44,457 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
18:22:44,458 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
18:22:44,460 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
18:22:44,461 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
18:22:44,462 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
18:22:44,463 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
18:22:44,463 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
18:22:44,463 DEBUG [main][Persistence] Type converter support loaded
18:22:44,464 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
18:22:44,464 DEBUG [main][MetaData] Registering listener for metadata initialisation
18:22:44,464 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
18:22:44,466 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
18:22:44,467 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
18:22:44,468 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
18:22:44,469 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
18:22:44,470 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
18:22:44,471 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
18:22:44,472 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
18:22:44,473 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
18:22:44,474 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
18:22:44,476 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")
18:22:44,482 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
18:22:45,250 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
18:22:45,252 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
18:22:45,252 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
18:22:45,280 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
18:22:45,285 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
18:22:45,286 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
18:22:45,287 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
18:22:45,287 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
18:22:45,288 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
18:22:45,288 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
18:22:45,289 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
18:22:45,290 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
18:22:45,290 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
18:22:45,291 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
18:22:45,291 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
18:22:45,292 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
18:22:45,292 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
18:22:45,293 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
18:22:45,293 DEBUG [main][Datastore] Creating StoreManager for datastore
18:22:45,301 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
18:22:45,301 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
18:22:45,302 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
18:22:45,312 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
18:22:54,567 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
18:22:54,568 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
18:22:55,472 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@53d6cbe8" opened
18:22:55,481 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)
18:22:55,482 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)
18:22:55,482 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)
18:22:55,483 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)
18:22:55,483 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)
18:22:55,483 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)
18:22:55,483 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)
18:22:55,484 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)
18:22:55,484 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)
18:22:55,484 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)
18:22:55,485 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)
18:22:55,485 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)
18:22:55,485 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)
18:22:55,486 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)
18:22:55,486 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)
18:22:55,486 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)
18:22:55,487 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)
18:22:55,487 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)
18:22:55,487 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)
18:22:55,488 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)
18:22:55,488 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)
18:22:55,489 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)
18:22:55,489 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)
18:22:55,489 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)
18:22:55,489 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.Short (jdbc-type=INTEGER, sql-type=INT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.IntegerRDBMSMapping, default=false)
18:22:55,490 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)
18:22:55,490 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=CHAR, sql-type=CHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.CharRDBMSMapping, default=false)
18:22:55,490 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=BIGINT, sql-type=BIGINT, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.BigIntRDBMSMapping, default=false)
18:22:55,491 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=LONGVARCHAR, sql-type=LONGVARCHAR, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.LongVarcharRDBMSMapping, default=false)
18:22:55,491 DEBUG [main][Datastore] Adding RDBMS support for Java type java.lang.String (jdbc-type=CLOB, sql-type=CLOB, datastore-mapping-type=org.datanucleus.store.rdbms.mapping.datastore.ClobRDBMSMapping, default=false)
18:22:55,491 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)
18:22:55,492 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)
18:22:55,492 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)
18:22:55,493 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)
18:22:55,493 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)
18:22:55,493 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)
18:22:55,494 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)
18:22:55,494 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)
18:22:55,494 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)
18:22:55,494 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)
18:22:55,495 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)
18:22:55,495 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)
18:22:55,495 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)
18:22:55,496 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)
18:22:55,496 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)
18:22:55,496 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)
18:22:55,496 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)
18:22:55,497 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)
18:22:55,497 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)
18:22:55,497 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)
18:22:55,497 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)
18:22:55,498 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)
18:22:55,498 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)
18:22:55,498 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)
18:22:55,498 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)
18:22:55,499 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)
18:22:55,499 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)
18:22:55,499 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)
18:22:55,500 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)
18:22:55,500 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)
18:22:55,500 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)
18:22:55,501 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)
18:22:55,501 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)
18:22:55,704 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
18:22:55,705 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
18:22:55,716 DEBUG [main][Datastore] ======================= Datastore =========================
18:22:55,716 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
18:22:55,716 DEBUG [main][Datastore] Datastore : read-write
18:22:55,716 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
18:22:55,717 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
18:22:55,717 DEBUG [main][Datastore] Queries : Timeout=0
18:22:55,717 DEBUG [main][Datastore] ===========================================================
18:22:55,717 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
18:22:55,717 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
18:22:55,717 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
18:22:55,718 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.689v68ip/derby/cumulus4j;create=true]
18:22:55,718 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.689v68ip/derby/cumulus4j;create=true]
18:22:55,718 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
18:22:55,718 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
18:22:55,718 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
18:22:55,718 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
18:22:55,719 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
18:22:55,719 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
18:22:55,719 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
18:22:55,719 DEBUG [main][Datastore] Java-Types : string-default-length=255
18:22:55,719 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
18:22:55,719 DEBUG [main][Datastore] ===========================================================
18:22:55,773 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@53d6cbe8" non enlisted to a transaction is being committed.
18:22:55,773 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@53d6cbe8" closed
18:22:55,773 DEBUG [main][Datastore] StoreManager now created
18:22:55,773 DEBUG [main][Persistence] ================= NucleusContext ===============
18:22:55,773 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
18:22:55,774 DEBUG [main][Persistence] Persistence API : JDO
18:22:55,774 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
18:22:55,774 DEBUG [main][Persistence] ClassLoading : datanucleus
18:22:55,774 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
18:22:55,774 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
18:22:55,774 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
18:22:55,774 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
18:22:55,774 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
18:22:55,774 DEBUG [main][Persistence] ================================================
18:22:55,774 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
18:22:55,775 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
18:22:55,775 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=c1b88214-414d-4d4e-aad3-124380d346f1
18:22:55,775 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
18:22:55,775 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
18:22:55,776 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@3f4bc955" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@88f0bea" with txn="org.datanucleus.TransactionImpl@67573409"
18:22:55,776 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
18:22:55,874 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CBC/PKCS5Padding'. Using this encryption algorithm.
18:22:55,874 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'RC2'. Using this MAC algorithm.
18:22:55,875 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
18:22:55,875 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
18:22:55,875 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
18:22:55,875 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
18:22:55,876 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
18:22:55,876 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
18:22:55,877 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
18:22:55,877 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)
18:22:55,877 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
18:22:55,878 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
18:22:55,878 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)
18:22:55,878 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
18:22:55,879 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)
18:22:55,880 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
18:22:55,880 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
18:22:55,881 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@db03ddc" opened with isolation level "serializable" and auto-commit=false
18:22:55,881 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@db03ddc" with isolation "serializable"
18:22:55,950 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
18:22:55,951 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
18:22:55,951 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
)
18:22:56,023 DEBUG [main][Schema] Execution Time = 72 ms
18:22:56,024 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
18:22:56,156 DEBUG [main][Schema] Execution Time = 132 ms
18:22:56,194 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@db03ddc"
18:22:56,219 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@db03ddc"
18:22:56,219 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@db03ddc" non enlisted to a transaction is being committed.
18:22:56,220 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@db03ddc" closed
18:22:56,220 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
18:22:56,223 DEBUG [main][Query] JDOQL Query : Compile Time = 3 ms
18:22:56,223 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]
18:22:56,224 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
18:22:56,230 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 6 ms
18:22:56,231 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 = ?"
18:22:56,231 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4307dfbd [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@3f4bc955 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@39f213ac]
18:22:56,232 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
18:22:56,232 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@43e99eec" opened with isolation level "read-committed" and auto-commit=false
18:22:56,253 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@566ab457"
18:22:56,254 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'>
18:22:56,255 DEBUG [main][Retrieve] Execution Time = 1 ms
18:22:56,256 DEBUG [main][Query] JDOQL Query : Execution Time = 24 ms
18:22:56,256 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@43e99eec" non enlisted to a transaction is being committed.
18:22:56,257 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@43e99eec" closed
18:22:56,257 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@4307dfbd [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@43e99eec, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@3f4bc955 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@39f213ac]
18:22:56,257 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2"
18:22:56,258 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
18:22:56,259 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" being inserted into table "ENCRYPTIONCOORDINATESET"
18:22:56,260 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@3d1a5a40 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@3f4bc955 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@39f213ac]
18:22:56,260 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@d1b3f17" opened with isolation level "read-committed" and auto-commit=false
18:22:56,277 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@726b8972" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@d1b3f17"
18:22:56,277 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (MACALGORITHM,CIPHERTRANSFORMATION,VERSION) VALUES (<'RC2'>,<'TWOFISH/CBC/PKCS5PADDING'>,<1>)
18:22:56,281 DEBUG [main][Persist] Execution Time = 4 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@726b8972"
18:22:56,289 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" was inserted in the datastore and was given strategy value of "1"
18:22:56,289 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
18:22:56,290 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@726b8972"
18:22:56,296 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@d1b3f17" non enlisted to a transaction is being committed.
18:22:56,296 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@d1b3f17" closed
18:22:56,296 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@3d1a5a40 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@d1b3f17, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@3f4bc955 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@39f213ac]
18:22:56,297 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
18:22:56,297 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
18:22:56,298 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
18:22:56,298 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
18:22:56,299 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
18:22:56,299 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@e78b6b3" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
18:22:56,300 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
18:22:56,300 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
18:23:01,661 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
18:23:01,661 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
18:23:03,149 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
18:23:03,284 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1922307521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
18:23:03,424 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1922307521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
18:23:03,424 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@1922307521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with new IV (without key).
18:23:03,460 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1922307521 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
18:23:03,460 TRACE [main][CryptoCache] clear: entered
18:23:03,595 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@1478519979 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
18:23:03,631 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@1478519979 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
18:23:03,657 TRACE [main][CryptoCache] clear: entered
18:23:03,657 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
18:23:03,791 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@952007616 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
18:23:03,804 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=366224 actual=366213
18:23:03,826 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@952007616 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
18:23:04,035 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@952007616 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with new IV (without key).
18:23:04,048 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=366224 actual=366213
18:23:04,069 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@952007616 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
18:23:04,070 TRACE [main][CryptoCache] clear: entered
18:23:04,070 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
18:23:04,204 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@223528912 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING and keyID=123. Initialising it with key and IV.
18:23:04,217 DEBUG [main][KeyManagerCryptoSession] decrypt: precalculated output-size does not match actually written output: expected=366224 actual=366213
18:23:04,239 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@223528912 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CBC/PKCS5PADDING keyID=123.
18:23:04,256 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2 from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@436774a2, lifecycle=P_NONTRANS]
18:23:04,257 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
18:23:04,257 DEBUG [main][Cache] Level 1 Cache cleared
18:23:04,257 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@3f4bc955" closed
18:23:04,429 DEBUG [main][Persistence] Unmanaging Persistence of all classes
18:23:04,430 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
18:23:04,430 DEBUG [main][Cache] Level 2 Cache cleared
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 39.196 sec
Running org.cumulus4j.store.crypto.keymanager.test.TestKeyManagerCryptoSession_Twofish_CFB_NoPadding_HMACSHA256
18:23:05,213 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)
18:23:05,216 INFO [main][MessageBrokerRegistry] setActiveMessageBroker: New activeMessageBroker=org.cumulus4j.store.crypto.keymanager.test.MockMessageBroker@20e5d2a3
18:23:05,221 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..
18:23:05,222 DEBUG [main][General] Using PluginRegistry org.datanucleus.plugin.NonManagedPluginRegistry
18:23:05,229 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.
18:23:05,233 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.
18:23:05,236 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.
18:23:05,237 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
18:23:05,239 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.
18:23:05,244 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.
18:23:05,245 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.
18:23:05,247 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.
18:23:05,262 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.
18:23:05,268 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.
18:23:05,274 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.
18:23:05,282 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.
18:23:05,296 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.
18:23:05,302 INFO [main][Persistence] Property cumulus4j.macAlgorithm unknown - will be ignored
18:23:05,302 INFO [main][Persistence] Property cumulus4j.encryptionAlgorithm unknown - will be ignored
18:23:05,303 DEBUG [main][Persistence] Java types support initialising ...
18:23:05,312 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
18:23:05,312 DEBUG [main][Persistence] Type converter support initialising ...
18:23:05,313 DEBUG [main][Persistence] Added converter for java.math.BigDecimal<->java.lang.String using org.datanucleus.store.types.converters.BigDecimalStringConverter
18:23:05,313 DEBUG [main][Persistence] Added converter for java.math.BigInteger<->java.lang.String using org.datanucleus.store.types.converters.BigIntegerStringConverter
18:23:05,313 DEBUG [main][Persistence] Added converter for java.util.BitSet<->java.lang.String using org.datanucleus.store.types.converters.BitSetStringConverter
18:23:05,313 DEBUG [main][Persistence] Added converter for java.util.Calendar<->java.lang.String using org.datanucleus.store.types.converters.CalendarStringConverter
18:23:05,314 DEBUG [main][Persistence] Added converter for java.lang.Class<->java.lang.String using org.datanucleus.store.types.converters.ClassStringConverter
18:23:05,314 DEBUG [main][Persistence] Added converter for java.awt.Color<->java.lang.String using org.datanucleus.store.types.converters.ColorStringConverter
18:23:05,314 DEBUG [main][Persistence] Added converter for java.lang.Integer<->java.lang.String using org.datanucleus.store.types.converters.IntegerStringConverter
18:23:05,315 DEBUG [main][Persistence] Added converter for java.lang.Long<->java.lang.String using org.datanucleus.store.types.converters.LongStringConverter
18:23:05,315 DEBUG [main][Persistence] Added converter for java.util.Currency<->java.lang.String using org.datanucleus.store.types.converters.CurrencyStringConverter
18:23:05,315 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.Long using org.datanucleus.store.types.converters.DateLongConverter
18:23:05,315 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.String using org.datanucleus.store.types.converters.DateStringConverter
18:23:05,316 DEBUG [main][Persistence] Added converter for java.util.Locale<->java.lang.String using org.datanucleus.store.types.converters.LocaleStringConverter
18:23:05,316 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.Long using org.datanucleus.store.types.converters.SqlDateLongConverter
18:23:05,316 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.String using org.datanucleus.store.types.converters.SqlDateStringConverter
18:23:05,316 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimeLongConverter
18:23:05,317 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.String using org.datanucleus.store.types.converters.SqlTimeStringConverter
18:23:05,317 DEBUG [main][Persistence] Added converter for java.sql.Timestamp<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimestampLongConverter
18:23:05,317 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
18:23:05,318 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
18:23:05,318 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
18:23:05,318 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
18:23:05,318 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
18:23:05,319 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
18:23:05,321 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
18:23:05,322 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
18:23:05,323 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
18:23:05,323 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
18:23:05,324 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
18:23:05,324 DEBUG [main][Persistence] Type converter support loaded
18:23:05,324 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
18:23:05,324 DEBUG [main][MetaData] Registering listener for metadata initialisation
18:23:05,324 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
18:23:05,326 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
18:23:05,327 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
18:23:05,328 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
18:23:05,329 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
18:23:05,330 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
18:23:05,332 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
18:23:05,332 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
18:23:05,333 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
18:23:05,333 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
18:23:05,334 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")
18:23:05,337 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
18:23:06,314 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
18:23:06,315 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
18:23:06,316 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
18:23:06,319 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
18:23:06,325 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
18:23:06,327 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
18:23:06,328 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
18:23:06,329 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
18:23:06,330 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
18:23:06,331 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
18:23:06,332 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
18:23:06,333 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
18:23:06,334 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
18:23:06,335 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
18:23:06,336 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
18:23:06,337 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
18:23:06,339 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
18:23:06,339 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
18:23:06,340 DEBUG [main][Datastore] Creating StoreManager for datastore
18:23:06,353 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
18:23:06,353 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
18:23:06,354 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
18:23:06,370 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
18:23:14,903 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
18:23:14,904 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
18:23:17,228 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6d36d4df" opened
18:23:17,237 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)
18:23:17,237 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)
18:23:17,238 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)
18:23:17,238 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)
18:23:17,239 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)
18:23:17,239 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)
18:23:17,239 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)
18:23:17,240 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)
18:23:17,240 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)
18:23:17,240 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)
18:23:17,240 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)
18:23:17,241 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)
18:23:17,241 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)
18:23:17,241 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)
18:23:17,242 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)
18:23:17,242 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)
18:23:17,242 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)
18:23:17,243 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)
18:23:17,243 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)
18:23:17,243 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)
18:23:17,243 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)
18:23:17,244 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)
18:23:17,244 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)
18:23:17,245 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)
18:23:17,245 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)
18:23:17,245 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)
18:23:17,245 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)
18:23:17,246 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)
18:23:17,246 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)
18:23:17,246 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)
18:23:17,247 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)
18:23:17,248 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)
18:23:17,248 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)
18:23:17,248 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)
18:23:17,248 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)
18:23:17,249 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)
18:23:17,249 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)
18:23:17,249 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)
18:23:17,250 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)
18:23:17,250 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)
18:23:17,250 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)
18:23:17,251 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)
18:23:17,251 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)
18:23:17,251 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)
18:23:17,251 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)
18:23:17,252 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)
18:23:17,252 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)
18:23:17,252 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)
18:23:17,252 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)
18:23:17,252 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)
18:23:17,253 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)
18:23:17,253 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)
18:23:17,253 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)
18:23:17,253 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)
18:23:17,254 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)
18:23:17,254 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)
18:23:17,254 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)
18:23:17,255 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)
18:23:17,255 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)
18:23:17,255 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)
18:23:17,256 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)
18:23:17,256 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)
18:23:17,256 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)
18:23:17,487 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
18:23:17,487 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
18:23:17,496 DEBUG [main][Datastore] ======================= Datastore =========================
18:23:17,496 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
18:23:17,496 DEBUG [main][Datastore] Datastore : read-write
18:23:17,497 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
18:23:17,497 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
18:23:17,497 DEBUG [main][Datastore] Queries : Timeout=0
18:23:17,497 DEBUG [main][Datastore] ===========================================================
18:23:17,497 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
18:23:17,497 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
18:23:17,497 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
18:23:17,497 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.7fc2zx2u/derby/cumulus4j;create=true]
18:23:17,497 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.7fc2zx2u/derby/cumulus4j;create=true]
18:23:17,497 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
18:23:17,497 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
18:23:17,497 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
18:23:17,498 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
18:23:17,498 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
18:23:17,498 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
18:23:17,498 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
18:23:17,498 DEBUG [main][Datastore] Java-Types : string-default-length=255
18:23:17,498 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
18:23:17,498 DEBUG [main][Datastore] ===========================================================
18:23:17,554 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6d36d4df" non enlisted to a transaction is being committed.
18:23:17,554 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@6d36d4df" closed
18:23:17,554 DEBUG [main][Datastore] StoreManager now created
18:23:17,555 DEBUG [main][Persistence] ================= NucleusContext ===============
18:23:17,555 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
18:23:17,555 DEBUG [main][Persistence] Persistence API : JDO
18:23:17,555 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
18:23:17,555 DEBUG [main][Persistence] ClassLoading : datanucleus
18:23:17,555 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
18:23:17,555 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
18:23:17,555 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
18:23:17,555 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
18:23:17,555 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
18:23:17,555 DEBUG [main][Persistence] ================================================
18:23:17,556 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
18:23:17,556 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
18:23:17,556 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=88b62e2e-5ccc-4ccf-944b-e39cb562701a
18:23:17,556 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
18:23:17,557 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
18:23:17,557 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@461956ee" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@299a4736" with txn="org.datanucleus.TransactionImpl@4fb93f90"
18:23:17,558 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
18:23:17,558 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CFB/NoPadding'. Using this encryption algorithm.
18:23:17,558 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'HMAC-SHA256'. Using this MAC algorithm.
18:23:17,558 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
18:23:17,558 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
18:23:17,559 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
18:23:17,559 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
18:23:17,559 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
18:23:17,560 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
18:23:17,564 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
18:23:17,565 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)
18:23:17,565 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
18:23:17,565 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
18:23:17,566 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)
18:23:17,566 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
18:23:17,566 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)
18:23:17,567 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
18:23:17,567 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
18:23:17,567 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@194d874b" opened with isolation level "serializable" and auto-commit=false
18:23:17,567 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@194d874b" with isolation "serializable"
18:23:17,628 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
18:23:17,628 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
18:23:17,628 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
)
18:23:17,716 DEBUG [main][Schema] Execution Time = 88 ms
18:23:17,716 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
18:23:17,868 DEBUG [main][Schema] Execution Time = 152 ms
18:23:17,903 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@194d874b"
18:23:17,922 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@194d874b"
18:23:17,923 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@194d874b" non enlisted to a transaction is being committed.
18:23:17,923 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@194d874b" closed
18:23:17,923 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
18:23:17,930 DEBUG [main][Query] JDOQL Query : Compile Time = 7 ms
18:23:17,931 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]
18:23:17,932 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
18:23:17,936 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 4 ms
18:23:17,937 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 = ?"
18:23:17,937 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1ffb28a4 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@461956ee in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@22293763]
18:23:17,938 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
18:23:17,938 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3ff3561a" opened with isolation level "read-committed" and auto-commit=false
18:23:17,960 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@3f779cb"
18:23:17,961 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'>
18:23:17,962 DEBUG [main][Retrieve] Execution Time = 1 ms
18:23:17,963 DEBUG [main][Query] JDOQL Query : Execution Time = 25 ms
18:23:17,963 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3ff3561a" non enlisted to a transaction is being committed.
18:23:17,964 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3ff3561a" closed
18:23:17,964 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1ffb28a4 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3ff3561a, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@461956ee in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@22293763]
18:23:17,965 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7"
18:23:17,965 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
18:23:17,966 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" being inserted into table "ENCRYPTIONCOORDINATESET"
18:23:17,967 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@55b6ed96 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@461956ee in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@22293763]
18:23:17,967 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@5ca83ed0" opened with isolation level "read-committed" and auto-commit=false
18:23:17,984 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@7617f67f" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@5ca83ed0"
18:23:17,984 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (MACALGORITHM,CIPHERTRANSFORMATION,VERSION) VALUES (<'HMAC-SHA256'>,<'TWOFISH/CFB/NOPADDING'>,<1>)
18:23:17,988 DEBUG [main][Persist] Execution Time = 4 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@7617f67f"
18:23:17,996 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" was inserted in the datastore and was given strategy value of "1"
18:23:17,996 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
18:23:17,997 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@7617f67f"
18:23:18,009 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@5ca83ed0" non enlisted to a transaction is being committed.
18:23:18,009 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@5ca83ed0" closed
18:23:18,010 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@55b6ed96 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@5ca83ed0, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@461956ee in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@22293763]
18:23:18,010 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
18:23:18,010 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
18:23:18,011 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
18:23:18,011 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
18:23:18,012 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
18:23:18,012 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@434c4af3" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
18:23:18,013 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
18:23:18,013 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
18:23:23,309 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
18:23:23,309 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
18:23:24,463 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
18:23:24,598 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@2006269138 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
18:23:24,603 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@2006269138 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
18:23:24,603 TRACE [main][CryptoCache] getKeyData: Found cached key with keyID=123.
18:23:24,604 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@830583970 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
18:23:24,606 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@830583970 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
18:23:24,606 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7 from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@4dc938e7, lifecycle=P_NONTRANS]
18:23:24,606 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
18:23:24,606 DEBUG [main][Cache] Level 1 Cache cleared
18:23:24,606 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@461956ee" closed
18:23:24,746 DEBUG [main][Persistence] Unmanaging Persistence of all classes
18:23:24,747 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
18:23:24,747 DEBUG [main][Cache] Level 2 Cache cleared
18:23:25,661 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..
18:23:25,662 DEBUG [main][General] Using PluginRegistry org.datanucleus.plugin.NonManagedPluginRegistry
18:23:25,668 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.
18:23:25,672 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.
18:23:25,674 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.
18:23:25,675 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
18:23:25,677 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.
18:23:25,681 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.
18:23:25,682 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.
18:23:25,684 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.
18:23:25,699 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.
18:23:25,705 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.
18:23:25,711 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.
18:23:25,719 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.
18:23:25,733 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.
18:23:25,739 INFO [main][Persistence] Property cumulus4j.macAlgorithm unknown - will be ignored
18:23:25,739 INFO [main][Persistence] Property cumulus4j.encryptionAlgorithm unknown - will be ignored
18:23:25,740 DEBUG [main][Persistence] Java types support initialising ...
18:23:25,748 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
18:23:25,749 DEBUG [main][Persistence] Type converter support initialising ...
18:23:25,749 DEBUG [main][Persistence] Added converter for java.math.BigDecimal<->java.lang.String using org.datanucleus.store.types.converters.BigDecimalStringConverter
18:23:25,750 DEBUG [main][Persistence] Added converter for java.math.BigInteger<->java.lang.String using org.datanucleus.store.types.converters.BigIntegerStringConverter
18:23:25,750 DEBUG [main][Persistence] Added converter for java.util.BitSet<->java.lang.String using org.datanucleus.store.types.converters.BitSetStringConverter
18:23:25,750 DEBUG [main][Persistence] Added converter for java.util.Calendar<->java.lang.String using org.datanucleus.store.types.converters.CalendarStringConverter
18:23:25,751 DEBUG [main][Persistence] Added converter for java.lang.Class<->java.lang.String using org.datanucleus.store.types.converters.ClassStringConverter
18:23:25,751 DEBUG [main][Persistence] Added converter for java.awt.Color<->java.lang.String using org.datanucleus.store.types.converters.ColorStringConverter
18:23:25,751 DEBUG [main][Persistence] Added converter for java.lang.Integer<->java.lang.String using org.datanucleus.store.types.converters.IntegerStringConverter
18:23:25,751 DEBUG [main][Persistence] Added converter for java.lang.Long<->java.lang.String using org.datanucleus.store.types.converters.LongStringConverter
18:23:25,752 DEBUG [main][Persistence] Added converter for java.util.Currency<->java.lang.String using org.datanucleus.store.types.converters.CurrencyStringConverter
18:23:25,752 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.Long using org.datanucleus.store.types.converters.DateLongConverter
18:23:25,752 DEBUG [main][Persistence] Added converter for java.util.Date<->java.lang.String using org.datanucleus.store.types.converters.DateStringConverter
18:23:25,752 DEBUG [main][Persistence] Added converter for java.util.Locale<->java.lang.String using org.datanucleus.store.types.converters.LocaleStringConverter
18:23:25,753 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.Long using org.datanucleus.store.types.converters.SqlDateLongConverter
18:23:25,753 DEBUG [main][Persistence] Added converter for java.sql.Date<->java.lang.String using org.datanucleus.store.types.converters.SqlDateStringConverter
18:23:25,753 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimeLongConverter
18:23:25,754 DEBUG [main][Persistence] Added converter for java.sql.Time<->java.lang.String using org.datanucleus.store.types.converters.SqlTimeStringConverter
18:23:25,754 DEBUG [main][Persistence] Added converter for java.sql.Timestamp<->java.lang.Long using org.datanucleus.store.types.converters.SqlTimestampLongConverter
18:23:25,754 DEBUG [main][Persistence] Added converter for java.lang.StringBuffer<->java.lang.String using org.datanucleus.store.types.converters.StringBufferStringConverter
18:23:25,754 DEBUG [main][Persistence] Added converter for java.util.TimeZone<->java.lang.String using org.datanucleus.store.types.converters.TimeZoneStringConverter
18:23:25,755 DEBUG [main][Persistence] Added converter for java.net.URI<->java.lang.String using org.datanucleus.store.types.converters.URIStringConverter
18:23:25,755 DEBUG [main][Persistence] Added converter for java.net.URL<->java.lang.String using org.datanucleus.store.types.converters.URLStringConverter
18:23:25,755 DEBUG [main][Persistence] Added converter for java.util.UUID<->java.lang.String using org.datanucleus.store.types.converters.UUIDStringConverter
18:23:25,756 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDate<->java.lang.String ignored since java type not present in CLASSPATH
18:23:25,757 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.String ignored since java type not present in CLASSPATH
18:23:25,758 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalTime<->java.lang.Long ignored since java type not present in CLASSPATH
18:23:25,760 DEBUG [main][Persistence] TypeConverter for javax.time.calendar.LocalDateTime<->java.lang.String ignored since java type not present in CLASSPATH
18:23:25,760 DEBUG [main][Persistence] Added converter for java.io.Serializable<->java.lang.String using org.datanucleus.store.types.converters.SerializableStringConverter
18:23:25,760 DEBUG [main][Persistence] Added converter for java.io.Serializable<->[B using org.datanucleus.store.types.converters.SerializableByteArrayConverter
18:23:25,760 DEBUG [main][Persistence] Type converter support loaded
18:23:25,761 DEBUG [main][MetaData] MetaDataManager : Input=(XML,Annotations), XML-Validation=false, XML-Suffices=(persistence=*.jdo, orm=orm, query=*.jdoquery), JDO-listener=true
18:23:25,761 DEBUG [main][MetaData] Registering listener for metadata initialisation
18:23:25,761 DEBUG [main][MetaData] Listener found initialisation for persistable class org.cumulus4j.store.model.EncryptionCoordinateSet
18:23:25,762 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.jdo
18:23:25,763 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.jdo
18:23:25,764 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.jdo
18:23:25,765 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.jdo
18:23:25,766 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.jdo
18:23:25,767 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.jdo
18:23:25,768 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.jdo
18:23:25,769 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.jdo
18:23:25,770 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.jdo
18:23:25,772 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")
18:23:25,777 DEBUG [main][MetaData] XML Entity Public="" System="http://java.sun.com/dtd/jdo_3_0.dtd
18:23:26,855 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.jdo
18:23:26,857 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.jdo
18:23:26,857 DEBUG [main][MetaData] MetaData of type "jdo" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
18:23:26,859 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" has been specified with JDO annotations so using those.
18:23:26,865 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Populating Meta-Data
18:23:26,866 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /META-INF/package.orm
18:23:26,867 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /WEB-INF/package.orm
18:23:26,868 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /package.orm
18:23:26,869 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/package.orm
18:23:26,870 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org.orm
18:23:26,871 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/package.orm
18:23:26,872 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j.orm
18:23:26,873 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/package.orm
18:23:26,874 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store.orm
18:23:26,875 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/package.orm
18:23:26,876 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model.orm
18:23:26,877 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" NOT found at /org/cumulus4j/store/model/EncryptionCoordinateSet.orm
18:23:26,878 DEBUG [main][MetaData] MetaData of type "orm" for class "org.cumulus4j.store.model.EncryptionCoordinateSet" not found
18:23:26,879 DEBUG [main][Datastore] Creating StoreManager for datastore
18:23:26,891 DEBUG [main][Connection] Created tx data source using pooling type of dbcp-builtin
18:23:26,892 DEBUG [main][Connection] Registered transactional connection factory under name "rdbms/tx"
18:23:26,892 DEBUG [main][Connection] Registered nontransactional connection factory under name "rdbms/nontx"
18:23:26,908 DEBUG [main][Connection] Created nontx data source using pooling type of dbcp-builtin
18:23:37,491 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3301378d" opened
18:23:37,500 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)
18:23:37,500 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)
18:23:37,501 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)
18:23:37,502 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)
18:23:37,502 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)
18:23:37,503 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)
18:23:37,503 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)
18:23:37,504 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)
18:23:37,504 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)
18:23:37,505 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)
18:23:37,505 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)
18:23:37,506 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)
18:23:37,507 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)
18:23:37,507 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)
18:23:37,508 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)
18:23:37,508 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)
18:23:37,509 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)
18:23:37,509 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)
18:23:37,510 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)
18:23:37,510 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)
18:23:37,511 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)
18:23:37,512 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)
18:23:37,512 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)
18:23:37,512 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)
18:23:37,513 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)
18:23:37,514 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)
18:23:37,514 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)
18:23:37,515 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)
18:23:37,515 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)
18:23:37,516 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)
18:23:37,516 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)
18:23:37,517 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)
18:23:37,518 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)
18:23:37,518 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)
18:23:37,519 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)
18:23:37,519 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)
18:23:37,520 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)
18:23:37,521 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)
18:23:37,521 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)
18:23:37,522 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)
18:23:37,522 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)
18:23:37,523 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)
18:23:37,524 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)
18:23:37,524 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)
18:23:37,525 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)
18:23:37,525 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)
18:23:37,526 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)
18:23:37,526 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)
18:23:37,527 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)
18:23:37,527 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)
18:23:37,528 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)
18:23:37,528 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)
18:23:37,529 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)
18:23:37,529 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)
18:23:37,530 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)
18:23:37,530 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)
18:23:37,531 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)
18:23:37,531 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)
18:23:37,532 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)
18:23:37,532 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)
18:23:37,533 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)
18:23:37,533 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)
18:23:37,533 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)
18:23:37,721 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NCHAR, sql-type=NCHAR)
18:23:37,721 DEBUG [main][Datastore] Removing RDBMS support for Java type java.lang.String (jdbc-type=NVARCHAR, sql-type=NVARCHAR)
18:23:37,730 DEBUG [main][Datastore] ======================= Datastore =========================
18:23:37,730 DEBUG [main][Datastore] StoreManager : "rdbms" (org.datanucleus.store.rdbms.RDBMSStoreManager)
18:23:37,730 DEBUG [main][Datastore] Datastore : read-write
18:23:37,731 DEBUG [main][Datastore] Schema Control : AutoCreate(Tables), Validate(None)
18:23:37,731 DEBUG [main][Datastore] Query Languages : [JDOQL, JPQL, SQL, STOREDPROC]
18:23:37,731 DEBUG [main][Datastore] Queries : Timeout=0
18:23:37,731 DEBUG [main][Datastore] ===========================================================
18:23:37,731 DEBUG [main][Datastore] Datastore Adapter : org.datanucleus.store.rdbms.adapter.DerbyAdapter
18:23:37,731 DEBUG [main][Datastore] Datastore : name="Apache Derby" version="10.7.1.1 - (1040133)"
18:23:37,731 DEBUG [main][Datastore] Datastore Driver : name="Apache Derby Embedded JDBC Driver" version="10.7.1.1 - (1040133)"
18:23:37,732 DEBUG [main][Datastore] Primary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.2ainy199/derby/cumulus4j;create=true]
18:23:37,732 DEBUG [main][Datastore] Secondary Connection Factory : URL[jdbc:derby:/tmp/cumulus4j-test.2ainy199/derby/cumulus4j;create=true]
18:23:37,732 DEBUG [main][Datastore] Datastore Identifiers : factory="datanucleus2" case=UPPERCASE catalog= schema=ROOT
18:23:37,732 DEBUG [main][Datastore] Supported Identifier Cases : "MixedCase" UPPERCASE "MixedCase-Sensitive"
18:23:37,732 DEBUG [main][Datastore] Supported Identifier Lengths (max) : Table=128 Column=128 Constraint=128 Index=128 Delimiter="
18:23:37,732 DEBUG [main][Datastore] Support for Identifiers in DDL : catalog=false schema=true
18:23:37,732 DEBUG [main][Datastore] Datastore : checkTableViewExistence, rdbmsConstraintCreateMode=DataNucleus, initialiseColumnInfo=ALL
18:23:37,733 DEBUG [main][Datastore] Support Statement Batching : yes (max-batch-size=50)
18:23:37,733 DEBUG [main][Datastore] Queries : Results direction=forward, type=forward-only, concurrency=read-only
18:23:37,733 DEBUG [main][Datastore] Java-Types : string-default-length=255
18:23:37,733 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
18:23:37,733 DEBUG [main][Datastore] ===========================================================
18:23:37,790 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3301378d" non enlisted to a transaction is being committed.
18:23:37,790 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@3301378d" closed
18:23:37,790 DEBUG [main][Datastore] StoreManager now created
18:23:37,790 DEBUG [main][Persistence] ================= NucleusContext ===============
18:23:37,790 DEBUG [main][Persistence] DataNucleus Context : Version "3.2.4" with JRE "1.7.0_67" on "Linux"
18:23:37,790 DEBUG [main][Persistence] Persistence API : JDO
18:23:37,791 DEBUG [main][Persistence] Plugin Registry : org.datanucleus.plugin.NonManagedPluginRegistry
18:23:37,791 DEBUG [main][Persistence] ClassLoading : datanucleus
18:23:37,791 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
18:23:37,791 DEBUG [main][Persistence] AutoStart : mechanism=None, mode=Quiet
18:23:37,791 DEBUG [main][Persistence] Transactions : type=RESOURCE_LOCAL, mode=datastore, isolation=read-committed
18:23:37,791 DEBUG [main][Persistence] ValueGeneration : txn-isolation=read-committed connection=New
18:23:37,791 DEBUG [main][Persistence] Cache : Level1 (soft), Level2 (soft, mode=UNSPECIFIED), QueryResults (soft), Collections/Maps
18:23:37,791 DEBUG [main][Persistence] ================================================
18:23:37,791 DEBUG [main][Cache] Level 2 Cache of type "soft" initialised
18:23:37,792 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryTimerPeriod: Property 'cumulus4j.cryptoSessionExpiryTimer.period' is not set. Using default value 60000.
18:23:37,792 TRACE [main][AbstractCryptoSession] setCryptoSessionID: cryptoSessionID=cd4d2ebb-5410-4fc9-a337-76b52ca3c62d
18:23:37,792 INFO [main][AbstractCryptoManager] getCryptoSessionExpiryAgeMSec: Property 'cumulus4j.cryptoSessionExpiryAge' is not set. Using default value 1800000.
18:23:37,792 DEBUG [main][Persistence] Started pool of ExecutionContext (maxPool=20, reaperThread=false)
18:23:37,793 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@7d0024e9" opened for datastore "org.datanucleus.store.rdbms.RDBMSStoreManager@14777d1c" with txn="org.datanucleus.TransactionImpl@30b6c3c3"
18:23:37,793 DEBUG [main][Cache] Level 1 Cache of type "soft" initialised
18:23:38,072 INFO [main][AbstractCryptoManager] getEncryptionAlgorithm: Property 'cumulus4j.encryptionAlgorithm' is set to 'Twofish/CFB/NoPadding'. Using this encryption algorithm.
18:23:38,072 INFO [main][AbstractCryptoManager] getMACAlgorithm: Property 'cumulus4j.macAlgorithm' is set to 'HMAC-SHA256'. Using this MAC algorithm.
18:23:38,072 DEBUG [main][Cache] Query Cache of type "org.datanucleus.query.cache.SoftQueryCompilationCache" initialised
18:23:38,072 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryDatastoreCompilationCache" initialised
18:23:38,073 DEBUG [main][Cache] Query Cache of type "org.datanucleus.store.query.cache.SoftQueryResultsCache" initialised
18:23:38,073 DEBUG [main][Query] JDOQL Single-String with "SELECT UNIQUE WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
18:23:38,074 DEBUG [main][MetaData] Class "org.cumulus4j.store.model.EncryptionCoordinateSet" : Initialising Meta-Data
18:23:38,074 DEBUG [main][Persistence] Managing Persistence of Class : org.cumulus4j.store.model.EncryptionCoordinateSet [Table : ENCRYPTIONCOORDINATESET, InheritanceStrategy : new-table]
18:23:38,075 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.ENCRYPTIONCOORDINATESETID" added to internal representation of table.
18:23:38,075 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)
18:23:38,075 DEBUG [main][Schema] Table ENCRYPTIONCOORDINATESET will manage the persistence of the fields for class org.cumulus4j.store.model.EncryptionCoordinateSet (inheritance strategy="new-table")
18:23:38,075 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.CIPHERTRANSFORMATION" added to internal representation of table.
18:23:38,076 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)
18:23:38,076 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.MACALGORITHM" added to internal representation of table.
18:23:38,076 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)
18:23:38,076 DEBUG [main][Schema] Column "ENCRYPTIONCOORDINATESET.VERSION" added to internal representation of table.
18:23:38,077 DEBUG [main][Schema] Table/View ENCRYPTIONCOORDINATESET has been initialised
18:23:38,077 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@14f7ca3a" opened with isolation level "serializable" and auto-commit=false
18:23:38,077 DEBUG [main][Schema] Schema Transaction started with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@14f7ca3a" with isolation "serializable"
18:23:38,139 DEBUG [main][Schema] Check of existence of ENCRYPTIONCOORDINATESET returned no table
18:23:38,140 DEBUG [main][Schema] Creating table ENCRYPTIONCOORDINATESET
18:23:38,140 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
)
18:23:38,240 DEBUG [main][Schema] Execution Time = 99 ms
18:23:38,240 DEBUG [main][Schema] ALTER TABLE ENCRYPTIONCOORDINATESET ADD CONSTRAINT ENCRYPTIONCOORDINATESET_PK PRIMARY KEY (ENCRYPTIONCOORDINATESETID)
18:23:38,378 DEBUG [main][Schema] Execution Time = 136 ms
18:23:38,414 DEBUG [main][Schema] Schema Transaction committing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@14f7ca3a"
18:23:38,436 DEBUG [main][Schema] Schema Transaction closing with connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@14f7ca3a"
18:23:38,436 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@14f7ca3a" non enlisted to a transaction is being committed.
18:23:38,437 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@14f7ca3a" closed
18:23:38,437 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm"
18:23:38,440 DEBUG [main][Query] JDOQL Query : Compile Time = 3 ms
18:23:38,440 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]
18:23:38,441 DEBUG [main][Query] JDOQL Query : Compiling "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" for datastore
18:23:38,445 DEBUG [main][Query] JDOQL Query : Compile Time for datastore = 4 ms
18:23:38,445 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 = ?"
18:23:38,446 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@527a7162 [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@7d0024e9 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@64aa033b]
18:23:38,446 DEBUG [main][Query] JDOQL Query : Executing "SELECT UNIQUE FROM org.cumulus4j.store.model.EncryptionCoordinateSet WHERE this.cipherTransformation == :cipherTransformation && this.macAlgorithm == :macAlgorithm" ...
18:23:38,447 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@55ba4a1e" opened with isolation level "read-committed" and auto-commit=false
18:23:38,467 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.datasource.dbcp.DelegatingPreparedStatement@6f89cd7e"
18:23:38,468 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'>
18:23:38,469 DEBUG [main][Retrieve] Execution Time = 1 ms
18:23:38,470 DEBUG [main][Query] JDOQL Query : Execution Time = 24 ms
18:23:38,470 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@55ba4a1e" non enlisted to a transaction is being committed.
18:23:38,471 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@55ba4a1e" closed
18:23:38,471 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@527a7162 [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@55ba4a1e, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@7d0024e9 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@64aa033b]
18:23:38,472 DEBUG [main][Persistence] Making object persistent : "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d"
18:23:38,472 DEBUG [main][Persistence] Started pool of ObjectProviders (maxPool=0, reaperThread=false)
18:23:38,473 DEBUG [main][Persistence] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" being inserted into table "ENCRYPTIONCOORDINATESET"
18:23:38,474 DEBUG [main][Connection] Connection added to the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1b393f8f [conn=null, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@7d0024e9 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@64aa033b]
18:23:38,474 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b7bd33f" opened with isolation level "read-committed" and auto-commit=false
18:23:38,490 DEBUG [main][Datastore] Using PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@52a1d040" for connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b7bd33f"
18:23:38,491 DEBUG [main][Native] INSERT INTO ENCRYPTIONCOORDINATESET (CIPHERTRANSFORMATION,MACALGORITHM,VERSION) VALUES (<'TWOFISH/CFB/NOPADDING'>,<'HMAC-SHA256'>,<1>)
18:23:38,494 DEBUG [main][Persist] Execution Time = 3 ms (number of rows = 1) on PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@52a1d040"
18:23:38,502 DEBUG [main][Persist] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" was inserted in the datastore and was given strategy value of "1"
18:23:38,503 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") added to Level 1 cache (loadedFlags="[YYY]")
18:23:38,503 DEBUG [main][Datastore] Closing PreparedStatement "org.datanucleus.store.rdbms.ParamLoggingPreparedStatement@52a1d040"
18:23:38,513 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b7bd33f" non enlisted to a transaction is being committed.
18:23:38,514 DEBUG [main][Connection] Connection "org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b7bd33f" closed
18:23:38,514 DEBUG [main][Connection] Connection removed from the pool : org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl@1b393f8f [conn=org.datanucleus.store.rdbms.datasource.dbcp.PoolingDataSource$PoolGuardConnectionWrapper@4b7bd33f, commitOnRelease=true, closeOnRelease=true, closeOnTxnEnd=true] for key=org.datanucleus.ExecutionContextImpl@7d0024e9 in factory=ConnectionFactory:nontx[org.datanucleus.store.rdbms.ConnectionFactoryImpl@64aa033b]
18:23:38,515 DEBUG [main][Persistence] ExecutionContext.internalFlush() process started using ordered flush - 1 enlisted objects
18:23:38,516 DEBUG [main][Persistence] ExecutionContext.internalFlush() process finished
18:23:38,516 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" (id="1") added to Level 2 cache (fields="[0, 1, 2]", version="1")
18:23:38,517 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "P_NEW"->"HOLLOW"
18:23:38,517 DEBUG [main][Transaction] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") being evicted from transactional cache
18:23:38,518 DEBUG [main][Persistence] Detaching copy of object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" (depth=0) as "org.cumulus4j.store.model.EncryptionCoordinateSet@3a76f65f" with detached-fields [0, 1, 2] and fields-to-load=[0, 2]
18:23:38,519 DEBUG [main][Cache] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" (id="1") is loading the following fields from the Level 2 cache object : [0, 2]
18:23:38,520 DEBUG [main][Lifecycle] Object "org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d" (id="org.cumulus4j.store.model.EncryptionCoordinateSet:1") has a lifecycle change : "HOLLOW"->"P_NONTRANS"
18:23:39,242 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
18:23:39,243 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
18:23:43,074 DEBUG [CryptoCache][CryptoCache$CleanupTask] run: entered
18:23:43,075 INFO [CryptoCache][CryptoCache$CleanupTask] run: CryptoCache was garbage-collected. Cancelling this TimerTask.
18:23:55,279 INFO [main][CryptoCache] Persistence property 'cumulus4j.CryptoCache.cleanupTimer.period' is not set. Using default value 60000.
18:23:55,414 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@204629152 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
18:23:55,599 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@204629152 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
18:23:55,599 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@204629152 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with new IV (without key).
18:23:55,654 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@204629152 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
18:23:55,654 TRACE [main][CryptoCache] clear: entered
18:23:55,775 DEBUG [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: entered
18:23:55,775 INFO [AbstractCryptoManager][AbstractCryptoManager$CloseExpiredSessionsTask] run: AbstractCryptoManager was garbage-collected. Cancelling this TimerTask.
18:23:55,789 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@93827346 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
18:23:55,843 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@93827346 for opmode=ENCRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
18:23:55,901 TRACE [main][CryptoCache] clear: entered
18:23:55,901 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
18:23:56,034 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@703207324 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
18:23:56,118 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@703207324 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
18:23:56,628 TRACE [main][CryptoCache] acquireCipherEntry: Found cached Cipher@703207324 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with new IV (without key).
18:23:56,700 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@703207324 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
18:23:56,700 TRACE [main][CryptoCache] clear: entered
18:23:56,700 TRACE [main][CryptoCache] getKeyData: No cached key with keyID=123 found.
18:23:56,833 TRACE [main][CryptoCache] acquireCipherEntry: Created new Cipher@10812284 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING and keyID=123. Initialising it with key and IV.
18:23:56,906 TRACE [main][CryptoCache] releaseCipherEntry: Releasing Cipher@10812284 for opmode=DECRYPT, encryptionAlgorithm=TWOFISH/CFB/NOPADDING keyID=123.
18:23:56,945 DEBUG [main][Persistence] Disconnecting org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d from StateManager[pc=org.cumulus4j.store.model.EncryptionCoordinateSet@6f48e70d, lifecycle=P_NONTRANS]
18:23:56,945 DEBUG [main][Cache] Object with id="org.cumulus4j.store.model.EncryptionCoordinateSet:1" being removed from Level 1 cache [current cache size = 1]
18:23:56,945 DEBUG [main][Cache] Level 1 Cache cleared
18:23:56,945 DEBUG [main][Persistence] ExecutionContext "org.datanucleus.ExecutionContextImpl@7d0024e9" closed
18:23:57,083 DEBUG [main][Persistence] Unmanaging Persistence of all classes
18:23:57,084 DEBUG [main][MetaData] Deregistering listener for metadata initialisation
18:23:57,084 DEBUG [main][Cache] Level 2 Cache cleared
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 52.792 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