Merge pull request #129 from hmrc/BDOG-1378

BDOG-1378 Deprecate MdcLoggingExecutionContext and fix mdc in Retries

http-verbs-common/src/main/scala/uk/gov/hmrc/http/Retries.scala

@@ -36,16 +36,21 @@ trait Retries {
   private val logger = LoggerFactory.getLogger("application")
 
   def retry[A](verb: String, url: String)(block: => Future[A])(implicit ec: ExecutionContext): Future[A] = {
-    def loop(remainingIntervals: Seq[FiniteDuration])(mdcData: Map[String, String])(block: => Future[A]): Future[A] =
+    def loop(remainingIntervals: Seq[FiniteDuration]): Future[A] = {
       // scheduling will loose MDC data. Here we explicitly ensure it is available on block.
-      Mdc.withMdc(block, mdcData)
+      block
         .recoverWith {
           case ex @ `sslEngineClosedMatcher`() if remainingIntervals.nonEmpty =>
             val delay = remainingIntervals.head
             logger.warn(s"Retrying $verb $url in $delay due to '${ex.getMessage}' error")
-            after(delay, actorSystem.scheduler)(loop(remainingIntervals.tail)(mdcData)(block))
+              val mdcData = Mdc.mdcData
+              after(delay, actorSystem.scheduler){
+                Mdc.putMdc(mdcData)
+                loop(remainingIntervals.tail)
+              }
         }
-    loop(intervals)(Mdc.mdcData)(block)
+      }
+    loop(intervals)
   }
 
   private[http] lazy val intervals: Seq[FiniteDuration] =

http-verbs-common/src/main/scala/uk/gov/hmrc/play/http/logging/Mdc.scala

@@ -30,17 +30,16 @@ object Mdc {
     block.map { a =>
       putMdc(mdcData)
       a
-    }.recover {
+    }.recoverWith {
       case t =>
         putMdc(mdcData)
-        throw t
+        Future.failed(t)
     }
 
-  private def putMdc(mdc: Map[String, String]): Unit = {
+  def putMdc(mdc: Map[String, String]): Unit =
     mdc.foreach {
       case (k, v) => MDC.put(k, v)
     }
-  }
 
   /** Restores MDC data to the continuation of a block, which may be discarding MDC data (e.g. uses a different execution context)
     */

http-verbs-common/src/main/scala/uk/gov/hmrc/play/http/logging/MdcLoggingExecutionContext.scala

@@ -20,6 +20,7 @@ import org.slf4j.MDC
 
 import scala.concurrent.ExecutionContext
 
+@deprecated("MdcLoggingExecutionContext no longer required, please inject Play's default EC instead", "15.6.0")
 class MdcLoggingExecutionContext(wrapped: ExecutionContext, mdcData: Map[String, String])
   extends ExecutionContext {
 

http-verbs-common/src/test/scala/uk/gov/hmrc/http/RetriesSpec.scala

@@ -17,6 +17,7 @@
 package uk.gov.hmrc.http
 
 import java.time.Instant
+import java.util.concurrent.Executors
 
 import akka.actor.ActorSystem
 import com.typesafe.config.{Config, ConfigFactory}
@@ -29,6 +30,7 @@ import org.slf4j.MDC
 import play.api.libs.json.{JsValue, Json, Writes}
 import uk.gov.hmrc.http.HttpReads.Implicits._
 import uk.gov.hmrc.http.hooks.{HttpHook, HttpHooks}
+import uk.gov.hmrc.play.http.logging.Mdc
 
 import scala.collection.JavaConverters._
 import scala.concurrent.duration._
@@ -181,26 +183,28 @@ class RetriesSpec extends AnyWordSpecLike with Matchers with MockitoSugar with S
       }
 
       val mdcData = Map("key1" -> "value1")
-      mdcData.foreach { case (k, v) => MDC.put("key1", "value1") }
-      val mdcEc = new uk.gov.hmrc.play.http.logging.MdcLoggingExecutionContext(implicitly[ExecutionContext], mdcData)
+
+      implicit val mdcEc = ExecutionContext.fromExecutor(new uk.gov.hmrc.play.http.logging.MDCPropagatingExecutorService(Executors.newFixedThreadPool(2)))
 
       val expectedResponse = HttpResponse(404, "")
 
       val resultF =
-        retries.retry("GET", "url") {
-          // assert mdc available to block execution
-          Option(MDC.getCopyOfContextMap).map(_.asScala.toMap).getOrElse(Map.empty) shouldBe mdcData
-
-          retries.failFewTimesAndThenSucceed(
-            success   = Future.successful(expectedResponse),
-            exception = new SSLException("SSLEngine closed already")
-          )
-        }(mdcEc)
-        .map { res =>
+        for {
+          _   <- Future.successful(Mdc.putMdc(mdcData))
+          res <- retries.retry("GET", "url") {
+                  // assert mdc available to block execution
+                  Option(MDC.getCopyOfContextMap).map(_.asScala.toMap).getOrElse(Map.empty) shouldBe mdcData
+
+                  retries.failFewTimesAndThenSucceed(
+                    success   = Future.successful(expectedResponse),
+                    exception = new SSLException("SSLEngine closed already")
+                  )
+                }
+        } yield {
           // assert mdc available to continuation
           Option(MDC.getCopyOfContextMap).map(_.asScala.toMap).getOrElse(Map.empty) shouldBe mdcData
           res
-        }(mdcEc)
+        }
 
       whenReady(resultF) { response =>
         response shouldBe expectedResponse
@@ -372,14 +376,15 @@ class RetriesSpec extends AnyWordSpecLike with Matchers with MockitoSugar with S
 
   trait SucceedNthCall {
     var failureCounter: Int = 0
-    val maxFailures: Int    = Random.nextInt(3)
-    def failFewTimesAndThenSucceed[A, B](success: Future[A], exception: Exception): Future[A] =
+    val maxFailures: Int    = 1 + Random.nextInt(2)
+    def failFewTimesAndThenSucceed[A, B](success: Future[A], exception: Exception): Future[A] = {
+      println(s"failFewTimesAndThenSucceed = $failureCounter, $maxFailures")
       if (failureCounter < maxFailures) {
         failureCounter += 1
         Future.failed(exception)
-      } else {
+      } else
         success
-      }
+    }
   }
 
   trait TestHttpPost extends HttpPost {

http-verbs-common/src/test/scala/uk/gov/hmrc/play/http/logging/MdcLoggingExecutionContextSpec.scala

@@ -18,6 +18,7 @@ package uk.gov.hmrc.play.http.logging
 
 import java.util.concurrent.{CountDownLatch, Executors}
 
+import com.github.ghik.silencer.silent
 import ch.qos.logback.classic.spi.ILoggingEvent
 import ch.qos.logback.classic.{Level, Logger => LogbackLogger}
 import ch.qos.logback.core.AppenderBase
@@ -33,6 +34,7 @@ import scala.concurrent.duration._
 import scala.concurrent.{Await, ExecutionContext, Future}
 import scala.reflect._
 
+@silent("deprecated")
 class MdcLoggingExecutionContextSpec
     extends AnyWordSpecLike
     with Matchers

http-verbs-common/src/test/scala/uk/gov/hmrc/http/logging/MdcSpec.scala → http-verbs-common/src/test/scala/uk/gov/hmrc/play/http/logging/MdcSpec.scala

@@ -14,22 +14,24 @@
  * limitations under the License.
  */
 
-package uk.gov.hmrc.http.logging
+package uk.gov.hmrc.play.http.logging
 
 import akka.dispatch.ExecutorServiceDelegate
 import org.scalatest.BeforeAndAfter
-import org.scalatest.concurrent.{IntegrationPatience, ScalaFutures}
+import org.scalatest.concurrent.ScalaFutures
 import org.scalatest.matchers.should.Matchers
 import org.scalatest.wordspec.AnyWordSpecLike
-import org.scalatestplus.mockito.MockitoSugar
 import org.slf4j.MDC
-import uk.gov.hmrc.play.http.logging.Mdc
 
 import java.util.concurrent.{ExecutorService, Executors}
 import scala.concurrent.duration.DurationInt
 import scala.concurrent.{ExecutionContext, Future}
 
-class MdcSpec extends AnyWordSpecLike with Matchers with MockitoSugar with ScalaFutures with BeforeAndAfter with IntegrationPatience {
+class MdcSpec
+  extends AnyWordSpecLike
+     with Matchers
+     with ScalaFutures
+     with BeforeAndAfter {
 
   before {
     MDC.clear()
@@ -58,9 +60,9 @@ class MdcSpec extends AnyWordSpecLike with Matchers with MockitoSugar with Scala
       implicit val mdcEc: ExecutionContext = mdcPropagatingExecutionContext()
 
       (for {
-        _ <- Future.successful(org.slf4j.MDC.put("k", "v"))
-        _ <- Mdc.preservingMdc(runActionWhichLosesMdc())
-      } yield
+         _ <- Future.successful(org.slf4j.MDC.put("k", "v"))
+         _ <- Mdc.preservingMdc(runActionWhichLosesMdc())
+       } yield
         Option(MDC.get("k"))
       ).futureValue shouldBe Some("v")
     }
@@ -72,16 +74,15 @@ class MdcSpec extends AnyWordSpecLike with Matchers with MockitoSugar with Scala
          _ <- Future.successful(org.slf4j.MDC.put("k", "v"))
          _ <- Mdc.preservingMdc(runActionWhichLosesMdc(fail = true))
        } yield ()
-      )
-      .recover { case _ =>
+      ).recover { case _ =>
         Option(MDC.get("k"))
       }.futureValue shouldBe Some("v")
     }
   }
 
   private def runActionWhichLosesMdc(fail: Boolean = false): Future[Any] = {
-    val as = akka.actor.ActorSystem("different-as")
-    akka.pattern.after(1.second, as.scheduler)(Future(())(as.dispatcher))(as.dispatcher)
+    val as = akka.actor.ActorSystem("as")
+    akka.pattern.after(10.millis, as.scheduler)(Future(())(as.dispatcher))(as.dispatcher)
       .map(a => if (fail) sys.error("expected test exception") else a)(as.dispatcher)
   }
 
@@ -105,17 +106,16 @@ class MDCPropagatingExecutorService(val executor: ExecutorService) extends Execu
         try {
           command.run()
         } finally {
+          // this means any Mdc updates on the ec will not be propagated once it steps out
           setMDC(oldMdcData)
         }
       }
     })
   }
 
-  private def setMDC(context: java.util.Map[String, String]): Unit = {
-    if (context == null) {
+  private def setMDC(context: java.util.Map[String, String]): Unit =
+    if (context == null)
       MDC.clear()
-    } else {
+    else
       MDC.setContextMap(context)
-    }
-  }
 }