POST request with Content-Length header produces "Sending an 2xx 'early' response"

halyph · September 10, 2021, 3:06pm

Hello,
I am getting the following WARN’s

[2021-09-10 16:41:57,406] [WARN] [akka.actor.ActorSystemImpl] [default-akka.actor.default-dispatcher-16] [akka.actor.ActorSystemImpl(default)] - Sending an 2xx 'early' response before end of request for http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID received... Note that the connection will be closed after this response. Also, many clients will not read early responses! Consider only issuing this response after the request data has been completely read!

while external client calls my service like this (see demo app below)

curl --request POST 'http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID' \
-H 'Content-Type: application/json' \
-H 'Content-Length: 1234'

Please note that it’s a POST request and it contains Content-Length header.

Logs:

[2021-09-10 16:41:57,406] [INFO] [akka.actor.ActorSystemImpl] [default-akka.actor.default-dispatcher-16] [akka.actor.ActorSystemImpl(default)] - Client ReST: Response for
  Request : HttpRequest(HttpMethod(POST),http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID,List(Timeout-Access: <function1>, Host, User-Agent: curl/7.54.0, Accept: */*),HttpEntity.Default(application/json,1234 bytes total),HttpProtocol(HTTP/1.1))
  Response: Complete(HttpResponse(200 OK,List(),HttpEntity.Strict(application/json,24 bytes total),HttpProtocol(HTTP/1.1)))
[2021-09-10 16:41:57,406] [WARN] [akka.actor.ActorSystemImpl] [default-akka.actor.default-dispatcher-16] [akka.actor.ActorSystemImpl(default)] - Sending an 2xx 'early' response before end of request for http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID received... Note that the connection will be closed after this response. Also, many clients will not read early responses! Consider only issuing this response after the request data has been completely read!

I am sure that I’ve been getting these WARNs because Content-Length header.
Side note: when request is POST + Content-Length HttpEntity type is Default (see logs above)

The following call doesn’t produce any warning:

curl --location --request POST 'http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID' \
-H 'Content-Type: application/json'

Logs:

[2021-09-10 16:42:10,575] [INFO] [akka.actor.ActorSystemImpl] [default-akka.actor.default-dispatcher-4] [akka.actor.ActorSystemImpl(default)] - Client ReST: Response for
  Request : HttpRequest(HttpMethod(POST),http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID,List(Timeout-Access: <function1>, Host, User-Agent: curl/7.54.0, Accept: */*),HttpEntity.Strict(application/json,0 bytes total),HttpProtocol(HTTP/1.1))
  Response: Complete(HttpResponse(200 OK,List(),HttpEntity.Strict(application/json,24 bytes total),HttpProtocol(HTTP/1.1)))

Side note: when request POST + without Content-Length HttpEntity type is Strict (see logs above)

As I said it’s an external client. I can’t change the API as well as can’t force client to exclude Content-Length from their POST request.

Question

is it possible to “mute” this particular WARN via akka-http Directive or another workaround?
P.S. I can’t “mute” akka.actor.ActorSystemImpl because it might produce other important warnings.

References

akka-http issue: “Early response warning when ignoring the last chunk in a chunked request #2455” Early response warning when ignoring the last chunk in a chunked request · Issue #2455 · akka/akka-http · GitHub

Demo app

lib verions:

lazy val akkaHttpVersion = "10.2.6"
lazy val akkaVersion    = "2.6.16"

libraryDependencies ++= Seq(
  "com.typesafe.akka" %% "akka-http"                % akkaHttpVersion,
  "com.typesafe.akka" %% "akka-http-spray-json"     % akkaHttpVersion,
  "com.typesafe.akka" %% "akka-actor-typed"         % akkaVersion,
  "com.typesafe.akka" %% "akka-stream"              % akkaVersion,
  "ch.qos.logback"    % "logback-classic"           % "1.2.3"

Souce

package com.example

import akka.actor.ActorSystem
import akka.event.Logging
import akka.http.scaladsl.Http
import akka.http.scaladsl.server.Directives._
import akka.http.scaladsl.server.Route
import akka.http.scaladsl.server.directives.DebuggingDirectives
import spray.json.DefaultJsonProtocol

import scala.concurrent.Future
import scala.io.StdIn

object JsonFormats  {
  import DefaultJsonProtocol._
  implicit val userJsonFormat = jsonFormat1(User)
}

final case class User(name: String)

object CollectionRoutes {

  import JsonFormats._
  import akka.http.scaladsl.marshallers.sprayjson.SprayJsonSupport._

  val collectionRoute: Route = {
    pathPrefix("collection-ids") {
      post {
        parameters("entity_class") { entityClass =>
          complete(Future.successful(User(entityClass)))
        }
      }
    }
  }

  val collectionRouteLogged = DebuggingDirectives.logRequestResult("Client ReST", Logging.InfoLevel)(collectionRoute)
}

object HttpServerHighLevel {
  def main(args: Array[String]): Unit = {
    implicit val system = ActorSystem()
    implicit val executionContext = system.dispatcher

    val bindingFuture = Http().newServerAt("localhost", 8080).bind(CollectionRoutes.collectionRouteLogged)
    println(s"Server online at http://localhost:8080/\nPress RETURN to stop...")
    StdIn.readLine()
    bindingFuture
      .flatMap(_.unbind())
      .onComplete(_ => system.terminate())
  }
}

jrudolph · September 14, 2021, 2:03pm

Make sure to completely read the request entity before completing the request to avoid this warning.

halyph · September 14, 2021, 10:55pm

I’ve used this curl request to reproduce the issue and received HTTP 200 response, i.e. it was read completely.

On the other hand I might misunderstand this suggestion:

@jrudolph could you please clarify what you mean by this ^^?

jrudolph · September 21, 2021, 11:08am

In the example, you ignored the incoming request body which leads to the warning. If you use a directive like entity(as[...]) the body will be read before the response is sent out which should avoid the warning.

halyph · September 21, 2021, 4:55pm

I have added entity(as[String]) directive (request body is empty).

  val collectionRoute: Route = {
    pathPrefix("collection-ids") {
      post {
        entity(as[String]) { _ =>
          parameters("entity_class") { entityClass =>
            complete(User(entityClass))
          }
        }
      }
    }
  }

Additional note, my client doesn’t send POST's request body, see sample curl request below:

$ curl --request POST 'http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID' -H 'Content-Type: application/json' -H 'Content-Length: 1' -v
*   Trying ::1...
* TCP_NODELAY set
* Connection failed
* connect to ::1 port 8080 failed: Connection refused
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8080 (#0)
> POST /collection-ids?entity_class=SOME_CLASS_ID HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.54.0
> Accept: */*
> Content-Type: application/json
> Content-Length: 1
> 
* Recv failure: Connection reset by peer
* stopped the pause stream!
* Closing connection 0
curl: (56) Recv failure: Connection reset by peer

and corresponding WARN logs:

[2021-09-21 18:38:56,650] [INFO] [akka.actor.ActorSystemImpl] [default-akka.actor.default-dispatcher-5] [akka.actor.ActorSystemImpl(default)] - Client ReST: Response for
  Request : HttpRequest(HttpMethod(POST),http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID,List(Timeout-Access: <function1>, Host, User-Agent: curl/7.54.0, Accept: */*),HttpEntity.Default(application/json,1 bytes total),HttpProtocol(HTTP/1.1))
  Response: Rejected(List(MalformedRequestContentRejection(HTTP idle-timeout encountered, no bytes passed in the last 60 seconds. This is configurable by akka.http.[server|client].idle-timeout.,akka.http.impl.engine.HttpIdleTimeoutException: HTTP idle-timeout encountered, no bytes passed in the last 60 seconds. This is configurable by akka.http.[server|client].idle-timeout.), TransformationRejection(akka.http.scaladsl.server.directives.BasicDirectives$$Lambda$715/0x00000008005da040@3fe96858)))

Please note message MalformedRequestContentRejection(HTTP idle-timeout encountered, no bytes passed in the last 60 seconds.

Also, I’ve tried different ways to transform HttpEntity Default to Strict using extractStrictEntity and I’ve got timeouts:

  val collectionRoute: Route = {
    pathPrefix("collection-ids") {
      post {
        extractStrictEntity(3.seconds) { _ =>
          parameters("entity_class") { entityClass =>
            complete(User(entityClass))
          }
        }
      }
    }
  }

Timeout (with Content-Length)

$ curl --request POST 'http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID' -H 'Content-Type: application/json' -H 'Content-Length: 1' 
Request timed out after 3 seconds while waiting for entity data

it works without Content-Length:

$ curl --request POST 'http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID' -H 'Content-Type: application/json' 
{"name":"SOME_CLASS_ID"}

and logs:

[2021-09-21 18:49:43,094] [INFO] [akka.actor.ActorSystemImpl] [default-akka.actor.default-dispatcher-8] [akka.actor.ActorSystemImpl(default)] - Client ReST: Response for
  Request : HttpRequest(HttpMethod(POST),http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID,List(Timeout-Access: <function1>, Host, User-Agent: curl/7.54.0, Accept: */*),HttpEntity.Strict(application/json,0 bytes total),HttpProtocol(HTTP/1.1))
  Response: Complete(HttpResponse(200 OK,List(),HttpEntity.Strict(application/json,24 bytes total),HttpProtocol(HTTP/1.1)))

I need somehow modify the incoming stream to make HttpEntity.Strict, unfortunately, I have no idea how to do this.

halyph · October 13, 2021, 9:04am

Just to follow up, maybe somebody has ideas for the “fix”

jrudolph · October 13, 2021, 9:18am

You use -H "Content-Length: 1" but then send no data, so the request is stuck and eventually times out. What’s the actual request you want to send?

halyph · October 13, 2021, 1:49pm

Some client is sending the following request (it’s a sample, with some random Content-Length)

halyph · October 13, 2021, 1:56pm

@jrudolph, The main problem is to allow clients to send this request and avoid getting WARN (it’s from the beginning of this thread)

[2021-09-10 16:41:57,406] [WARN] [akka.actor.ActorSystemImpl] [default-akka.actor.default-dispatcher-16] [akka.actor.ActorSystemImpl(default)] - Sending an 2xx 'early' response before end of request for http://localhost:8080/collection-ids?entity_class=SOME_CLASS_ID received... Note that the connection will be closed after this response. Also, many clients will not read early responses! Consider only issuing this response after the request data has been completely read!

it’s 500 RPS so I have bloated logs with noisy WARNs :-/

jrudolph · October 14, 2021, 9:09am

These client requests are broken (i.e. the client not sending over the amount of bytes it announced to send over), so some kind of consequence is expected.

The right way to handle these broken requests is to use the entity directive and let the requests fail with a timeout (as you observed before). If that also produces a noisy warning, that’s something we could fix.

Topic		Replies	Views
Handle post with big raw data Akka Streams & Alpakka akka , akka-http	5	1408	June 29, 2018
Early response warning issued even after canceeling the connection Akka HTTP scala	0	784	January 17, 2019
Intermittent High Latency while using Akka HTTP ( 10.1.10) Play Framework akka , akka-http , scala	0	480	January 20, 2022
Akka HTTP 10.2.7 Released with Security Fix Akka HTTP announcement , security	0	616	November 2, 2021
Follow up to "Add `aroundRequest` directive which captures complete request / response processing duration" Akka akka-http	0	492	May 26, 2020