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

HttpEntity.CloseDelimited toStrict times out (on the client-side) when using SSL #380

Closed
nodefactory-bk opened this issue Oct 11, 2016 · 25 comments · Fixed by akka/akka#21786 or #1420
Labels
3 - in progress Someone is working on this ticket bug t:client Issues related to the HTTP Client t:core Issues related to the akka-http-core module t:tls
Projects
Milestone

Comments

@nodefactory-bk
Copy link

HTTP Client fails to get all data in a CloseDelimited entity when requests are done over https.

The .toStrict method times out even though the remote end has closed the connection and all data has been sent.
This is only a problem with SSL connections, plaintext-connections work as expected.

I have confirmed this behaviour against akka http servers and other http servers.

The attachked file contains a scalatest test class to reproduce this problem using akka as client and server and also a keystore required for ssl to work.

tostrict.zip

@jrudolph
Copy link
Member

Thanks, @nodefactory-bk for the report and the reproducer.

@jrudolph jrudolph added bug 1 - triaged Tickets that are safe to pick up for contributing in terms of likeliness of being accepted t:http:server t:tls labels Oct 11, 2016
@jrudolph jrudolph added this to the 2.4.11 milestone Oct 11, 2016
@jrudolph
Copy link
Member

jrudolph commented Oct 11, 2016

For me the test fails with:

[info] - should get strict data via https *** FAILED ***
[info]   The future returned an exception of type: akka.stream.ConnectionException, with message: Hostname verification failed! Expected session to be for localhost. (AkkaToStrictTests.scala:72)

which would point to a problem with the provided certificate.

@jrudolph
Copy link
Member

jrudolph commented Oct 11, 2016

The tests succeed for me when using a certificate that contains the host name. (I used ExampleHttpContexts.exampleClientContext and ExampleHttpContexts.exampleServerContext running against akka.example.org instead of localhost, adding 127.0.0.1 akka.example.org to /etc/hosts).

@nodefactory-bk can you verify if that works for you as well?

@nodefactory-bk
Copy link
Author

I couldn't find the ExampleHttpContexts. Is this some internal akka testing helper? I'm running my tests as an entirely separate sbt project.

I've attached a complete sbt project that recreates this issue on localhost for you since that file was taken from an .
I've also attached the output from "sbt test" in that project on my machine.

akka-closedelim-test.zip

sbt-test-out.txt

@nodefactory-bk
Copy link
Author

here's a version of the output with color codes stripped so it is easier to read:
sbt-test-out-nocolor.txt

@jrudolph
Copy link
Member

Yes, right, for testing I integrated your test case into our sources to be able to use ExampleHttpContexts.

It seems your test fails on an older version (from mid September) but seems to succeed on top of current master. I pushed the test to https://github.com/akka/akka-http/tree/w/380 where it actually fails as well.

If you rebase/cherry-pick the same commit on current master it seems to run through.

@jrudolph
Copy link
Member

I just bisected it. It seems that a recent fix indeed solved the problem: 8e586da

We'll try to release a new version of akka-http from this repository quite soon. We'll let you know so you can try if your issue is fixed in the new version.

@nodefactory-bk
Copy link
Author

Sounds great.
Thanks for the very fast response!

@jrudolph jrudolph modified the milestones: 2.4.11, 3.0.0 Oct 17, 2016
@ktoso ktoso modified the milestones: FIRST_STABLE, backlog Oct 26, 2016
@sashagavrilov
Copy link

Have the same issue. v3.0.0-RC1 didn't solve it.

@nodefactory-bk
Copy link
Author

My test case works fine on V3.0.0-RC1.
I haven't had a chance to test it against external servers. WIll see if I can get it done today.

@jrudolph
Copy link
Member

@ilucker can you give more information about what you did exactly and what you expected and what you observed?

@nodefactory-bk
Copy link
Author

I've managed to reproduce the problem with 3.0.0-RC1
However I cannot reproduce it in a simple way with akka itself, I only get it in some cases using an external server. I have tested other clients with the same request and they handle it and the server is nginx so I don't think it's a bad server.

Unfortunately as it is a 3rd party server that requires auth I cannot give you access to it to reproduce it. Maybe @ilucker can?

What I do is a POST request with json data like this:

   val url = ???
    val ent = HttpEntity(ContentTypes.`application/json`, ???)

    val req = HttpRequest(HttpMethods.POST, url, hdrs, ent)
    println(req)
    val resp = Http().singleRequest(req);
    resp.isReadyWithin(10.seconds)

    /* We need a closedelimited */
    println(resp.futureValue)
    assert(resp.futureValue.entity.isInstanceOf[HttpEntity.CloseDelimited])

    /* Strictify it */
    val strict = resp.futureValue.toStrict(3.second)
    strict.isReadyWithin(10.seconds)

and the strict test at end fails with a timeout.
I've replaced the sensitive parts with ???

This is a redacted request as sent:

HttpRequest(HttpMethod(POST),???,List(Client-Secret:` ???, Access-Token: ???),HttpEntity.Strict(application/json,{ ... `}),HttpProtocol(HTTP/1.1))`

And this is the response:

HttpResponse(400 Bad Request,List(Server: nginx, Date: Thu, 27 Oct 2016 07:38:45 GMT, Connection: close),HttpEntity.CloseDelimited(application/json),HttpProtocol(HTTP/1.1))'

If there is anything else you need, just ask!

@nodefactory-bk
Copy link
Author

nodefactory-bk commented Oct 27, 2016

Here's a curl session sending the exact same request to the same server in case it might be of use.

* Hostname was NOT found in DNS cache
*   Trying ???...
* Connected to ??? (???) port 443 (#0)
* successfully set certificate verify locations:
*   CAfile: none
  CApath: /etc/ssl/certs
* SSLv3, TLS handshake, Client hello (1):
* SSLv3, TLS handshake, Server hello (2):
* SSLv3, TLS handshake, CERT (11):
* SSLv3, TLS handshake, Server key exchange (12):
* SSLv3, TLS handshake, Server finished (14):
* SSLv3, TLS handshake, Client key exchange (16):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* Server certificate:
*        subject: ???
*        start date: ???
*        expire date: ???
*        issuer: ???
*        SSL certificate verify ok.
> POST /3/articles HTTP/1.1
> User-Agent: curl/7.38.0
> Host: ???
> Accept: */*
> Client-Secret: ???
> Access-Token: ???
> Content-Type: application/json
> Content-Length: 109
>
* upload completely sent off: 109 out of 109 bytes
< HTTP/1.1 400 Bad Request
* Server nginx is not blacklisted
< Server: nginx
< Date: Thu, 27 Oct 2016 07:57:52 GMT
< Content-Type: application/json
< Connection: close
<
* Closing connection 0
* SSLv3, TLS alert, Client hello (1):

@sashagavrilov
Copy link

sashagavrilov commented Oct 28, 2016

@jrudolph i can't provide more info since the problem is reproducing with an internal ssl server which is not available from outside. But i believe i was able to trace down the cause of the issue. And i also believe it is related to #87

So, there is lastHandshakeStatus analysis missed in the akka.stream.impl.io.TLSActor's doInbound

private def doInbound(isOutboundClosed: Boolean, inboundState: TransferState): Boolean =
    if (inputBunch.isDepleted(TransportIn) && transportInChoppingBlock.isEmpty) {
      if (tracing) log.debug("closing inbound")
      try engine.closeInbound()
      catch { case ex: SSLException  outputBunch.enqueue(UserOut, SessionTruncated) }
//>>add  lastHandshakeStatus = engine.getHandshakeStatus here since closeInbound can change status to NEED_WRAP and completeOrFlush will skip the last wrap and flush and a stream will hung
      completeOrFlush()
      false
    } else if (inboundState != inboundHalfClosed && outputBunch.isCancelled(UserOut)) {
      if (!isOutboundClosed && closing.ignoreCancel) {
        if (tracing) log.debug("ignoring UserIn cancellation")
        nextPhase(inboundClosed)
      } else {
        if (tracing) log.debug("closing inbound due to UserOut cancellation")
        engine.closeOutbound() // this is the correct way of shutting down the engine
        lastHandshakeStatus = engine.getHandshakeStatus
        nextPhase(flushingOutbound)
      }
      true
    } else if (inboundState.isReady) {
      transportInChoppingBlock.chopInto(transportInBuffer)
      try {
        doUnwrap()
        true
      } catch {
        case ex: SSLException 
          if (tracing) log.debug(s"SSLException during doUnwrap: $ex")
          fail(ex, closeTransport = false)
          engine.closeInbound()
//>>add  lastHandshakeStatus = engine.getHandshakeStatus here for the same reasons
          completeOrFlush()
          false
      }
    } else true

@jrudolph
Copy link
Member

@ilucker have you tried out your changes in TLSActor? Can you explain how it fixes the issue?

@raboof raboof modified the milestones: 10.0.10, 10.0.9 Jun 26, 2017
@raboof raboof modified the milestones: 10.0.10, 10.0.11 Aug 31, 2017
jrudolph added a commit to jrudolph/akka-http that referenced this issue Sep 11, 2017
…cenario

That is we are simulating a TLS truncation attack here. Before
akka/akka#21786 the TLS stage just got stuck
(I tested again an old Akka version).

Now, all streams are properly closed and also the response entity
stream is completed. A stricter version would actually fail the response
entity stream when TLS truncation is detected. If that is worthwhile is
actually questionable. See akka#235
for more information.
jrudolph added a commit to jrudolph/akka-http that referenced this issue Sep 11, 2017
…cenario

That is we are simulating a TLS truncation attack here. Before
akka/akka#21786 the TLS stage just got stuck
(I tested again an old Akka version).

Now, all streams are properly closed and also the response entity
stream is completed. A stricter version would actually fail the response
entity stream when TLS truncation is detected. If that is worthwhile is
actually questionable. See akka#235
for more information.
jrudolph added a commit that referenced this issue Sep 25, 2017
…-truncation-test

=htc #380 add test case for server->client missing close_notify scenario
@jonas jonas moved this from PR / In Progress to Done in Bug Hunting Oct 6, 2017
@nodefactory-bk
Copy link
Author

This issue seems to have reappeared in 10.0.10.
The attached test case works with 10.0.9, but not with 10.0.10 or 10.0.11
Both times with akka 2.5.9.

akka-closedelim-test.zip

Just run sbt test and it will fail. Feel free to include this test case or a variant of it into akka-http.

The output when it fails is:

[info] AkkaToStrictTests:
[info] Test web server
[info] - should start (1 second, 143 milliseconds)
[info]   + Starting test web server on port 46188 
[info] ToStrict
[info] - should get strict data via https *** FAILED *** (10 seconds, 496 milliseconds)
[info]   The future returned an exception of type: java.util.concurrent.TimeoutException, with message: HttpEntity.toStrict timed out after 10 seconds while still waiting for outstanding data. (AkkaToStrictTests.scala:81)
[info]   org.scalatest.exceptions.TestFailedException:
[info]   at org.scalatest.concurrent.Futures$FutureConcept.tryTryAgain$1(Futures.scala:531)
[info]   at org.scalatest.concurrent.Futures$FutureConcept.futureValueImpl(Futures.scala:550)
[info]   at org.scalatest.concurrent.Futures$FutureConcept.futureValueImpl$(Futures.scala:479)
[info]   at org.scalatest.concurrent.ScalaFutures$$anon$1.futureValueImpl(ScalaFutures.scala:275)
[info]   at org.scalatest.concurrent.Futures$FutureConcept.futureValue(Futures.scala:476)
[info]   at org.scalatest.concurrent.Futures$FutureConcept.futureValue$(Futures.scala:475)
[info]   at org.scalatest.concurrent.ScalaFutures$$anon$1.futureValue(ScalaFutures.scala:275)
[info]   at AkkaToStrictTests.$anonfun$new$5(AkkaToStrictTests.scala:81)
[info]   at org.scalatest.OutcomeOf.outcomeOf(OutcomeOf.scala:85)
[info]   at org.scalatest.OutcomeOf.outcomeOf$(OutcomeOf.scala:83)
[info]   at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:22)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:20)
[info]   at org.scalatest.FlatSpecLike$$anon$1.apply(FlatSpecLike.scala:1682)
[info]   at org.scalatest.TestSuite.withFixture(TestSuite.scala:196)
[info]   at org.scalatest.TestSuite.withFixture$(TestSuite.scala:195)
[info]   at org.scalatest.FlatSpec.withFixture(FlatSpec.scala:1685)
[info]   at org.scalatest.FlatSpecLike.invokeWithFixture$1(FlatSpecLike.scala:1680)
[info]   at org.scalatest.FlatSpecLike.$anonfun$runTest$1(FlatSpecLike.scala:1692)
[info]   at org.scalatest.SuperEngine.runTestImpl(Engine.scala:289)
[info]   at org.scalatest.FlatSpecLike.runTest(FlatSpecLike.scala:1692)
[info]   at org.scalatest.FlatSpecLike.runTest$(FlatSpecLike.scala:1674)
[info]   at org.scalatest.FlatSpec.runTest(FlatSpec.scala:1685)
[info]   at org.scalatest.FlatSpecLike.$anonfun$runTests$1(FlatSpecLike.scala:1750)
[info]   at org.scalatest.SuperEngine.$anonfun$runTestsInBranch$1(Engine.scala:396)
[info]   at scala.collection.immutable.List.foreach(List.scala:389)
[info]   at org.scalatest.SuperEngine.traverseSubNodes$1(Engine.scala:384)
[info]   at org.scalatest.SuperEngine.runTestsInBranch(Engine.scala:373)
[info]   at org.scalatest.SuperEngine.$anonfun$runTestsInBranch$1(Engine.scala:410)
[info]   at scala.collection.immutable.List.foreach(List.scala:389)
[info]   at org.scalatest.SuperEngine.traverseSubNodes$1(Engine.scala:384)
[info]   at org.scalatest.SuperEngine.runTestsInBranch(Engine.scala:379)
[info]   at org.scalatest.SuperEngine.runTestsImpl(Engine.scala:461)
[info]   at org.scalatest.FlatSpecLike.runTests(FlatSpecLike.scala:1750)
[info]   at org.scalatest.FlatSpecLike.runTests$(FlatSpecLike.scala:1749)
[info]   at org.scalatest.FlatSpec.runTests(FlatSpec.scala:1685)
[info]   at org.scalatest.Suite.run(Suite.scala:1147)
[info]   at org.scalatest.Suite.run$(Suite.scala:1129)
[info]   at org.scalatest.FlatSpec.org$scalatest$FlatSpecLike$$super$run(FlatSpec.scala:1685)
[info]   at org.scalatest.FlatSpecLike.$anonfun$run$1(FlatSpecLike.scala:1795)
[info]   at org.scalatest.SuperEngine.runImpl(Engine.scala:521)
[info]   at org.scalatest.FlatSpecLike.run(FlatSpecLike.scala:1795)
[info]   at org.scalatest.FlatSpecLike.run$(FlatSpecLike.scala:1793)
[info]   at org.scalatest.FlatSpec.run(FlatSpec.scala:1685)
[info]   at org.scalatest.tools.Framework.org$scalatest$tools$Framework$$runSuite(Framework.scala:314)
[info]   at org.scalatest.tools.Framework$ScalaTestTask.execute(Framework.scala:499)
[info]   at sbt.ForkMain$Run$2.call(ForkMain.java:300)
[info]   at sbt.ForkMain$Run$2.call(ForkMain.java:290)
[info]   at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[info]   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[info]   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[info]   at java.lang.Thread.run(Thread.java:748)
[info]   Cause: java.util.concurrent.TimeoutException: HttpEntity.toStrict timed out after 10 seconds while still waiting for outstanding data
[info]   at akka.http.impl.util.ToStrict$$anon$1.onTimer(package.scala:139)
[info]   at akka.stream.stage.TimerGraphStageLogic.onInternalTimer(GraphStage.scala:1452)
[info]   at akka.stream.stage.TimerGraphStageLogic.$anonfun$getTimerAsyncCallback$1(GraphStage.scala:1441)
[info]   at akka.stream.stage.TimerGraphStageLogic.$anonfun$getTimerAsyncCallback$1$adapted(GraphStage.scala:1441)
[info]   at akka.stream.impl.fusing.GraphInterpreter.runAsyncInput(GraphInterpreter.scala:447)
[info]   at akka.stream.impl.fusing.GraphInterpreterShell$AsyncInput.execute(ActorGraphInterpreter.scala:465)
[info]   at akka.stream.impl.fusing.GraphInterpreterShell.processEvent(ActorGraphInterpreter.scala:560)
[info]   at akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$processEvent(ActorGraphInterpreter.scala:742)
[info]   at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$receive$1.applyOrElse(ActorGraphInterpreter.scala:757)
[info]   at akka.actor.Actor.aroundReceive(Actor.scala:517)
[info]   at akka.actor.Actor.aroundReceive$(Actor.scala:515)
[info]   at akka.stream.impl.fusing.ActorGraphInterpreter.aroundReceive(ActorGraphInterpreter.scala:667)
[info]   at akka.actor.ActorCell.receiveMessage(ActorCell.scala:527)
[info]   at akka.actor.ActorCell.invoke(ActorCell.scala:496)
[info]   at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)
[info]   at akka.dispatch.Mailbox.run(Mailbox.scala:224)
[info]   at akka.dispatch.Mailbox.exec(Mailbox.scala:234)
[info]   at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
[info]   at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
[info]   at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
[info]   at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
[info] cleanup
[info] - should kill actor system (137 milliseconds)
[info] Run completed in 17 seconds, 4 milliseconds.
[info] Total number of tests run: 3
[info] Suites: completed 1, aborted 0
[info] Tests: succeeded 2, failed 1, canceled 0, ignored 0, pending 0
[info] *** 1 TEST FAILED ***
[error] Failed tests:
[error]         AkkaToStrictTests
[error] (Test / testQuick) sbt.TestsFailedException: Tests unsuccessful
[error] Total time: 33 s, completed Jan 17, 2018 1:48:14 PM

@nodefactory-bk
Copy link
Author

Just tested with 10.1.0-RC1, it fails aswell.

@jrudolph
Copy link
Member

Thanks a lot, @nodefactory-bk. It seems the test I added had a slightly different scenario than the one here so the regression was missed.

From your example it seems, that this seems to be a server-side problem this time as the server doesn't send a TLS close_notify message nor does it close the connection when the CloseDelimited payload has been delivered.

@jrudolph
Copy link
Member

I haven't actually checked but from a quick look into the differences between 10.0.9 and 10.0.10 I would assume that face38e could be the culprit.

@jrudolph jrudolph reopened this Jan 17, 2018
jrudolph added a commit to jrudolph/akka-http that referenced this issue Jan 29, 2018
…ompletion

Before introduction of the `delayCancellation` stage TLS closing worked
despite of the default `TLSCLosing.ignoreComplete` mode somewhat
accidentally because cancellation would close the TCP connection.

With the introduction of `delayCancellation`, stream completion is the signal
to act on.
jrudolph added a commit to jrudolph/akka-http that referenced this issue Jan 29, 2018
…ompletion

Before introduction of the `delayCancellation` stage TLS closing worked
despite of the default `TLSCLosing.ignoreComplete` mode somewhat
accidentally because cancellation would close the TCP connection.

With the introduction of `delayCancellation`, stream completion is the signal
to act on.

Without this fix, the server TLS side does not close the connection
eagerly but only the idle-timeout will do so later on.
@jrudolph
Copy link
Member

The above commit was indeed the problem because after that change, the TLS layer didn't actually close the connection any more as it should.

@jrudolph
Copy link
Member

PR in #1822.

jrudolph added a commit that referenced this issue Feb 2, 2018
 =htc #380 TLS should close connection when instructed by stream completion
@jrudolph jrudolph modified the milestones: 10.0.11, 10.1.0 final Feb 2, 2018
jrudolph added a commit to jrudolph/akka-http that referenced this issue Dec 20, 2018
…by stream completion

Before introduction of the `delayCancellation` stage TLS closing worked
despite of the default `TLSCLosing.ignoreComplete` mode somewhat
accidentally because cancellation would close the TCP connection.

With the introduction of `delayCancellation`, stream completion is the signal
to act on.

Without this fix, the server TLS side does not close the connection
eagerly but only the idle-timeout will do so later on.

(cherry picked from commit 3b9735f)
raboof pushed a commit that referenced this issue Dec 21, 2018
* [backport] =htc delayCancellation should also apply for Http().serverLayer

Before it was only applied for all the other server APIs.

(cherry picked from commit 58e493b)

* [backport] =htc #380 TLS should close connection when instructed by stream completion

Before introduction of the `delayCancellation` stage TLS closing worked
despite of the default `TLSCLosing.ignoreComplete` mode somewhat
accidentally because cancellation would close the TCP connection.

With the introduction of `delayCancellation`, stream completion is the signal
to act on.

Without this fix, the server TLS side does not close the connection
eagerly but only the idle-timeout will do so later on.

(cherry picked from commit 3b9735f)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
3 - in progress Someone is working on this ticket bug t:client Issues related to the HTTP Client t:core Issues related to the akka-http-core module t:tls
Projects
No open projects
6 participants