Async Tracing for Scala broken when using Promises

[jmreardon-yoppworks]

Description

I am trying to use the Scala instrumentation and asyncTrace to track a transaction in Scala code. One of the Futures is ultimately backed by a Scala Promise that is completed by another thread pool. When I have one of these futures in the chain offlatMaps, subsequent operations are not captured in the transaction.

Similar behavior happens if a Future started outside the transaction is included in the flatMap chain.

(Specifically, the Future is the result of an Akka Stream, but I can reproduce the issue without using Akka).

Expected Behavior

I expect my async traces to work regardless of how the Futures involved in it are created/completed.

Steps to Reproduce

This repository reproduces the issue: https://github.com/jmreardon-yoppworks/new-relic-promises

During my testing I found I could recover the transaction by explicitly linking the transaction with a token, but I needed to nest a Future oddly to make it work.

Your Environment

Mac OS Intel

[workato-integration[bot]]

https://new-relic.atlassian.net/browse/NR-314323

[kanderson250]

Hi @jmreardon-yoppworks , thank you for submitting this issue and for the insightful repro. I've been looking into this. Although this behavior isn’t ideal, we do think the agent is working as-designed in its handling of promises. Here is some more detail on that.

Why transaction context is lost for Promises:

We instrument scala futures when they are submitted to the executor. There are a few reasons for this, the main one being that we want to tie the future to at most one transaction. We want to avoid automatically tying the future to every transaction with a reference to it. Linking on submit is a pattern that’s used throughout our future instrumentation (including for Java). A future doesn't necessarily have to be constructed (or completed) in a transaction, but it does have to be submitted within the transaction context.

This works well if the future is constructed with a Future{ ... } inside the transaction, because the apply method of Future submits it to the executor immediately. But for promises, the future typically isn’t submitted until the promise completes it, like in the case of this repro with p.trySuccess. By the time p.future is submitted, the Transaction is already gone. As you called out, this would also be the case for futures constructed the normal way, outside a Transaction.

val p = Promise[Unit]()
val f = broken(p)
p.trySuccess(()) //p.future is submitted here, Transaction has already completed
Await.ready(f, 15.seconds)

@Trace(dispatcher = true)
def broken: Future[Unit] =  {
  for {
  _ <- asyncTrace("promise"){p.future} //p.future does not submit to the executor here
  _ <- future("future")
  } yield printTransaction("Done")
}

That’s why we’re losing context for p.future. Again, as you called out, the flatmap chaining underlying the for comprehension explains why the rest of the futures lose their context too (I’ve taken the asyncTrace calls out):

p.future.flatMap( _ => future("future").map( _ => printTransaction("Done)))

Since the downstream futures are submitted in callbacks, rather than inside the original transaction, losing context in p.future means the rest of these futures will lose their context as well.

asyncTrace will correctly time p.future, but will not be able to recover the downstream futures once the transaction context is lost. This is because asyncTrace creates segments, which don’t link threadhops together.

Suggestions for recovering tracing:

If your code depends on for comprehensions/future chaining, you may have to link tokens, like you already have tried. Here is a working example that is a bit simpler :

@Trace(dispatcher = true)
def fixed: Future[Unit] = {
 val t : Token = NewRelic.getAgent.getTransaction.getToken
 for {
   _ <- asyncTrace("promise"){p.future}
   _ <- future("future", t)
 } yield printTransaction("Done")
}


@Trace(async = true)
def future(name: String, t: Token): Future[Unit] = {
 t.linkAndExpire()
 Future {
   printTransaction(name)
 }
}

Here, the asyncTrace API method will capture the timing of p.future, the @Trace(async=true) will capture the timing of the future method call, and the token will prevent future from losing context during the threadhops. Two segments ("promise", named explicitly, and "future", named after the annotated method call) and their timing will be reflected in the transaction.

If it’s feasible, you can also construct your futures outside the for comprehension. This will work too:

@Trace(dispatcher = true)
def fixed: Future[Unit] = txn {
 val f = future("future")
 for {
 _ <- asyncTrace("promise"){p.future}
 _ <- f
 } yield printTransaction("Done")
}

If you have further questions or concerns about this, please, let us know - it may be that we also need to do some troubleshooting with Akka since that’s what your service is using.

[kanderson250]

Agent working as designed; closing.