akka-http occasionally throws akka.stream.scaladsl.One2OneBidiFlow$OutputTruncationException$: null when using https

[akka-ci]

Issue by FrankvanMeeuwen
_Tuesday Jan 26, 2016 at 13:16 GMT_
_Originally opened as https://github.com/akka/akka/issues/19617_

---

We have build a client using akka-http which sends a single request to a rest api on demand. This is working fine when using http with the cachedHostConnectionPool. However when using https, with the cachedHostConnectionPoolTls, occasionally we receive the akka.stream.scaladsl.One2OneBidiFlow$OutputTruncationException$: null exception. I found that preceding the error, the server initiates to close the connection by sending a [FIN,ACK]. (It does not send a close_notify first, which is not according to the specifications but seems to be used by more servers.)

When turning on debug logging i can see that javax.net.sll throws an exception when the closeInbound() is called, which might be related to the problem.

plugin-framework-akka.actor.default-dispatcher-248, called closeInbound()
plugin-framework-akka.actor.default-dispatcher-248, fatal error: 80: Inbound closed before receiving peer's close_notify: possible truncation attack?
javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
%% Invalidated: [Session-3, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256]
plugin-framework-akka.actor.default-dispatcher-248, SEND TLSv1.2 ALERT: fatal, description = internal_error

The problem is that quite some request fail with this akka.stream.scaladsl.One2OneBidiFlow$OutputTruncationException$: null exception, as if they still use the connection which the server wants to close. With wireshark i could see that no request are even send to the server when this exception occurs.

As a workaround, i found out that, because the server closes connections after 5 seconds of inactivity, if i use the configuration setting: {akka.http.idle-timeout = 4 seconds} the problem disappears.

[akka-ci]

Comment by rkuhn
_Tuesday Feb 02, 2016 at 09:23 GMT_

---

Thanks for raising this; it looks a bit fishy that the servers don’t close the connection properly, but I’ll let @sirthias and @jrudolph chime in on what the policy should be in this case.

[akka-ci]

Comment by ktoso
_Wednesday May 18, 2016 at 21:27 GMT_

---

Related to the sovled https://github.com/akka/akka/issues/19777 ?

[akka-ci]

Comment by FrankvanMeeuwen
_Tuesday May 24, 2016 at 07:46 GMT_

---

It indeed seems to be related as it also has to do with the server closing the connection. Unfortunately it is hard for me to reproduce locally, but I will try if the latest akka version fixes this for the client.

[akka-ci]

Comment by eswenson1
_Friday Jul 29, 2016 at 22:07 GMT_

---

I'm running into this issue, too, on akka-2.4.8.

[akka-ci]

Comment by FrankvanMeeuwen
_Saturday Jul 30, 2016 at 07:32 GMT_

---

Recently the customer where the error showed up, tested again with akka 2.4.8 using https and the cachedHostConnectionPoolTls. Now the following errors show up in the logfile:

ERROR akka.actor.RepointableActorRef - Error in stage [One2OneBidi]: Inner stream finished before inputs completed. Outputs might have been truncated.

So we switched back to not using the connectionPool, by opening a connection for each request, and the error did not show up anymore.

[akka-ci]

Comment by FrankvanMeeuwen
_Saturday Jul 30, 2016 at 21:24 GMT_

---

I managed to reproduce a similar scenario when connecting to another https server, which seems to have the same behaviour. It closes the connection after 5 seconds of inactivity, and probably also does not send an close_notify first. (Did not verify this)
To trigger the error, set the interval of the tickSource higher than 5 seconds.
This is with the latest akka 2.4.8 release.

import akka.actor.{ActorSystem, Cancellable}
import akka.event.Logging
import akka.http.scaladsl.Http
import akka.http.scaladsl.Http.HostConnectionPool
import akka.http.scaladsl.client.RequestBuilding._
import akka.http.scaladsl.model.{HttpRequest, HttpResponse}
import akka.http.scaladsl.unmarshalling.Unmarshal
import akka.stream.ActorMaterializer
import akka.stream.scaladsl.{Flow, Source}

import scala.concurrent.Future
import scala.concurrent.duration._
import scala.util.{Failure, Success, Try}

object OutputTruncationHttps extends App {
  implicit val system = ActorSystem()
  implicit val mat = ActorMaterializer()
  implicit val executionContext = system.dispatcher
  val log = Logging(system, this.getClass)

  val connectionPool = Http().cachedHostConnectionPoolHttps[Int]("www.openssl.org", 443)

  Source.tick(0.seconds, 7.seconds, Unit)
    .scan(0)((prev, _) => prev + 1)
    .map(attempt => Get("/") -> attempt)
    .via(connectionPool)
    .mapAsync(1) {
      case (Success(r), attempt) =>
        Unmarshal(r.entity).to[String].map(_ => s"Succesfully unmarshalled" -> attempt)
      case (Failure(e), attempt) =>
        Future.successful(s"No response obtained for request $attempt. ${e.getMessage}" -> attempt)
    }
    .runForeach {
      case (msg, attempt) => log.info("Materialized #{}:{}",attempt, msg)
    }
}

[ymeymann]

Having same problem here connecting to api.deezer.com with Akka 2.4.10.
Many thanks @FrankvanMeeuwen - with your code I am able to consistently reproduce the problem. What is weird is the order in which the responses are received:

14:33:33.337 [default-akka.actor.default-dispatcher-3] INFO OutputTruncationHttps$ - Materialized #0:Succesfully unmarshalled
14:33:46.843 [default-akka.actor.default-dispatcher-9] INFO OutputTruncationHttps$ - Materialized #2:Succesfully unmarshalled
14:34:00.865 [default-akka.actor.default-dispatcher-9] INFO OutputTruncationHttps$ - Materialized #4:Succesfully unmarshalled
14:34:15.105 [default-akka.actor.default-dispatcher-9] INFO OutputTruncationHttps$ - Materialized #6:Succesfully unmarshalled
14:34:29.189 [default-akka.actor.default-dispatcher-2] INFO OutputTruncationHttps$ - Materialized #8:Succesfully unmarshalled
14:34:39.762 [default-akka.actor.default-dispatcher-8] ERROR akka.actor.RepointableActorRef - Error in stage [One2OneBidi]: Inner stream finished before inputs completed. Outputs might have been truncated.
akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$: Inner stream finished before inputs completed. Outputs might have been truncated.
14:34:40.779 [default-akka.actor.default-dispatcher-3] INFO OutputTruncationHttps$ - Materialized #1:Succesfully unmarshalled
14:34:42.480 [default-akka.actor.default-dispatcher-8] INFO OutputTruncationHttps$ - Materialized #10:Succesfully unmarshalled
14:34:53.589 [default-akka.actor.default-dispatcher-2] ERROR akka.actor.RepointableActorRef - Error in stage [One2OneBidi]: Inner stream finished before inputs completed. Outputs might have been truncated.
akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$: Inner stream finished before inputs completed. Outputs might have been truncated.
14:34:54.400 [default-akka.actor.default-dispatcher-5] INFO OutputTruncationHttps$ - Materialized #3:Succesfully unmarshalled
14:34:56.379 [default-akka.actor.default-dispatcher-5] INFO OutputTruncationHttps$ - Materialized #12:Succesfully unmarshalled
14:35:07.596 [default-akka.actor.default-dispatcher-6] ERROR akka.actor.RepointableActorRef - Error in stage [One2OneBidi]: Inner stream finished before inputs completed. Outputs might have been truncated.
akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$: Inner stream finished before inputs completed. Outputs might have been truncated.
14:35:08.383 [default-akka.actor.default-dispatcher-6] INFO OutputTruncationHttps$ - Materialized #5:Succesfully unmarshalled
14:35:10.351 [default-akka.actor.default-dispatcher-2] INFO OutputTruncationHttps$ - Materialized #14:Succesfully unmarshalled
14:35:21.585 [default-akka.actor.default-dispatcher-2] ERROR akka.actor.RepointableActorRef - Error in stage [One2OneBidi]: Inner stream finished before inputs completed. Outputs might have been truncated.
akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$: Inner stream finished before inputs completed. Outputs might have been truncated.
14:35:22.808 [default-akka.actor.default-dispatcher-5] INFO OutputTruncationHttps$ - Materialized #7:Succesfully unmarshalled
14:35:24.389 [default-akka.actor.default-dispatcher-8] INFO OutputTruncationHttps$ - Materialized #16:Succesfully unmarshalled
14:35:35.666 [default-akka.actor.default-dispatcher-6] ERROR akka.actor.RepointableActorRef - Error in stage [One2OneBidi]: Inner stream finished before inputs completed. Outputs might have been truncated.
akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$: Inner stream finished before inputs completed. Outputs might have been truncated.
14:35:36.781 [default-akka.actor.default-dispatcher-8] INFO OutputTruncationHttps$ - Materialized #9:Succesfully unmarshalled
14:35:38.400 [default-akka.actor.default-dispatcher-9] INFO OutputTruncationHttps$ - Materialized #18:Succesfully unmarshalled
14:35:47.295 [default-akka.actor.default-dispatcher-6] ERROR akka.actor.RepointableActorRef - Error in stage [One2OneBidi]: Inner stream finished before inputs completed. Outputs might have been truncated.
akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$: Inner stream finished before inputs completed. Outputs might have been truncated.
14:35:48.599 [default-akka.actor.default-dispatcher-5] INFO OutputTruncationHttps$ - Materialized #11:Succesfully unmarshalled

[ktoso]

The Akka ticket was solved/merged, will be part of 2.4.13.
Kudos to https://github.com/ilucker for hacking on it, thanks!

[jrudolph]

To close this, we should test if 2.4.13 will actually change the behavior. Apart from that we should see if something can be done about the extra error message:

ERROR akka.actor.RepointableActorRef - Error in stage [One2OneBidi]: Inner stream finished before inputs completed. Outputs might have been truncated.
akka.http.impl.util.One2OneBidiFlow$OutputTruncationException$: Inner stream finished before inputs completed. Outputs might have been truncated.

This message is not helpful at all. It usually means that on a client connection a request was still outstanding when the connection was closed. As long as the error is propagated it doesn't need to be logged.

[ymeymann]

I tried the test with Akka 2.4.14 and Akka-Http 10.0.0, and the elements are now timely processed, but the error is still printed. Maybe just reduce the severity to warning?

[jrudolph]

We improved the error message in #617. So closing for now.