I’m having some trouble getting client side tracing to work.  The connections are managed by Glassfish connection pool so I don’t know where to set the traceDirectory and traceLevel properties.   Can these be specified as properties like the password, etc.

 

Just a little more info as well.

 

Once of the threads got this error:

 

[#|2011-12-21T10:28:54.224-0800|INFO|sun-appserver2.1|javax.enterprise.system.container.ejb|_ThreadID=20;_ThreadName=httpSSLWorkerThread-8080-0;|

javax.ejb.TransactionRolledbackLocalException: Exception thrown from bean; nested exception is: Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.3.v20091002-r5404): org.eclipse.persistence.exceptions.DatabaseException

Internal Exception: java.sql.SQLTransactionRollbackException: DERBY SQL error: SQLCODE: -1, SQLSTATE: 40XL2, SQLERRMC:

 

There was a long time where a lock could not be obtained and then next thing reported by the thread is:

 

[#|2011-12-21T10:28:54.269-0800|WARNING|sun-appserver2.1|javax.enterprise.system.core.transaction|_ThreadID=20;_ThreadName=httpSSLWorkerThread-8080-0;_RequestID=5e6bd3ac-516f-4d96-8018-baf3ce187f69;|JTS5064: Unexpected exception occurred while delisting the resource

org.apache.derby.client.am.XaException: XAER_RMFAIL : No current connection.

                at org.apache.derby.client.net.NetXAResource.throwXAException(NetXAResource.java:766)

                at org.apache.derby.client.net.NetXAResource.throwXAException(NetXAResource.java:663)

                at org.apache.derby.client.net.NetXAResource.connectionClosedFailure(NetXAResource.java:933)

                at org.apache.derby.client.net.NetXAResource.end(NetXAResource.java:230)

                at com.sun.gjc.spi.XAResourceImpl.end(XAResourceImpl.java:100)

                at com.sun.jts.jta.TransactionState.rollback(TransactionState.java:199)

                at com.sun.jts.jtsxa.OTSResourceImpl.rollback(OTSResourceImpl.java:311)

                ….

And then later:

 

[#|2011-12-21T10:28:54.380-0800|SEVERE|sun-appserver2.1|javax.enterprise.system.core.transaction|_ThreadID=20;_ThreadName=httpSSLWorkerThread-8080-0;org.omg.CORBA.INTERNAL:   vmcid: 0x0  minor code: 0 completed: Maybe;rollback;_RequestID=5e6bd3ac-516f-4d96-8018-baf3ce187f69;|JTS5031: Exception [org.omg.CORBA.INTERNAL:   vmcid: 0x0  minor code: 0 completed: Maybe] on Resource [rollback] operation.|#]

 

And then later:

 

[#|2011-12-21T10:28:54.382-0800|WARNING|sun-appserver2.1|javax.enterprise.resource.resourceadapter|_ThreadID=20;_ThreadName=httpSSLWorkerThread-8080-0;_RequestID=5e6bd3ac-516f-4d96-8018-baf3ce187f69;|RAR7115: Unable to set ClientInfo for connection

java.sql.SQLClientInfoException: No current connection.

                at org.apache.derby.client.net.NetConnection40.setClientInfo(NetConnection40.java:274)

                at org.apache.derby.client.am.LogicalConnection40.setClientInfo(LogicalConnection40.java:254)

                at com.sun.gjc.spi.jdbc40.ConnectionHolder40.setClientInfo(ConnectionHolder40.java:304)

                at com.sun.gjc.spi.jdbc40.ConnectionHolder40.close(ConnectionHolder40.java:513)

                at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.closeDatasourceConnection(DatabaseAccessor.java:450)

                at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.closeConnection(DatasourceAccessor.java:488)

 

Another thread saw:

 

[#|2011-12-21T10:28:54.315-0800|INFO|sun-appserver2.1|javax.enterprise.system.container.ejb|_ThreadID=75;_ThreadName=httpSSLWorkerThread-8080-3;|

javax.ejb.TransactionRolledbackLocalException: Exception thrown from bean; nested exception is: Exception [EclipseLink-4002] (Eclipse Persistence Services - 1.1.3.v20091002-r5404): org.eclipse.persistence.exceptions.DatabaseException

Internal Exception: java.sql.SQLTransactionRollbackException: DERBY SQL error: SQLCODE: -1, SQLSTATE: 40XL2, SQLERRMC:

Wed Dec 21 10:28:54 PST 2011

 

And then saw:

 

[#|2011-12-21T10:28:54.326-0800|WARNING|sun-appserver2.1|javax.enterprise.system.core.transaction|_ThreadID=75;_ThreadName=httpSSLWorkerThread-8080-3;_RequestID=b2c68a79-1eb1-497d-aab5-f3875f656ed4;|JTS5064: Unexpected exception occurred while delisting the resource

java.lang.NullPointerException

                at org.apache.derby.client.net.Request.sendBytes(Request.java:1289)

                at org.apache.derby.client.net.Request.flush(Request.java:1283)

                at org.apache.derby.client.net.NetAgent.sendRequest(NetAgent.java:393)

                at org.apache.derby.client.net.NetAgent.flush_(NetAgent.java:273)

                at org.apache.derby.client.am.Agent.flowOutsideUOW(Agent.java:196)

                at org.apache.derby.client.net.NetXAResource.end(NetXAResource.java:242)

                at com.sun.gjc.spi.XAResourceImpl.end(XAResourceImpl.java:100)

 

and then saw:

 

[#|2011-12-21T10:28:54.389-0800|WARNING|sun-appserver2.1|javax.enterprise.resource.resourceadapter|_ThreadID=75;_ThreadName=httpSSLWorkerThread-8080-3;_RequestID=b2c68a79-1eb1-497d-aab5-f3875f656ed4;|RAR7115: Unable to set ClientInfo for connection

java.sql.SQLClientInfoException: No current connection.

                at org.apache.derby.client.net.NetConnection40.setClientInfo(NetConnection40.java:274)

                at org.apache.derby.client.am.LogicalConnection40.setClientInfo(LogicalConnection40.java:254)

                at com.sun.gjc.spi.jdbc40.ConnectionHolder40.setClientInfo(ConnectionHolder40.java:304)

                at com.sun.gjc.spi.jdbc40.ConnectionHolder40.close(ConnectionHolder40.java:513)

                at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.closeDatasourceConnection(DatabaseAccessor.java:450)

                at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.closeConnection(DatasourceAccessor.java:488)

                at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.closeConnection(DatabaseAccessor.java:473)

                at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.closeJTSConnection(DatasourceAccessor.java:174)

 

So it looks like something is closing the internals of the connections in not a good way as the NullPointerException above can only occur if the socketOutputStream passed to sendBytes is null.

 

Note that the Glassfish database connection pool is setup to close all connection on a connection error.

 

From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Wednesday, December 21, 2011 11:34 AM
To: derby-dev@db.apache.org
Subject: RE: Problem with a deadlock with Derby 10.8.1.2 and Glassfish V2.1.1

 

I cannot upgrade to 10.8.8.2 at this point as this is in production without upgrade possibility.  A also at this point, I don’t want to change to many variables and have the problem disappear.  Right now I can get it to reproduce pretty readily.

 

I was able to connect with a debug and indeed the thread is blocking on the “java.net.SocketInputStream.read”.  Through the debugger if I force an interrupt, I returns from the socket call with an I/O error.  So does this mean that the problem is in the derby server side since the socket is  valid and not closed before I issue the interrupt?

 

I am going to enable tracing and see what I find.

 

From: Katherine Marsden [mailto:kmarsdenderby@sbcglobal.net]
Sent: Wednesday, December 21, 2011 11:14 AM
To: derby-dev@db.apache.org
Subject: Re: Problem with a deadlock with Derby 10.8.1.2 and Glassfish V2.1.1

 

On 12/21/2011 6:14 AM, Bergquist, Brett wrote:

I have a problem with a deadlock with Derby 10.8.1.2 and Glassfish V2.1.1 but at this point I cannot tell if it is a Derby problem or a Glassfish problem so I am looking for some guidance. 

 

A database pool is created using the “org.apache.derby.jdbc.ClientXADataSource” XADataSource.   Connection validation is turned on and uses “auto-commit” to validate the connection and attempts to close all connections on any validation failure.

 

The deadlock is triggered when I have a couple of transactions that cause a Derby locks deadlock.  Deadlock detection and tracing is turned on in Derby and it correctly detects the locking deadlock and terminates one of the transactions.   Soon after this, however,  Glassfish becomes stuck.  Here is the only reference to Derby in the “jstack” output of Glassfish:

 

"PMCollectionActivationManager.newPmTestResult" daemon prio=3 tid=0x0000000103926800 nid=0xaf runnable [0xfffffffc218fa000]

   java.lang.Thread.State: RUNNABLE

                at java.net.SocketInputStream.socketRead0(Native Method)

                at java.net.SocketInputStream.read(SocketInputStream.java:129)

                at org.apache.derby.client.net.Reply.fill(Unknown Source)

                at org.apache.derby.client.net.Reply.ensureALayerDataInBuffer(Unknown Source)

                at org.apache.derby.client.net.Reply.readDssHeader(Unknown Source)

                at org.apache.derby.client.net.Reply.startSameIdChainParse(Unknown Source)

                at org.apache.derby.client.net.NetXAConnectionReply.readLocalXACommit(Unknown Source)

                at org.apache.derby.client.net.NetXAConnection.readLocalXACommit_(Unknown Source)

                at org.apache.derby.client.net.NetXAConnection.readCommit(Unknown Source)

                at org.apache.derby.client.net.NetConnection.readXACommit_(Unknown Source)

                at org.apache.derby.client.am.Connection.readCommit(Unknown Source)

                at org.apache.derby.client.am.Connection.readAutoCommit(Unknown Source)

                at org.apache.derby.client.am.Connection.flowClose(Unknown Source)

                at org.apache.derby.client.am.Connection.closeResourcesX(Unknown Source)

                at org.apache.derby.client.am.Connection.closeResources(Unknown Source)

                - locked <0xfffffffc91831e18> (a org.apache.derby.client.net.NetConnection40)

                at org.apache.derby.client.net.NetConnection.closeResources(Unknown Source)

                - locked <0xfffffffc91831e18> (a org.apache.derby.client.net.NetConnection40)

                at org.apache.derby.client.ClientPooledConnection.close(Unknown Source)

                - locked <0xfffffffc91831cf8> (a org.apache.derby.client.ClientXAConnection40)

                at org.apache.derby.client.ClientXAConnection.close(Unknown Source)

                - locked <0xfffffffc91831cf8> (a org.apache.derby.client.ClientXAConnection40)

                at com.sun.gjc.spi.ManagedConnection.destroy(ManagedConnection.java:276)


First thing I would suggest is move up to 10.8.2.2 just to get running on the latest.
I wonder is there indication in the derby.log what went wrong here?  If not, I would suggest enabling client and server side DRDA tracing to get a clue as to what went wrong with the protocol here.
http://wiki.apache.org/db-derby/ProtocolDebuggingTips


Maybe there is some issue with the logic that dermines if autocommit will generate flow.

   // precondition: autoCommit_ is true
    void readAutoCommit() throws SqlException {
        if (willAutoCommitGenerateFlow()) {
            readCommit();
        }
    }

  public boolean willAutoCommitGenerateFlow() throws org.apache.derby.client.am.SqlException {
        if (!autoCommit_) {
            return false;
        }
        if (! allowLocalCommitRollback_()) {
            return false;
        }
        return true;
    }