Http4s: Error in asynchronous callback

[ljwagerfield]

HTTP4S 0.21.2 and 0.21.3 produce the following error (version 0.21.1 does not).

If you git clone this repository, update the build.sbt to use 0.21.2 and then hit sbt run you'll see the errors on each request:

https://github.com/ljwagerfield/http4s-request-body-error

The error occurs in the background after calling Client[Task].fetch; the resulting Task[A] is not in a failed state, and the application appears to continue running as normal.

This happens on every request (these are a mix of GET, PUT and DELETE).

As mentioned, 0.21.1 is fine (does not exhibit the problem).

[ERROR] org.http4s.client.asynchttpclient.AsyncHttpClient - Error in asynchronous callback
monix.execution.exceptions.CallbackCalledMultipleTimesException: onSuccess
    at monix.eval.internal.TaskCreate$CallbackForCreate.onSuccess(TaskCreate.scala:196)
    at monix.execution.Callback.apply(Callback.scala:105)
    at monix.execution.Callback.apply(Callback.scala:82)
    at org.http4s.client.asynchttpclient.AsyncHttpClient$$anon$1.$anonfun$onCompleted$1(AsyncHttpClient.scala:126)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
    at monix.eval.internal.TaskRunLoop$.startFull(TaskRunLoop.scala:81)
    at monix.eval.internal.TaskRunLoop$.$anonfun$restartAsync$1(TaskRunLoop.scala:222)
    at monix.execution.schedulers.TracingRunnable.run(TracingRunnable.scala:33)
    at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1429)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)

[rossabaker]

It was caused by this. I think it may already be fixed in https://github.com/http4s/http4s/pull/3338.

We are preparing a release with that, but you can test the fix now: Add to your build:

resolvers += Resolver.sonatypeRepo("snapshots")

And use http4s version 0.21.3+62-605506b0-SNAPSHOT. If that's still noisy on Monix, then we can add another guard to that callback invocation.

[ljwagerfield]

I updated to the snapshot you suggested, but I still get these on every request:

[ERROR] org.http4s.client.asynchttpclient.AsyncHttpClient - Error in asynchronous callback
monix.execution.exceptions.CallbackCalledMultipleTimesException: onSuccess
        at monix.eval.internal.TaskCreate$CallbackForCreate.onSuccess(TaskCreate.scala:196)
        at monix.execution.Callback.apply(Callback.scala:105)
        at monix.execution.Callback.apply(Callback.scala:82)
        at org.http4s.client.asynchttpclient.AsyncHttpClient$$anon$1.$anonfun$onCompleted$1(AsyncHttpClient.scala:127)
        at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
        at monix.eval.internal.TaskRunLoop$.startFull(TaskRunLoop.scala:81)
        at monix.eval.internal.TaskRunLoop$.$anonfun$restartAsync$1(TaskRunLoop.scala:222)
        at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1429)
        at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
        at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1016)

[rossabaker]

Thanks for retesting. We can add a guard to be sure that is only called once.

[rossabaker]

Oops, #3338 was only on master. I still think that might fix it. I'm backporting that now, and will report back with a snapshot version that contains it. If it's still being called twice, then we can wrap it in another Deferred gate.

[rossabaker]

Okay, 0.21.3+63-2e9fd3ae-SNAPSHOT tests what I thought we were testing last round.

If that's still not right, I've still got another idea.

[ljwagerfield]

Yes, that fixes it.

[rossabaker]

Excellent. This will be in 0.21.4, which I expect out early this week. Thanks for reporting and testing!

[henricook]

@rossabaker Do you think this error could be related?

[info]   java.lang.IllegalStateException: This publisher only supports one subscriber
[info]   at com.typesafe.netty.HandlerPublisher.subscribe(HandlerPublisher.java:167)
[info]   at org.http4s.client.asynchttpclient.AsyncHttpClient$$anon$1.$anonfun$onStream$3(AsyncHttpClient.scala:90)
[info]   at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
[info]   at monix.eval.internal.TaskRunLoop$.startFull(TaskRunLoop.scala:81)
[info]   at monix.eval.Task$.unsafeStartNow(Task.scala:4672)
[info]   at monix.eval.internal.TaskBracket$BaseStart$$anon$1.onSuccess(TaskBracket.scala:196)
[info]   at monix.eval.internal.TaskRunLoop$.startFull(TaskRunLoop.scala:165)
[info]   at monix.eval.Task$.unsafeStartNow(Task.scala:4672)
[info]   at monix.eval.internal.TaskBracket$BaseStart.apply(TaskBracket.scala:179)
[info]   at monix.eval.internal.TaskBracket$BaseStart.apply(TaskBracket.scala:166)

[rossabaker]

I think that's a separate issue, but may have been rattled by the same series of commits. Please open a separate issue on that, and add reproduction notes if you have any, and we'll take a look.