Logging middleware consumes request body when using OkHttpClient, leading to null body

[GrafBlutwurst]

As the title says, minimized example:

Note this example uses a publicly available API that just echos back the payload sent.

I do have a very very ugly workaround right now that solves my problem but at mem and performance cost, essentially i just copy the request and responses in a naive manner and then defer one set to logging, and one to actual use:

https://gist.github.com/GrafBlutwurst/2bc68aff07c742902188f82699ac4f2c

build.sbt:

ThisBuild / scalaVersion := "2.13.3"

val catsEffectVersion = "2.2.0"
val catsVersion = "2.2.0"
val circeVersion = "0.13.0"
val http4sVersion = "0.21.8"


libraryDependencies ++= Seq(
      "org.typelevel" %% "cats-effect" % catsEffectVersion,
      "io.circe" %% "circe-core" % circeVersion,
      "io.circe" %% "circe-generic" % circeVersion,
      "io.circe" %% "circe-parser" % circeVersion,
      "io.circe" %% "circe-refined" % circeVersion,
      "org.http4s" %% "http4s-okhttp-client" % http4sVersion,
      "org.http4s" %% "http4s-dsl" % http4sVersion,
      "org.http4s" %% "http4s-circe" % http4sVersion,
    )

organization := "example"
name := "bug"
version := "0.0.1"

Main.scala

package example

import cats.effect.IO
import okhttp3.OkHttpClient
import org.http4s.client.okhttp.OkHttpBuilder
import cats.effect.Blocker
import cats.implicits._
import cats.effect.implicits._
import cats.effect.ExitCode
import org.http4s.Method
import org.http4s.Request
import org.http4s.Uri
import cats.effect.implicits._
import cats.implicits._
import org.http4s.Request
import org.http4s.Uri
import io.circe.Json
import org.http4s.circe._
import org.http4s.Method
import org.http4s.EntityEncoder
import io.circe.syntax._
import org.http4s.MediaType
import org.http4s.Charset
import org.http4s.headers.`Content-Type`
import org.http4s.HttpVersion
import org.http4s.Headers
import org.http4s.Header
import cats.effect.Resource
import org.http4s.client.Client

object Main extends cats.effect.IOApp {

  val payload = """{"foo": "bar"}"""

  def makeRequest(client: Client[IO]): IO[Json] =
    client
      .run(
        Request[IO](
          Method.POST,
          Uri.uri(
            "https://postman-echo.com/post"
          ),
          HttpVersion.`HTTP/1.1`
        )
          .withEntity(payload)
          .withContentType(
            `Content-Type`(
              MediaType.application.json,
              Some(Charset.`UTF-8`)
            )
          )
      )
      .use(
        _.as[Json].flatMap(j =>
          IO.fromEither(j.hcursor.downField("json").as[Json])
        )
      )

  override def run(args: List[String]): cats.effect.IO[cats.effect.ExitCode] =
    Blocker[IO]
      .flatMap(blocker =>
        for {
          builder <-
            OkHttpBuilder
              .withDefaultClient[IO](
                blocker
              )

          client <- builder.resource
          loggedClient = org.http4s.client.middleware.Logger[IO](
            true,
            true,
            _ => false,
            Some((s: String) => IO.delay(println(s)))
          )(client)
        } yield (client, loggedClient)
      )
      .use { tpl =>
        val (client, loggedClient) = tpl
        for {

          echoContent1 <- makeRequest(client)

          echoContent2 <- makeRequest(loggedClient)

          //would expect to output the same
          _ = println("Echo Content using normal Client: ")
          _ = println(echoContent1.spaces2) // outputs payload
          _ = println("Echo Content using logged Client: ")
          _ = println(echoContent2.spaces2) // outputs null

        } yield ()
      }
      .as(ExitCode.Success)

}

Example Run:

[rossabaker]

This is an excellent bug report. It is a less excellent bug. 😆

When logging, I can observe a correct chunk being passed as b on this line, but the sink.write(b) effect never completes. Still diagnosing why.

[rossabaker]

Looks like a race condition from trying one of okhttp's callbacks asynchronously. I can't find any relevant documentation, but blocking one of their threads 😓 seems to work.