finagle-mysql: Don't log exceptions if we fail to rollback a transact…

…ion and it was a ChannelClosedException

Problem:
If a rollback fails due to a ChannelClosedException, the logs are very
spammy and leads devs triaging issues to falsely blame them.

Solution:
If the rollback fails due to a ChannelClosedException (which happens if the
underlying service has already been closed by a lower-level call), don't log
the exception

Result:
Any rollbacks that fail due to a ChannelClosedExceptions don't log the exception,
but we still poison the connection and try and close it again.

JIRA Issues: CSL-8242

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

CHANGELOG.rst

@@ -77,6 +77,9 @@ Bug Fixes
 * finagle-zipkin-core: Fix a race condition which could cause a span to get logged
   missing some annotations. ``PHAB_ID=D319367``
 
+* finagle-mysql: Don't log `c.t.f.ChannelClosedException` when rolling back a transaction
+  fails. ``PHAB_ID=D327111``
+
 19.5.1
 ------
 

finagle-mysql/src/main/scala/com/twitter/finagle/mysql/RollbackFactory.scala

@@ -46,20 +46,31 @@ final class RollbackFactory(client: ServiceFactory[Request, Result], statsReceiv
           rollbackLatencyStat.add(elapsed().inMillis)
           result match {
             case Return(_) => self.close(deadline)
+            case Throw(_: ChannelClosedException) =>
+              // Don't log the exception on ChannelClosedExceptions because it is noisy.
+
+              // We want to close the connection if we can't issue a rollback
+              // since we assume it isn't a "clean" connection to put back into
+              // the pool.
+              poisonAndClose(deadline)
             case Throw(t) =>
               log.warning(
                 t,
                 "rollback failed when putting service back into pool, closing connection"
               )
-              // we want to close the connection if we can't issue a rollback
+              // We want to close the connection if we can't issue a rollback
               // since we assume it isn't a "clean" connection to put back into
               // the pool.
-              self(PoisonConnectionRequest).transform { _ =>
-                self.close(deadline)
-              }
+              poisonAndClose(deadline)
           }
         }
       }
+
+      private[this] def poisonAndClose(deadline: Time): Future[Unit] = {
+        self(PoisonConnectionRequest).transform { _ =>
+          self.close(deadline)
+        }
+      }
     }
 
   private[this] val wrapFn: Service[Request, Result] => Service[Request, Result] = { svc =>

finagle-mysql/src/test/scala/com/twitter/finagle/mysql/unit/RollbackFactoryTest.scala

@@ -2,7 +2,7 @@ package com.twitter.finagle.mysql
 
 import com.twitter.conversions.DurationOps._
 import com.twitter.finagle.stats.NullStatsReceiver
-import com.twitter.finagle.{ClientConnection, Service, ServiceFactory}
+import com.twitter.finagle.{ChannelClosedException, ClientConnection, Service, ServiceFactory}
 import com.twitter.util.{Await, Awaitable, Future, Time}
 import org.scalatest.FunSuite
 
@@ -95,4 +95,34 @@ class RollbackFactoryTest extends FunSuite {
     assert(requests == Seq(QueryRequest("1"), PoisonConnectionRequest))
     assert(closeCalled)
   }
+
+  test("poison request is sent when rollback fails with ChannelClosedException") {
+    var requests: Seq[Request] = Seq.empty
+    var closeCalled = false
+    val client: ServiceFactory[Request, Result] = new ServiceFactory[Request, Result] {
+      private[this] val svc: Service[Request, Result] = new Service[Request, Result] {
+        def apply(req: Request): Future[EOF] = req match {
+          case QueryRequest("ROLLBACK") => Future.exception(new ChannelClosedException())
+          case _ =>
+            requests = requests :+ req
+            Future.value(EOF(0, ServerStatus(0)))
+        }
+        override def close(when: Time): Future[Unit] = {
+          closeCalled = true
+          Future.Done
+        }
+      }
+      def apply(c: ClientConnection): Future[Service[Request, Result]] = Future.value(svc)
+      def close(deadline: Time): Future[Unit] = svc.close(deadline)
+    }
+
+    val rollbackClient = new RollbackFactory(client, NullStatsReceiver)
+
+    await(rollbackClient().flatMap { svc =>
+      svc(QueryRequest("1")).ensure { svc.close() }
+    })
+
+    assert(requests == Seq(QueryRequest("1"), PoisonConnectionRequest))
+    assert(closeCalled)
+  }
 }