TransactionImple.delistResource warns about an unknown resource (ARJUNA016087)

[Olivier Cailloux]

Dear forum,

I have created a sample application involving Jetty, Jersey, Hibernate, Weld and Narayana: https://github.com/oliviercailloux/sample-jetty.

Its bootstrapping is inspired by the jta-and-hibernate-standalone quickstart example. But, contrary to that example, I get a warning in the log at start, when Hibernate activates Narayana and creates my Database:

WARN  com.arjuna.ats.jta - ARJUNA016087: TransactionImple.delistResource - unknown resource

The full log (and application code) is visible here: https://github.com/oliviercailloux/sample-jetty/blob/8ec551935f1ab64c90f6e235f14c44b906730349/out.log.

Is this something I should worry about? If not, how can I avoid having this warning appear in the logs? I like to have a clean log!

Thank you for any pointer.

[Ondra Chaloupka]

It seems like there is a transaction where the resource being delisted while it was not enlisted before or the association of the resource to transaction did not proceed. I'm not sure why that could be happening.
Would you have some reproducer for this where we can check the behaviour? I think it's nothing serious as it happens on application boot-up and then not during application processing. This happens at time the application starts up, could that be connected with Hibernate creating the tables?

[Tom Jenkinson]

Hi Olivier,

I think finding out what is calling delistResource [1] may be a useful activity to help understand why it is being called for the case.

A link to the source for where the statement is produced can be found at [2] may be helpful to you (perhaps you can use a debugger to find out the call stack at that point?).

Best regards,

Tom

[1] https://jakarta.ee/specifications/transactions/2.0/apidocs/jakarta/transaction/transaction#delistResource-javax.transaction.xa.XAResource-int- (that is the Jakarta EE version of the API)

[2] https://github.com/jbosstm/narayana/blob/5.10.6.Final/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/TransactionImple.java#L856

--
You received this message because you are subscribed to the Google Groups "narayana-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to narayana-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/narayana-users/e5226571-7e82-47b1-bc82-364bf7929c1en%40googlegroups.com.

[Olivier Cailloux]

Thank you both for your replies.

Yes, the sample code published at https://github.com/oliviercailloux/sample-jetty reproduces the problem deterministically. I tried to simplify it as much as I could, but it seems very difficult to make it much simpler than it is: the problem seems to happen because of some combination of Jetty, CDI and Hibernate being present. In particular, if I manage my transaction manually (using userTransaction.begin() and userTransaction.commit()), while still using Hibernate’s EntityManager in the same way, the warning disappears. It seems like the transactional interceptors have something to do with the warning.

Yes, perhaps the problem happens when Hibernate tries to create the tables: the log (linked to in my original post) shows that the warning is produced before the statements “drop table if exists” etc. But it’s hard to be sure. In particular, creating the EMF manually before querying the Jetty server does not trigger the warning.

Here below is the stack trace when the breakpoint placed at TransactionImple.java#L856 is hit. If this may be useful, the debugger indicates that the value of the parameter xaRes is com.arjuna.ats.internal.jdbc.IsSameRMOverrideXAResource@17f520e4, and it contains a wrappedXAResource of type JdbcXAConnection, printing as xads0: conn0: url=jdbc:h2:mem: user=SA.

Olivier

Thread [qtp2028017635-21] (Suspended (breakpoint at line 856 in TransactionImple))   
    owns: StandardServiceRegistryImpl  (id=116)   
    owns: ContextualInstanceStrategy$ApplicationScopedContextualInstanceStrategy<T>  (id=117)   
    TransactionImple.delistResource(XAResource, int) line: 856   
    ConnectionImple.close() line: 300   
    TransactionalConnectionProvider.closeConnection(Connection) line: 57   
    JdbcEnvironmentInitiator$ConnectionProviderJdbcConnectionAccess.releaseConnection(Connection) line: 185   
    JdbcEnvironmentInitiator.initiateService(Map, ServiceRegistryImplementor) line: 125   
    JdbcEnvironmentInitiator.initiateService(Map, ServiceRegistryImplementor) line: 35   
    StandardServiceRegistryImpl.initiateService(ServiceInitiator<R>) line: 101   
    StandardServiceRegistryImpl(AbstractServiceRegistryImpl).createService(ServiceBinding<R>) line: 263   
    StandardServiceRegistryImpl(AbstractServiceRegistryImpl).initializeService(ServiceBinding<R>) line: 237   
    StandardServiceRegistryImpl(AbstractServiceRegistryImpl).getService(Class<R>) line: 214   
    DefaultIdentifierGeneratorFactory.injectServices(ServiceRegistryImplementor) line: 152   
    StandardServiceRegistryImpl(AbstractServiceRegistryImpl).injectDependencies(ServiceBinding<R>) line: 286   
    StandardServiceRegistryImpl(AbstractServiceRegistryImpl).initializeService(ServiceBinding<R>) line: 243   
    StandardServiceRegistryImpl(AbstractServiceRegistryImpl).getService(Class<R>) line: 214   
    InFlightMetadataCollectorImpl.<init>(BootstrapContext, MetadataBuildingOptions) line: 176   
    MetadataBuildingProcess.complete(ManagedResources, BootstrapContext, MetadataBuildingOptions) line: 118   
    EntityManagerFactoryBuilderImpl.metadata() line: 1224   
    EntityManagerFactoryBuilderImpl.build() line: 1255   
    HibernatePersistenceProvider.createEntityManagerFactory(String, Map) line: 56   
    Persistence.createEntityManagerFactory(String, Map) line: 79   
    EntityManagerFactoryProducer.produceEntityManagerFactory() line: 29   
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]   
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62   
    DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43   
    Method.invoke(Object, Object...) line: 566   
    VirtualMethodInjectionPoint<T,X>(StaticMethodInjectionPoint<T,X>).invoke(Object, Object[], Class<RuntimeException>) line: 95   
    VirtualMethodInjectionPoint<T,X>(StaticMethodInjectionPoint<T,X>).invoke(Object, Object, BeanManagerImpl, CreationalContext<?>, Class<RuntimeException>) line: 85   
    ProducerMethod$1(ProducerMethodProducer<X,T>).produce(Object, CreationalContext<T>) line: 103   
    ProducerMethod$1(AbstractMemberProducer<X,T>).produce(CreationalContext<T>) line: 161   
    ProducerMethod<X,T>(AbstractProducerBean<X,T,S>).create(CreationalContext<T>) line: 180   
    ApplicationContextImpl(AbstractContext).get(Contextual<T>, CreationalContext<T>) line: 96   
    ContextualInstanceStrategy$ApplicationScopedContextualInstanceStrategy<T>(ContextualInstanceStrategy$DefaultContextualInstanceStrategy<T>).get(Bean<T>, BeanManagerImpl, CreationalContext<?>) line: 100   
    ContextualInstanceStrategy$ApplicationScopedContextualInstanceStrategy<T>.get(Bean<T>, BeanManagerImpl, CreationalContext<?>) line: 140   
    ContextualInstance.get(Bean<T>, BeanManagerImpl, CreationalContext<?>) line: 50   
    ContextBeanInstance<T>.getInstance() line: 102   
    ProxyMethodHandler.invoke(Object, Method, Method, Object[]) line: 105   
    EntityManagerFactory$50543834$Proxy$_$$_WeldClientProxy.getCriteriaBuilder() line: not available   
    QueryHelper.selectAll(Class<T>) line: 16   
    QueryHelper$Proxy$_$$_WeldClientProxy.selectAll(Class) line: not available   
    ItemService$Proxy$_$$_WeldSubclass(ItemService).getAll() line: 26   
    ItemService$Proxy$_$$_WeldSubclass.getAll$$super() line: not available   
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]   
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62   
    DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43   
    Method.invoke(Object, Object...) line: 566   
    TerminalAroundInvokeInvocationContext.proceedInternal() line: 51   
    TerminalAroundInvokeInvocationContext(AroundInvokeInvocationContext).proceed() line: 78   
    TransactionalInterceptorRequired(TransactionalInterceptorBase).invokeInOurTx(InvocationContext, TransactionManager, RunnableWithException) line: 180   
    TransactionalInterceptorRequired(TransactionalInterceptorBase).invokeInOurTx(InvocationContext, TransactionManager) line: 168   
    TransactionalInterceptorRequired.doIntercept(TransactionManager, Transaction, InvocationContext) line: 53   
    TransactionalInterceptorRequired(TransactionalInterceptorBase).intercept(InvocationContext) line: 86   
    TransactionalInterceptorRequired.intercept(InvocationContext) line: 47   
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]   
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62   
    DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43   
    Method.invoke(Object, Object...) line: 566   
    SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(InvocationContext) line: 73   
    InterceptorMethodHandler.executeAroundInvoke(Object, Method, Method, Object[], InterceptorMethodHandler$CachedInterceptionChain, InterceptionDecorationContext$Stack) line: 84   
    InterceptorMethodHandler.executeInterception(Object, Method, Method, Object[], InterceptionType, InterceptionDecorationContext$Stack) line: 72   
    InterceptorMethodHandler.invoke(InterceptionDecorationContext$Stack, Object, Method, Method, Object[]) line: 56   
    CombinedInterceptorAndDecoratorStackMethodHandler.invoke(InterceptionDecorationContext$Stack, Object, Method, Method, Object[], boolean, boolean) line: 79   
    CombinedInterceptorAndDecoratorStackMethodHandler.invoke(InterceptionDecorationContext$Stack, Object, Method, Method, Object[]) line: 68   
    ItemService$Proxy$_$$_WeldSubclass.getAll() line: not available   
    ItemService$Proxy$_$$_WeldClientProxy.getAll() line: not available   
    ItemResource.getItems() line: 37   
    ItemResource$Proxy$_$$_WeldClientProxy.getItems() line: not available   
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]   
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62   
    DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43   
    Method.invoke(Object, Object...) line: 566   
    ResourceMethodInvocationHandlerFactory.lambda$static$0(Object, Method, Object[]) line: 52   
    622450145.invoke(Object, Method, Object[]) line: not available   
    AbstractJavaResourceMethodDispatcher$1.run() line: 124   
    JavaResourceMethodDispatcherProvider$TypeOutInvoker(AbstractJavaResourceMethodDispatcher).invoke(ContainerRequest, Object, Object...) line: 167   
    JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(Object, ContainerRequest) line: 219   
    JavaResourceMethodDispatcherProvider$TypeOutInvoker(AbstractJavaResourceMethodDispatcher).dispatch(Object, ContainerRequest) line: 79   
    ResourceMethodInvoker.invoke(RequestProcessingContext, Object) line: 469   
    ResourceMethodInvoker.apply(RequestProcessingContext) line: 391   
    ResourceMethodInvoker.apply(Object) line: 80   
    ServerRuntime$1.run() line: 255   
    Errors$1.call() line: 248   
    Errors$1.call() line: 244   
    Errors.process(Callable<T>, boolean) line: 292   
    Errors.process(Producer<T>, boolean) line: 274   
    Errors.process(Runnable) line: 244   
    Hk2RequestScope(RequestScope).runInScope(RequestContext, Runnable) line: 265   
    ServerRuntime.process(ContainerRequest) line: 234   
    ApplicationHandler.handle(ContainerRequest) line: 680   
    WebComponent.serviceImpl(URI, URI, HttpServletRequest, HttpServletResponse) line: 394   
    WebComponent.service(URI, URI, HttpServletRequest, HttpServletResponse) line: 346   
    ServletContainer.service(URI, URI, HttpServletRequest, HttpServletResponse) line: 366   
    ServletContainer.service(HttpServletRequest, HttpServletResponse) line: 319   
    ServletContainer.service(ServletRequest, ServletResponse) line: 205   
    ServletHolder.handle(Request, ServletRequest, ServletResponse) line: 763   
    ServletHandler.doHandle(String, Request, HttpServletRequest, HttpServletResponse) line: 563   
    ServletContextHandler(ScopedHandler).nextHandle(String, Request, HttpServletRequest, HttpServletResponse) line: 233   
    ServletContextHandler(ContextHandler).doHandle(String, Request, HttpServletRequest, HttpServletResponse) line: 1434   
    ServletHandler(ScopedHandler).nextScope(String, Request, HttpServletRequest, HttpServletResponse) line: 188   
    ServletHandler.doScope(String, Request, HttpServletRequest, HttpServletResponse) line: 501   
    ServletContextHandler(ScopedHandler).nextScope(String, Request, HttpServletRequest, HttpServletResponse) line: 186   
    ServletContextHandler(ContextHandler).doScope(String, Request, HttpServletRequest, HttpServletResponse) line: 1349   
    ServletContextHandler(ScopedHandler).handle(String, Request, HttpServletRequest, HttpServletResponse) line: 141   
    HandlerList.handle(String, Request, HttpServletRequest, HttpServletResponse) line: 59   
    Server(HandlerWrapper).handle(String, Request, HttpServletRequest, HttpServletResponse) line: 127   
    Server.handle(HttpChannel) line: 516   
    HttpChannelOverHttp(HttpChannel).lambda$handle$1() line: 383   
    2113332774.dispatch() line: not available   
    HttpChannelOverHttp(HttpChannel).dispatch(DispatcherType, HttpChannel$Dispatchable) line: 556   
    HttpChannelOverHttp(HttpChannel).handle() line: 375   
    HttpConnection.onFillable() line: 273   
    AbstractConnection$ReadCallback.succeeded() line: 311   
    AbstractEndPoint$1(FillInterest).fillable() line: 105   
    ChannelEndPoint$1.run() line: 104   
    EatWhatYouKill.runTask(Runnable) line: 336   
    EatWhatYouKill.doProduce(boolean) line: 313   
    EatWhatYouKill.tryProduce(boolean) line: 171   
    EatWhatYouKill.run() line: 129   
    ReservedThreadExecutor$ReservedThread.run() line: 375   
    QueuedThreadPool.runJob(Runnable) line: 773   
    QueuedThreadPool$Runner.run() line: 905   
    Thread.run() line: 834   

[Tom Jenkinson]

I assume Narayana's transactional driver is issuing the delistResource: https://github.com/jbosstm/narayana/blob/5.10.6.Final/ArjunaJTA/jdbc/classes/com/arjuna/ats/internal/jdbc/ConnectionImple.java#L300 (at least the line matches up).

Is it possible to know if the enlistResource also took place: https://github.com/jbosstm/narayana/blob/5.10.6.Final/ArjunaJTA/jdbc/classes/com/arjuna/ats/internal/jdbc/ConnectionImple.java#L939 and if so, whether the `tx` and `xares` references related to enlistResource match the `tx` and `_transactionalDriverXAConnectionConnection.getResource()` related to the delistResource, please? Please can you also confirm the count of how many calls to the enlistResource|delistResource for this connection and what the values of those parameters were?

Thanks,

Tom

To view this discussion on the web, visit https://groups.google.com/d/msgid/narayana-users/cddb5fb3-f523-4f77-9c3c-724b4d78e46bn%40googlegroups.com.

[Ondra Chaloupka]

I went through the source and tried to debug the application a bit and I have few observations. And  maybe a partial solution.

First, the WARN is not linked to Hibernate table creation.

Second note, please be aware that the we do not consider the JDBC driver production ready. If you consider to use your app in some bigger load consider using another database connection pooling library. This is a little bit broad topic and in fact I've never tried to configure this with Jetty. Still I wrote few articles on this topic at our blog, if you are interested 1, 2, 3, 4.

(a note: this is not the case currently for your app but if you consider using the Narayana XA capability you need to configure recovery manager in your app as well)

About the warning `WARN  com.arjuna.ats.jta - ARJUNA016087: TransactionImple.delistResource - unknown resource`.

The call on delist is emitted by Hibernate when it initializes the EntityManager - it's from here: https://github.com/hibernate/hibernate-orm/blob/5.2.0/hibernate-core/src/main/java/org/hibernate/engine/jdbc/env/internal/JdbcEnvironmentInitiator.java#L125

The call stack is like

`Item (POST)` -> `ItemService.persist` (https://github.com/oliviercailloux/sample-jetty/blob/master/src/main/java/io/github/oliviercailloux/jetty/ItemService.java#L31)
At time the `ItemService` is invoked there is called the @Transactional interceptor which begins the transaction.

After that there is issued your producer for EntityManager (https://github.com/oliviercailloux/sample-jetty/blob/master/src/main/java/io/github/oliviercailloux/jee/EntityManagerProducer.java).

At time the entity manager is created for the particular persistent unit there is done that connection lookup for information about database (done by Hibernate at `JdbcEnvironmentInitiator`). But the connection for this info lookup is taken inside of the started transaction. The `releaseConnection` call then tries to delist from transaction. But as this was just a connection info lookup which makes no real data access then the Hibernate has no reason to enlist such connection to the transaction. Then the release can see the active transaction and tries to delist but the resource was not enlisted and the transaction knows nothing about it and prints the warning.

When I forced manual entity manager initialization (I did just dummy call for `em.getProperties()` before txn was started, ie. before `itemS.persiste()` is invoked) then the `WARN` disappeared. You could try similar but more sophisticated.

Ondra

[Tom Jenkinson]

Thanks for following up Ondra.

Would you agree that a JBTM should be created for the "Transactional Driver" component to check if the connection was enlisted with the transaction before delisting (in the close operation: https://github.com/jbosstm/narayana/blob/master/ArjunaJTA/jdbc/classes/com/arjuna/ats/internal/jdbc/ConnectionImple.java#L277)?

To view this discussion on the web, visit https://groups.google.com/d/msgid/narayana-users/b1f6c987-c308-457e-9a92-21d1ea8e0da5n%40googlegroups.com.

[Ondra Chaloupka]

That's a good point. I was thinking whether it's the CDI and Hibernate handling it in different order. But you're right. This seems to be a general behaviour that could be addressed with a check in the ConnectionImple.

The only trouble is that we are not able to do without assuming that we work with the Narayana Transaction implementation. For JTA API it's the "javax.transaction.Transaction.delistResource" which can do such check. When the resource is not enlisted then Narayana continues in processing and only WARN is printed.

The "javax.transaction.Transaction" does not provide any API do check list of enlisted resources. We can cast the instance to "com.arjuna.ats.jta.transaction.Transaction".

I will try to scetch a PR with it. Let's see.

[Ondra Chaloupka]

@olivier.cailloux: the issue was created at https://issues.redhat.com/browse/JBTM-3409

[Olivier Cailloux]

Thanks a lot for the issue and patch!

Thank you as well for the remarks about my sample. I would like to make sure that I understand them all, because I do not want my sample about jetty + Narayana to give bad advices to my readers. I have also taken time to read the four blog posts you kindly provided, this helps.

You wrote here below that the JDBC pooling library is not considered “production ready”. Does this mean simply that it “provides lightweight JDBC pooling layer that could be nice for small projects”, as written in the Narayana JDBC integration for Tomcat blog post, thus, I suppose, implicitly discouraging it for bigger projects, or for “bigger loads” as you also wrote here? Also in that blog post, you wrote “Unfortunately, this is fine up to the time you need to process some more sophisticated pooling strategies. In this aspect the transactional driver does not play well with the default factory and some further integration work would be needed”. This also suggests that I could use the default Narayana JDBC pooling library for a small project without issues, and switch to something else when required.

It is very different if by not production ready you mean that unrecoverable data corruption could occur, or other important issues that serious developers (and myself) certainly do not want, even for small projects.

Could you be more specific about the risks one take in using the default pooling library? Is it fine to start with this and then change as needs evolve, or should one not consider this as a viable option at all?

Unrelatedly, what you wrote here below also suggests that my app currently does not use the Narayana XA capabilities. I guess you mention this because I currently use only one DB. I have a related question, actually. I took the Hibernate configuration bit from the jta-and-hibernate-standalone Narayana quickstart sample, but this illustrates single connection. I suppose I can extend this to two connexions by providing another TransactionalConnectionProvider which would use the same TransactionalDriver instance but a different connexion string. Is this correct? Relatedly, I wonder if I could somehow get rid of the TransactionalConnectionProvider class, which provides the glue from Hibernate to Narayana. I thought Hibernate could do this for me and that I would just have to tell hibernate (in the persistence.xml file) my user name and password and jdbc connection string, as per the standard JPA specs; but I am not sure whether this is officially supported. In other words, I wonder if (or why) I have to implement a specific Hibernate interface (ConnectionProvider) instead of using more standard JPA constructs.

Finally, I wonder about the recovery manager. Is my understanding correct that I can run my app without a recovery manager simultaneously running, and if a problem occurs, start another app that would run the recovery manager and solve the problem? I realize that this requires someone to be there to start this process manually, and therefore risks some down time. But I do not mind that currently, and I appreciate in counterpart the greater simplicity of the base application. Is this a sensible strategy, or will it be too late to recover anything if I was not running a recovery manager at the time a problem happened?

-- 

Olivier

[Ondra Chaloupka]

Hi Olivier,

it's as you wrote. The Narayana Transaction Driver could be used for small projects, there should not be any harm for your data (there are tests and quickstarts in the project), but the pooling capabilities and performance testing were not tuned.

I would agree with the statement that's good for the start and if the load increases and the pooling strategy is not suitable any more then you can switch to another library.

I mentioned that your app does not use the XA capabilities because you use only one database. If you assume to use only one database in your application then you are probably fine with "RESOURCE_LOCAL" transaction type of the persistence unit (when you are not running on the JEE application server where the "JTA" is recommended to be the default option). If you use the resource local transactions (https://www.infoq.com/minibooks/JTDS/) then you don't need the JTA transaction manager (ie. Narayana), you can use the user/password/jdbc connection and it's fine for you not gluing the code with the ConnectionProvider.

When you want to configure the service to use the JTA transaction manager then you need to (unfortunately) glue all the parts together. The JTA spec is about XAResources and 2PC capability. Simple JDBC Connection does not provide the API which can be managed by JTA transaction manager. This is the part where the library like transactional driver provides the capabilities and all is then glued together with some integration tweaks, like existence of the TransactionalConnectionProvider. There are probably other ways to configure the gluing. Another could be the hibernate pointing to the datasource directly: https://docs.jboss.org/hibernate/orm/5.3/userguide/html_single/chapters/jdbc/Database_Access.html#database-connectionprovider-datasource . Maybe it would be more clear and doing the same work, just I haven't tried that personally.

On question if you can have two connections using the same library, then yes, that's right. You can use the a second TransactionalConnectionProvider or there should be possible to use the same class but just parametrize it with some properties. For some more general implementation of the provider it would be good to check some elaborated one e.g.  https://github.com/hibernate/hibernate-orm/blob/5.4.27/hibernate-agroal/src/main/java/org/hibernate/agroal/internal/AgroalConnectionProvider.java#L51 (the Agroal one).

And regarding the recovery manager. You are right that you can run the recovery manager as a separate application (JVM process) but for JTA is not tested and I would really not recommend it. The correct set-up would need fine tuning of recovery modules for the recovery manager not causing data integrity issues.

Normal processing is that (for JTA) the recovery manager is run as a separate thread which communicates with the transaction manager. It's triggered periodically to check if there are some unfinished 2PC transactions and if so it fixes them and cleans the transaction log store.

When you are going to use the XA transactions then from the Narayana design perspective I would say the recovery manager is needed to be configured and used. The recovery manager does not cleans just some crashes of the system but it helps the system to withstand temporary connection unavailability and similar occurrences.