How do I add error logging to my Akka streams in an idiomatic fashion?

Viewed 1033

I'm currently running an Akka streams setup similar to the following:

                 ┌───────────────┐                 
┌─────────────┐  │┌─────────────┐│                 
│REST endpoint│──▶│Queue source ││                 
└─────────────┘  │└──────╷──────┘│                 
                 │┌──────▼──────┐│                 
                 ││   Flow[T]   ││                 
                 │└──────╷──────┘│                 
                 │┌──────▼──────┐│  ┌─────────────┐
                 ││  KafkaSink  │├─▶│ Kafka topic │
                 │└─────────────┘│  └─────────────┘
                 └───────────────┘                 

While this working is well, I'd like to have some insight into the production system, i.e. have there been errors and what kind of errors. For example, I've wrapped the KafkaSink into a RestartSink.withBackoff and applied the following attributes to the wrapped sink:

private val decider: Supervision.Decider = {
  case x =>
    log.error("KafkaSink encountered an error and will stop", x)
    Supervision.Stop
}

Flow[...]
  .log("KafkaSink")
  .to(Producer.plainSink(...))
  .withAttributes(ActorAttributes.supervisionStrategy(decider))
  .addAttributes(
    ActorAttributes.logLevels(
      onElement = Logging.DebugLevel,
      onFinish = Logging.WarningLevel,
      onFailure = Logging.ErrorLevel
    )
  )

This does provide me with some insight, e.g. I'll get a log message that the downstream has closed as well as the exception that ocurred via the supervisionStrategy that I've added.

This solution, however, feels a little bit like a workaround (e.g. logging the exception the supervision strategy), and it also doesn't provide any insight into the behaviour of the RestartWithBackoffSink. I could, of course, enable DEBUG level logging for that class, but again, that feels like a workaround to be doing in production.

Long story short:

  • Are there any obvious shortcomings of the way I'm trying to gain insight into errors happening in my Akka streams
  • Is there a better / more idiomatic way of adding logging to Akka streams in production
1 Answers

I think you are almost there!!

Actually, it is the way as described in the documentation. Using log() approach gives you more fine-grained control of logging levels for elements flowing through the stream, finish and failure of the stream.Although, I do not prefer to add the log message inside the supervisor strategy. If you do want to show that particular exception, then, create a custom exception, catch it in the supervisor strategy and let Akka log that message for you. You can enable debug-logging in Akka stream config which is by default off for additional troubleshooting logging at the DEBUG log level. Apart from that, you can also enable logging at the actor level.(see this documentation).

I think in production, there might be two ways to log the errors:

1) log or rethrow exception in the recover stage. This way all exceptions from upstream will be caught and logged:

object AkkaStreamRecap extends App {

  implicit val system = ActorSystem("AkkaStreamsRecap")
  implicit val materialiser = ActorMaterializer()
  import system.dispatcher

  val source = Source(-5 to 5) 
  val sink = Sink.foreach[Int](println)
  val flow = Flow[Int].map(x => 1 / x)

  val runnableGraph = source.
    via(flow).
    recover {
      case e => throw e
    }.
    to(sink)

  runnableGraph.run()
}

Output:

0
0
0
0
-1
[ERROR] [03/06/2020 16:27:58.703] [AkkaStreamsRecap-akka.actor.default-dispatcher-2] [akka://AkkaStreamsRecap/system/StreamSupervisor-0/flow-0-0-ignoreSink] Error in stage [Recover(<function1>)]: / by zero
java.lang.ArithmeticException: / by zero
    at com.personal.akka.http.chapter1.AkkaStreamRecap$.$anonfun$flow$1(AkkaStreamRecap.scala:41)
    at scala.runtime.java8.JFunction1$mcII$sp.apply(JFunction1$mcII$sp.java:23)
    at akka.stream.impl.fusing.Map$$anon$1.onPush(Ops.scala:54)
    at akka.stream.impl.fusing.GraphInterpreter.processPush(GraphInterpreter.scala:523)
    at akka.stream.impl.fusing.GraphInterpreter.processEvent(GraphInterpreter.scala:480)
    at akka.stream.impl.fusing.GraphInterpreter.execute(GraphInterpreter.scala:376)
    at akka.stream.impl.fusing.GraphInterpreterShell.runBatch(ActorGraphInterpreter.scala:606)
    at akka.stream.impl.fusing.GraphInterpreterShell.init(ActorGraphInterpreter.scala:576)
    at akka.stream.impl.fusing.ActorGraphInterpreter.tryInit(ActorGraphInterpreter.scala:682)
    at akka.stream.impl.fusing.ActorGraphInterpreter.preStart(ActorGraphInterpreter.scala:731)
    at akka.actor.Actor.aroundPreStart(Actor.scala:550)
    at akka.actor.Actor.aroundPreStart$(Actor.scala:550)
    at akka.stream.impl.fusing.ActorGraphInterpreter.aroundPreStart(ActorGraphInterpreter.scala:671)
    at akka.actor.ActorCell.create(ActorCell.scala:676)
    at akka.actor.ActorCell.invokeAll$1(ActorCell.scala:547)
    at akka.actor.ActorCell.systemInvoke(ActorCell.scala:569)
    at akka.dispatch.Mailbox.processAllSystemMessages(Mailbox.scala:293)
    at akka.dispatch.Mailbox.run(Mailbox.scala:228)
    at akka.dispatch.Mailbox.exec(Mailbox.scala:241)
    at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
    at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
    at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
    at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

2) define custom supervision strategy and use it in stream attributes or in materializer settings:

object AkkaStreamRecap extends App {

  implicit val system = ActorSystem("AkkaStreamsRecap")

  private val decider: Supervision.Decider = {
    case e: ArithmeticException =>
      println("Arithmetic exception: Divide by Zero")
      Supervision.Stop
  }

  implicit val materialiser = ActorMaterializer(ActorMaterializerSettings(system).withSupervisionStrategy(decider))

  import system.dispatcher


  val source = Source(-5 to 5)
  val sink = Sink.foreach[Int](println)
  val flow = Flow[Int].map(x => 1 / x)

  val runnableGraph = source.via(flow).log("divide by zero").to(sink)

  runnableGraph.run()
}

output:

0
0
0
0
-1
Arithmetic exception: Divide by Zero
[ERROR] [03/06/2020 16:37:00.740] [AkkaStreamsRecap-akka.actor.default-dispatcher-2] [akka.stream.Log(akka://AkkaStreamsRecap/system/StreamSupervisor-0)] [divide by zero] Upstream failed.
java.lang.ArithmeticException: / by zero
    at com.personal.akka.http.chapter1.AkkaStreamRecap$.$anonfun$flow$1(AkkaStreamRecap.scala:26)
    at scala.runtime.java8.JFunction1$mcII$sp.apply(JFunction1$mcII$sp.java:23)
    at akka.stream.impl.fusing.Map$$anon$1.onPush(Ops.scala:54)
    at akka.stream.impl.fusing.GraphInterpreter.processPush(GraphInterpreter.scala:523)
    at akka.stream.impl.fusing.GraphInterpreter.processEvent(GraphInterpreter.scala:480)
    at akka.stream.impl.fusing.GraphInterpreter.execute(GraphInterpreter.scala:376)
    at akka.stream.impl.fusing.GraphInterpreterShell.runBatch(ActorGraphInterpreter.scala:606)
    at akka.stream.impl.fusing.GraphInterpreterShell.init(ActorGraphInterpreter.scala:576)
    at akka.stream.impl.fusing.ActorGraphInterpreter.tryInit(ActorGraphInterpreter.scala:682)
    at akka.stream.impl.fusing.ActorGraphInterpreter.preStart(ActorGraphInterpreter.scala:731)
    at akka.actor.Actor.aroundPreStart(Actor.scala:550)
    at akka.actor.Actor.aroundPreStart$(Actor.scala:550)
    at akka.stream.impl.fusing.ActorGraphInterpreter.aroundPreStart(ActorGraphInterpreter.scala:671)
    at akka.actor.ActorCell.create(ActorCell.scala:676)
    at akka.actor.ActorCell.invokeAll$1(ActorCell.scala:547)
    at akka.actor.ActorCell.systemInvoke(ActorCell.scala:569)
    at akka.dispatch.Mailbox.processAllSystemMessages(Mailbox.scala:293)
    at akka.dispatch.Mailbox.run(Mailbox.scala:228)
    at akka.dispatch.Mailbox.exec(Mailbox.scala:241)
    at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
    at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
    at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
    at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

Let me know if it helps!!

P.S... I could not find any source or way in the official documentation on other ways to log the errors.

Related