http4s / http4s

A minimal, idiomatic Scala interface for HTTP
https://http4s.org/
Apache License 2.0
2.57k stars 791 forks source link

Bug: Multipart client request hangs on error in fileData part stream #4651

Open kubukoz opened 3 years ago

kubukoz commented 3 years ago

This is happening in 1.0.0-M19.

To reproduce, run this:

import cats.effect.IO
import cats.effect.IOApp
import cats.implicits._
import fs2.Stream
import io.circe.Json
import org.http4s.circe.CirceEntityCodec._
import org.http4s.client.blaze.BlazeClientBuilder
import org.http4s.client.dsl.io._
import org.http4s.client.middleware.RequestLogger
import org.http4s.client.middleware.ResponseLogger
import org.http4s.dsl.io._
import org.http4s.implicits._
import org.http4s.multipart.Multipart
import org.http4s.multipart.Part

object Demo extends IOApp.Simple {

  def run: IO[Unit] =
    BlazeClientBuilder[IO](runtime.compute)
      .stream
      .map(RequestLogger(logHeaders = true, logBody = true, logAction = Some(IO.println(_))))
      .map(ResponseLogger(logHeaders = true, logBody = true, logAction = Some(IO.println(_))))
      .evalMap { implicit client =>
        // val data = Stream.emits("hello world".getBytes())
        val data = Stream.raiseError[IO](new Throwable("ops"))

        client
          .expect[Json] {
            val body = Multipart[IO](
              Vector(
                Part.fileData[IO]("file", "example.png", data)
              )
            )

            POST(uri"https://httpbin.org/post").withEntity(body)
          }
      }
      .compile
      .drain

}

Example output:

HTTP/1.1 POST https://httpbin.org/post Headers(Accept: application/json) body="--PSUlrZnSl'q(:MB8)9j4cnjQP2Cha.3VBr(,vuYB8
Content-Disposition: form-data; name="file"; filename="example.png"
Content-Transfer-Encoding: binary

"
2021-03-26 15:53:34 [io-compute-8] ERROR o.h.client.blaze.Http1Connection - Error rendering request
java.lang.Throwable: ops
    at com.kubukoz.ocrapi.Demo$.$anonfun$run$5(OCRAPI.scala:27)
    at fs2.Stream.$anonfun$evalMap$1(Stream.scala:998)
    at fs2.Stream.$anonfun$flatMap$1(Stream.scala:1215)
    at fs2.Pull$FlatMapR$1.go$2(Pull.scala:762)
    at fs2.Pull$FlatMapR$1.unconsed(Pull.scala:770)
    at fs2.Pull$FlatMapR$1.$anonfun$out$3(Pull.scala:780)
    at fs2.Pull$.$anonfun$compile$1(Pull.scala:630)
    at cats.effect.IOFiber.flatMapK(IOFiber.scala:1013)
    at cats.effect.IOFiber.succeeded(IOFiber.scala:818)
    at cats.effect.IOFiber.runLoop(IOFiber.scala:257)
    at cats.effect.IOFiber.execR(IOFiber.scala:929)
    at cats.effect.IOFiber.run(IOFiber.scala:135)
    at cats.effect.unsafe.WorkerThread.runFiber(WorkerThread.scala:162)
    at cats.effect.unsafe.WorkerThread.run(WorkerThread.scala:295)

then nothing for 45 seconds, then...

2021-03-26 15:52:28 [io-compute-5] INFO  org.http4s.client.PoolManager - Shutting down connection pool: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[E] Exception in thread "main" java.util.concurrent.TimeoutException: Request to https://httpbin.org timed out after 45000 ms
[E]     at org.http4s.client.blaze.BlazeClient$$anon$1.run(BlazeClient.scala:152)
[E]     at cats.effect.unsafe.WorkStealingThreadPool.$anonfun$execute$1(WorkStealingThreadPool.scala:318)
[E]     at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
[E]     at cats.effect.IOFiber.runLoop(IOFiber.scala:298)
[E]     at cats.effect.IOFiber.execR(IOFiber.scala:929)
[E]     at cats.effect.IOFiber.run(IOFiber.scala:135)
[E]     at cats.effect.unsafe.WorkerThread.runFiber(WorkerThread.scala:162)
[E]     at cats.effect.unsafe.WorkerThread.run(WorkerThread.scala:295)

If you send some other bytes (like the commented data) instead, you'll get a prompt response.

kubukoz commented 3 years ago

Note that I'm not really bothered too much about the hanging because it unblocks eventually and can be .timeouted to speed that process up, but I was curious if this could be caused by something in CE3: if so, it'd be best to triage before release.

One thing to check (for me) is to do the same in 0.21.x and compare.