SOLR-15550 Improvements to ObjectReleaseTracker (apache#227)

* Save submitter stack trace when tracking asynchronously allocated objects
* Defer substantiating exception trace string until we are sure we need it
* Refactor test for increased clarity

solr/core/src/java/org/apache/solr/cloud/ZkCollectionTerms.java

@@ -36,7 +36,7 @@ class ZkCollectionTerms implements AutoCloseable {
     this.collection = collection;
     this.terms = new HashMap<>();
     this.zkClient = client;
-    ObjectReleaseTracker.track(this);
+    assert ObjectReleaseTracker.track(this);
   }
 
 
@@ -65,7 +65,7 @@ public void close() {
     synchronized (terms) {
       terms.values().forEach(ZkShardTerms::close);
     }
-    ObjectReleaseTracker.release(this);
+    assert ObjectReleaseTracker.release(this);
   }
 
 }

solr/core/src/java/org/apache/solr/cloud/ZkShardTerms.java

@@ -103,7 +103,7 @@ public ZkShardTerms(String collection, String shard, SolrZkClient zkClient) {
     ensureTermNodeExist();
     refreshTerms();
     retryRegisterWatcher();
-    ObjectReleaseTracker.track(this);
+    assert ObjectReleaseTracker.track(this);
   }
 
   /**
@@ -154,7 +154,7 @@ public void close() {
     synchronized (listeners) {
       listeners.clear();
     }
-    ObjectReleaseTracker.release(this);
+    assert ObjectReleaseTracker.release(this);
   }
 
   // package private for testing, only used by tests

solr/core/src/java/org/apache/solr/request/SolrQueryRequestBase.java

@@ -33,6 +33,7 @@
 import org.apache.solr.common.util.CommandOperation;
 import org.apache.solr.common.util.ContentStream;
 import org.apache.solr.common.util.JsonSchemaValidator;
+import org.apache.solr.common.util.ObjectReleaseTracker;
 import org.apache.solr.common.util.SuppressForbidden;
 import org.apache.solr.common.util.ValidatingJsonMap;
 import org.apache.solr.core.SolrCore;
@@ -126,6 +127,11 @@ public SolrIndexSearcher getSearcher() {
 
     if (searcherHolder==null) {
       searcherHolder = core.getSearcher();
+
+      // We start tracking here instead of at construction, because if getSearcher is never called, it's
+      // not fatal to forget close(), and lots of test code is sloppy about it. However, when we get another
+      // searcher reference, having this tracked may be a good hint about where the leak comes from.
+      assert ObjectReleaseTracker.track(this);
     }
 
     return searcherHolder.get();
@@ -183,6 +189,7 @@ public void updateSchemaToLatest() {
   @Override
   public void close() {
     if (searcherHolder!=null) {
+      assert ObjectReleaseTracker.release(this);
       searcherHolder.decref();
       searcherHolder = null;
     }

solr/core/src/test/org/apache/solr/common/util/TestObjectReleaseTracker.java

@@ -0,0 +1,144 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License.  You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.solr.common.util;
+
+import org.apache.solr.SolrTestCaseJ4;
+import org.hamcrest.MatcherAssert;
+import org.junit.Test;
+
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicReference;
+
+import static org.hamcrest.Matchers.containsString;
+import static org.hamcrest.Matchers.stringContainsInOrder;
+
+public class TestObjectReleaseTracker extends SolrTestCaseJ4 {
+
+  @Test
+  public void testReleaseObject() {
+    Object obj = new Object();
+    ObjectReleaseTracker.track(obj);
+    ObjectReleaseTracker.release(obj);
+    assertNull(SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1));
+
+    Object obj1 = new Object();
+    ObjectReleaseTracker.track(obj1);
+    Object obj2 = new Object();
+    ObjectReleaseTracker.track(obj2);
+    Object obj3 = new Object();
+    ObjectReleaseTracker.track(obj3);
+
+    ObjectReleaseTracker.release(obj1);
+    ObjectReleaseTracker.release(obj2);
+    ObjectReleaseTracker.release(obj3);
+    assertNull(SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1));
+  }
+
+  @Test
+  public void testUnreleased() {
+    Object obj1 = new Object();
+    Object obj2 = new Object();
+    Object obj3 = new Object();
+
+    ObjectReleaseTracker.track(obj1);
+    ObjectReleaseTracker.track(obj2);
+    ObjectReleaseTracker.track(obj3);
+
+    ObjectReleaseTracker.release(obj1);
+    ObjectReleaseTracker.release(obj2);
+    // ObjectReleaseTracker.release(obj3);
+
+    assertNotNull(SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1));
+    assertNull(SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1));
+  }
+
+  @Test
+  public void testReleaseDifferentObject() {
+    ObjectReleaseTracker.track(new Object());
+    ObjectReleaseTracker.release(new Object());
+    assertNotNull(SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1));
+    assertNull(SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1));
+  }
+
+  @Test
+  public void testAnonymousClasses() {
+    ObjectReleaseTracker.track(new Object() {});
+    String message = SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1);
+    MatcherAssert.assertThat(message, containsString("[Object]"));
+  }
+
+  @Test
+  public void testAsyncTracking() throws InterruptedException, ExecutionException {
+    ExecutorService es = ExecutorUtil.newMDCAwareSingleThreadExecutor(new SolrNamedThreadFactory("TestExec"));
+    Object trackable = new Object();
+
+    Future<?> result = es.submit(() -> {
+      ObjectReleaseTracker.track(trackable);
+    });
+
+    result.get(); // make sure that track has been called
+    String message = SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1);
+    MatcherAssert.assertThat(message, stringContainsInOrder(
+        ObjectReleaseTracker.ObjectTrackerException.class.getName(),
+        "Exception: Submitter stack trace",
+        getClassName() + "." + getTestName()));
+
+    // Test the grandparent submitter case
+    AtomicReference<Future<?>> indirectResult = new AtomicReference<>();
+    result = es.submit(() ->
+      indirectResult.set(es.submit(() -> {
+        ObjectReleaseTracker.track(trackable);
+      }))
+    );
+
+    result.get();
+    indirectResult.get().get();
+    message = SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1);
+    MatcherAssert.assertThat(message, stringContainsInOrder(
+        ObjectReleaseTracker.ObjectTrackerException.class.getName(),
+        "Exception: Submitter stack trace",
+        "Exception: Submitter stack trace",
+        getClassName() + "." + getTestName()));
+
+    // Now test great-grandparent, which we don't explicitly account for, but should have been recursively set
+    AtomicReference<Future<?>> indirectIndirect = new AtomicReference<>();
+    result = es.submit(() ->
+      indirectResult.set(es.submit(() ->
+        indirectIndirect.set(es.submit(() -> {
+          ObjectReleaseTracker.track(trackable);
+        }))
+      ))
+    );
+
+    result.get();
+    indirectResult.get().get();
+    indirectIndirect.get().get();
+    message = SolrTestCaseJ4.clearObjectTrackerAndCheckEmpty(1);
+    MatcherAssert.assertThat(message, stringContainsInOrder(
+        ObjectReleaseTracker.ObjectTrackerException.class.getName(),
+        "Exception: Submitter stack trace",
+        "Exception: Submitter stack trace",
+        "Exception: Submitter stack trace",
+        getClassName() + "." + getTestName()));
+
+    es.shutdown();
+    assertTrue(es.awaitTermination(1, TimeUnit.SECONDS));
+  }
+}

solr/solrj/src/java/org/apache/solr/common/util/ExecutorUtil.java

@@ -39,6 +39,8 @@
 public class ExecutorUtil {
   private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
 
+  static final ThreadLocal<Throwable> submitter = new ThreadLocal<>();
+
   private static volatile List<InheritableThreadLocalProvider> providers = new ArrayList<>();
 
   /**
@@ -110,7 +112,7 @@ public static void awaitTermination(ExecutorService pool) {
   public static ExecutorService newMDCAwareFixedThreadPool(int nThreads, ThreadFactory threadFactory) {
     return new MDCAwareThreadPoolExecutor(nThreads, nThreads,
         0L, TimeUnit.MILLISECONDS,
-        new LinkedBlockingQueue<Runnable>(),
+        new LinkedBlockingQueue<>(),
         threadFactory);
   }
 
@@ -196,7 +198,13 @@ public void execute(final Runnable command) {
 
       String ctxStr = contextString.toString().replace("/", "//");
       final String submitterContextStr = ctxStr.length() <= MAX_THREAD_NAME_LEN ? ctxStr : ctxStr.substring(0, MAX_THREAD_NAME_LEN);
-      final Exception submitterStackTrace = enableSubmitterStackTrace ? new Exception("Submitter stack trace") : null;
+      final Throwable submitterStackTrace; // Never thrown, only used as stack trace holder
+      if (enableSubmitterStackTrace) {
+        Throwable grandParentSubmitter = submitter.get();
+        submitterStackTrace = new Exception("Submitter stack trace", grandParentSubmitter);
+      } else {
+        submitterStackTrace = null;
+      }
       final List<InheritableThreadLocalProvider> providersCopy = providers;
       final ArrayList<AtomicReference<Object>> ctx = providersCopy.isEmpty() ? null : new ArrayList<>(providersCopy.size());
       if (ctx != null) {
@@ -220,6 +228,9 @@ public void execute(final Runnable command) {
         } else {
           MDC.clear();
         }
+        if (enableSubmitterStackTrace) {
+          submitter.set(submitterStackTrace);
+        }
         try {
           command.run();
         } catch (Throwable t) {