Very strange issue uncovered while tracing another (THOUSANDS of hidden "unsupported type" exceptions)

Support
#1

While trying to figure out an odd problem I’m having in my application, I turned the Jmix logging levels up to “trace.” In doing so, I noticed there are literally thousands upon thousands of hidden exceptions happening that the trace log level shows:

2023-11-09 10:33:39.320 TRACE 364790 --- [nio-8080-exec-5] io.jmix.data.impl.EntityFetcher          : Fetching instance com.medflex.medflexj.entity.carrier.Carrier-98fc5d9c-0fe3-607c-6799-04c1deb5004e [managed]
2023-11-09 10:33:39.320 TRACE 364790 --- [nio-8080-exec-5] io.jmix.data.impl.EntityFetcher          : Fetching property lineItem
2023-11-09 10:33:39.320 TRACE 364790 --- [nio-8080-exec-5] io.jmix.core.EntityStates                : EntityStates.isDetached is called for unsupported type 'InvoiceLine'. Stacktrace:
io.jmix.core.common.util.StackTrace.asString(StackTrace.java:29)
io.jmix.core.EntityStates.isDetached(EntityStates.java:120)
io.jmix.data.impl.EntityFetcher.fetch(EntityFetcher.java:159)
io.jmix.data.impl.EntityFetcher.fetch(EntityFetcher.java:69)
io.jmix.eclipselink.impl.JmixEclipseLinkQuery.lambda$getResultList$0(JmixEclipseLinkQuery.java:142)
io.jmix.eclipselink.impl.JmixEclipseLinkQuery.getResultFromCache(JmixEclipseLinkQuery.java:845)
io.jmix.eclipselink.impl.JmixEclipseLinkQuery.getResultList(JmixEclipseLinkQuery.java:138)
io.jmix.eclipselink.impl.JpaDataStore.executeQuery(JpaDataStore.java:576)
io.jmix.eclipselink.impl.JpaDataStore.loadAll(JpaDataStore.java:167)
io.jmix.core.datastore.AbstractDataStore.loadList(AbstractDataStore.java:127)
io.jmix.core.impl.UnconstrainedDataManagerImpl.loadList(UnconstrainedDataManagerImpl.java:112)
io.jmix.core.FluentLoader$ByQuery.list(FluentLoader.java:570)
com.medflex.medflexj.service.ReceivedPaymentsForGivenInvoiceService.getPaymentsFor(ReceivedPaymentsForGivenInvoiceService.java:28)
com.medflex.medflexj.web.screens.invoice.InvoiceEdit.fillPaymentsDc(InvoiceEdit.java:880)
com.medflex.medflexj.web.screens.invoice.InvoiceEdit.onInvoiceDcItemChange(InvoiceEdit.java:215)
io.jmix.core.common.event.EventHub.publish(EventHub.java:170)
io.jmix.ui.model.impl.InstanceContainerImpl.fireItemChanged(InstanceContainerImpl.java:167)
io.jmix.ui.model.impl.InstanceContainerImpl.setItem(InstanceContainerImpl.java:100)
io.jmix.ui.model.impl.InstanceLoaderImpl.load(InstanceLoaderImpl.java:106)
io.jmix.ui.component.dataloadcoordinator.OnFrameOwnerEventLoadTrigger.load(OnFrameOwnerEventLoadTrigger.java:48)
io.jmix.ui.component.dataloadcoordinator.OnFrameOwnerEventLoadTrigger.lambda$new$0(OnFrameOwnerEventLoadTrigger.java:39)
io.jmix.core.common.event.EventHub.publish(EventHub.java:170)
io.jmix.ui.screen.Screen.fireEvent(Screen.java:124)
io.jmix.ui.screen.UiControllerUtils.fireEvent(UiControllerUtils.java:58)
io.jmix.ui.sys.ScreensImpl.fireScreenBeforeShowEvent(ScreensImpl.java:1364)
com.haulmont.cuba.web.sys.CubaScreens.fireScreenBeforeShowEvent(CubaScreens.java:651)
io.jmix.ui.sys.ScreensImpl.show(ScreensImpl.java:357)
io.jmix.ui.screen.Screen.show(Screen.java:306)
io.jmix.ui.action.list.EditAction.execute(EditAction.java:377)
io.jmix.ui.action.list.EditAction.actionPerform(EditAction.java:324)
io.jmix.ui.component.impl.AbstractTable.handleClickAction(AbstractTable.java:1393)
io.jmix.ui.component.impl.AbstractTable.lambda$initComponent$db766529$1(AbstractTable.java:1110)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base/java.lang.reflect.Method.invoke(Method.java:568)
com.vaadin.event.ListenerMethod.receiveEvent(ListenerMethod.java:709)
com.vaadin.event.EventRouter.fireEvent(EventRouter.java:399)
com.vaadin.event.EventRouter.fireEvent(EventRouter.java:363)
com.vaadin.server.AbstractClientConnector.fireEvent(AbstractClientConnector.java:1216)
com.vaadin.v7.ui.Table.handleClickEvent(Table.java:3198)
com.vaadin.v7.ui.Table.changeVariables(Table.java:2988)
io.jmix.ui.widget.JmixTable.changeVariables(JmixTable.java:357)
io.jmix.ui.widget.JmixGroupTable.changeVariables(JmixGroupTable.java:297)
com.vaadin.server.communication.ServerRpcHandler.changeVariables(ServerRpcHandler.java:616)
com.vaadin.server.communication.ServerRpcHandler.handleInvocation(ServerRpcHandler.java:468)
com.vaadin.server.communication.ServerRpcHandler.handleInvocations(ServerRpcHandler.java:411)
com.vaadin.server.communication.ServerRpcHandler.handleRpc(ServerRpcHandler.java:275)
com.vaadin.server.communication.UidlRequestHandler.synchronizedHandleRequest(UidlRequestHandler.java:83)
com.vaadin.server.SynchronizedRequestHandler.handleRequest(SynchronizedRequestHandler.java:40)
com.vaadin.server.VaadinService.handleRequest(VaadinService.java:1636)
com.vaadin.server.VaadinServlet.service(VaadinServlet.java:465)
javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:209)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
io.jmix.core.impl.logging.LogMdcFilter.doFilterInternal(LogMdcFilter.java:28)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:337)
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115)
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:122)
org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:116)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126)
org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:109)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter.doFilter(RememberMeAuthenticationFilter.java:106)
org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter.doFilter(RememberMeAuthenticationFilter.java:97)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.session.ConcurrentSessionFilter.doFilter(ConcurrentSessionFilter.java:147)
org.springframework.security.web.session.ConcurrentSessionFilter.doFilter(ConcurrentSessionFilter.java:125)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103)
org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90)
org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:112)
org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:82)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.session.DisableEncodeUrlFilter.doFilterInternal(DisableEncodeUrlFilter.java:42)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:346)
org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:221)
org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:186)
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354)
org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:390)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:926)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1790)
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.base/java.lang.Thread.run(Thread.java:840)

There are literally thousands of these (it eventually crashes IDEA with the spam). They are thrown for most of the entity types in my application - all of these entities are ones that existed when the app was still a CUBA app, which was migrated (by you guys; it was a paid migration). All of them have the old CUBA extends StandardEntity in their class delcarations.

Is this a bug with the CUBA compatibility module? These have likely always been happening; turning the logging up to TRACE uncovered them.

I wonder if this could be the cause of many of the weird problems I keep seeing. If the framework can’t detect if something’s detached or not… that could likely be a big problem .

1 Like
#2

This is probably the source of many odd issues in migrated CUBA → Jmix apps, and also likely a hidden performance issue, too, since these exceptions are thrown in quantities of thousands!

#3

Two months ago we completed the first Cuba->Jmix migration.
This is our internal application with a technical support database, the number of users is no more than 10 and performance is not very important…
But I also see this in the log.
It’s really important to understand why this happens and how it affects the application.

1 Like
#5

If you take a look at the code line mentioned in the stacktrace, you’ll find that no exception is thrown. The stacktrace is printed just for debugging purposes (as any trace message does):

    public boolean isDetached(Object entity) {
        checkNotNullArgument(entity, "entity is null");
        if (entity instanceof Entity && getUncheckedEntityEntry(entity).isDetached()) {
            return true;
        } else {
            if (log.isTraceEnabled()) {
                log.trace("EntityStates.isDetached is called for unsupported type '{}'. Stacktrace:\n{}",
                        entity.getClass().getSimpleName(), StackTrace.asString());
            }
        }
        return false;
    }

So, this is not an exception, the message just informs that execution goes to the else branch of the if statement.

Probably this message should only be printed when the following condition is not true: entity instanceof Entity. If the entity is New or Managed, then no message should be printed. We’ll fix this.

You should not worry about this TRACE message.

P.S. Just in case, the TRACE logging level should be enabled only for a short time when you investigate some problem and should not be used permanently.

1 Like
#6

I think you’re missing the point! In a migrated CUBA–>Jmix app, the framework is not able to determined if the entity is detached or not because the instanceof Entity is failing because migrated CUBA entities have the old extends StandardEntity as part of their class definitions. So the framework is simply saying all of them are NOT detached - but it doesn’t really know if they are or not.

#7

Are you sure about that? Could you please put a breakpoint to this method and check that?

I’ve just tried to migrate a sample cuba project to Jmix and I see that migrated entity actually implements the Entity interface.

image

This interface is not defined in the entity source code, it is added by Jmix Gradle plugin while enhancing entities. So please, double check that for your entities the instanceof Entity is false.

#8

I don’t know why there would be thousands upon thousands of “called for unsupported type” messages if the instanceof call wasn’t failing. The message seems self-explanatory to me: the framework doesn’t think these objects are entities…but they definitely are!

I can make some test code and see what happens.

#9

As I already mentioned:

Probably this message should only be printed when the following condition is not true: entity instanceof Entity. If the entity is New or Managed, then no message should be printed. We’ll fix this.

I guess in your case the following condition && getUncheckedEntityEntry(entity).isDetached() is not satisfied. In this case the message is printed by mistake and we’ll fix it.

1 Like
#10

Ok, I see your point, the message alone is the bug, and CUBA migrated entities DO pass the instanceof Entity check (I tested this myself.)

This arose from trying to debug/figure out some very strange issues I’m having suddenly after things being 100% functional for quite some time —> [1.5.x/Classic UI] "Unable to access value holder..." - I need to find out how to trace down and figure out these messages.