Debug Improvements (#938)

sbSteveK · web-flow · commit 72b5023cd0f1 · 2025-11-18T13:06:51.000-08:00
diff --git a/src/main/java/software/amazon/awssdk/crt/CrtResource.java b/src/main/java/software/amazon/awssdk/crt/CrtResource.java
@@ -124,14 +124,15 @@ public CrtResource() {
      * @param resource The resource to add a reference to
      */
     public void addReferenceTo(CrtResource resource) {
+        if (debugNativeObjects) {
+            Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, 
+                String.format("%s(%d) is adding a reference to %s(%d)", 
+                this.getClass().getCanonicalName(), id, resource.getClass().getCanonicalName(), resource.id));
+        }
         resource.addRef();
         synchronized(this) {
             referencedResources.add(resource);
         }
-
-        if (debugNativeObjects) {
-            Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, String.format("Instance of class %s(%d) is adding a reference to instance of class %s(%d)", this.getClass().getCanonicalName(), id, resource.getClass().getCanonicalName(), resource.id));
-        }
     }
 
     /**
@@ -146,9 +147,13 @@ public void removeReferenceTo(CrtResource resource) {
 
         if (debugNativeObjects) {
             if (removed) {
-                Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, String.format("Instance of class %s(%d) is removing a reference to instance of class %s(%d)", this.getClass().getCanonicalName(), id, resource.getClass().getCanonicalName(), resource.id));
+                Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, 
+                    String.format("%s(%d) is removing a reference to %s(%d)", 
+                    this.getClass().getCanonicalName(), id, resource.getClass().getCanonicalName(), resource.id));
             } else {
-                Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, String.format("Instance of class %s(%d) erroneously tried to remove a reference to instance of class %s(%d) that it was not referencing", this.getClass().getCanonicalName(), id, resource.getClass().getCanonicalName(), resource.id));
+                Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, 
+                String.format("%s(%d) erroneously tried to remove a reference to %s(%d) that it was not referencing", 
+                this.getClass().getCanonicalName(), id, resource.getClass().getCanonicalName(), resource.id));
             }
         }
 
@@ -209,7 +214,8 @@ protected void acquireNativeHandle(long handle) {
      */
     private void release() {
         if (debugNativeObjects) {
-            Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, String.format("Releasing class %s(%d)", this.getClass().getCanonicalName(), id));
+            Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, 
+                String.format("Releasing class %s(%d)", this.getClass().getCanonicalName(), id));
 
             synchronized(CrtResource.class) {
                 CRT_RESOURCES.remove(id);
@@ -237,7 +243,25 @@ public long getNativeHandle() {
      * Increments the reference count to this resource.
      */
     public void addRef() {
-        refCount.incrementAndGet();
+        int updatedRefs = refCount.incrementAndGet();
+        if (debugNativeObjects) {
+           Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, 
+            String.format("%s(%d) is adding a reference. refCount is now %d", 
+            this.getClass().getCanonicalName(), id, updatedRefs));
+        }
+    }
+
+    /**
+     * Increments the reference count to this resource with a description.
+     * @param desc Descrption string of why the reference is being incremented.
+     */
+    public void addRef(String desc) {
+       int updatedRefs = refCount.incrementAndGet();
+       if (debugNativeObjects) {
+           Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, 
+            String.format("%s(%d) is adding a reference for: (%s). RefCount is now %d", 
+            this.getClass().getCanonicalName(), id, desc, updatedRefs));
+       }
     }
 
     /**
@@ -274,7 +298,11 @@ public boolean isNull() {
 
     @Override
     public void close() {
-        decRef();
+        decRef("close() called");
+    }
+
+    public void close(String desc) {
+        decRef(desc);
     }
 
     /**
@@ -286,12 +314,37 @@ public void decRef(CrtResource decRefInstigator) {
         int remainingRefs = refCount.decrementAndGet();
 
         if (debugNativeObjects) {
-            if (decRefInstigator != null) {
-                Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, String.format(
-                    "DecRef instance of class %s(%d) called by %s(%d). %d remaining refs", this.getClass().getCanonicalName(), id, 
-                    decRefInstigator.getClass().getCanonicalName(), decRefInstigator.id, remainingRefs));
+            Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, String.format(
+                "DecRef of %s(%d) called by %s(%d). %d remaining refs", this.getClass().getCanonicalName(), id, 
+                decRefInstigator.getClass().getCanonicalName(), decRefInstigator.id, remainingRefs));
+        }
+
+        if (remainingRefs != 0) {
+            return;
+        }
+
+        release();
+
+        if (canReleaseReferencesImmediately()) {
+            releaseReferences();
+        }
+    }
+
+    /**
+     * Decrements the reference count to this resource with a description.
+     * @param desc Descrption string of why the reference is being decremented.
+     */
+    public void decRef(String desc) {
+        int remainingRefs = refCount.decrementAndGet();
+
+        if (debugNativeObjects) {
+            if (desc != null) {
+                Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, 
+                    String.format("DecRef on %s(%d) for: (%s). %d remaining refs", 
+                    this.getClass().getCanonicalName(), id, desc, remainingRefs));
             } else {
-                Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, String.format("DecRef instance of class %s(%d) via self.close(). %d remaining refs", 
+                Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource,
+                    String.format("Defref on %s(%d). %d remaining refs",
                     this.getClass().getCanonicalName(), id, remainingRefs));
             }
         }
@@ -306,11 +359,12 @@ public void decRef(CrtResource decRefInstigator) {
             releaseReferences();
         }
     }
+
     /**
      * Decrements the reference count to this resource.
      */
     public void decRef() {        
-        decRef(null);
+        decRef((String)null);
     }
 
     /**
@@ -320,7 +374,9 @@ public void decRef() {
      */
     protected void releaseReferences() {
         if (debugNativeObjects) {
-            Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, String.format("Instance of class %s(%d) closing all referenced objects", this.getClass().getCanonicalName(), id));
+            Log.log(ResourceLogLevel, Log.LogSubject.JavaCrtResource, 
+            String.format("%s(%d) closing all referenced objects", 
+            this.getClass().getCanonicalName(), id));
         }
 
         synchronized(this) {
diff --git a/src/main/java/software/amazon/awssdk/crt/eventstream/ClientConnectionContinuationHandler.java b/src/main/java/software/amazon/awssdk/crt/eventstream/ClientConnectionContinuationHandler.java
@@ -67,7 +67,7 @@ public CompletableFuture<Void> getContinuationClosedFuture() {
     @Override
     public void close() {
         if (continuation != null) {
-            continuation.decRef();
+            continuation.decRef("close() called");
             continuation = null;
         }
     }
diff --git a/src/main/java/software/amazon/awssdk/crt/eventstream/ClientConnectionHandler.java b/src/main/java/software/amazon/awssdk/crt/eventstream/ClientConnectionHandler.java
@@ -93,7 +93,7 @@ public void close() {
             if (clientConnection.isOpen()) {
                 clientConnection.closeConnection(0);
             }
-            clientConnection.decRef();
+            clientConnection.decRef("close() called");
             clientConnection = null;
         }
     }
diff --git a/src/main/java/software/amazon/awssdk/crt/eventstream/ServerConnectionContinuationHandler.java b/src/main/java/software/amazon/awssdk/crt/eventstream/ServerConnectionContinuationHandler.java
@@ -68,7 +68,7 @@ public CompletableFuture<Void> getContinuationClosedFuture() {
     @Override
     public void close() {
         if (continuation != null) {
-            continuation.decRef();
+            continuation.decRef("close() called");
             continuation = null;
         }
     }
diff --git a/src/main/java/software/amazon/awssdk/crt/eventstream/ServerConnectionHandler.java b/src/main/java/software/amazon/awssdk/crt/eventstream/ServerConnectionHandler.java
@@ -76,7 +76,7 @@ public void close() {
         if (connection.isConnectionOpen()) {
             connection.closeConnection(0);
         }
-        connection.decRef();
+        connection.decRef("close() called");
         connection = null;
     }
 }
diff --git a/src/main/java/software/amazon/awssdk/crt/io/ClientBootstrap.java b/src/main/java/software/amazon/awssdk/crt/io/ClientBootstrap.java
@@ -90,7 +90,7 @@ private void onShutdownComplete() {
     public static void closeStaticDefault() {
         synchronized (ClientBootstrap.class) {
             if (staticDefaultClientBootstrap != null) {
-                staticDefaultClientBootstrap.close();
+                staticDefaultClientBootstrap.close("closeStaticDefault");
             }
             staticDefaultClientBootstrap = null;
         }
diff --git a/src/main/java/software/amazon/awssdk/crt/io/EventLoopGroup.java b/src/main/java/software/amazon/awssdk/crt/io/EventLoopGroup.java
@@ -95,7 +95,7 @@ public static void setStaticDefaultNumThreads(int numThreads) {
     public static void closeStaticDefault() {
         synchronized (EventLoopGroup.class) {
             if (staticDefaultEventLoopGroup != null) {
-                staticDefaultEventLoopGroup.close();
+                staticDefaultEventLoopGroup.close("closeStaticDefault");
             }
             staticDefaultEventLoopGroup = null;
         }
diff --git a/src/main/java/software/amazon/awssdk/crt/io/HostResolver.java b/src/main/java/software/amazon/awssdk/crt/io/HostResolver.java
@@ -73,7 +73,7 @@ public static void setStaticDefaultMaxEntries(int maxEntries) {
     public static void closeStaticDefault() {
         synchronized (HostResolver.class) {
             if (staticDefaultResolver != null) {
-                staticDefaultResolver.close();
+                staticDefaultResolver.close("closeStaticDefault");
             }
             staticDefaultResolver = null;
         }
diff --git a/src/test/java/software/amazon/awssdk/crt/test/CrtTestFixture.java b/src/test/java/software/amazon/awssdk/crt/test/CrtTestFixture.java
@@ -23,13 +23,19 @@
 import org.junit.BeforeClass;
 import org.junit.After;
 import org.junit.Assume;
+import org.junit.Rule;
+import org.junit.rules.TestName;
+
 
 import java.util.Optional;
 
 public class CrtTestFixture {
 
     private CrtTestContext context;
 
+    @Rule
+    public TestName testName = new TestName();
+
     public final CrtTestContext getContext() {
         return context;
     }
@@ -230,6 +236,7 @@ public static void setupOnce() {
     /* The setup function will be run before every test */
     @Before
     public void setup() {
+        System.out.println("[TEST START] " + testName.getMethodName());
         Log.log(Log.LogLevel.Debug, LogSubject.JavaCrtGeneral, "CrtTestFixture setup begin");
 
         // TODO this CrtTestContext should be removed as we are using System Properties
@@ -258,6 +265,7 @@ public void tearDown() {
             }
         }
         Log.log(Log.LogLevel.Debug, LogSubject.JavaCrtGeneral, "CrtTestFixture tearDown end");
+        System.out.println("[TEST END] " + testName.getMethodName());
     }
 
     protected TlsContext createTlsContextOptions(byte[] trustStore) {

Original file line number	Diff line number	Diff line change
`@@ -67,7 +67,7 @@ public CompletableFuture<Void> getContinuationClosedFuture() {`
`67`	`67`	`@Override`
`68`	`68`	`public void close() {`
`69`	`69`	`if (continuation != null) {`
`70`		`- continuation.decRef();`
	`70`	`+ continuation.decRef("close() called");`
`71`	`71`	`continuation = null;`
`72`	`72`	`}`
`73`	`73`	`}`
Original file line number	Diff line number	Diff line change
`@@ -93,7 +93,7 @@ public void close() {`
`93`	`93`	`if (clientConnection.isOpen()) {`
`94`	`94`	`clientConnection.closeConnection(0);`
`95`	`95`	`}`
`96`		`- clientConnection.decRef();`
	`96`	`+ clientConnection.decRef("close() called");`
`97`	`97`	`clientConnection = null;`
`98`	`98`	`}`
`99`	`99`	`}`
Original file line number	Diff line number	Diff line change
`@@ -68,7 +68,7 @@ public CompletableFuture<Void> getContinuationClosedFuture() {`
`68`	`68`	`@Override`
`69`	`69`	`public void close() {`
`70`	`70`	`if (continuation != null) {`
`71`		`- continuation.decRef();`
	`71`	`+ continuation.decRef("close() called");`
`72`	`72`	`continuation = null;`
`73`	`73`	`}`
`74`	`74`	`}`
Original file line number	Diff line number	Diff line change
`@@ -76,7 +76,7 @@ public void close() {`
`76`	`76`	`if (connection.isConnectionOpen()) {`
`77`	`77`	`connection.closeConnection(0);`
`78`	`78`	`}`
`79`		`- connection.decRef();`
	`79`	`+ connection.decRef("close() called");`
`80`	`80`	`connection = null;`
`81`	`81`	`}`
`82`	`82`	`}`
Original file line number	Diff line number	Diff line change
`@@ -90,7 +90,7 @@ private void onShutdownComplete() {`
`90`	`90`	`public static void closeStaticDefault() {`
`91`	`91`	`synchronized (ClientBootstrap.class) {`
`92`	`92`	`if (staticDefaultClientBootstrap != null) {`
`93`		`- staticDefaultClientBootstrap.close();`
	`93`	`+ staticDefaultClientBootstrap.close("closeStaticDefault");`
`94`	`94`	`}`
`95`	`95`	`staticDefaultClientBootstrap = null;`
`96`	`96`	`}`
Original file line number	Diff line number	Diff line change
`@@ -95,7 +95,7 @@ public static void setStaticDefaultNumThreads(int numThreads) {`
`95`	`95`	`public static void closeStaticDefault() {`
`96`	`96`	`synchronized (EventLoopGroup.class) {`
`97`	`97`	`if (staticDefaultEventLoopGroup != null) {`
`98`		`- staticDefaultEventLoopGroup.close();`
	`98`	`+ staticDefaultEventLoopGroup.close("closeStaticDefault");`
`99`	`99`	`}`
`100`	`100`	`staticDefaultEventLoopGroup = null;`
`101`	`101`	`}`
Original file line number	Diff line number	Diff line change
`@@ -73,7 +73,7 @@ public static void setStaticDefaultMaxEntries(int maxEntries) {`
`73`	`73`	`public static void closeStaticDefault() {`
`74`	`74`	`synchronized (HostResolver.class) {`
`75`	`75`	`if (staticDefaultResolver != null) {`
`76`		`- staticDefaultResolver.close();`
	`76`	`+ staticDefaultResolver.close("closeStaticDefault");`
`77`	`77`	`}`
`78`	`78`	`staticDefaultResolver = null;`
`79`	`79`	`}`