Subsequent Akka ask spans do not share the same parent

[steinybot]

Expected:

The spans created by:

val future = for {
  _ <- first ? "Hello?"
  _ <- second ? "Goodbye!"
} yield ()

Should have the same parent.

Actual:

The span from the first ask is the parent of the second.

See this unit test which reproduces the problem.

[steinybot]

I'm not sure if this is a good workaround but it works:

        val future = for {
          _ <- Kamon.runWithSpan(span) {
            first ? "Hello?"
          }
          _ <- Kamon.runWithSpan(span) {
            second ? "Goodbye!"
          }
        } yield ()

[ivantopo]

Hey @steinybot!

I remember working on this long ago. Not specifically for the ask pattern, but for Futures which is what seems to be kicking-in here. I think it was around the time of this: kamon-io/kamon-futures#12. I do remember having the explicit intent of moving from "all future transformations are siblings" in Kamon 1.x to "all future transformations are a children chain" as it is in Kamon 2.x. I also remember it being super hard to get it done, but I made it happen!

But time seems to prove that it was wrong to do so 😭. I'm not sure if people are expecting these Spans to be siblings because of historical behavior from Kamon 1.x, or because it is actually more natural to be like that.

I'm starting to think that we should let users decide whether they want one behavior or the other, probably via some new setting, but that seems like non-trivial work. The more feedback we can get before touching this the better 🙏

What are your thoughts on that? Should Spans from chained futures be siblings or children of each other?

Also invoking the folks I know might be interested in the topic: @jatcwang @jtjeferreira @SimunKaracic @nadavwr @danielkman @yiminyuan @danischroeter. Please feel free to add more people who might be interested in the topic.

[nadavwr]

For comprehensions, much like Haskell's do notation (where this is more apparent) kinda emulates imperative calls:

do putStr "What is your first name? "
   first <- getLine
   putStr "And your last name? "
   last <- getLine
   let full = first ++ " " ++ last
   putStrLn ("Pleased to meet you, " ++ full ++ "!")

It seems to me that the code above is comprised of sibling statements—that's the user intent at least. However, deeply nested flatMaps (manually) would also be how I'd expect to describe a sequence of spans—after all, there's an obvious "contains" relationship (this is what you chose already so skipping example 🙂).

When I write for comprehensions my intent is usually for siblings—same goes for flatMap callchains. When I write nested flatMaps (desugared equivalent to for comprehensions) my intent is usually for a sequence of children.

There seems to me to be a matter of user intent, with the following heuristics:

• for comprehension: usually siblings
• manually nested flatMaps: usually children

The problem is that the two cases would be virtually indistinguishable for instrumentation purposes.

I think best case scenario (minimal disruption) would be to continue treating them as children by default, and figure out a way to make @steinybot's workaround a bit nicer. Though I can't imagine how exactly.

[steinybot]

What I always find a bit strange with tracing is when there is a parent span which finishes before the child starts. It looks especially weird when there is a large delay between the parent finishing and the child starting as you cannot visually identify which span is the parent. Whenever I see that I wonder why they aren't siblings, especially if there is a clear sequencing to them.

If you can use the result of the Future (like in flatMap, onComplete etc.) then I would expect them to always be siblings (like in chained flatMaps). If you are creating a Future to use as the result of the "current" Future then they should be children (like in nested flatMaps).

Is it not possible to tell the difference? Even without for-comprehension, chained flatMaps look quite different to nested flatMaps.

Here is some code which illustrates what I would expect:

import java.util.concurrent.{ConcurrentLinkedDeque, ConcurrentLinkedQueue}
import java.util.concurrent.atomic.AtomicInteger
import scala.concurrent.ExecutionContext.Implicits.global
import scala.concurrent.duration._
import scala.concurrent.{Await, Future}
import scala.jdk.CollectionConverters._

val clock = new AtomicInteger(0)

final case class Span(name: String, parent: Option[Span], start: Int, end: Option[Int]) {
  def depth: Int = parent.map(_.depth + 1).getOrElse(0)
  override def toString = s"Span($name, ${parent.map(_.name).getOrElse("<root>")}, $start, ${end.getOrElse("<running>")})"
}

val spanStack = new ConcurrentLinkedDeque[Span]()
val finishedSpans = new ConcurrentLinkedQueue[Span]()

def startSpan(name: String): Span = {
  val parent = if (spanStack.isEmpty) None else Some(spanStack.getLast)
  val span   = Span(name, parent, clock.getAndIncrement(), None)
  spanStack.offerLast(span)
  span
}

def endSpan[A](a: A): A = {
  val span = spanStack.removeLast()
  finishedSpans.add(span.copy(end = Some(clock.getAndIncrement())))
  a
}

def endSpanF[A](f: Future[A]): Future[A] =
  f.map(endSpan)

def span[A](name: String)(f: => A): A = {
  startSpan(name)
  f match {
    case fa: Future[_] => endSpanF(fa).asInstanceOf[A]
    case a             => endSpan(a)
  }
}

def compute[A](a: => A): A = {
  clock.getAndAdd(4)
  a
}

def showSpans(): Unit = {
  val sorted = finishedSpans.asScala.toList.sorted(Ordering.by((span: Span) => (span.depth, span.start, span.end.map(- _))))
  sorted.foldLeft(0) {
    case (time, span) =>
      if (span.start < time) {
        println
        print(" " * span.start)
      } else {
        print(" " * (span.start - time))
      }
      val dashes = span.end.getOrElse(0) - span.start - span.name.length - 1
      val dashesLeft = dashes / 2
      val dashesRight = dashes / 2 + dashes % 2
      print(s"|${"-" * dashesLeft}${span.name}${"-" * dashesRight}|")
      span.end.getOrElse(Int.MaxValue - 1) + 1
  }
  println
}

val result =
  Future(span("A1")(compute(0))).flatMap { a =>
    span("A2") {
      Future(span("B1")(compute(a + 1))).flatMap { b =>
        span("B2") {
          Future(span("C1")(compute(b * 2)))
        }
      }
    }
  }.flatMap { a =>
    span("A3") {
      Future(span("D1")(compute(a + 1))).flatMap { d =>
        span("D2") {
          Future(span("E1")(compute(d * 2)))
        }
      }
    }
  }

Await.result(result, 1.second) // 6

showSpans()

/*
|-A1-||------A2------||------A3------|
       |-B1-||--B2--|  |-D1-||--D2--|
              |-C1-|          |-E1-|

 */

Where A1, A2, and A3 are siblings and A2 is the parent of B2 which is the parent of C1.

[ivantopo]

Hey folks, let me share some additional info about this:

First, history! There are two pieces of history that were important for this issue:

• add utilities to create Spans from Futures #645 is the PR where I added a few utilities to create Spans from Futures and there is some detail about the reasoning behind the current implementation (already mentioned above, but worth re-linking)
• This comment about the different things that should be tracked with Futures.

The more I dig, the more obvious it seems to me that we should just go back to how Kamon 1.x was behaving, and have a single function for creating Spans that looks pretty similar to this:

  def trace[A](operationName: String)(f: => A): A = {
    val span = Kamon.internalSpanBuilder(operationName, "manual").start()

    Kamon.runWithSpan(span, finishSpan = false)(f) match {
      case future: Future[_] => {
        future.onComplete {
          case Failure(t) => span.fail(t).finish()
          case _          => span.finish()
        }(CallingThreadExecutionContext)

        future.asInstanceOf[A]
      }

      case other =>
        span.finish()
        other
    }
  }

It is kind of the same as Kamon.runWithSpan(...), but it will ensure that if A is a Future, the Span will only be finished when that future completes.

I took @steinybot's example, replaced his span function with the trace function I pasted above, and ran it with the Kamon 1.x instrumentation (using this hack: #846 (comment)). The result was exactly what was expected:

And, these changes also solve #829 🎉

What will happen next?

I'm not sure about the details because things might get weird once I start with the implementation, but the idea is to deprecate all the current instrumentation and release it as Kamon 2.1.21 (along with other deprecated things) and then bring the old behavior back with Kamon 2.2.0.

I'll start working on this right away and get back to you when I have something concrete.

[jatcwang]

👍 for making for comprehension siblings. I think I made a similar argument back in https://gitter.im/kamon-io/Kamon?at=5dc072fd10bd4128a1bcfce2

[ivantopo]

Hey folks, this is fixed and released with Kamon 2.2.0. Please share if you find any issues with the new version!

[neboduus]

Hi, I am using Kamon to instrument a Scala Play app that sends traces through a Zipkin Server directly to Google Stackdriver. I have updated to version 2.2.0, but in for comprehensions, only the first span gets registered and stored as children of the outer scope parent span.

In my setup I only use the utility function span[A](operationName: String)(f: => A): A

[jatcwang]

It's best to supply an example project to demonstrate the issue :)
Some common reasons I've seen include not including kamon-executors dependency, or not having the kanela agent instrumenting your app.

[neboduus]

I cannot share my project, cause is a private one. However, I can share my setup:

Play Framework 2.7.x
Scala 2.12
Kamon libs

  "io.kamon"                     %% "kamon-core"                    % "2.2.0",
  "io.kamon"                     %% "kamon-status-page"             % "2.2.0",
  "io.kamon"                     %% "kamon-zipkin"                  % "2.2.0",

I correctly configure the agent because I am able to see the traces and I've been using the instrumentation for quite a long time now (8 months). However, I eagerly bind it like so

package module

import com.google.inject.AbstractModule
import kamon.Kamon
import javax.inject.Singleton

@Singleton
class KamonInitializer{
  Kamon.init()
}

class KamonModule extends AbstractModule {
  override def configure(): Unit = {
    bind(classOf[KamonInitializer]).asEagerSingleton()
  }
}

I have a Controller where I trace the entire action defined as so

class Controller @Inject()(
    @Named("myNamedService") service: Service,
) extends AbstractController(cc) with LazyLogging {

  def action(): Action[JsValue] = Action.async(parse.tolerantJson) { implicit request: Request[JsValue] =>
    span("action"){
      Ok(service.doSomething())
    }
  }
}

Now the doSomething() function is defined like this on the Service

class Service {
  def doSomething(){
    span("step1"){ step1() }
    span("step2"){ step2() }
    for {
      future1 <- computeFuture1()
      future2 <- computeFuture2()
    }
  }

  def computeFuture1 = {
    span("computeFuture1) { Future(None) }
  }

  def computeFuture2 = {
    span("computeFuture2) { Future(None) }
  }
}

And when I look at the traces received i see 2 traces trees.

1. action -> step1 -> step2 -> computeFuture1
2. computeFuture2

Instead I should see:

• action -> step1 -> step2 -> computeFuture1 -> computeFuture2

[jatcwang]

@neboduus Thanks can you put this in a SBT project on github? It makes it easy for someone to reproduce the issue otherwise their setup may be different even following your reproduction steps

[neboduus]

Will Need some time to do so cause in currently very busy. Will post here once I'll do it

[jatcwang]

From looking at your reproduction steps, I think you're missing https://mvnrepository.com/artifact/io.kamon/kamon-scala-future which is required for tracing to work when scala Future is involved. (If you're also using other effect libraries like cats-effect you'll need additional library which instrument those too).