quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.78k stars 2.68k forks source link

AssertionError in EntityInitializerImpl.resolveInstanceSubInitializers after upgrading to 3.14 #43296

Open jendib opened 1 month ago

jendib commented 1 month ago

Describe the bug

After upgrading to Quarkus 3.14 I'm getting this error on a Panache "list" operation:

java.lang.AssertionError
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveInstanceSubInitializers(EntityInitializerImpl.java:582)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveInstance(EntityInitializerImpl.java:888)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveInstance(EntityInitializerImpl.java:94)
    at org.hibernate.sql.results.graph.Initializer.resolveInstance(Initializer.java:149)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveInstanceSubInitializers(EntityInitializerImpl.java:599)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:534)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:424)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:94)
    at org.hibernate.sql.results.graph.Initializer.resolveKey(Initializer.java:101)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKeySubInitializers(EntityInitializerImpl.java:618)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:546)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:424)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:94)
    at org.hibernate.sql.results.graph.Initializer.resolveKey(Initializer.java:101)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKeySubInitializers(EntityInitializerImpl.java:618)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:546)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:424)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:94)
    at org.hibernate.sql.results.internal.StandardRowReader.coordinateInitializers(StandardRowReader.java:235)
    at org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:141)
    at org.hibernate.sql.results.spi.ListResultsConsumer.read(ListResultsConsumer.java:249)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:201)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:35)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:224)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:102)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.executeQuery(JdbcSelectExecutor.java:91)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:165)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.lambda$new$1(ConcreteSqmSelectQueryPlan.java:152)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.withCacheableSqmInterpretation(ConcreteSqmSelectQueryPlan.java:442)
    at org.hibernate.query.sqm.internal.ConcreteSqmSelectQueryPlan.performList(ConcreteSqmSelectQueryPlan.java:362)
    at org.hibernate.query.sqm.internal.SqmSelectionQueryImpl.doList(SqmSelectionQueryImpl.java:299)
    at org.hibernate.query.spi.AbstractSelectionQuery.list(AbstractSelectionQuery.java:136)
    at org.hibernate.query.SelectionQuery.getResultList(SelectionQuery.java:124)
    at io.quarkus.hibernate.orm.panache.common.runtime.CommonPanacheQueryImpl.list(CommonPanacheQueryImpl.java:303)
    at io.quarkus.hibernate.orm.panache.runtime.PanacheQueryImpl.list(PanacheQueryImpl.java:150)
    at io.quarkus.hibernate.orm.panache.runtime.JpaOperations.list(JpaOperations.java:24)
    at io.quarkus.hibernate.orm.panache.runtime.JpaOperations.list(JpaOperations.java:10)
    at io.quarkus.hibernate.orm.panache.common.runtime.AbstractJpaOperations.list(AbstractJpaOperations.java:265)

It's probably related to the underlying Hibernate 6.6 upgrade but I cannot understand why. The assertion is expection a "Status.LOADING" but if I put a breakpoint here I have "Status.MANAGED".

Expected behavior

No response

Actual behavior

No response

How to Reproduce?

No response

Output of uname -a or ver

No response

Output of java -version

No response

Quarkus version or git rev

3.14.4

Build tool (ie. output of mvnw --version or gradlew --version)

No response

Additional information

No response

quarkus-bot[bot] commented 1 month ago

/cc @FroMage (panache), @loicmathieu (panache)

geoand commented 1 month ago

cc @yrodiere

yrodiere commented 1 month ago

Thanks for reporting.

Can you please provide a reproducer (a small project that exhibits the issue)?

jendib commented 1 month ago

@yrodiere That's the problem, I dont know exactly how to reproduce it. I'm going through that code at other places without issue so it must be some internal Hibernate state.

yrodiere commented 1 month ago

@yrodiere That's the problem, I dont know exactly how to reproduce it. I'm going through that code at other places without issue so it must be some internal Hibernate state.

Might be a side effect from having other entities already loaded in the same session.

You're going to have to iterate: remove code, check it still fails, repeat :/

jendib commented 1 month ago

It's definitely related to loading another entity with a @ManyToOne relation to the entity failing to load. I deleted some code and it works if the "list" is the first query in the session.

cmadsen commented 1 month ago

On 6.6.0 i sometimes get:

java.lang.AssertionError
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveInstance(EntityInitializerImpl.java:844)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveInstance(EntityInitializerImpl.java:94)
    at org.hibernate.sql.results.graph.Initializer.resolveInstance(Initializer.java:149)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveInstanceSubInitializers(EntityInitializerImpl.java:599)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:534)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:424)
    at org.hibernate.sql.results.graph.entity.internal.EntityInitializerImpl.resolveKey(EntityInitializerImpl.java:94)
    at org.hibernate.sql.results.graph.Initializer.resolveKey(Initializer.java:101)
    at org.hibernate.sql.results.graph.collection.internal.AbstractImmediateCollectionInitializer.resolveKeySubInitializers(AbstractImmediateCollectionInitializer.java:189)
    at org.hibernate.sql.results.graph.collection.internal.AbstractImmediateCollectionInitializer.resolveKey(AbstractImmediateCollectionInitializer.java:120)
    at org.hibernate.sql.results.graph.collection.internal.AbstractImmediateCollectionInitializer.resolveKey(AbstractImmediateCollectionInitializer.java:42)
    at org.hibernate.sql.results.internal.StandardRowReader.coordinateInitializers(StandardRowReader.java:235)
    at org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:141)
    at org.hibernate.sql.results.spi.ListResultsConsumer.readUnique(ListResultsConsumer.java:283)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:195)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:35)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:224)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:102)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.executeQuery(JdbcSelectExecutor.java:91)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:165)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:142)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:132)
    at org.hibernate.loader.ast.internal.CollectionLoaderSingleKey.load(CollectionLoaderSingleKey.java:120)
    at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:747)
    at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:69)
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:127)
    at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:1724)
    at org.hibernate.collection.spi.AbstractPersistentCollection.lambda$initialize$3(AbstractPersistentCollection.java:617)
    at org.hibernate.collection.spi.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:266)
    at org.hibernate.collection.spi.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:615)
    at org.hibernate.collection.spi.AbstractPersistentCollection.forceInitialization(AbstractPersistentCollection.java:818)
    at org.hibernate.engine.internal.StatefulPersistenceContext.initializeNonLazyCollections(StatefulPersistenceContext.java:1162)
    at org.hibernate.engine.internal.StatefulPersistenceContext.initializeNonLazyCollections(StatefulPersistenceContext.java:1148)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:224)
    at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:35)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:224)
    at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:102)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.executeQuery(JdbcSelectExecutor.java:91)
    at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:165)
    at org.hibernate.loader.ast.internal.SingleIdLoadPlan.load(SingleIdLoadPlan.java:145)
    at org.hibernate.loader.ast.internal.SingleIdLoadPlan.load(SingleIdLoadPlan.java:117)
    at org.hibernate.loader.ast.internal.SingleIdEntityLoaderStandardImpl.load(SingleIdEntityLoaderStandardImpl.java:74)
    at org.hibernate.persister.entity.AbstractEntityPersister.doLoad(AbstractEntityPersister.java:3777)
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3766)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:604)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromCacheOrDatasource(DefaultLoadEventListener.java:590)
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:560)
    at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:544)
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:206)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadWithRegularProxy(DefaultLoadEventListener.java:289)
    at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:241)
    at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:110)
    at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:69)
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:138)
    at org.hibernate.internal.SessionImpl.fireLoadNoChecks(SessionImpl.java:1229)
    at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:1217)
    at org.hibernate.loader.internal.IdentifierLoadAccessImpl.load(IdentifierLoadAccessImpl.java:210)
    at org.hibernate.loader.internal.IdentifierLoadAccessImpl.doLoad(IdentifierLoadAccessImpl.java:161)
    at org.hibernate.loader.internal.IdentifierLoadAccessImpl.lambda$load$1(IdentifierLoadAccessImpl.java:150)
    at org.hibernate.loader.internal.IdentifierLoadAccessImpl.perform(IdentifierLoadAccessImpl.java:113)
    at org.hibernate.loader.internal.IdentifierLoadAccessImpl.load(IdentifierLoadAccessImpl.java:150)
    at org.hibernate.internal.SessionImpl.get(SessionImpl.java:1025)

on 6.5.2 the issue is not present.

yrodiere commented 1 month ago

@cmadsen Thanks for reporting. A reproducer would help a lot :)

cmadsen commented 1 month ago
String id = manyToOneRelation.getXYZ().getId();
getCurrentSession().delete(manyToOneRelation);
getCurrentSession().get(XYZ.class, id);
yrodiere commented 1 month ago
String id = manyToOneRelation.getXYZ().getId();
getCurrentSession().delete(manyToOneRelation);
getCurrentSession().get(XYZ.class, id);

Nope, that works: https://github.com/yrodiere/hibernate-test-case-templates/commit/291ceadbe1f6e5f49575bdb26316ef43bfd9c159

[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.734 s -- in org.hibernate.bugs.QuarkusLikeORMUnitTestCase

I'm afraid there's a little more to it than 3 lines of code.

Please provide an actual reproducer?

Vinche59 commented 1 month ago

@yrodiere @cmadsen I've got the same kind of errors trying to upgrade to Quarkus 3.14 and Hibernate 6.6.0. I think it's cause by this bug https://hibernate.atlassian.net/browse/HHH-18565 and hoping for a resolution in Hibernate 6.6.1

yrodiere commented 1 month ago

Alright, thanks for the heads-up!

Since we don't have a reproducer, I'll assume HHH-18565 is indeed the same problem, and will close this issue upon upgrading to 6.6.1 (#43348). => No, see below.

cmadsen commented 1 month ago

This will reproduce it, but only with the right compiler options.

@Entity
@Cacheable
public class Child {

    @Id
    private Long id;

    @OneToMany(mappedBy = "child")
    @OrderColumn
    @Cache(usage = NONSTRICT_READ_WRITE)
    List<ManyToMany> children = new ArrayList<>();

    public Long getId() {
        return id;
    }

    public void setId(Long id) {
        this.id = id;
    }

    public List<ManyToMany> getChildren() {
        return children;
    }

    public void setChildren(List<ManyToMany> children) {
        this.children = children;
    }

}

@Entity
@Cacheable
public class Parent {

    @Id
    private Long id;

    @OneToMany(mappedBy = "parent")
    @Cache(usage = NONSTRICT_READ_WRITE)
    @LazyCollection(LazyCollectionOption.FALSE)
    List<ManyToMany> children = new ArrayList<>();

    public Long getId() {
        return id;
    }

    public void setId(Long id) {
        this.id = id;
    }

    public List<ManyToMany> getChildren() {
        return children;
    }

    public void setChildren(List<ManyToMany> children) {
        this.children = children;
    }

}

@Entity
public class ManyToMany {

    @Id
    private Long id;

    @ManyToOne
    private Parent parent;

    @ManyToOne
    private Child child;

    public Long getId() {
        return id;
    }

    public void setId(Long id) {
        this.id = id;
    }

    public Parent getParent() {
        return parent;
    }

    public void setParent(Parent parent) {
        this.parent = parent;
    }

    public Child getChild() {
        return child;
    }

    public void setChild(Child child) {
        this.child = child;
    }
}

@Transactional
public class Dao {

    SessionFactory sessionFactory;

    public Dao(SessionFactory sessionFactory) {
        this.sessionFactory = sessionFactory;
    }

    public void save(Object o) {
        sessionFactory.getCurrentSession().save(o);
    }

    public List<Object> getAll(Class c) {
        Session session = sessionFactory.getCurrentSession();
        CriteriaBuilder cb = session.getCriteriaBuilder();
        CriteriaQuery<Object> query = cb.createQuery(c);
        Root<Object> root = query.from(c);
        return session.createQuery(query).getResultList();
    }

    public void doInSession(Consumer<Session> s) {
        s.accept(sessionFactory.getCurrentSession());
    }

}

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(classes = { TestHib6.TestConfig.class })
public class TestHib6 {

    @Autowired
    SessionFactory sessionFactory;

    @Autowired
    Dao dao;

    @Test
    public void testHib6Step1() {
        try {
            Parent p = new Parent();
            p.setId(1L);
            Child c = new Child();
            c.setId(2L);
            ManyToMany m = new ManyToMany();
            m.setId(3L);
            m.setParent(p);
            m.setChild(c);
            p.setChildren(Arrays.asList(m));
            c.setChildren(Arrays.asList(m));
            dao.save(p);
            dao.save(c);
            dao.save(m);
        } catch (Exception e) {
            e.printStackTrace();
            throw e;
        }
    }

    @Test
    public void testHib6Step2() {
        try {
            ManyToMany m = (ManyToMany) dao.getAll(ManyToMany.class).get(0);
            assertThat(m, is(notNullValue()));
            assertThat(m.getId(), is(3L));
            dao.doInSession(s -> {
                s.delete(m);
                Parent p = s.get(Parent.class, 1);
                Child c = s.get(Child.class, 2);
                System.out.println("id=" + p.getId() + " c.id=" + c.getId());
            });

        } catch (Exception e) {
            e.printStackTrace();
            throw e;
        }
    }

    @Configuration
    @EnableTransactionManagement
    static class TestConfig {

        static private final String H2_JDBC_URL = "jdbc:h2:mem:test;DB_CLOSE_DELAY=-1;DATABASE_TO_LOWER=true;"
                + "DEFAULT_NULL_ORDERING=HIGH;CASE_INSENSITIVE_IDENTIFIERS=FALSE"
                + ";TRACE_LEVEL_SYSTEM_OUT=1;NON_KEYWORDS=VALUE,YEAR,MONTH;MODE=PostgreSQL";

        @Bean
        protected DataSource dataSource() {
            BasicDataSource dataSource = new BasicDataSource();
            dataSource.setDriverClassName("org.h2.Driver");
            dataSource.setUrl(H2_JDBC_URL);
            return dataSource;
        }

        @Bean
        public PlatformTransactionManager transactionManager(
                SessionFactory sessionFactory) {
            return new HibernateTransactionManager(sessionFactory);
        }

        @Bean
        protected LocalSessionFactoryBean sessionFactory() {
            LocalSessionFactoryBean factoryBean = new LocalSessionFactoryBean();
            try {
                Properties pp = new Properties();
                pp.setProperty("hibernate.dialect",
                        "org.hibernate.dialect.PostgreSQLDialect");
                pp.setProperty("hibernate.hbm2ddl.auto", "create");
                pp.setProperty("hibernate.show_sql", "true");
                pp.setProperty("hibernate.format_sql", "false");
                pp.setProperty("hibernate.use_sql_comments", "true");
                pp.setProperty("hibernate.cache.use_second_level_cache",
                        "false");
                pp.setProperty("hibernate.generate_statistics", "true");
                pp.setProperty("hibernate.cache.use_query_cache", "false");
                factoryBean.setDataSource(dataSource());
                factoryBean
                        .setPackagesToScan("test.hib6");
                factoryBean.setHibernateProperties(pp);
                factoryBean.afterPropertiesSet();
            } catch (Exception e) {
                e.printStackTrace();
            }
            return factoryBean;
        }

        @Bean
        public Dao dao() {
            return new Dao(sessionFactory().getObject());
        }

    }

}
yrodiere commented 1 month ago

Thanks. Reported as https://hibernate.atlassian.net/browse/HHH-18631. Still a problem in ORM 6.6.1.

jendib commented 1 month ago

A fix has already been made. Do you know how to test locally if it's now working? My use case is a bit different (only read, no delete) so I would like to try it myself.

yrodiere commented 1 month ago

Do you know how to test locally if it's now working?

Right now you won't be able to, because the fix is targeting Hibernate ORM's main branch, which is Hibernate ORM 7.0, and Quarkus uses Hibernate ORM 6.6. Upgrading to 7.0 is work in progress (#41310). If the PR was targeting branch 6.6, the process would have been essentially:

FWIW, if your use case is read only, it might already be fixed with 6.6.1 (https://hibernate.atlassian.net/browse/HHH-18565), which we'll be upgrading to soon: #43348 . That should be easier for you to test.

jendib commented 1 month ago

@yrodiere Actually I forced hibernate-core to 6.6.1 and it indeed works in my case.

yrodiere commented 4 days ago

https://hibernate.atlassian.net/browse/HHH-18631 was fixed in ORM 6.6.2, so this will get fixed once 6.6.2 is released and we upgrade.