[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