How do i locate the issue of One2OneBidiFlow$OutputTruncationException?

[cwei-bgl]

Hi,

I am using akka-http 10.0.5 with akka 2.4.17. Now in my server log, I occasionally received the following errors. I have looked through the related issues in the repository, but I still have not come up an idea of identifying the cause. I am using both http and websocket. As the error stack has no clue about what request is related to the error, I am having difficulty in locating the issue. Could you please give me some clue? Thanks.

akka.http.impl.util.One2OneBidiFlow$OutputTruncationException: Inner flow was completed without producing result elements for 1 outstanding elements
	at akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$.apply(One2OneBidiFlow.scala:22)
	at akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$.apply(One2OneBidiFlow.scala:22)
	at akka.http.impl.util.One2OneBidiFlow$One2OneBidi$$anon$1$$anon$4.onUpstreamFinish(One2OneBidiFlow.scala:97)
	at akka.stream.impl.fusing.GraphInterpreter.processEvent(GraphInterpreter.scala:732)
	at akka.stream.impl.fusing.GraphInterpreter.execute(GraphInterpreter.scala:616)
	at akka.stream.impl.fusing.GraphInterpreterShell.runBatch(ActorGraphInterpreter.scala:471)
	at akka.stream.impl.fusing.GraphInterpreterShell.receive(ActorGraphInterpreter.scala:423)
	at akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$processEvent(ActorGraphInterpreter.scala:603)
	at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$receive$1.applyOrElse(ActorGraphInterpreter.scala:618)
	at akka.actor.Actor$class.aroundReceive(Actor.scala:497)
	at akka.stream.impl.fusing.ActorGraphInterpreter.aroundReceive(ActorGraphInterpreter.scala:529)
	at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)
	at akka.actor.ActorCell.invoke_aroundBody0(ActorCell.scala:495)
	at akka.actor.ActorCell$AjcClosure1.run(ActorCell.scala:1)
	at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:149)
	at akka.kamon.instrumentation.ActorMonitors$TrackedActor$$anonfun$processMessage$2.apply(ActorMonitor.scala:79)
	at kamon.trace.Tracer$.withContext(TracerModule.scala:58)
	at akka.kamon.instrumentation.ActorMonitors$TrackedActor.processMessage(ActorMonitor.scala:78)
	at akka.kamon.instrumentation.ActorCellInstrumentation.aroundBehaviourInvoke(ActorInstrumentation.scala:45)
	at akka.actor.ActorCell.invoke(ActorCell.scala:488)
	at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)
	at akka.dispatch.Mailbox.run(Mailbox.scala:224)
	at akka.dispatch.Mailbox.exec(Mailbox.scala:234)
	at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
	at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
	at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
	at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) 

[jrudolph]

Can you show how you start the server?

The only reason I can think of that this would happen is if you use Http.bindAndHandle(flow) and the flow you give to that call sends out completion before handling all the requests. But that seems to be an unlikely pattern.

[cwei-bgl]

Thanks @jrudolph . Yes, I do use Http.bindAndHandle(flow) as follows:

routes = route1 ~ route2 ~ ... ~ routeN // linking route together with some filterings e.g., ip filtering.
val routeFlow = RouteResult.route2HandlerFlow(routes)
val bindingFuture = Http(system).bindAndHandle(routeFlow, host, port)

The problem with the error message above is I don't know where to locate the issue, as there is not a helpful hint in the error what request caused it. In this concurrent context, it is especially difficult to identify the cause. I just wonder if there is a way to include any extra useful information into the exception - OutputTruncationException, for example, request information, route information of the flow and so on.

My routes construction code as follows:

private def buildRoutes(): Route = {
    val controller1 = new Controller1(...)
    val controller2 = new Controller2(...)
    val controller3 = new Controller3(...)
    val mainController = new MainController()

    def isIpAllowed(remoteAddress: RemoteAddress): Boolean = {
      remoteAddress.toOption.map { inetAddress =>
        log.info("client ip: {}", inetAddress.getHostAddress)
        trustedIps.contains(inetAddress.getHostAddress)
      }.getOrElse(false)
    }

    val internalRoutes = extractClientIP { remoteAddress =>
      val ipAllowed = isIpAllowed(remoteAddress)

      if (ipAllowed) {
        publicationChoice match {
          case ByRest =>
            controller1.route ~ controller2.route ~ controller3.route
          case _ =>
            controller1.route ~ controller3.route
        }
      } else {
        complete(HttpResponse(StatusCodes.Forbidden, entity = "access denied"))
      }
    }

    val corsSettings = CorsSettings.defaultSettings
    val externalRoutes = cors(corsSettings) {
      controller3.webSocketRoute ~ mainController.route
    }

    externalRoutes ~ internalRoutes
  }

Thanks, Cheng

[jrudolph]

When using it with RouteResult.route2HandlerFlow it should not happen. It may be an effect of the idle timeout triggering onComplete instead of something else here. In that regard we could treat it as a variation of #1026.

[cwei-bgl]

Thanks @jrudolph , I will have a try when #1026 is fixed.

[cwei-bgl]

@jrudolph , It seems this issue was resolved in v10.0.6. I upgraded to v10.0.6 some days before. It seemed there were no more errors of this kind in my log. But in v10.0.6 Release notes, I did not see anything related?

[jrudolph]

It might have been accidentally fixed.

[cwei-bgl]

Thanks, @jrudolph . Close for now.

[jypma]

I'm seeing the exception on 10.0.7, also using bindAndHandle with a "normal" route DSL scala route, reproduceable on a particular request. I'll spend some time to see if I can find the root cause.

[jypma]

Not found root cause yet, but it happens in the following scenario. We're implementing an http routing proxy, with akka-http both on the server and client side. The error occurs when passing an incoming HttpRequest.entity of type HttpEntity$Chunked directly as body to an outgoing HttpRequest.

I'll see if it is reproducable on a smaller test-case.

[jrudolph]

@jypma can you post a snippet of how the connection is made through the proxy? Could it be related to idle timeouts triggering as I suggested in #1028 (comment)?

[jypma]

For me, using Kamon was the culprit. Removing kamon-akka-http made the error go away.

Apperently their FlowWrapper that wraps the HTTP server flow for monitoring, doesn't quite get the timing right when handling chunked incoming requests.

I'll raise an issue there.

[jypma]

@jrudolph As I wrote above, it luckily wasn't timeouts for us, "just" the BidiFlow from Kamon being inaccurate.

I know it's outside of akka-http scope, but if you can spot the issue in FlowWrapper within a minute, it'd be much appreciated :-) Somehow it indeed triggers a completion of the wrapped flow, but I don't understand yet how, since it doesn't explicitly even call .complete().

[jypma]

Got it. Was missing all the "finish" directives.

[pranavkapoorr]

@jrudolph I faced similar exception and co-incidentally the cause of this exception is always traceless. I had to literally debug line by line to find the issue. The issue was related to Base64 to utf conversion bug.

Thanks anyways for always being there to support us. :)