Improve debug logging in RequestFinalizers.

RB=1905097 G=si-core-reviewers R=cxu,dmessink A=dmessink
linkedin · Dec 10, 2019 · 72849a1 · 72849a1
1 parent 3a80c39
commit 72849a1
Show file tree

Hide file tree

Showing 5 changed files with 42 additions and 43 deletions.
diff --git a/CHANGELOG b/CHANGELOG
@@ -1,5 +1,10 @@
+28.0.13
+-------
+
 28.0.12
 -------
+(RB=1905097)
+Improve debug logging in RequestFinalizers.
 
 28.0.11
 -------

diff --git a/gradle.properties b/gradle.properties
@@ -1,4 +1,4 @@
-version=28.0.11
+version=28.0.12
 sonatypeUsername=please_set_in_home_dir_if_uploading_to_maven_central
 sonatypePassword=please_set_in_home_dir_if_uploading_to_maven_central
 org.gradle.configureondemand=true

diff --git a/r2-core/src/main/java/com/linkedin/r2/filter/ClientRequestFinalizerFilter.java b/r2-core/src/main/java/com/linkedin/r2/filter/ClientRequestFinalizerFilter.java
@@ -146,25 +146,9 @@ private void doFinalizeRequest(RequestContext requestContext, Response response,
     {
       final boolean finalized = manager.finalizeRequest(response, ex);
 
-      if (finalized)
+      if (!finalized)
       {
-        if (LOG.isDebugEnabled())
-        {
-          LOG.debug("Finalized request for the first time.", new RuntimeException("First client request finalizer."));
-        }
-      }
-      else
-      {
-        final String message = "Request has already been finalized, but we expect this to be the first time.";
-
-        if (LOG.isDebugEnabled())
-        {
-          LOG.debug(message, new RuntimeException("Client request finalizer warning."));
-        }
-        else
-        {
-          LOG.warn(message);
-        }
+        LOG.warn("Request has already been finalized, but we expect this to be the first time.");
       }
     }
   }

diff --git a/r2-core/src/main/java/com/linkedin/r2/util/finalizer/RequestFinalizerDispatcher.java b/r2-core/src/main/java/com/linkedin/r2/util/finalizer/RequestFinalizerDispatcher.java
@@ -75,16 +75,12 @@ public void handleStreamRequest(StreamRequest req, Map<String, String> wireAttrs
   private class RequestFinalizerTransportCallback<T extends Response> implements TransportCallback<T>
   {
     private final RequestFinalizerManagerImpl _manager;
-    private final RequestContext _requestContext;
-    private final Request _request;
     private final TransportCallback<T> _transportCallback;
 
     public RequestFinalizerTransportCallback(TransportCallback<T> transportCallback, RequestContext requestContext,
         Request request)
     {
       _manager = addRequestFinalizerManager(request, requestContext);
-      _requestContext = requestContext;
-      _request = request;
       _transportCallback = transportCallback;
     }
 
@@ -170,25 +166,9 @@ private void finalizeRequest(Response response, Throwable error)
     {
       final boolean finalized = _manager.finalizeRequest(response, error);
 
-      if (finalized)
+      if (!finalized)
       {
-        if (LOG.isDebugEnabled())
-        {
-          LOG.debug("Finalized request for the first time.", new RuntimeException("First server request finalizer."));
-        }
-      }
-      else
-      {
-        final String message = "Request has already been finalized, but we expect this to be the first time.";
-
-        if (LOG.isDebugEnabled())
-        {
-          LOG.debug(message, new RuntimeException("Server request finalizer warning."));
-        }
-        else
-        {
-          LOG.warn(message);
-        }
+        LOG.warn("Request has already been finalized, but we expect this to be the first time.");
       }
     }
   }

diff --git a/r2-core/src/main/java/com/linkedin/r2/util/finalizer/RequestFinalizerManagerImpl.java b/r2-core/src/main/java/com/linkedin/r2/util/finalizer/RequestFinalizerManagerImpl.java
@@ -21,7 +21,8 @@
 import java.util.List;
 import java.util.concurrent.CopyOnWriteArrayList;
 import java.util.concurrent.atomic.AtomicBoolean;
-import java.util.concurrent.atomic.AtomicReference;
+import java.util.concurrent.atomic.AtomicInteger;
+
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -38,19 +39,27 @@
 public class RequestFinalizerManagerImpl implements RequestFinalizerManager
 {
   private static final Logger LOG = LoggerFactory.getLogger(RequestFinalizerManagerImpl.class);
+  private static final AtomicInteger INSTANCE_COUNT = new AtomicInteger();
 
   private final Request _request;
   private final RequestContext _requestContext;
   private final List<RequestFinalizer> _requestFinalizers;
   private final AtomicBoolean _isFinalized;
 
+  // For debug logging.
+  private final int _id;
+  private final AtomicInteger _numFinalizations = new AtomicInteger();
+  private RuntimeException _firstFinalization;
+
   public RequestFinalizerManagerImpl(Request request, RequestContext requestContext)
   {
     _request = request;
     _requestContext = requestContext;
 
     _requestFinalizers = new CopyOnWriteArrayList<>();
     _isFinalized = new AtomicBoolean();
+
+    _id = INSTANCE_COUNT.getAndIncrement();
   }
 
   @Override
@@ -79,6 +88,12 @@ public boolean finalizeRequest(Response response, Throwable error)
   {
     if (_isFinalized.compareAndSet(false, true))
     {
+      if (LOG.isDebugEnabled())
+      {
+        _numFinalizations.incrementAndGet();
+        _firstFinalization = new RuntimeException("Finalized at time: " + System.currentTimeMillis());
+      }
+
       for (RequestFinalizer requestFinalizer: _requestFinalizers)
       {
         try
@@ -92,6 +107,21 @@ public boolean finalizeRequest(Response response, Throwable error)
       }
       return true;
     }
-    return false;
+    else
+    {
+      if (LOG.isDebugEnabled())
+      {
+        final int numFinalizations = _numFinalizations.incrementAndGet();
+
+        if (numFinalizations == 2)
+        {
+          // Log the first finalization since we now know the request will be finalized at least twice.
+          LOG.debug("Request finalized the first time. FinalizerManager ID = " + _id, _firstFinalization);
+        }
+
+        LOG.debug("Request finalized " + numFinalizations + " times. FinalizerManager ID = " + _id, new RuntimeException());
+      }
+      return false;
+    }
   }
 }