Re: [hibernate-dev] Failing test for issue HHH-12688

I ran it again and seems to be failing consistently. This is the info I can get: Stacktrace: java.lang.AssertionError: expected:<1> but was:<0> at org.junit.Assert.fail(Assert.java:88) at org.junit.Assert.failNotEquals(Assert.java:834) at org.junit.Assert.assertEquals(Assert.java:645) at org.junit.Assert.assertEquals(Assert.java:631) at org.hibernate.test.annotations.uniqueconstraint.UniqueConstraintBatchingTest.testBatching(UniqueConstraintBatchingTest.java:91) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at org.hibernate.testing.junit4.ExtendedFrameworkMethod.invokeExplosively(ExtendedFrameworkMethod.java:45) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.lang.Thread.run(Thread.java:745) Std Output: 11:04:52,916 INFO Version:46 - HHH000412: Hibernate Core {[WORKING]} 11:04:52,968 INFO Environment:198 - HHH000205: Loaded properties from resource hibernate.properties: {hibernate.connection.driver_class=org.h2.Driver, javax.persistence.validation.mode=NONE, hibernate.service.allow_crawling=false, hibernate.max_fetch_depth=5, hibernate.dialect=org.hibernate.dialect.H2Dialect, hibernate.format_sql=true, hibernate.cache.region.factory_class=org.hibernate.testing.cache.CachingRegionFactory, hibernate.hql.bulk_id_strategy.global_temporary.drop_tables=true, hibernate.connection.username=sa, hibernate.cache.region_prefix=hibernate.test, hibernate.connection.url=jdbc:h2:mem:db1;DB_CLOSE_DELAY=-1;LOCK_TIMEOUT=10000, hibernate.bytecode.use_reflection_optimizer=false, hibernate.show_sql=false, hibernate.connection.password=****, hibernate.session.events.log=true, hibernate.connection.pool_size=5} 11:04:53,543 INFO Dialect:157 - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect 11:04:56,792 INFO CustomRunner:116 - BeforeClass: org.hibernate.test.annotations.uniqueconstraint.UniqueConstraintBatchingTest 11:04:56,794 INFO Dialect:157 - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect 11:04:56,899 INFO CustomRunner:123 - Test: testBatching 11:04:57,277 INFO LogHelper:31 - HHH000204: Processing PersistenceUnitInfo [ name: UniqueConstraintBatchingTest ...] 11:05:00,085 WARN CachingRegionFactory:48 - org.hibernate.testing.cache.CachingRegionFactory should be only used for testing. 11:05:00,085 DEBUG RegionFactoryInitiator:49 - Cache region factory : org.hibernate.testing.cache.CachingRegionFactory 11:05:00,260 INFO Version:49 - HCANN000001: Hibernate Commons Annotations {5.0.4.Final} 11:05:01,801 WARN pooling:73 - HHH10001002: Using Hibernate built-in connection pool (not for production use!) 11:05:02,541 INFO pooling:129 - HHH10001005: using driver [org.h2.Driver] at URL [jdbc:h2:mem:db1;DB_CLOSE_DELAY=-1;LOCK_TIMEOUT=10000] 11:05:02,542 INFO pooling:138 - HHH10001001: Connection properties: {user=sa, password=****} 11:05:02,542 INFO pooling:143 - HHH10001003: Autocommit mode: false 11:05:02,566 INFO DriverManagerConnectionProviderImpl:281 - HHH000115: Hibernate connection pool size: 5 (min=1) 11:05:03,436 INFO Dialect:157 - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect 11:05:08,568 INFO beans:73 - HHH10005002: No explicit CDI BeanManager reference was passed to Hibernate, but CDI is available on the Hibernate ClassLoader. 11:05:12,424 DEBUG SQL:94 - drop table House if exists 11:05:12,457 INFO access:47 - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@33284695] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. 11:05:12,458 DEBUG SQL:94 - drop table Room if exists 11:05:12,475 DEBUG SQL:94 - create table House ( id bigint not null, height bigint, cost integer, room_id bigint not null, primary key (id) ) 11:05:12,477 INFO access:47 - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@65d0ead8] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. 11:05:12,514 DEBUG SQL:94 - create table Room ( id bigint not null, name varchar(255), primary key (id) ) 11:05:12,516 DEBUG SQL:94 - alter table House add constraint uniqueWithInherited unique (room_id, cost) 11:05:12,537 DEBUG SQL:94 - alter table House add constraint FKhmla6idcdpqljalxpwltebw88 foreign key (room_id) references Room 11:05:12,557 INFO SchemaCreatorImpl:489 - HHH000476: Executing import script 'org.hibernate.tool.schema.internal.exec.ScriptSourceInputNonExistentImpl@77576dd0' 11:05:13,999 DEBUG StatisticsInitiator:101 - Statistics initialized [enabled=false] 11:05:14,500 TRACE Cascade:86 - Processing cascade ACTION_PERSIST_ON_FLUSH for: org.hibernate.test.annotations.uniqueconstraint.Room 11:05:14,500 TRACE Cascade:172 - Done processing cascade ACTION_PERSIST_ON_FLUSH for: org.hibernate.test.annotations.uniqueconstraint.Room 11:05:14,691 DEBUG SQL:94 - insert into Room (name, id) values (?, ?) 11:05:14,720 TRACE BasicBinder:65 - binding parameter [1] as [VARCHAR] - [livingRoom] 11:05:14,721 TRACE BasicBinder:65 - binding parameter [2] as [BIGINT] - [1] 11:05:14,781 INFO StatisticalLoggingSessionEventListener:258 - Session Metrics { 65789 nanoseconds spent acquiring 1 JDBC connections; 109298 nanoseconds spent releasing 1 JDBC connections; 963539 nanoseconds spent preparing 1 JDBC statements; 0 nanoseconds spent executing 0 JDBC statements; 23443890 nanoseconds spent executing 1 JDBC batches; 0 nanoseconds spent performing 0 L2C puts; 0 nanoseconds spent performing 0 L2C hits; 0 nanoseconds spent performing 0 L2C misses; 319872705 nanoseconds spent executing 1 flushes (flushing a total of 1 entities and 0 collections); 0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections) } 11:05:14,797 DEBUG SQL:94 - select room_.id, room_.name as name2_1_ from Room room_ where room_.id=? 11:05:14,798 TRACE BasicBinder:65 - binding parameter [1] as [BIGINT] - [1] 11:05:14,841 TRACE BasicExtractor:61 - extracted value ([name2_1_] : [VARCHAR]) - [livingRoom] 11:05:14,842 TRACE Cascade:86 - Processing cascade ACTION_PERSIST_ON_FLUSH for: org.hibernate.test.annotations.uniqueconstraint.House 11:05:14,843 TRACE Cascade:172 - Done processing cascade ACTION_PERSIST_ON_FLUSH for: org.hibernate.test.annotations.uniqueconstraint.House 11:05:14,843 DEBUG SQL:94 - insert into House (height, room_id, cost, id) values (?, ?, ?, ?) 11:05:14,844 TRACE BasicBinder:65 - binding parameter [1] as [BIGINT] - [1000] 11:05:14,845 TRACE BasicBinder:65 - binding parameter [2] as [BIGINT] - [1] 11:05:14,847 TRACE BasicBinder:65 - binding parameter [3] as [INTEGER] - [100] 11:05:14,847 TRACE BasicBinder:65 - binding parameter [4] as [BIGINT] - [1] 11:05:14,849 INFO StatisticalLoggingSessionEventListener:258 - Session Metrics { 16103 nanoseconds spent acquiring 1 JDBC connections; 30533 nanoseconds spent releasing 1 JDBC connections; 491727 nanoseconds spent preparing 2 JDBC statements; 1032600 nanoseconds spent executing 1 JDBC statements; 560252 nanoseconds spent executing 1 JDBC batches; 0 nanoseconds spent performing 0 L2C puts; 0 nanoseconds spent performing 0 L2C hits; 0 nanoseconds spent performing 0 L2C misses; 6714811 nanoseconds spent executing 1 flushes (flushing a total of 1 entities and 0 collections); 0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections) } 11:05:14,852 DEBUG SQL:94 - select room_.id, room_.name as name2_1_ from Room room_ where room_.id=? 11:05:14,853 TRACE BasicBinder:65 - binding parameter [1] as [BIGINT] - [1] 11:05:14,854 TRACE BasicExtractor:61 - extracted value ([name2_1_] : [VARCHAR]) - [livingRoom] 11:05:14,855 TRACE Cascade:86 - Processing cascade ACTION_PERSIST_ON_FLUSH for: org.hibernate.test.annotations.uniqueconstraint.House 11:05:14,856 TRACE Cascade:172 - Done processing cascade ACTION_PERSIST_ON_FLUSH for: org.hibernate.test.annotations.uniqueconstraint.House 11:05:14,857 DEBUG SQL:94 - insert into House (height, room_id, cost, id) values (?, ?, ?, ?) 11:05:14,858 TRACE BasicBinder:65 - binding parameter [1] as [BIGINT] - [1001] 11:05:14,858 TRACE BasicBinder:65 - binding parameter [2] as [BIGINT] - [1] 11:05:14,859 TRACE BasicBinder:65 - binding parameter [3] as [INTEGER] - [100] 11:05:14,859 TRACE BasicBinder:65 - binding parameter [4] as [BIGINT] - [2] 11:05:14,876 INFO AbstractBatchImpl:193 - HHH000010: On release of batch it still contained JDBC statements 11:05:14,877 ERROR BatchingBatch:127 - HHH000315: Exception executing batch [org.h2.jdbc.JdbcBatchUpdateException: Violación de indice de Unicidad ó Clave primaria: "UNIQUEWITHINHERITED_INDEX_4 ON PUBLIC.HOUSE(ROOM_ID, COST) VALUES (1, 100, 1)" Unique index or primary key violation: "UNIQUEWITHINHERITED_INDEX_4 ON PUBLIC.HOUSE(ROOM_ID, COST) VALUES (1, 100, 1)"; SQL statement: insert into House (height, room_id, cost, id) values (?, ?, ?, ?) [23505-196]], SQL: insert into House (height, room_id, cost, id) values (?, ?, ?, ?) 11:05:14,878 WARN SqlExceptionHelper:137 - SQL Error: 23505, SQLState: 23505 11:05:14,878 ERROR SqlExceptionHelper:142 - Violación de indice de Unicidad ó Clave primaria: "UNIQUEWITHINHERITED_INDEX_4 ON PUBLIC.HOUSE(ROOM_ID, COST) VALUES (1, 100, 1)" Unique index or primary key violation: "UNIQUEWITHINHERITED_INDEX_4 ON PUBLIC.HOUSE(ROOM_ID, COST) VALUES (1, 100, 1)"; SQL statement: insert into House (height, room_id, cost, id) values (?, ?, ?, ?) [23505-196] 11:05:14,915 ERROR ExceptionMapperStandardImpl:39 - HHH000346: Error during managed flush [org.hibernate.exception.ConstraintViolationException: could not execute batch] 11:05:14,930 INFO StatisticalLoggingSessionEventListener:258 - Session Metrics { 13637 nanoseconds spent acquiring 1 JDBC connections; 74345 nanoseconds spent releasing 1 JDBC connections; 300536 nanoseconds spent preparing 2 JDBC statements; 98205 nanoseconds spent executing 1 JDBC statements; 16805422 nanoseconds spent executing 1 JDBC batches; 0 nanoseconds spent performing 0 L2C puts; 0 nanoseconds spent performing 0 L2C hits; 0 nanoseconds spent performing 0 L2C misses; 40652537 nanoseconds spent executing 1 flushes (flushing a total of 1 entities and 0 collections); 0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections) } 11:05:14,931 INFO SchemaDropperImpl$DelayedDropActionImpl:524 - HHH000477: Starting delayed evictData of schema as part of SessionFactory shut-down' 11:05:14,948 DEBUG SQL:94 - drop table House if exists 11:05:14,948 INFO access:47 - HHH10001501: Connection obtained from JdbcConnectionAccess [org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess@3c44b653] for (non-JTA) DDL execution was not in auto-commit mode; the Connection 'local transaction' will be committed and the Connection will be set into auto-commit mode. 11:05:14,965 DEBUG SQL:94 - drop table Room if exists 11:05:14,969 INFO pooling:233 - HHH10001008: Cleaning up connection pool [jdbc:h2:mem:db1;DB_CLOSE_DELAY=-1;LOCK_TIMEOUT=10000] Error msg: Loading class `com.mysql.jdbc.Driver'. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver'. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary. I’m running under Mac OS 10.13.4, JDK 1.8.0 I couldn’t analyze the report yet but I can do it this afternoon (is almost noon at the time of writing this) Hope this helps. Best regards: Alvaro E. Pedraza