Live reloading an app with quarkus-hibernate-search-standalone-elasticsearch results in UncaughtExceptions being logged

[marko-bekhta]

Describe the bug

Live reloading an application that uses the Hibernate Search Standalone Pojo Mapper results in an error being logged:

18:07:57 ERROR [i.qu.ar.im.UncaughtExceptions] Error occurred while destroying instance of SYNTHETIC bean [types=[java.lang.Object, org.hibernate.search.mapper.pojo.standalone.mapping.SearchMapping], qualifiers=[@jakarta.enterprise.inject.Default, @Any], target=n/a]: java.lang.ClassCastException: class org.hibernate.search.mapper.pojo.standalone.mapping.impl.StandalonePojoMapping cannot be cast to class java.io.Closeable (org.hibernate.search.mapper.pojo.standalone.mapping.impl.StandalonePojoMapping is in unnamed module of loader io.quarkus.bootstrap.classloading.QuarkusClassLoader @56de5251; java.io.Closeable is in module java.base of loader 'bootstrap') [Error Occurred After Shutdown]

issue discovered in quarkusio/search.quarkus.io#286

Expected behavior

Live reloading an app should not produce an UncaughtExceptions log.

Actual behavior

A log is printed:

18:07:57 ERROR [i.qu.ar.im.UncaughtExceptions] Error occurred while destroying instance of SYNTHETIC bean [types=[java.lang.Object, org.hibernate.search.mapper.pojo.standalone.mapping.SearchMapping], qualifiers=[@jakarta.enterprise.inject.Default, @Any], target=n/a]: java.lang.ClassCastException: class org.hibernate.search.mapper.pojo.standalone.mapping.impl.StandalonePojoMapping cannot be cast to class java.io.Closeable (org.hibernate.search.mapper.pojo.standalone.mapping.impl.StandalonePojoMapping is in unnamed module of loader io.quarkus.bootstrap.classloading.QuarkusClassLoader @56de5251; java.io.Closeable is in module java.base of loader 'bootstrap') [Error Occurred After Shutdown]

How to Reproduce?

1. Start an app that uses quarkus-hibernate-search-standalone-elasticsearch
2. Make some changes to trigger live reload
3. Inspect the logs

Output of uname -a or ver

Linux fedora 6.8.11-200.fc39.x86_64 #1 SMP PREEMPT_DYNAMIC Sun May 26 20:05:41 UTC 2024 x86_64 GNU/Linux

Output of java -version

openjdk version "17.0.10" 2024-01-16 OpenJDK Runtime Environment Temurin-17.0.10+7 (build 17.0.10+7) OpenJDK 64-Bit Server VM Temurin-17.0.10+7 (build 17.0.10+7, mixed mode, sharing)

Quarkus version or git rev

3.11.1

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

Apache Maven 3.9.3 (21122926829f1ead511c958d89bd2f672198ae9f)

Additional information

No response

[yrodiere]

I guess the logs don't include the full stack trace? :/

[marko-bekhta]

Nope, that's all that's logged there 😔 😕
buuut ... I've started debugging it a bit:

isLoggable:36, LogCleanupFilter (io.quarkus.runtime.logging)
isLoggable:347, Handler (java.util.logging)
publish:87, ExtHandler (org.jboss.logmanager)
publish:438, LoggerNode (org.jboss.logmanager)
publish:480, LoggerNode (org.jboss.logmanager)
publish:480, LoggerNode (org.jboss.logmanager)
publish:480, LoggerNode (org.jboss.logmanager)
publish:480, LoggerNode (org.jboss.logmanager)
publish:480, LoggerNode (org.jboss.logmanager)
logRaw:1089, Logger (org.jboss.logmanager)
log:1052, Logger (org.jboss.logmanager)
log:1064, Logger (org.jboss.logmanager)
doLog:43, JBossLogManagerLogger (org.jboss.logging)
error:1497, Logger (org.jboss.logging)
destroy:-1, SearchMapping_A3Pwpzj6LZ1U3ryq007Z-Hp-28Q_Synthetic_Bean (org.hibernate.search.mapper.pojo.standalone.mapping)
destroy:-1, SearchMapping_A3Pwpzj6LZ1U3ryq007Z-Hp-28Q_Synthetic_Bean (org.hibernate.search.mapper.pojo.standalone.mapping)
destroyInternal:78, AbstractInstanceHandle (io.quarkus.arc.impl)
destroy:26, ContextInstanceHandleImpl (io.quarkus.arc.impl)
destroy:102, AbstractSharedContext (io.quarkus.arc.impl)
shutdown:455, ArcContainerImpl (io.quarkus.arc.impl)
shutdown:65, Arc (io.quarkus.arc)
run:53, ArcRecorder$1 (io.quarkus.arc.runtime)
runAllAndClear:87, StartupContext (io.quarkus.runtime)
close:79, StartupContext (io.quarkus.runtime)
doStop:-1, ApplicationImpl (io.quarkus.runner)
stop:208, Application (io.quarkus.runtime)
stop:155, Application (io.quarkus.runtime)
run:229, ApplicationLifecycleManager (io.quarkus.runtime)
run:71, Quarkus (io.quarkus.runtime)
run:44, Quarkus (io.quarkus.runtime)
run:124, Quarkus (io.quarkus.runtime)
main:-1, GeneratedMain (io.quarkus.runner)
invoke0:-1, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:77, NativeMethodAccessorImpl (jdk.internal.reflect)
invoke:43, DelegatingMethodAccessorImpl (jdk.internal.reflect)
invoke:568, Method (java.lang.reflect)
run:113, StartupActionImpl$1 (io.quarkus.runner.bootstrap)
run:840, Thread (java.lang)

so I'm guessing it has to do with

quarkus/independent-projects/arc/processor/src/main/java/io/quarkus/arc/processor/BeanGenerator.java

Line 825 in ed77ee2

protected void implementDestroy(BeanInfo bean, ClassCreator beanCreator, ProviderType providerType,

but that's as far as I got 🙈

[yrodiere]

Right, I meant the stack trace of the cause, not the logging.

Related code:

quarkus/extensions/hibernate-search-standalone-elasticsearch/deployment/src/main/java/io/quarkus/hibernate/search/standalone/elasticsearch/deployment/HibernateSearchStandaloneProcessor.java

Line 280 in 1dc2262

.destroyer(BeanDestroyer.CloseableDestroyer.class)

I don't know if it's the CloseableDestroyer failing (seems odd given it's very simple) or SearchMapping#close throwing an exception for some reason.

[marko-bekhta]

Oh but I guess that's the problem .. that it is not an AutoCloseableDestroyer, no? I mean it throws that class cast exception after all, I'll try if that helps