Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Akka NoSuchElementException in RouteConcatenation$RouteWithConcatenation #13049

Open
Matzz opened this issue Jan 15, 2025 · 8 comments · May be fixed by #13360
Open

Akka NoSuchElementException in RouteConcatenation$RouteWithConcatenation #13049

Matzz opened this issue Jan 15, 2025 · 8 comments · May be fixed by #13360
Labels
bug Something isn't working repro provided

Comments

@Matzz
Copy link

Matzz commented Jan 15, 2025

Hi,
I'm getting following error when using akka + tapir integration:

[otel.javaagent 2025-01-03 16:36:51:073 +0000] [xyz-akka.actor.default-dispatcher-28] DEBUG io.opentelemetry.javaagent.bootstrap.ExceptionLogger - Failed to handle exception in instrumentation for akka.http.scaladsl.server.RouteConcatenation$RouteWithConcatenation
java.util.NoSuchElementException
	at java.base/java.util.ArrayDeque.removeFirst(Unknown Source)
	at java.base/java.util.ArrayDeque.pop(Unknown Source)
	at io.opentelemetry.javaagent.instrumentation.akkahttp.server.route.AkkaRouteHolder.restore(AkkaRouteHolder.java:68)
	at akka.http.scaladsl.server.RouteConcatenation$RouteWithConcatenation.$anonfun$$tilde$1(RouteConcatenation.scala:44)
	at akka.http.scaladsl.server.RouteConcatenation$RouteWithConcatenation.$anonfun$$tilde$2(RouteConcatenation.scala:47)
	at akka.http.scaladsl.util.FastFuture$.strictTransform$1(FastFuture.scala:40)
	at akka.http.scaladsl.util.FastFuture$.$anonfun$transformWith$3(FastFuture.scala:50)
	at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:484)
	at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:64)
	at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:101)
	at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
	at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:94)
	at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:101)
	at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:49)
	at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:48)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool.scan(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(Unknown Source)

As a result traces are recorded only with http method without path.

For the same endpoint defined without tapir it works fine.
tapir version 1.11.12
akka version 2.8.5

Tapir endpoint definition looks more or less like that:

  val definition =
    baseEndpoint.get
      .in("catalog" / "api" / "v1" / "actions")
      .in(QueryParams.actionIdOpt)
      .mapInTo[ActionEnpointInput]
      .out(statusCode.and(jsonBody[Seq[ActionMessage]]))

Steps to reproduce

Create scala application with tapir + akka http server. Instrument it with otel agent. Set OTEL_JAVAAGENT_DEBUG=true.

Expected behavior

OTEL will record span with http method and path.

Actual behavior

As a span name I get only method name without path.

Javaagent or library instrumentation version

2.11.0

Environment

JDK: AdoptOpenJDK OpenJDK 64-Bit Server VM 11.0.7+10
OS: Linux 5.10.230-223.885.amzn2.x86_64

Additional context

No response

@Matzz Matzz added bug Something isn't working needs triage New issue that requires triage labels Jan 15, 2025
@laurit
Copy link
Contributor

laurit commented Jan 16, 2025

Could you provide a minimal application that reproduces the issue along with any necessary instructions.

@steverao steverao added needs author feedback Waiting for additional feedback from the author and removed needs triage New issue that requires triage labels Jan 18, 2025
Copy link
Contributor

This has been automatically marked as stale because it has been marked as needing author feedback and has not had any activity for 7 days. It will be closed automatically if there is no response from the author within 7 additional days from this comment.

@github-actions github-actions bot added the stale label Jan 25, 2025
@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Feb 1, 2025
@masonedmison
Copy link

@laurit Sorry for the delay; I work with @Matzz, and we now have a minimal reproducible example.

Here is the reproduction. I'm happy to help try to help fix this issue, though I may need a bit of guidance.

@trask trask reopened this Feb 14, 2025
@trask trask added repro provided and removed needs author feedback Waiting for additional feedback from the author stale labels Feb 14, 2025
@masonedmison
Copy link

FWIW, I also added a MimimalPekkoApp that has the same nested endpoint structure as the failing MimimalTapirApp and it succeeds--no error:

[error] === PekkoRouteHolder Debug ===
[error] holder.stack: []
[error] holder.stack.getClass(): class java.util.ArrayDeque
[error] holder.route: 
[error] Thread: minimal-pekko-app-pekko.actor.default-dispatcher-5
[error] === PekkoRouteHolder Debug ===
[error] holder.stack: []
[error] holder.stack.getClass(): class java.util.ArrayDeque
[error] holder.route: 
[error] Thread: minimal-pekko-app-pekko.actor.default-dispatcher-5
[error] === PekkoRouteHolder Debug ===
[error] holder.stack: []
[error] holder.stack.getClass(): class java.util.ArrayDeque
[error] holder.route: 
[error] Thread: minimal-pekko-app-pekko.actor.default-dispatcher-5
[error] [otel.javaagent 2025-02-14 12:02:30:949 -0600] [minimal-pekko-app-pekko.actor.default-dispatcher
-5] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'GET /api/v1/subitems' : 3a567c69d8aca2
49bd2d4afe7762c8e3 0b061c227f29e42c SERVER [tracer: io.opentelemetry.pekko-http-1.0:2.12.0-alpha-SNAPSHO
T] AttributesMap{data={http.request.method=GET, network.protocol.version=1.1, http.route=/api/v1/subitem
s, server.address=localhost, user_agent.original=curl/8.9.1, url.path=/api/v1/subitems, url.scheme=http,
 thread.name=minimal-pekko-app-pekko.actor.default-dispatcher-5, thread.id=23, http.response.status_code
=200, server.port=8080}, capacity=128, totalAddedValues=11}
[error] [otel.javaagent 2025-02-14 12:02:30:958 -0600] [minimal-pekko-app-pekko.actor.default-dispatcher
-5] DEBUG io.opentelemetry.javaagent.tooling.AgentInstaller$TransformLoggingListener - Transformed org.a
pache.pekko.stream.stage.GraphStageLogic$$Lambda$974 -- jdk.internal.loader.ClassLoaders$AppClassLoader@
251a69d7

So this does appear to be specific to Tapir with using the Pekko integration.

@masonedmison
Copy link

masonedmison commented Feb 14, 2025

I've been continuing to dig into this. The ordering between how the advice classes are applied is indeed different between the two programs 🤔.

Tapir with tilde print logs

[error] ===In tilde1 onEnter===
[error] ===In tilde1 onEnter===
[error] ===In tilde1 onExit===
[error] ===In tilde1 onExit===
[error] ===In tilde2 onEnter===
[error] ===In tilde2 onEnter===
[error] ===In tilde1 onEnter===
[error] Failed to handle
exception in instrumentation for org.apache.pekko.http.scaladsl.server.RouteConcatenation$Rou
teWithConcatenation
[error] java.lang.NullPointerException
[error] ===In tilde1 onExit===
[error] Failed to handle
exception in instrumentation for org.apache.pekko.http.scaladsl.server.RouteConcatenation$Rou
teWithConcatenation
[error] java.util.NoSuchElementException
[error] ===In tilde2 onEnter===

Pekko with tilde print logs

[error] ===In tilde1 onEnter===
[error] ===In tilde1 onEnter===
[error] ===In tilde2 onEnter===
[error] ===In tilde1 onExit===
[error] ===In tilde2 onEnter===
[error] ===In tilde1 onEnter===
[error] ===In tilde2 onEnter===
[error] ===In tilde1 onExit===
[error] ===In tilde1 onExit===

Note: this is the file I added printlns to.

@masonedmison
Copy link

masonedmison commented Feb 17, 2025

@trask Is there anyway to "save" the transformed bytecode (that could then be decompiled) to get a clearer sense of why the ordering is different between plain Pekko and Tapir/Pekko applications?

@masonedmison
Copy link

Disregard, I just discovered the lovely debugging.md file 😄

@masonedmison
Copy link

masonedmison commented Feb 19, 2025

@trask @laurit I think I've found the issue, but I'm not sure of how to fix it.

RouteConcatenation transforms the RouteConcatenation ~ roughly as follows.

  def myTilde(other: RequestContext => Future[RouteResult]): RequestContext => Future[RouteResult] = { ctx =>
    try {
      System.err.println(s"===In tilde1 onEnter=== [${Thread.currentThread().getName}:${Thread.currentThread().getId}]")
      MyPekkoRouteHolder.save()

      FastFuture // <-- Race condition!
        .EnhancedFuture(route(ctx))
        .fast
        .flatMap { result =>
          $anonfun$$tilde$2(other, ctx, result)
        }(ctx.executionContext)
    } finally {
      System.err.println(s"===In tilde1 onExit=== [${Thread.currentThread().getName}:${Thread.currentThread().getId}]")
      try
        MyPekkoRouteHolder.restore()
      catch {
        case t: Throwable =>
          System.err.println(
            "Failed to handle exception in instrumentation for org.apache.pekko.http.scaladsl.server.RouteConcatenation$RouteWithConcatenation"
          )
          ExceptionLogger.logSuppressedError(
            "Failed to handle exception in instrumentation for org.apache.pekko.http.scaladsl.server.RouteConcatenation$RouteWithConcatenation",
            t
          )
      }
    }
  }

The problem is that since the constructed Future will be scheduled and return immediately, the finally block can (and in the case of tapir, always seems to), run before tilde$2 is executed--meaning that we have a sequence of calls like PekkoRouteHolder.save, PekkoRouteHolder.reset, PekkoHolder.restore which leads to the exception being thrown shared in the description.

To verify this is the case, I implemented a tilde function that ensures the finally logic is executed after tilde$2 executes:

  def myTilde(other: RequestContext => Future[RouteResult]): RequestContext => Future[RouteResult] = { ctx =>
    System.err.println(s"===In tilde1 onEnter=== [${Thread.currentThread().getName}:${Thread.currentThread().getId}]")
    MyPekkoRouteHolder.save()

    implicit val ec: ExecutionContext = ctx.executionContext
    FastFuture
      .EnhancedFuture(route(ctx))
      .fast
      .flatMap { result =>
        $anonfun$$tilde$2(other, ctx, result)
      }(ctx.executionContext)
      .andThen { _ =>
        System.err.println(
          s"===In tilde1 onExit=== [${Thread.currentThread().getName}:${Thread.currentThread().getId}]"
        )
        MyPekkoRouteHolder.restore()
      }
  }

With this implementation, everything works as expected--in my "minimal" programs, the ordering of the Advice printlns match.

With all of this said, it's unclear what the best way to proceed is since we obviously can't add this finalization logic to the Future as I've done above using Advice classes. It seems we could add some additional logic within PekkoRouteHolder to enforce order, but this feels a little hacky.

@masonedmison masonedmison linked a pull request Feb 20, 2025 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working repro provided
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants