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

Alvaro Pedraza aepedraza3117 at gmail.com
Tue Jul 17 10:53:17 EDT 2018


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 at 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 at 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 at 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 at 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

> El 17 jul. 2018, a las 06:31, Guillaume Smet <guillaume.smet at gmail.com <mailto:guillaume.smet at gmail.com>> escribió:
> 
> Does it fail every time you run the build or is it a transient failure?
> 
> If it's consistent, please check the result of the test (the Gradle log points you to a HTML file containing all the info) and paste the full error message and stracktrace here.
> 
> Information about your environment might also be useful: OS, JDK version...
> 
> Thanks!
> 
> On Tue, Jul 17, 2018 at 6:04 AM Alvaro Pedraza <aepedraza3117 at gmail.com <mailto:aepedraza3117 at gmail.com>> wrote:
> Hi, working in something else I ran ./gradlew tests and exited with one failing test at org.hibernate.test.annotations.uniqueconstraint.UniqueConstraintBatchingTest I’ve been seeing https://hibernate.atlassian.net/browse/HHH-12688 <https://hibernate.atlassian.net/browse/HHH-12688> <https://hibernate.atlassian.net/browse/HHH-12688 <https://hibernate.atlassian.net/browse/HHH-12688>> and it’s been closed and pushed, but the test is failing for me and just wanted to raise a flag just in case.
> Hope this helps.
> 
> Best regards: Alvaro E. Pedraza 
> _______________________________________________
> hibernate-dev mailing list
> hibernate-dev at lists.jboss.org <mailto:hibernate-dev at lists.jboss.org>
> https://lists.jboss.org/mailman/listinfo/hibernate-dev <https://lists.jboss.org/mailman/listinfo/hibernate-dev>


More information about the hibernate-dev mailing list