Future onComplete callback is not called

user_2159158 0
Viewed 182

I am trying to log the elapsed time of each task as follows.

The problem I have encountered is that the callback method within the logElapsedTime never gets called for some reason.

Only the very last callback to Future f is called.

How can I fix this so that each elapsed time is correctly logged?

    def logElapsedTime[T](f: Future[T], description: String): Future[T] = {
      val start = System.currentTimeMillis()
      f onComplete (_ => logger.debug(s"$description took [${System.currentTimeMillis() - start}]"))
      f
    }

    val f = for {
      _ <- logElapsedTime(task1(), "1st task to be executed")
      result <- logElapsedTime(task2(), "2nd task to be executed")
      _ <- logElapsedTime(task3(), "3rd task to be executed")
      _ <- logElapsedTime(task4(), "4th task to be executed")
    } yield result

    f onComplete {
      case Success(v) =>
        logger.info(s"tasks succeeded !!!! $v")
      case Failure(ex) =>
        logger.error(ex.getMessage)
        throw ex
    }

Output Samples ↓

when succeeded:

tasks succeeded !!!! some value

when failed:

some error message

No other inputs are logged.
(Log level is set to debug and above)

playframework scala
2 Answers

There is nothing wrong with your logic. Few modifications applied that I suggest you to try out. 

import org.slf4j.LoggerFactory

import scala.concurrent.Future
import concurrent.ExecutionContext.Implicits.global
import scala.io.StdIn
import scala.util.{Failure, Success}

object FutureOnComplete extends App {

  private val logger = LoggerFactory.getLogger("test")

  def logElapsedTime[T](f: => Future[T], description: String): Future[T] = {
    val start = System.currentTimeMillis()
    f.onComplete(
      _ =>
        logger.warn(
          s"$description took [${System.currentTimeMillis() - start}]"))
    f
  }

  val f = for {
    _ <- logElapsedTime(Future(1), "1st task to be executed")
    result <- logElapsedTime(Future(2), "2nd task to be executed")
    _ <- logElapsedTime(Future(2), "3rd task to be executed")
    _ <- logElapsedTime(Future(2), "4th task to be executed")
  } yield result

  f.onComplete {
    case Success(v) =>
      logger.info(s"tasks succeeded !!!! $v")
    case Failure(ex) =>
      logger.error(ex.getMessage)
      throw ex
  }

  StdIn.readLine()

}
  • Increase the log level to warn to make sure your logging is not to blame. Or replace it with println
  • Wait in your main thread for future completion with StdIn.readLine() for example. This allows the async processes to finish and onComplete to run.
  • Use => Future[T] by name parameter to start execution of future inside the method logElapsedTime. This just changes when the future is started but not the logic of logging
user_48038420

Consider andThen when we just want to execute logging as side-effect without transforming the value inside the Future, for example

object futureAndThenLogging extends App with LazyLogging {

  def logElapsedTime[T](f: Future[T], description: String): Future[T] = {
    val start = System.currentTimeMillis()
    f andThen { case _ => logger.debug(s"$description took [${System.currentTimeMillis() - start}]") }
  }

  def task1() = Future(1)
  def task2() = Future(2)
  def task3() = Future(3)
  def task4() = Future(4)

  (for {
    _ <- logElapsedTime(task1(), "1st task to be executed")
    result <- logElapsedTime(task2(), "2nd task to be executed")
    _ <- logElapsedTime(task3(), "3rd task to be executed")
    _ <- logElapsedTime(task4(), "4th task to be executed")
  } yield result)
    .andThen {
      case Success(v) => logger.info(s"tasks succeeded !!!! $v")
      case Failure(ex) => logger.error(ex.getMessage)
    }

  Thread.sleep(1000) // just for demonstration purposes
}

Note how we did not have to re-throw ex in case Failure(ex) => logger.error(ex.getMessage).

user_52050220
Related