lunes, 26 de agosto de 2013

BEA-001153 using non-transactional AQ backed MDB in Weblogic

I started receiving the following warning in the Weblogic log after changing the transactionality of an AQ backed MDB:

BEA-001153: Forcibly releasing inactive/harvested connection "weblogic.jdbc.wrapper.PoolConnection_oracle_jdbc_driver_T4CConnection@4a8025" back into the data source connection pool "jdbc/XYZ", currently reserved by: java.lang.Exception

The complete stack trace is (BEA-001153):

Forcibly releasing inactive/harvested connection "weblogic.jdbc.wrapper.PoolConnection_oracle_jdbc_driver_T4CConnection@4a8025" back into the data source connection pool "jdbc/XYZ", currently reserved by: java.lang.Exception
        at weblogic.jdbc.common.internal.ConnectionEnv.setup(ConnectionEnv.java:352)
        at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:364)
        at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:330)
        at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:487)
        at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:380)
        at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:132)
        at weblogic.jdbc.common.internal.RmiDataSource.getPoolConnection(RmiDataSource.java:474)
        at weblogic.jdbc.common.internal.RmiDataSource.getConnectionInternal(RmiDataSource.java:558)
        at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:518)
        at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:511)
        at oracle.jms.AQjmsDBConnMgr.getConnection(AQjmsDBConnMgr.java:566)
        at oracle.jms.AQjmsConnection.setExceptionListener(AQjmsConnection.java:418)
        at weblogic.ejb.container.internal.JMSConnectionPoller.setUpQueueSessions(JMSConnectionPoller.java:1712)
        at weblogic.ejb.container.internal.JMSConnectionPoller.createJMSConnection(JMSConnectionPoller.java:2298)
        at weblogic.ejb.container.internal.JMSConnectionPoller.connect(JMSConnectionPoller.java:808)
        at weblogic.ejb.container.internal.MDConnectionManager.timerExpired(MDConnectionManager.java:177)
        at weblogic.timers.internal.TimerImpl.run(TimerImpl.java:293)
        at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:545)
        at weblogic.work.ExecuteThread.execute(ExecuteThread.java:256)
        at weblogic.work.ExecuteThread.run(ExecuteThread.java:221)

Although this is a very well known exception, it is easier to deal with it when you're working with plain JDBC or in scenarios when you have more control of the underlying connection; but in my case, the connection administration code is provided from server managed components (Foreign Server, JMS Module, destination and connection factory, MDB, etc.).

Before start receiving the warnings, the MDB was using container managed transactionality. Now is using the following attributes (non-transactional):

@TransactionManagement(TransactionManagementType.BEAN)
@TransactionAttribute(TransactionAttributeType.NOT_SUPPORTED)

After doing some research ([1], [2]), I found that when a Weblogic MDB has Bean managed or NOT_SUPPORTED transaction type, then two dedicated connections are reserved for that MDB:
Looking at the stack trace, it is reasonable to think the warning corresponds to the "AQ JMS Exception Listener" connection (and not to the polling one). Looking at the documentation, you can see the default ping frequency for the periodical exception listener database ping es 2 minutes (Setting the Ping Period for the Exception Listener). So, this connection is idle during 2 minutes each time.

Casually, in my environment, the underlying JDBC data source (jdbc/XYZ: the one you specify in the datasource JNDI Property of the Foreign Server) had a "Inactive Connection Timeout" value of 60 seconds.

Hence, having these simultaneous settings, has to be the reason the warning is being generated (the underlying data source checks for idle connection more often that the Exception Listener connection gets busy):

Data Source "Inactive Connection Timeout" = 60 (seconds) < MDB Exception Listener connection "ping period" = 120 (seconds)

After increasing the Data Source "Inactive Connection Timeout", the warning stopped appearing.

It would be better to reduce the Exception Listener "ping period" value, but I haven't find a way to do it (neither in the JMS Module, Foreign Server, Destination, Connection Factory or MDB).

References:


jueves, 15 de agosto de 2013

Inspecting Weblogic classloaders (without using ws-cat)

I know Weblogic have a great application called ws-cat that you can use to diagnose classloading problems in the deployed applications. But, sometimes a find myself needing "a little more". I've had the necessity of knowing the classloaders involved in the classloader hierarchy and the classpath for each one...even if I know this is unsupported, that some of the involved classloaders have no documented behaviour,..etc.

I started with a typical EAR/WAR packaged Web application with a servlet, containing some code like this:

ClassLoader cl = this.getClass().getClassLoader();
while(cl != null) {
  System.out.println("Cl: " + cl + ", class: " + cl.getClass());
  cl = cl.getParent();
}

Invoking the servlet, I obtained this:

Cl: weblogic.utils.classloaders.ChangeAwareClassLoader@22dd997d finder: weblogic.utils.classloaders.CodeGenClassFinder@704fd3b4 annotation: TestClApp@TestClWeb, class: class weblogic.utils.classloaders.ChangeAwareClassLoader
Cl: weblogic.utils.classloaders.FilteringClassLoader@8d40807 finder: weblogic.utils.classloaders.CodeGenClassFinder@185b0818 annotation: TestClApp@TestClWeb, class: class weblogic.utils.classloaders.FilteringClassLoader
Cl: weblogic.utils.classloaders.GenericClassLoader@b39c954 finder: weblogic.utils.classloaders.CodeGenClassFinder@706c26 annotation: TestClApp@, class: class weblogic.utils.classloaders.GenericClassLoader
Cl: weblogic.utils.classloaders.FilteringClassLoader@54cc3303 finder: weblogic.utils.classloaders.CodeGenClassFinder@2a293573 annotation: , class: class weblogic.utils.classloaders.FilteringClassLoader
Cl: weblogic.utils.classloaders.GenericClassLoader@1f0fde7d finder: weblogic.utils.classloaders.CodeGenClassFinder@1db2cc30 annotation: , class: class weblogic.utils.classloaders.GenericClassLoader
Cl: sun.misc.Launcher$AppClassLoader@752a2259, class: class sun.misc.Launcher$AppClassLoader
Cl: sun.misc.Launcher$ExtClassLoader@21353d27, class: class sun.misc.Launcher$ExtClassLoader

Thus, the classloader hierarchy in my webapp is: ChangeAwareClassLoader -> FilteringClassLoader -> GenericClassLoader -> FilteringClassLoader -> GenericClassLoader -> AppClassLoader (JVM) -> ExtClassLoader (JVM).

But now I want to know if I can obtain some information from them. Using a little reflection, we can see the methods the classloaders offer us:

ClassLoader cl = this.getClass().getClassLoader();

while(cl != null) {
  System.out.println("Cl: " + cl + ", class: " + cl.getClass());
  if(cl.getClass().getName().contains("ChangeAwareClassLoader") || 
     cl.getClass().getName().contains("FilteringClassLoader") ||
     cl.getClass().getName().contains("GenericClassLoader")) {

    System.out.println("Methods:");
    Method[] methods = cl.getClass().getMethods();
    for(Method method : methods) {
   System.out.println("- " + method);
}
  }
  
  cl = cl.getParent();
}

Observing the output, yo can see all of the involved Weblogic classloaders offer the following method:

public java.lang.String weblogic.utils.classloaders.ChangeAwareClassLoader.getClassPath()

You can use again some reflection to invoke that method. If you do it, you can find the method returns the classpath for the classloader, with each entry separated by ';' (in Windows?). So, doing something like this, yo can obtain the classloader classpath.

ClassLoader cl = this.getClass().getClassLoader();
while(cl != null) {
  System.out.println("Cl: " + cl + ", class: " + cl.getClass());
  
  if(cl.getClass().getName().contains("ChangeAwareClassLoader") || 
     cl.getClass().getName().contains("FilteringClassLoader") ||
     cl.getClass().getName().contains("GenericClassLoader")) {
 
    System.out.println("Classpath:");
    Method method = cl.getClass().getMethod("getClassPath");
String classpath[] = ((String)method.invoke(cl)).split(";");
for(String cpEntry : classpath) {
  System.out.println(cpEntry);
}
  }
  
  cl = cl.getParent();
}

That gives us very cool information about our application runtime. For example we can check if the documentation is telling us the truth :P, which classloaders have the web module classes, which have the EJB module classes, which have the App-level classes, etc. It can be even more useful if you're using shared libraries and want to know what's really going on.

In my tests I used

ClassLoader cl = this.getClass().getClassLoader();

but maybe is more useful to use:

ClassLoader cl = Thread.currentThread().getContextClassLoader();

Luckily, for my scenario, the results are exactly the same.

As I said at the post start, you may not use the output of this code as a "source of truth", but just as a means to get more light in your diagnosing efforts. This is internal Weblogic material that I guess "we should not use". For example, each of the Weblogic classloaders, has a companion "finder" classloader with its own classpath; what does it does?

method = cl.getClass().getMethod("getFinderClassPath");
classpath = ((String)method.invoke(cl)).split(";");
for(String cpEntry : classpath) {
  System.out.println(cpEntry);
}



martes, 13 de agosto de 2013

"Connection refused" debugging Weblogic using Eclipse OEPE

Error in Eclipse OEPE: Failed to connect to remote VM. Connection refused. Connection refused: connect.


In this case, the cause was my local development server was configured to run in production mode. In this mode, the debug options are not included in the start order.


One way to fix it is look for the PRODUCTION_MODE variable setting that is causing the server to start in that mode. In my case that variable was set in the setDomainEnv script to true. Fix: