Issue Details (XML | Word | Printable)

Key: GLASSFISH-11094
Type: Bug Bug
Status: Resolved Resolved
Resolution: Incomplete
Priority: Major Major
Assignee: Jagadish
Reporter: eduardp
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
glassfish

SessionContext objects are caching resources that have been destroyed by the resource pool

Created: 18/Nov/09 09:47 PM   Updated: 15/Dec/09 03:24 AM   Resolved: 15/Dec/09 03:24 AM
Component/s: jca
Affects Version/s: 9.1peur2
Fix Version/s: 9.1peur2

Time Tracking:
Not Specified

Environment:

Operating System: All
Platform: Linux


Issuezilla Id: 11,094
Status Whiteboard:

v3_exclude

Tags:
Participants: eduardp, Jagadish and marina vatkina


 Description  « Hide

The short story :

I believe the pool of SessionContext(SessionContextImpl) objects are caching
resources(via the EJBContextImpl base class) that have been destroyed by the
resource pool

The long story :

we use sjsas 9.1 update 2 and get the following warning intermittedly in our
server.log file :

[#|2009-11-18T07:42:40.131+0200|WARNING|sun-appserver9.1|javax.enterprise.system.core.transaction|_ThreadID=763;_ThreadName=p:
thread-pool-1; w:
34472;_RequestID=cb02a7e8-2b02-4436-9dd8-1a3fb3e36923;|JTS5041: The resource
manager is doing work outside a global transaction
javax.transaction.xa.XAException
at
com.ibm.as400.access.AS400JDBCXAResource.throwXAException(AS400JDBCXAResource.java:970)
at
com.ibm.as400.access.AS400JDBCXAResource.start(AS400JDBCXAResource.java:938)
at com.sun.gjc.spi.XAResourceImpl.start(XAResourceImpl.java:222)
at
com.sun.jts.jta.TransactionState.startAssociation(TransactionState.java:305)
at com.sun.jts.jta.TransactionImpl.enlistResource(TransactionImpl.java:205)
at
com.sun.enterprise.distributedtx.J2EETransaction.enlistResource(J2EETransaction.java:562)
at
com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.enlistResource(J2EETransactionManagerImpl.java:372)
at
com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.enlistResource(J2EETransactionManagerOpt.java:144)
at
com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.enlistComponentResources(J2EETransactionManagerImpl.java:563)
at
com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.enlistComponentResources(J2EETransactionManagerImpl.java:404)
at com.sun.ejb.containers.BaseContainer.startNewTx(BaseContainer.java:3350)
at com.sun.ejb.containers.BaseContainer.preInvokeTx(BaseContainer.java:3270)
at com.sun.ejb.containers.BaseContainer.preInvoke(BaseContainer.java:1244)
at
com.sun.ejb.containers.EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:202)
at
com.sun.ejb.containers.EJBObjectInvocationHandlerDelegate.invoke(EJBObjectInvocationHandlerDelegate.java:77)
at $Proxy199.execDroid(Unknown Source)
at sun.reflect.GeneratedMethodAccessor246.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
com.sun.corba.ee.impl.presentation.rmi.ReflectiveTie._invoke(ReflectiveTie.java:154)
at
com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:687)
at
com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:227)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1846)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:1706)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleInput(CorbaMessageMediatorImpl.java:1088)
at
com.sun.corba.ee.impl.protocol.giopmsgheaders.RequestMessage_1_2.callback(RequestMessage_1_2.java:223)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:806)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.dispatch(CorbaMessageMediatorImpl.java:563)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.doWork(CorbaMessageMediatorImpl.java:2567)
at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)

which is always followed by

[#|2009-11-18T07:42:40.424+0200|INFO|sun-appserver9.1|javax.enterprise.system.container.ejb|_ThreadID=763;_ThreadName=p:
thread-pool-1; w: 34472;|
javax.ejb.EJBException: Unable to complete container-managed transaction.;
nested exception is: javax.transaction.SystemException: org.omg.CORBA.INTERNAL:
JTS5031: Exception [org.omg.CORBA.INTERNAL: vmcid: 0x0 minor code: 0
completed: Maybe] on Resource [rollback] operation. vmcid: 0x0 minor code: 0
completed:
No
javax.transaction.SystemException: org.omg.CORBA.INTERNAL: JTS5031: Exception
[org.omg.CORBA.INTERNAL: vmcid: 0x0 minor code: 0 completed: Maybe] on
Resource [rollback] operation. vmcid: 0x0 minor code: 0 completed: No
at
com.sun.jts.jta.TransactionManagerImpl.commit(TransactionManagerImpl.java:321)
at
com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.commit(J2EETransactionManagerImpl.java:1004)
at
com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.commit(J2EETransactionManagerOpt.java:397)
at
com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:3792)
at
com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:3571)
at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:1354)
at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:1316)
at
com.sun.ejb.containers.EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:210)
at
com.sun.ejb.containers.EJBObjectInvocationHandlerDelegate.invoke(EJBObjectInvocationHandlerDelegate.java:77)
at $Proxy199.execDroid(Unknown Source)
at sun.reflect.GeneratedMethodAccessor246.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
com.sun.corba.ee.impl.presentation.rmi.ReflectiveTie._invoke(ReflectiveTie.java:154)
at
com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:687)
at
com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:227)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1846)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:1706)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleInput(CorbaMessageMediatorImpl.java:1088)
at
com.sun.corba.ee.impl.protocol.giopmsgheaders.RequestMessage_1_2.callback(RequestMessage_1_2.java:223)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:806)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.dispatch(CorbaMessageMediatorImpl.java:563)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.doWork(CorbaMessageMediatorImpl.java:2567)
at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)
javax.ejb.EJBException: Unable to complete container-managed transaction.;
nested exception is: javax.transaction.SystemException: org.omg.CORBA.INTERNAL:
JTS5031: Exception [org.omg.CORBA.INTERNAL: vmcid: 0x0 minor code: 0
completed: Maybe] on Resource [rollback] operation. vmcid: 0x0 minor code: 0
completed:
No
at
com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:3803)
at
com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:3571)
at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:1354)
at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:1316)
at
com.sun.ejb.containers.EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:210)
at
com.sun.ejb.containers.EJBObjectInvocationHandlerDelegate.invoke(EJBObjectInvocationHandlerDelegate.java:77)
at $Proxy199.execDroid(Unknown Source)
at sun.reflect.GeneratedMethodAccessor246.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
com.sun.corba.ee.impl.presentation.rmi.ReflectiveTie._invoke(ReflectiveTie.java:154)
at
com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:687)
at
com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:227)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1846)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:1706)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleInput(CorbaMessageMediatorImpl.java:1088)
at
com.sun.corba.ee.impl.protocol.giopmsgheaders.RequestMessage_1_2.callback(RequestMessage_1_2.java:223)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:806)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.dispatch(CorbaMessageMediatorImpl.java:563)
at
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.doWork(CorbaMessageMediatorImpl.java:2567)
at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)

#]

This causes some of our ejb calls to break. The way it breaks is interesting -
we use a remote client, the remote client immediately gets a RemoteException, but
the ejb business method continues and seems to complete without a problem.

We access a db2 database on an iSeries mainframe using the jtopen jdbc driver.
We use the connection pool via both jdbc and jpa.
To troubleshoot the first stack trace/warning I wrote a btrace script to trace
into the jdbc driver and found that it throws an XAException.XAER_RMFAIL exception
because the connection to the database has been closed (I'm not sure why the
appserver translates this to a XAException.XAER_OUTSIDE).

Then I wrote another btrace program to find out why the connection was being
closed and I came up with this (filtered) output :

close==============
com.ibm.as400.access.AS400JDBCConnection@1c2f978.close
as400_=com.ibm.as400.access.AS400ThreadedServer@12c0c8a
com.ibm.as400.access.AS400JDBCPooledConnection.close(AS400JDBCPooledConnection.java:150)
com.sun.gjc.spi.ManagedConnection.destroy(ManagedConnection.java:275)
com.sun.enterprise.resource.ConnectorAllocator.destroyResource(ConnectorAllocator.java:175)
com.sun.enterprise.resource.AbstractResourcePool.destroyResource(AbstractResourcePool.java:924)
com.sun.enterprise.resource.AbstractResourcePool.resizePool(AbstractResourcePool.java:1384)
com.sun.enterprise.resource.AbstractResourcePool$Resizer.run(AbstractResourcePool.java:1532)
java.util.TimerThread.mainLoop(Timer.java:512)
java.util.TimerThread.run(Timer.java:462)

throw=============

{connection_=com.ibm.as400.access.AS400JDBCConnection@1c2f978, resourceManagerID_=50815, started_=null, allXids=[], transactionManager_=com.ibm.as400.access.JDTransactionManager@333db0, transactionTimeout_=0, lockWait_=-1, }

java.sql.SQLException: The connection does not exist.
com.ibm.as400.access.JDError.throwSQLException(JDError.java:384)
com.ibm.as400.access.AS400JDBCConnection.checkOpen(AS400JDBCConnection.java:418)
com.ibm.as400.access.AS400JDBCConnection.sendAndReceive(AS400JDBCConnection.java:2836)
com.ibm.as400.access.AS400JDBCConnection.sendAndReceive(AS400JDBCConnection.java:2796)
com.ibm.as400.access.AS400JDBCXAResource.start(AS400JDBCXAResource.java:913)
com.sun.gjc.spi.XAResourceImpl.start(XAResourceImpl.java:222)
com.sun.jts.jta.TransactionState.startAssociation(TransactionState.java:305)
com.sun.jts.jta.TransactionImpl.enlistResource(TransactionImpl.java:205)
com.sun.enterprise.distributedtx.J2EETransaction.enlistResource(J2EETransaction.java:562)
com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.enlistResource(J2EETransactionManagerImpl.java:372)
com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.enlistResource(J2EETransactionManagerOpt.java:144)
com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.enlistComponentResources(J2EETransactionManagerImpl.java:563)
com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.enlistComponentResources(J2EETransactionManagerImpl.java:404)
com.sun.ejb.containers.BaseContainer.startNewTx(BaseContainer.java:3350)
com.sun.ejb.containers.BaseContainer.preInvokeTx(BaseContainer.java:3270)
com.sun.ejb.containers.BaseContainer.preInvoke(BaseContainer.java:1244)
com.sun.ejb.containers.EJBObjectInvocationHandler.invoke(EJBObjectInvocationHandler.java:202)
com.sun.ejb.containers.EJBObjectInvocationHandlerDelegate.invoke(EJBObjectInvocationHandlerDelegate.java:77)
$Proxy199.execDroid(Unknown Source)
sun.reflect.GeneratedMethodAccessor246.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
com.sun.corba.ee.impl.presentation.rmi.ReflectiveTie._invoke(ReflectiveTie.java:154)
com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatchToServant(CorbaServerRequestDispatcherImpl.java:687)
com.sun.corba.ee.impl.protocol.CorbaServerRequestDispatcherImpl.dispatch(CorbaServerRequestDispatcherImpl.java:227)
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequestRequest(CorbaMessageMediatorImpl.java:1846)
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:1706)
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleInput(CorbaMessageMediatorImpl.java:1088)
com.sun.corba.ee.impl.protocol.giopmsgheaders.RequestMessage_1_2.callback(RequestMessage_1_2.java:223)
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.handleRequest(CorbaMessageMediatorImpl.java:806)
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.dispatch(CorbaMessageMediatorImpl.java:563)
com.sun.corba.ee.impl.protocol.CorbaMessageMediatorImpl.doWork(CorbaMessageMediatorImpl.java:2567)
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)
============

As you can see the connection gets closed when the pool gets resized, and then
some time afterwards the connection gets used again, which in my opinion is a
bug because it
has been destroyed previously.
One thing I should mention is that the AS400JDBCXAResource keeps a reference to
the connection, I don't know if it is supposed to (based on some spec/contract)
acquire
a new connection if it's current one is closed.

I then tried to see where the appserver was getting the destroyed resource from
by analyzing the last stack trace above and using btrace. And I came up with this :
As you can see (J2EETransactionManagerImpl.java:563) gets called when a new
transaction is started. Before that point in the code it calls
getExistingResourceList which
gets resources from ctx.getResourceList() where ctx is an instance of
SessionContextImpl. Looking at the source it seems that
StatelessSessionContainer keeps a pool of
SessionContextImpl objects and allocates one to each ejb call. If you look as
SessionContextImpl, I can't see where it's cached resources in the
EJBContextImpl base class
will be invalidated/released when they are destroyed, although there might be
calls to unregisterResource or some listener mechanism that I don't know about.

The fact remains that the appserver should not try to reuse the destroyed
connection, this I believe is a bug.



marina vatkina added a comment - 19/Nov/09 12:08 AM

Let's start with connections behavior...


Jagadish added a comment - 19/Nov/09 12:48 AM

setting the correct target so as to not consider it for v3.

Please post the connection pool configuration.
Is connection-leak-tracing and connection-reclaim enabled in the connection pool ?
I expect this to be a connection leak & reclaim behavior.
If you see leak-tracing related logs in server.log, correct solution is to fix
the code that is leaking the connections.

For leak-tracing details, please refer :
http://blogs.sun.com/kshitiz/entry/connection_leak_tracing

Also, are the connections cached in the session or bean instance ?
There is no need to cache the connections as appserver provides the connection
pool. Hence doing ds.getConnection() is not an expensive operation.


Jagadish added a comment - 19/Nov/09 12:50 AM

excluding from v3 as it is past HCF and the bug is reported for 9.1


eduardp added a comment - 19/Nov/09 01:12 AM

removed


Jagadish added a comment - 19/Nov/09 10:12 AM

> One thing I should mention is that the AS400JDBCXAResource keeps a reference to
> the connection, I don't know if it is supposed to (based on some spec/contract)
acquire
> a new connection if it's current one is closed.

Above comment seems interesting as it is not supposed to exhibit such behavior
as a general rule.

However, resizer of connection pool will process and kill (if needed) only a
"freed" connection ie., a connection returned by the application.

In the reported case, I see that the connection "AS400JDBCConnection@1c2f978" is
killed by resizer, but is also used by a component later.

The only possibility where it can happen is :
component-a : gets a connection [the connection is registered with the component-a]
component-a passes the connection (or any of
statement/prepared-statement/result-set/callble-statement) to component-b
component-b uses the connection and closes it.
Now, it is possible that the connection is returned to pool, resizer may kill it
while still there is a reference of the connection with component-a.

Do you see such behavior in the application ?


eduardp added a comment - 22/Nov/09 10:48 PM

Hi

I assume by component you mean session bean or message driven bean. I had a look
at the code and we don't pass connections between components.

We use only remote stateless session beans. Each bean keeps a reference to the
connection while the business method is in progress, but then closes the
connection before exit. As a fail safe, we've got a base class of all our beans
that implements an @AroundInvoke method and makes sure the connection gets closed.

We sometimes see funny metrics reported by the connection pool monitoring - for
example when I looked now, the numConnectionsUsed was -5.

Regards
Eduard


Jagadish added a comment - 23/Nov/09 12:36 AM

If you are closing the connection before the end of the method invocation, I
guess there is no need to keep a reference of the connection in the bean ?

In any case, a connection will remain associated with a component instance
only if it is not closed.
With the data that we have, resizer closes the connection but application still
has a reference to the connection.

  • resizer will process/close a connection only if its explicitly closed by the
    application or "leak-reclaim" is enabled.

Probably, you can try the following options :
1) Fix the application code that is reported to be leaking connections
2) There is no need to keep connection references. As a better programming
practice, it is recommended to acquire a connection and close it once it is
used, as pooling infrastructure is in place to provide efficiency.
3) Try to narrow down your use case and post a test-case for reproducing it
(preferably using other databases like Derby)
4) Try the same application against other databases (so as to rule out the
possibility of "AS400JDBCXAResource" keeping the reference of closed connections)


Jagadish added a comment - 23/Nov/09 12:48 AM

> We sometimes see funny metrics reported by the connection pool monitoring - for
> example when I looked now, the numConnectionsUsed was -5.

It might be issue 6613


Jagadish added a comment - 15/Dec/09 03:24 AM

Marking as not an issue.