12:03 a.m.
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> 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
5:31 a.m.
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(a)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> 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(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/hibernate-dev
10:53 a.m.
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
El 17 jul. 2018, a las 06:31, Guillaume Smet
<guillaume.smet(a)gmail.com <mailto:guillaume.smet@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(a)gmail.com
<mailto:aepedraza3117@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(a)lists.jboss.org <mailto:hibernate-dev@lists.jboss.org>
https://lists.jboss.org/mailman/listinfo/hibernate-dev
<https://lists.jboss.org/mailman/listinfo/hibernate-dev>
2108
days inactive
2108
days old
2 comments
2 participants
participants (2)
-
Alvaro Pedraza -
Guillaume Smet