AsyncHttpClientMonixBackend prints stack trace when a request is cancelled

[pvgoran]

When a long-running HTTP request made via AsyncHttpClientMonixBackend is cancelled via a call to Cancelable.cancel(), something is printing the stack trace with java.lang.InterruptedException to the console.

The code (Scala 3):

// Imports omitted for brevity.

@main
def main2(): Unit = {
  implicit val scheduler : Scheduler = Scheduler.io()
  val asyncHttpClient : AsyncHttpClient =
    // DefaultAsyncHttpClient()
    DefaultAsyncHttpClient(DefaultAsyncHttpClientConfig.Builder().build())
  val sttpBackend : SttpBackend[Task, MonixStreams with WebSockets] = AsyncHttpClientMonixBackend.usingClient(asyncHttpClient)

  def delayingUrl = "https://deelay.me/8000/https://w1.weather.gov/xml/current_obs/PHNL.xml"
  // deelay.me delays its response on the specified number of milliseconds, this is to simulate
  // a long-running request which I might want to cancel.

  val responseTask : Task[Response[String]] = basicRequest
    .get(Uri.unsafeParse(delayingUrl))
    .response(asString.getRight)
    .send(sttpBackend)

  val responseCancelable : Cancelable = responseTask
    .runAsync {
      case Right(res : Response[String]) =>
        println("Received DELAYING text: " + res.body)
      case Left(ex) =>
        println("DELAYING error: " + ex)
    }

  Thread.sleep(5000)
  responseCancelable.cancel()
}

build.sbt:

ThisBuild / version := "0.1.0-SNAPSHOT"

ThisBuild / scalaVersion := "3.1.3"

val sttpVersion = "3.7.+"

lazy val root = (project in file("."))
  .settings(
    name := "SttpInterruption"
  )

libraryDependencies ++= Seq(
  "com.softwaremill.sttp.client3" %% "core" % sttpVersion,
  "com.softwaremill.sttp.client3" %% "async-http-client-backend-monix" % sttpVersion,
)

The output:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
java.lang.InterruptedException
	at sttp.client3.asynchttpclient.AsyncHttpClientBackend.sendRegular$$anonfun$1$$anonfun$1(AsyncHttpClientBackend.scala:60)
	at sttp.client3.impl.monix.TaskMonadAsyncError$.async$$anonfun$1$$anonfun$1(TaskMonadAsyncError.scala:22)
	at sttp.client3.impl.monix.TaskMonadAsyncError$.async$$anonfun$1$$anonfun$adapted$1(TaskMonadAsyncError.scala:22)
	at monix.eval.internal.TaskRunLoop$.startLight(TaskRunLoop.scala:299)
	at monix.eval.Task.runAsyncUncancelableOpt(Task.scala:934)
	at monix.eval.Task.runAsyncAndForgetOpt(Task.scala:867)
	at monix.eval.Task.runAsyncAndForget(Task.scala:842)
	at monix.eval.internal.UnsafeCancelUtils$.taskToCancelable$$anonfun$1(UnsafeCancelUtils.scala:35)
	at monix.execution.Cancelable$CancelableTask.cancel(Cancelable.scala:140)
	at main2$package$.main2(main2.scala:41)
	at main2.main(main2.scala:17)
Cancelled.

I'm running it in IntelliJ IDEA, and the output is all red, except for the last line. The complaints from SLF4J are irrelevant: in the actual project where logging is configured the stack trace is printed just the same. The stack trace looks like an output of JVM's default exception handler which executed on a background thread.

I have a longer sample code with various kinds of tracing, and it shows that cancellation happens successfully and everything works mostly as expected, except for the stack trace. (Also, a thread may be removed from the thread pool, but it's not an observable effect at this point.)

[pvgoran]

ArmeriaMonixBackend and OkHttpMonixBackend exhibit similar behaviour: some kind of stack trace (with different exceptions) is printed after cancellation. (With Armeria, an exception only appears with the extended sample that I didn't describe.)

[pvgoran]

Backends based on ZIO (AsyncHttpClientMonixBackend and ArmeriaZioBackend) don't seem to have this problem.

[adamw]

I don't think we're doing any logging. There's a LOGGER.debug(t.getMessage(), t); inAsyncCompletionHandler.onThrowable which is called from NettyResponseFuture.abort. Both classes come from async-http-handler. So maybe it is their logging that you can see?

I'm also wondering why we're using .abort instead of .cancel on the future returned by AHC, I've created a PR to see if the tests pass using the other variant.

[pvgoran]

I don't think it's logging that I observe, because SLF4J is non-operational in my example. (See the beginning of the output where SLF4J says logging will be no-op.) Like I said, it looks like an output of JVM's default exception handler which executed on a background thread.

[adamw]

Yeah you're right that's an slf4j logger. Something must be installing the exception handler as you write - either Monix or AHC. It's not sttp in either case :)

[pvgoran]

Actually, my assumption is that an exception handler is, on the contrary, not installed. (I mean, in the stack trace, not within Monix.) The exception is thrown, not caught, it terminates the thread, and JVM prints the stack trace.

Anyway, can you suggest how I could approach this problem? I'm new to both async-http-client and Monix (and async programming in general), so it looks difficult to me. :)

[adamw]

I think by default exceptions are swallowed unless you do a Thread.setDefaultUncaughtExceptionHandler - but this seems to be unused both by monix and AHC (at least it doesn't show up in search).

I'm not sure what could the solution here ... my first bet would be to use HttpClientMonixBackend which is the "default" one (based on a client provided with the JVM). Should be usable exactly the same as the AHC-based one.

[pvgoran]

HttpClientMonixBackend won't work for me, because I use Java 1.8. As a work-around I'll try using ZIO backends.

[adamw]

@pvgoran ah I see :) turns out quite a number of people are still on java 8!

I hope the ZIO backends did work out for you :)

[pvgoran]

@adamw ZIO backends work fine for now, and ZIO itself looks like a sound system.

[Pask423]

As far as I manged to check it is not a logger but result of calling printStackTrace(). It comes from line 28 of DefaultUncaughtExceptionReporter from monix.execution.internal package. It is provided by Scheduler - first line of your example implicit val scheduler: Scheduler = Scheduler.io()

[pvgoran]

Why was this closed? The problem is quite real and prevents use of this backend in certain legitimate scenarios.

Judging from the discussion, the problem seems to happen because STTP allows InterruptedException to propagate to the Monix code. Is this a proper way to handle cancellations in the code run under Monix?

[adamw]

Task cancellation should be fully managed by the effects library - here we are using monix-provided .cancel method, so we aren't doing anything extraordinary. I don't think it should be sttp's responsibility to catch InterruptedExceptions (which is almost always a bad idea). But that's probably a question to monix - maybe a good place to ask would be to create an issue in https://github.com/monix/monix/issues ?