Bug 579886

Each time I see this NPE in the log, the below "javax.resource.ResourceException: Transaction is not active" exception occurs right afterwards, so I'm guessing it's a side effect of the NPE...

16:02:02,850 INFO  [ResourceManagerBean] User [org.rhq.core.domain.auth.Subject[id=1,name=admin]] is marking resource [Resource[id=10165, type=RHQ Server Content Source Server Plugin Subsystem, key=rhq.serverplugin:service=ContentSourcePluginService, name=RHQ Server Content Source Server Plugin Subsystem, parent=jetengine RHQ Server,  JBoss AS 4.2.3.GA default (0.0.0.0:2099)]] for asychronous deletion
16:02:02,855 WARN  [JDBCExceptionReporter] SQL Error: 0, SQLState: null
16:02:02,855 ERROR [JDBCExceptionReporter] Transaction is not active: tx=TransactionImple < ac, BasicAction: 7f000001:81e6:4bbb92e8:135 status: ActionStatus.ABORT_ONLY >; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: 7f000001:81e6:4bbb92e8:135 status: ActionStatus.ABORT_ONLY >)
16:02:02,862 ERROR [ProductPluginDeployer] Failed to register RHQ plugin file [file:/home/ips/Applications/jon-server-2.4.0-SNAPSHOT/jbossas/server/default/deploy/rhq.ear/rhq-downloads/rhq-plugins/jopr-rhq-server-plugin-3.0.0-20100406.173753-27.jar]
javax.ejb.EJBException: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection
	at org.jboss.ejb3.tx.Ejb3TxPolicy.handleExceptionInOurTx(Ejb3TxPolicy.java:63)
	at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:83)
	at org.jboss.aspects.tx.TxInterceptor$RequiresNew.invoke(TxInterceptor.java:253)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:95)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
	at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:110)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:240)
	at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:210)
	at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:84)
	at $Proxy302.deleteResource(Unknown Source)
	at org.rhq.enterprise.server.resource.metadata.ResourceMetadataManagerBean.removeObsoleteTypes(ResourceMetadataManagerBean.java:431)
	at org.rhq.enterprise.server.resource.metadata.ResourceMetadataManagerBean.updateTypes(ResourceMetadataManagerBean.java:407)
	at org.rhq.enterprise.server.resource.metadata.ResourceMetadataManagerBean.registerPlugin(ResourceMetadataManagerBean.java:323)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
	at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
	at org.rhq.enterprise.server.common.TransactionInterruptInterceptor.addCheckedActionToTransactionManager(TransactionInterruptInterceptor.java:77)
	at sun.reflect.GeneratedMethodAccessor196.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
	at org.rhq.enterprise.server.authz.RequiredPermissionsInterceptor.checkRequiredPermissions(RequiredPermissionsInterceptor.java:156)
	at sun.reflect.GeneratedMethodAccessor195.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
	at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
	at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:191)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:95)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
	at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:110)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:240)
	at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:210)
	at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:84)
	at $Proxy409.registerPlugin(Unknown Source)
	at org.rhq.enterprise.server.core.plugin.ProductPluginDeployer.registerPluginJar(ProductPluginDeployer.java:504)
	at org.rhq.enterprise.server.core.plugin.ProductPluginDeployer.access$000(ProductPluginDeployer.java:56)
	at org.rhq.enterprise.server.core.plugin.ProductPluginDeployer$LatchedPluginDeploymentService.executeService(ProductPluginDeployer.java:613)
	at org.rhq.enterprise.server.core.concurrency.LatchedServiceController$LatchedService.run(LatchedServiceController.java:266)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection
	at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:629)
	at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:73)
	at org.rhq.enterprise.server.resource.ResourceManagerBean.deleteResource(ResourceManagerBean.java:288)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:112)
	at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
	at org.rhq.enterprise.server.common.TransactionInterruptInterceptor.addCheckedActionToTransactionManager(TransactionInterruptInterceptor.java:77)
	at sun.reflect.GeneratedMethodAccessor196.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
	at org.rhq.enterprise.server.authz.RequiredPermissionsInterceptor.checkRequiredPermissions(RequiredPermissionsInterceptor.java:156)
	at sun.reflect.GeneratedMethodAccessor195.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:118)
	at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
	at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
	at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
	... 70 more
Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection
	at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
	at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:426)
	at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
	at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:140)
	at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1547)
	at org.hibernate.loader.Loader.doQuery(Loader.java:673)
	at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
	at org.hibernate.loader.Loader.doList(Loader.java:2213)
	at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2104)
	at org.hibernate.loader.Loader.list(Loader.java:2099)
	at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:378)
	at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338)
	at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172)
	at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121)
	at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
	at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:64)
	... 94 more
Caused by: org.jboss.util.NestedSQLException: Transaction is not active: tx=TransactionImple < ac, BasicAction: 7f000001:81e6:4bbb92e8:135 status: ActionStatus.ABORT_ONLY >; - nested throwable: (javax.resource.ResourceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: 7f000001:81e6:4bbb92e8:135 status: ActionStatus.ABORT_ONLY >)
	at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:95)
	at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:47)
	at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
	... 108 more
Caused by: javax.resource.ResourceException: Transaction is not active: tx=TransactionImple < ac, BasicAction: 7f000001:81e6:4bbb92e8:135 status: ActionStatus.ABORT_ONLY >
	at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:319)
	at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:402)
	at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:849)
	at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:89)
	... 110 more

> "since I know you added the code to delete Resources with no-longer-existing types to the plugin metadata update code recently"

I did not add that code (at least that doesn't sound familiar). But I will say that we need to be VERY CAREFUL before we change the order of the things that StartupServlet does. It seems everytime we alter the order of those things, bad side effects happen that we aren't aware of (that's why there is a long warning comment in that section of code in the StartupServlet).

I'll look to see if we can change the scheduler startup earlier.

as suspected, we can't reorder when the scheduler is started compared to where the plugin deployment starts. If we start the scheduler before starting the plugin deployer, that means we start the scheduler before we start the comm layer and before the server plugin container. Both would be bad. We need to figure out another way to solve this. This is the comment in StartupServlet that explains things:

        // The order here is important!!!
        // IF YOU WANT TO CHANGE THE ORDER YOU MUST GET THE CHANGE PEER-REVIEWED FIRST BEFORE COMMITTING IT!!!
        //
        // If we start the scheduler before the comm layer, what happens if a stored job needs to send a message?
        // But if we start the comm layer before the scheduler, what happens if a message is received that needs
        // a job scheduled for it? I think the former is more likely to happen than the latter
        // (that is, a scheduled job would more likely need to send a message; as opposed to an incoming message
        // causing a job to be scheduled), so that explains the ordering of the comm layer and the scheduler.
        startHibernateStatistics();
        startPluginDeployer(); // make sure this is before starting the server plugin container
        startServerPluginContainer(); // before comm in case an agent wants to talk to it
        installJaasModules();
        startServerCommunicationServices();
        startScheduler();

how did we never see this before? this code was added by joe back in june 2009 (see bit blame, line 433):

cf56307a (Joseph Marques  2009-06-28 05:56:35 +0000  431)                             List<Integer> deletedIds = resourceManager.deleteResource(overlord, res
cf56307a (Joseph Marques  2009-06-28 05:56:35 +0000  432)                             for (Integer deletedResourceId : deletedIds) {
cf56307a (Joseph Marques  2009-06-28 05:56:35 +0000  433)                                 resourceManager.deleteSingleResourceInNewTransaction(overlord, dele
cf56307a (Joseph Marques  2009-06-28 05:56:35 +0000  434)                             }

and I bet it was there even before joe's commit because the previous version had deleteResource call - and that was from 2008:

Resource res = resIter.next();
resourceManager.deleteResource(overlord, res.getId());
resIter.remove();

from commit 9f57b8901fcc1102e66ddcdda8b3138557223378 on may 21, 2008

the problem is due to the call to deleteSingleResourceInNewTransaction which was added in cf56307a if I read the history correctly

(In reply to comment #6)
> the problem is due to the call to deleteSingleResourceInNewTransaction which
> was added in cf56307a if I read the history correctly    

sorry, the problem is line 431 - the call to deleteResource.

We need to figure out how to work around the fact that we need to delete the resource but the scheduler isn't available yet (i.e. we need to unschedule the job later)

commit: 296ca231d68e97db1cb3012ac6734b7d2069e52a

Refactored the way the scheduler is started. The startup servlet will now just "init" the scheduler earlier, but it will not start it. It will then do the plugin deployment stuff and then start the scheduler in the same order as before. This provides a non-null scheduler that can be used to unschedule jobs but the scheduler won't actually start or run the jobs until the proper time.

Here's how to replicate the problem/test the solution:

1) copy the attached "test-plugin-1.0.jar" in <server-home-dir>/plugins
2) start server and agent
3) import the Sample Plugin Server resource into inventory
4) shutdown the server and agent
5) delete the <server-home-dir>/plugins/test-plugin-1.0.jar you copied in step 1
6) copy the version 2.0 of the test plugin (see attached test-plugin-2.0.jar). This introduces a new resource type (the old resource type no longer exists)
7) start the server up again
8) verify that you do not get those ugly error messages again and verify that the resource you inventoried in step 3 is now gone (it will have been deleted when the new plugin metadata was updated)

Created attachment 405079 [details]
test-plugin-1.0.jar

Created attachment 405080 [details]
test-plugin-2.0.jar

tested JON#124 Revision 10615

Steps: 
1)Copied the test-plugin-1.0.jar into the server-home-dir>/plugins
2)Start the server and agent.
3)import the sample plugin server resource to the inventory.
4)shut down the server and agent.
5)delete the <server-home-dir>/plugins/test-plugin-1.0.jar i copied in step
1

6)copy the version 2.0 of the test plugin.
7)start the server up  again.

observation : there is no error message on the server log.
But the old resource type still shows up.

so moving it back to dev.

This needs some triage to determine relevancy wrt the beta release

Here's a better set of replication procedures - use these to test:

1) copy the attached "test-plugin-1.0.jar" in <server-home-dir>/plugins
2) start server and wait for it to start up completely
3) start the agent
4) import the "My Resource" Sample Plugin Server resource into inventory
5) shutdown the server and agent
6) copy the version 2.0 of the test plugin to <server-home-dir>/plugins (see attached test-plugin-2.0.jar).
This introduces a new resource type (the old resource type no longer exists)
7) start the server up again
8) verify that you do not get those ugly error messages again and verify that
the resource you inventoried in step 3 is now gone (it will have been deleted
when the new plugin metadata was updated). You may have to wait some amount of seconds before the asynchronous deletion job kicks off - but it should not take on the order of minutes - it should be pretty quick that you see the old resource get removed.

You should see messages like this in the server log to let you know it did the right thing:

INFO  [ProductPluginDeployer] Deploying [1] new or updated agent plugins: [SkeletonPlugin]

INFO  [ResourceMetadataManagerBean] Persisting new type [ResourceType[id=0, category=Server, name=NEW NAME Sample Plugin Server, plugin=SkeletonPlugin]]...

INFO  [ResourceManagerBean] User [org.rhq.core.domain.auth.Subject[id=1,name=admin]] is marking resource [Resource[id=10002, type=Sample Plugin Server, key=My Resource Key, name=My Resource, parent=localhost, version=1.0]] for asynchronous deletion

Verified on JON build #180 - Revision: 10621
http://hudson-qe.rhq.rdu.redhat.com:8080/job/jon/180/

1) copy the attached "test-plugin-1.0.jar" in <server-home-dir>/plugins
2) start server and agent
3) import the Sample Plugin Server resource into inventory
4) shutdown the server and agent
5) delete the <server-home-dir>/plugins/test-plugin-1.0.jar you copied in step
1
6) copy the version 2.0 of the test plugin (see attached test-plugin-2.0.jar).
This introduces a new resource type (the old resource type no longer exists)
7) start the server up again

Verify that there isn't error/exception like EJBTransactionRolledbackException or 'Transaction is not active' in server log.
The resource inventoried in step-3 has gone and it have been deleted when the new plugin metadata was updated.

The server log:
2010-06-01 14:52:05,254 INFO  [org.rhq.enterprise.server.core.plugin.ProductPluginDeployer] Deploying [1] new or updated agent plugins: [SkeletonPlugin]
2010-06-01 14:52:05,379 INFO  [org.rhq.enterprise.server.resource.metadata.ResourceMetadataManagerBean] Persisting new type [ResourceType[id=0, category=Server, name=NEW NAME Sample Plugin Server, plugin=SkeletonPlugin]]...
2010-06-01 14:52:05,563 INFO  [org.rhq.enterprise.server.resource.ResourceManagerBean] User [org.rhq.core.domain.auth.Subject[id=1,name=admin]] is marking resource [Resource[id=10002, type=Sample Plugin Server, key=My Resource Key, name=My Resource, parent=10.65.193.1, version=1.0]] for asynchronous deletion

Mass-closure of verified bugs against JON.