Fix a TLS handshake stall where wrap is recursively called post hands…

[mpilquist]

…hake completion but never makes progress

Original bug posted by @tpolecat in Gitter:

I'm getting the following behavior with TLS negotiation.

wrap result: Status = OK HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 172
unwrapHandshake result: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 62 bytesProduced = 0
unwrapHandshake result: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 695 bytesProduced = 0
unwrapHandshake result: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 338 bytesProduced = 0
unwrapHandshake result: Status = OK HandshakeStatus = NEED_TASK
bytesConsumed = 9 bytesProduced = 0
unwrapHandshake result: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0
wrapHandshake result: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 75
wrapHandshake result: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 6
wrapHandshake result: Status = OK HandshakeStatus = NEED_UNWRAP
bytesConsumed = 0 bytesProduced = 45
unwrapHandshake result: Status = OK HandshakeStatus = NEED_UNWRAP
bytesConsumed = 6 bytesProduced = 0
unwrapHandshake result: Status = OK HandshakeStatus = FINISHED
bytesConsumed = 45 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 126 bytesProduced = 155
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
wrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 0 bytesProduced = 0
... forever

[tpolecat]

This fix doesn't seem to work for me. What happens is that negotiation finishes but as soon as I try to read from the TLSSocket it starts spinning.

Here is a reproduction that is a teensy bit involved but this is the simplest I could get it.

• First start up a Postgres server with SSL enabled. Run this in a new directory because it writes a few cruft files.

#!/bin/bash

set -euo pipefail

openssl req -new -text -passout pass:abcd -subj /CN=localhost -out server.req -keyout privkey.pem
openssl rsa -in privkey.pem -passin pass:abcd -out server.key
openssl req -x509 -in server.req -text -key server.key -out server.crt
chmod 600 server.key
test $(uname -s) == Linux && chown 70 server.key
docker run -d \
  -p5432:5432 \
  -e POSTGRES_HOST_AUTH_METHOD=trust \
  -v "$(pwd)/server.crt:/var/lib/postgresql/server.crt:ro" \
  -v "$(pwd)/server.key:/var/lib/postgresql/server.key:ro" \
  postgres:12-alpine \
  -c ssl=on \
  -c ssl_cert_file=/var/lib/postgresql/server.crt \
  -c ssl_key_file=/var/lib/postgresql/server.key

• Run the following program with the negotiate line in socket commented out to ensure that you can connect to Postgres ok without TLS.

• Uncomment the line and try again.

import cats.effect._
import cats.implicits._
import fs2.Chunk
import fs2.io.tcp.{ Socket, SocketGroup }
import fs2.io.tls.{ TLSContext }
import java.net.InetSocketAddress
import java.nio.ByteBuffer
import java.util.concurrent.Executors
import scala.concurrent.duration._

/**
 * Connect to Postgres via TLS and do the first step in the startup protocol. This requires a
 * Postgres server running with SSL turned on, with user 'postgres' and database 'postgres'.
 */
object Repro extends IOApp {

  // Just in case
  val timeout: Option[FiniteDuration] = Some(1.second)

  val sslRequest: Array[Byte] =
    Array[Byte](0, 0, 0, 8, 4, -46, 22, 47)

  val startupMessage: Array[Byte] =
    Array[Byte](
      0,0,0,-124,
      0, 3, 0, 0, 117, 115, 101, 114, 0, 112, 111, 115, 116, 103, 114, 101, 115, 0, 100, 97, 116,
      97, 98, 97, 115, 101, 0, 112, 111, 115, 116, 103, 114, 101, 115, 0, 99, 108, 105, 101, 110,
      116, 95, 109, 105, 110, 95, 109, 101, 115, 115, 97, 103, 101, 115, 0, 87, 65, 82, 78, 73,
      78, 71, 0, 68, 97, 116, 101, 83, 116, 121, 108, 101, 0, 73, 83, 79, 44, 32, 77, 68, 89, 0,
      73, 110, 116, 101, 114, 118, 97, 108, 83, 116, 121, 108, 101, 0, 105, 115, 111, 95, 56, 54,
      48, 49, 0, 99, 108, 105, 101, 110, 116, 95, 101, 110, 99, 111, 100, 105, 110, 103, 0, 85,
      84, 70, 56, 0, 0
    )

  // I may have missed a memo, is there an easier way to get a blocker?
  val blocker: Resource[IO, Blocker] =
    Resource.make(IO(Executors.newCachedThreadPool))(p => IO(p.shutdown()))
      .map(Blocker.liftExecutorService)

  // Logging, to distinguish out our output from TLS logging
  def log(s: String) = IO(println(s"${Console.GREEN}$s${Console.RESET}"))

  // Some socket helpers.
  implicit class SocketOps(socket: Socket[IO]) {
    def readExact(bytes: Int): IO[Array[Byte]] =
      log(s"Reading $bytes byte(s).") *>
      socket.read(bytes, timeout).map(_.map(_.toBitVector.toByteArray)).flatMap {
        case Some(bs) if bs.length == bytes => bs.pure[IO]
        case x  => IO.raiseError(new Exception(s"Expected $bytes byte(s), got ${x}."))
      }
    def readChar: IO[Char] = readExact(1).map(_(0).toChar)
    def readInt:  IO[Int]  = readExact(4).map(ByteBuffer.wrap(_).getInt)
    def write(bytes: Array[Byte]) =
      log(s"Writing ${bytes.length} byte(s).") *>
      socket.write(Chunk.array(bytes), timeout)
  }

  // After connecting (with or without TLS) let's do the first step of startup.
  def startup(sock: Socket[IO]): IO[ExitCode] =
    for {
      _ <- sock.write(startupMessage)
      c <- sock.readChar
      l <- sock.readInt
      _ <- sock.readExact(l)
      _ <- log(s"<- '$c' ($l bytes)") // 'R' (8 bytes) = plaintext password challenge
      _ <- log("Terminating.")
    } yield ExitCode.Success

  // Initiate SSL negotiation.
  def negotiate(sock: Socket[IO], blocker: Blocker): Resource[IO, Socket[IO]] =
    Resource.liftF(sock.write(sslRequest) *> sock.readChar).flatMap {

      // This is what we expect. The 'S' means the server will negotiate SSL.
      case 'S' =>
        for {
          ctx <- Resource.liftF(TLSContext.insecure[IO](blocker))
          tls <- ctx.client[IO](sock, logger = Some(s => IO(println(s))))
        } yield tls

      // Other possibilities.
      case 'N' => Resource.liftF(IO.raiseError(new Exception("Server can't do SSL!")))
      case c   => Resource.liftF(IO.raiseError(new Exception(s"Unpossible! Server said $c")))

    }

  // Our socket resource
  val socket: Resource[IO, Socket[IO]] =
    for {
      b <- blocker
      g <- SocketGroup[IO](b)
      s <- g.client[IO](new InetSocketAddress("localhost", 5432))
      s <- negotiate(s, b) // COMMENT THIS LINE OUT AND WE SUCCESSFULLY START UP WITHOUT TLS
    } yield s

  def run(args: List[String]): IO[ExitCode] =
    socket.use(startup)

}

[mpilquist]

@tpolecat What do you see when you run that? I added it directly to fs2/io/src/test/scala directory and ran sbt ;project io;test:run and I get this output, which appears to have gotten fully past TLS handshaking:

info] unwrap result: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0
[info] unwrap result: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0
[info] unwrap result: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 339 bytesProduced = 317
[error] java.lang.Exception: Expected 1 byte(s), got Some([B@5851b35d).
[error] 	at Repro$SocketOps.$anonfun$readExact$3(Rob.scala:49)

The maxBytes param passed to read isn't being respected in this case, but otherwise this appears to be working.

[tpolecat]

Hmmmmm. What I get is

[tpolecat]

I wonder if it's a JDK thing. What version are you on? I'm running on 1.8

[mpilquist]

That was with 11. I get same result as you with 1.8. 😠

[tpolecat]

Ok well this isn't super urgent and now that we can reproduce it I can have a look at tracking it down. Don't feel like you have to wade into the muck here.

[mpilquist]

Argh found it. The call to read checks if the TLS session is valid and if not, initiates a handshake by doing a 0 byte write. For whatever reason, session.isValid is returning false in this case.

[mpilquist]

Okay fixed in #1897. Tested against both jdk 1.8 and jdk 11.