finagle-core: in TimeoutFilter, only transform a timeout exception ca…

…used by TimeoutFilter

Problem

The TimeoutFilter transforms any TimeoutException it encounters into a new exception, regardless of whether the timeout exception was triggered by the TimeoutFilter's timer. As a result, information about the original timeout exception (including the timeout) can be lost because the TimeoutFilter will return a timeout exception with its own timeout.

Solution

Create an internal exception for the TimeoutFilter to throw and catch on timeout to ensure that the TimeoutFilter only transforms the timeout exception caused by its own timeout.

Note: this change uncovered a race condition in the MethodBuilderTest in which the global timeout was being thrown before the first retry had time to hit its per-request timeout. With this change, the test was no longer hitting a retry count of 2. To fix this we can enforce the order of events in the MethodBuilderTest.

Result

When a timeout exception is thrown from a source other than the TimeoutFilter, that exception will make its way all the way to the user, instead of being transformed into a different and misleading timeout exception in the TimeoutFilter.

JIRA Issues: CSL-11340

Differential Revision: https://phabricator.twitter.biz/D814094

CHANGELOG.rst

@@ -19,6 +19,10 @@ Runtime Behavior Changes
 
 * finagle: Bump version of Caffeine to 2.9.3. ``PHAB_ID=D815761``
 
+* finagle-core: in TimeoutFilter, only transform a timeout exception caused by TimeoutFilter. This also
+  changes the type of exception raised by the TimeoutFilter from a java.util.concurrent.TimeoutException
+  to a com.twitter.finagle.RequestTimeoutException. ``PHAB_ID=D814094``
+
 22.1.0
 ------
 

finagle-core/src/main/scala/com/twitter/finagle/service/TimeoutFilter.scala

@@ -18,6 +18,7 @@ import com.twitter.util.Duration
 import com.twitter.util.Future
 import com.twitter.util.Timer
 import com.twitter.util.tunable.Tunable
+import scala.util.control.NoStackTrace
 
 private[twitter] object DeadlineOnlyToggle {
   private val enableToggle = CoreToggles("com.twitter.finagle.service.DeadlineOnly")
@@ -391,6 +392,9 @@ class TimeoutFilter[Req, Rep](
   private[this] val deadlineAnnotation = rolePrefix + DeadlineAnnotation
   private[this] val timeoutAnnotation = rolePrefix + TimeoutAnnotation
 
+  private[this] class InternalTimeoutException extends Exception with NoStackTrace
+  private[this] val internalTimeoutEx = new InternalTimeoutException
+
   def apply(request: Req, service: Service[Req, Rep]): Future[Rep] = {
     val timeout = timeoutFn()
     val timeoutDeadline = Deadline.ofTimeout(timeout)
@@ -459,11 +463,12 @@ class TimeoutFilter[Req, Rep](
     if (!timeout.isFinite) {
       res
     } else {
-      res.within(timer, timeout).rescue {
-        case exc: java.util.concurrent.TimeoutException =>
-          res.raise(exc)
+      res.within(timer, timeout, internalTimeoutEx).rescue {
+        case exc if exc eq internalTimeoutEx =>
+          val timeoutEx = exceptionFn(timeout)
+          res.raise(timeoutEx)
           Trace.record(timeoutAnnotation)
-          Future.exception(exceptionFn(timeout))
+          Future.exception(timeoutEx)
       }
     }
   }

finagle-core/src/test/scala/com/twitter/finagle/client/MethodBuilderTest.scala

@@ -135,7 +135,11 @@ class MethodBuilderTest
 
     val perReqTimeout = 50.milliseconds
     val totalTimeout = perReqTimeout * 2 + 20.milliseconds
+
+    // keep track of the number of requests initiated
+    var tries = 0
     val svc: Service[Int, Int] = Service.mk { i =>
+      tries += 1
       Future.sleep(perReqTimeout + 1.millis)(timer).map(_ => i)
     }
 
@@ -169,11 +173,21 @@ class MethodBuilderTest
       timer.tick()
       assert(!rep.isDefined)
 
+      eventually {
+        // wait for the first request to time out and trigger a retry (2 tries initiated)
+        assert(tries == 2)
+      }
+
       // hit the 2nd per-req timeout.
       tc.advance(perReqTimeout)
       timer.tick()
       assert(!rep.isDefined)
 
+      eventually {
+        // wait for the second request (first retry) to time out and trigger another retry
+        assert(tries == 3)
+      }
+
       // hit the total timeout
       tc.advance(20.milliseconds)
       timer.tick()
@@ -803,7 +817,11 @@ class MethodBuilderTest
       case ReqRep(_, Throw(_: IndividualRequestTimeoutException)) =>
         ResponseClass.RetryableFailure
     }
+
+    // keep track of the number of requests initiated
+    var tries = 0;
     val svc: Service[Int, Int] = Service.mk { i =>
+      tries += 1
       Future.sleep(perReqTimeout + 1.millis)(timer).map(_ => i)
     }
 
@@ -840,11 +858,21 @@ class MethodBuilderTest
       timer.tick()
       assert(!rep.isDefined)
 
+      eventually {
+        // wait for the first request to time out and trigger a retry (2 tries initiated)
+        assert(tries == 2)
+      }
+
       // hit the 2nd per-req timeout.
       tc.advance(perReqTimeout)
       timer.tick()
       assert(!rep.isDefined)
 
+      eventually {
+        // wait for the second request (first retry) to time out and trigger another retry
+        assert(tries == 3)
+      }
+
       // hit the total timeout
       tc.advance(20.milliseconds)
       timer.tick()

finagle-core/src/test/scala/com/twitter/finagle/service/TimeoutFilterTest.scala

@@ -16,6 +16,7 @@ import com.twitter.finagle.tracing.TraceId
 import com.twitter.util._
 import com.twitter.util.tunable.Tunable
 import java.util.concurrent.atomic.AtomicReference
+import java.util.concurrent.TimeoutException
 import org.scalatest.funsuite.AnyFunSuite
 import org.scalatest.matchers.should.Matchers
 import org.scalatestplus.mockito.MockitoSugar
@@ -81,7 +82,7 @@ class TimeoutFilterTest extends AnyFunSuite with Matchers with MockitoSugar {
       timer.tick()
       assert(res.isDefined)
       val t = promise.interrupted
-      intercept[java.util.concurrent.TimeoutException] {
+      intercept[RequestTimeoutException] {
         throw t.get
       }
       intercept[IndividualRequestTimeoutException] {
@@ -90,6 +91,21 @@ class TimeoutFilterTest extends AnyFunSuite with Matchers with MockitoSugar {
     }
   }
 
+  test("TimeoutFilter should not transform a TimeoutException") {
+    val timeoutException = new TimeoutException("timeout exception")
+    val service = new Service[Unit, Unit] {
+      def apply(req: Unit) = throw timeoutException
+    }
+
+    val timeoutFilter = new TimeoutFilter[Unit, Unit](1.second, new MockTimer)
+    val timeoutService = timeoutFilter.andThen(service)
+
+    val exc = intercept[TimeoutException] {
+      Await.result(timeoutService())
+    }
+    assert(exc == timeoutException)
+  }
+
   class DeadlineCtx(val timeout: Duration) {
     val service = new Service[Unit, Option[Deadline]] {
       def apply(req: Unit) = Future.value(Deadline.current)