Part 4 for issue eclipse-ee4j#24900 Add more detailed logging to impr…

…ove log file

analysis. And fix a few merge errors after rebasing.

appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/ResourceHandle.java

@@ -359,7 +359,7 @@ public int hashCode() {
 
     @Override
     public String toString() {
-        return String.valueOf(id);
+        return "<ResourceHandle id=" + id + ", state=" + state + "/>";
     }
 
     public void setConnectionErrorOccurred() {

appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/listener/LocalTxConnectionEventListener.java

@@ -17,21 +17,24 @@
 
 package com.sun.enterprise.resource.listener;
 
+import java.util.IdentityHashMap;
+import java.util.Map;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 import com.sun.enterprise.connectors.ConnectorRuntime;
 import com.sun.enterprise.resource.ResourceHandle;
 import com.sun.enterprise.resource.pool.PoolManager;
-
+import com.sun.logging.LogDomains;
 import jakarta.resource.spi.ConnectionEvent;
 import jakarta.resource.spi.ManagedConnection;
 
-import java.util.IdentityHashMap;
-import java.util.Map;
-
 /**
  * @author Binod P.G
  */
 public class LocalTxConnectionEventListener extends ConnectionEventListener {
 
+    private static final Logger logger = LogDomains.getLogger(ResourceHandle.class, LogDomains.RSR_LOGGER);
+
     /**
      * A shortcut to the singleton PoolManager instance. Field could also be removed.
      */
@@ -56,14 +59,33 @@ public class LocalTxConnectionEventListener extends ConnectionEventListener {
 
     public LocalTxConnectionEventListener(ResourceHandle resource) {
         this.resource = resource;
+
+        if (logger.isLoggable(Level.FINE)) {
+            logger.log(Level.FINE, "LocalTxConnectionEventListener constructor, resource=" + resource + ", this=" + this);
+        }
     }
 
     @Override
     public synchronized void connectionClosed(ConnectionEvent evt) {
+        if (logger.isLoggable(Level.FINE)) {
+            logger.log(Level.FINE, "LocalTxConnectionEventListener.connectionClosed START, resource=" + resource + ", this=" + this);
+            for (Object key : associatedHandles.keySet()) {
+                ResourceHandle associatedHandle = associatedHandles.get(key);
+                logger.log(Level.FINE,
+                        "LocalTxConnectionEventListener.connectionClosed associatedHandles: key=" + key + ", handle=" + associatedHandle);
+                logger.log(Level.FINE,
+                        "LocalTxConnectionEventListener.connectionClosed associatedHandles: resource=" + associatedHandle.getResource());
+            }
+        }
+
         Object connectionHandle = evt.getConnectionHandle();
         ResourceHandle handle = associatedHandles.getOrDefault(connectionHandle, resource);
         // ManagedConnection instance is still valid and put back in the pool: do not remove the event listener.
         poolManager.resourceClosed(handle);
+
+        if (logger.isLoggable(Level.FINE)) {
+            logger.log(Level.FINE, "LocalTxConnectionEventListener.connectionClosed END, resource=" + resource + ", handle=" + handle + ", this=" + this);
+        }
     }
 
     @Override
@@ -117,6 +139,9 @@ public void localTransactionRolledback(ConnectionEvent evt) {
      * @param resourceHandle the original Handle
      */
     public synchronized void associateHandle(Object userHandle, ResourceHandle resourceHandle) {
+        if (logger.isLoggable(Level.FINE)) {
+            logger.log(Level.FINE, "LocalTxConnectionEventListener associateHandle, userHandle=" + userHandle + ", resourceHandle=" + resourceHandle + ", this=" + this);
+        }
         associatedHandles.put(userHandle, resourceHandle);
     }
 
@@ -128,6 +153,9 @@ public synchronized void associateHandle(Object userHandle, ResourceHandle resou
      * can also indicate that the map previously associated null with userHandle.
      */
     public synchronized ResourceHandle removeAssociation(Object userHandle) {
+        if (logger.isLoggable(Level.FINE)) {
+            logger.log(Level.FINE, "LocalTxConnectionEventListener removeAssociation, userHandle=" + userHandle + ", this=" + this);
+        }
         return associatedHandles.remove(userHandle);
     }
 
@@ -136,6 +164,8 @@ public synchronized ResourceHandle removeAssociation(Object userHandle) {
      * @return The clone of the associatedHandles map.
      */
     public synchronized Map<Object, ResourceHandle> getAssociatedHandlesAndClearMap() {
+        logger.log(Level.FINE, "LocalTxConnectionEventListener getAssociatedHandlesAndClearMap, this=" + this);
+
         // Clone the associatedHandles, because we will clear the list in this method
         IdentityHashMap<Object, ResourceHandle> result = (IdentityHashMap<Object, ResourceHandle>) associatedHandles.clone();
 

appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/AbstractPoolManager.java

@@ -17,15 +17,6 @@
 
 package com.sun.enterprise.resource.pool;
 
-<<<<<<< Upstream, based on origin/master
-import com.sun.enterprise.resource.ResourceSpec;
-
-import java.util.concurrent.ConcurrentHashMap;
-
-import org.glassfish.resourcebase.resources.api.PoolInfo;
-
-=======
->>>>>>> f4ffa0b Part 3 for issue #24900 More documentation and more unit test coverage.
 /**
  * Abstract Pool manager for unimplemented features. Throws UnsupportedOperationException when invoked.
  */

appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/ConnectionPool.java

@@ -1099,6 +1099,8 @@ public void resourceClosed(ResourceHandle handle) throws IllegalStateException {
 
         if (state.isUnenlisted() || (poolTxHelper.isNonXAResource(handle) && poolTxHelper.isLocalTransactionInProgress()
                 && poolTxHelper.isLocalResourceEligibleForReuse(handle))) {
+            // Note: the call to isLocalResourceEligibleForReuse can change the enlisted state of the 
+            // handle to false if the resource is eligible for reuse.
             freeUnenlistedResource(handle);
         }
 
@@ -1139,6 +1141,7 @@ protected void freeUnenlistedResource(ResourceHandle h) {
     }
 
     protected void freeResource(ResourceHandle resourceHandle) {
+        LOG.log(FINE, "freeResource handle: {0}", resourceHandle);
         try {
             getResourceFromPoolAndFreeResourceMethodsLock.lock();
             if (cleanupResource(resourceHandle)) {
@@ -1162,7 +1165,6 @@ protected void freeResource(ResourceHandle resourceHandle) {
         } finally {
             getResourceFromPoolAndFreeResourceMethodsLock.unlock();
         }
-
     }
 
     /**

appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/PoolManagerImpl.java

@@ -140,7 +140,10 @@ void createAndInitPool(final PoolInfo poolInfo, PoolType poolType, Hashtable env
     // invoked by DataSource objects to obtain a connection
     @Override
     public Object getResource(ResourceSpec resourceSpec, ResourceAllocator resourceAllocator, ClientSecurityInfo clientSecurityInfo) throws PoolingException, RetryableUnavailableException {
-
+        if (LOG.isLoggable(Level.FINE)) {
+            LOG.log(Level.FINE, "PoolManagerImpl.getResource START, resourceSpec=" + resourceSpec + "\nresourceAllocator="
+                    + resourceAllocator + "\nclientSecurityInfo=" + clientSecurityInfo);
+        }
         Transaction transaction = null;
         boolean transactional = resourceAllocator.isTransactional();
 
@@ -149,7 +152,9 @@ public Object getResource(ResourceSpec resourceSpec, ResourceAllocator resourceA
         }
 
         ResourceHandle resourceHandle = getResourceFromPool(resourceSpec, resourceAllocator, clientSecurityInfo, transaction);
-
+        if (LOG.isLoggable(Level.FINE)) {
+            LOG.log(Level.FINE, "PoolManagerImpl.getResource handle=" + resourceHandle + ", poolStatus" + getPoolStatus(resourceSpec.getPoolInfo()));
+        }
         if (!resourceHandle.supportsLazyAssociation()) {
             resourceSpec.setLazyAssociatable(false);
         }
@@ -178,6 +183,11 @@ public Object getResource(ResourceSpec resourceSpec, ResourceAllocator resourceA
         // resourceAllocator.
         resourceHandle.setResourceSpec(resourceSpec);
 
+        if (LOG.isLoggable(Level.FINE)) {
+            LOG.log(Level.FINE, "PoolManagerImpl.getResource, transaction=" + transaction + " resourceHandle=" + resourceHandle + " isUnenlisted="
+                    + resourceHandle.getResourceState().isUnenlisted());
+        }
+
         try {
             if (resourceHandle.getResourceState().isUnenlisted()) {
                 // The spec being used here is the spec with the updated lazy enlistment info.
@@ -188,6 +198,10 @@ public Object getResource(ResourceSpec resourceSpec, ResourceAllocator resourceA
                 // LazyEnlistableResourceManager
 
                 getResourceManager(resourceSpec).enlistResource(resourceHandle);
+            } else {
+                if (LOG.isLoggable(Level.FINE)) {
+                    LOG.log(Level.FINE, "PoolManagerImpl.getResource - DO NOT ENLIST because it is already Enlisted, resource=" + resourceHandle);
+                }
             }
         } catch (Exception e) {
             // In the rare cases where enlistResource throws exception, we should return the resource to the pool
@@ -200,7 +214,11 @@ public Object getResource(ResourceSpec resourceSpec, ResourceAllocator resourceA
             throw new PoolingException(e);
         }
 
-        return resourceHandle.getUserConnection();
+        Object result = resourceHandle.getUserConnection();
+        if (LOG.isLoggable(Level.FINE)) {
+            LOG.log(Level.FINE, "PoolManagerImpl.getResource END, resourceHandle=" + resourceHandle);
+        }
+        return result;
     }
 
     @Override
@@ -343,8 +361,18 @@ public void unregisterResource(com.sun.appserv.connectors.internal.api.ResourceH
 
     @Override
     public void resourceClosed(ResourceHandle resource) {
+        if (LOG.isLoggable(Level.FINE)) {
+            LOG.log(Level.FINE, "PoolManagerImpl.resourceClosed START, resource=" + resource);
+        }
+
         getResourceManager(resource.getResourceSpec()).delistResource(resource, TMSUCCESS);
         putbackResourceToPool(resource, false);
+
+        if (LOG.isLoggable(Level.FINE)) {
+            // Warning resource state logged here might not be valid, could be part of another thread already
+            // but logging the resource id is useful. 
+            LOG.log(Level.FINE, "PoolManagerImpl.resourceClosed END, resource=" + resource);
+        }
     }
 
     @Override
@@ -401,6 +429,9 @@ private void putbackBadResourceToPool(ResourceHandle resourceHandle) {
 
     @Override
     public void putbackResourceToPool(ResourceHandle resourceHandle, boolean errorOccurred) {
+        if (LOG.isLoggable(Level.FINE)) {
+            LOG.log(Level.FINE, "PoolManagerImpl.putbackResourceToPool START, resource=" + resourceHandle + ", errorOccurred=" + errorOccurred);
+        }
         // Notify pool
         PoolInfo poolInfo = resourceHandle.getResourceSpec().getPoolInfo();
         if (poolInfo != null) {
@@ -415,6 +446,9 @@ public void putbackResourceToPool(ResourceHandle resourceHandle, boolean errorOc
                 }
             }
         }
+        if (LOG.isLoggable(Level.FINE)) {
+            LOG.log(Level.FINE, "PoolManagerImpl.putbackResourceToPool END, resource=" + resourceHandle + ", errorOccurred=" + errorOccurred);
+        }
     }
 
     @Override

appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/PoolStatus.java

@@ -62,4 +62,9 @@ public void setPoolInfo(PoolInfo poolInfo) {
     public PoolStatus(PoolInfo poolInfo) {
         this.poolInfo = poolInfo;
     }
+
+    @Override
+    public String toString() {
+        return "PoolStatus [poolInfo=" + poolInfo + ", numConnFree=" + numConnFree + ", numConnUsed=" + numConnUsed + "]";
+    }
 }

appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/PoolTxHelper.java

@@ -55,7 +55,8 @@ public PoolTxHelper(PoolInfo poolInfo) {
      * Check whether the local resource can be put back to pool If true, unenlist the resource
      *
      * @param h ResourceHandle to be verified
-     * @return boolean
+     * @return true if the resource handle is eligible for reuse, otherwise false. NOTE in case of true, this method alters
+     * the handle state to enlisted=false
      */
     public boolean isLocalResourceEligibleForReuse(ResourceHandle h) {
         boolean result = false;
@@ -70,9 +71,17 @@ public boolean isLocalResourceEligibleForReuse(ResourceHandle h) {
                 }
                 return result;
             }
+
             h.getResourceState().setEnlisted(false);
+            if (_logger.isLoggable(Level.FINE)) {
+                _logger.log(Level.FINE, "Pool: isLocalResourceEligibleForReuse, eligible=true, enlisted changed to true for handle=" + h);
+            }
             result = true;
         }
+
+        if (_logger.isLoggable(Level.FINE)) {
+            _logger.log(Level.FINE, "Pool: isLocalResourceEligibleForReuse, eligible=false, handle=" + h);
+        }
         return result;
     }
 
@@ -153,7 +162,6 @@ public boolean isNonXAResource(ResourceHandle resource) {
      * @return boolean indicating whether thegiven non-xa resource is in transaction
      */
     private boolean isNonXAResourceInTransaction(JavaEETransaction tran, ResourceHandle resource) {
-
         return resource.equals(tran.getNonXAResource());
     }
 
@@ -175,6 +183,9 @@ public boolean isNonXAResourceAndFree(JavaEETransaction tran, ResourceHandle res
      * @param resource Resource to be enlisted in the transaction
      */
     public void resourceEnlisted(Transaction tran, ResourceHandle resource) {
+        if (_logger.isLoggable(Level.FINE)) {
+            _logger.log(Level.FINE, "Pool: resourceEnlisted START, tran=" + tran + ", resource=" + resource + ", poolInfo=" + poolInfo);
+        }
         try {
             JavaEETransaction j2eetran = (JavaEETransaction) tran;
             Set set = j2eetran.getResources(poolInfo);
@@ -192,7 +203,7 @@ public void resourceEnlisted(Transaction tran, ResourceHandle resource) {
         ResourceState state = resource.getResourceState();
         state.setEnlisted(true);
         if (_logger.isLoggable(Level.FINE)) {
-            _logger.log(Level.FINE, "Pool [ " + poolInfo + " ]: resourceEnlisted: " + resource);
+            _logger.log(Level.FINE, "Pool: resourceEnlisted END, tran=" + tran + ", resource=" + resource);
         }
     }
 
@@ -205,6 +216,10 @@ public void resourceEnlisted(Transaction tran, ResourceHandle resource) {
      * @return delisted resources
      */
     public List<ResourceHandle> transactionCompleted(Transaction tran, int status, PoolInfo poolInfo) {
+        if (_logger.isLoggable(Level.FINE)) {
+            _logger.log(Level.FINE, "Pool: transactionCompleted START, tran= " + tran + ", poolInfo=" + poolInfo);
+        }
+
         JavaEETransaction j2eetran;
         List<ResourceHandle> delistedResources = new ArrayList<>();
         try {
@@ -233,6 +248,10 @@ public List<ResourceHandle> transactionCompleted(Transaction tran, int status, P
                 _logger.log(Level.FINE, "Pool: transactionCompleted: " + resource);
             }
         }
+
+        if (_logger.isLoggable(Level.FINE)) {
+            _logger.log(Level.FINE, "Pool: transactionCompleted END, tran= " + tran);
+        }
         return delistedResources;
     }
 }

appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/UnpooledResource.java

@@ -81,6 +81,9 @@ protected ResourceHandle getUnenlistedResource(ResourceSpec spec, ResourceAlloca
             throw ex;
         }
         handle.getResourceState().reset();
+
+        // TODO: document that all get(Unenlisted)Resource methods must return state busy resource
+        // TODO: rename variables, they currently have 2 or 3 names by default: handle, resource and resourceHandle
         setResourceStateToBusy(handle);
         return handle;
     }