java.lang.IllegalStateException: Unbalanced enter/exit

[adamparslew]

Apologies if this has already been addressed. I have encountered the following problem:

• I attempt to create a websocket to a given URL but encountering a 503 during handshaking (rather than 101) resulting in a callback to onFailure().
• Within the callback I attempt to create a new websocket to the same URL, which gives rise to a second call to onFailure():

java.io.IOException: canceled due to java.lang.IllegalStateException: Unbalanced enter/exit
	at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:530)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
	Suppressed: java.lang.IllegalStateException: Unbalanced enter/exit
		at okio.AsyncTimeout$Companion.scheduleTimeout(AsyncTimeout.kt:225)
		at okio.AsyncTimeout$Companion.access$scheduleTimeout(AsyncTimeout.kt:201)
		at okio.AsyncTimeout.enter(AsyncTimeout.kt:54)
		at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:331)
		at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:427)
		at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:320)
		at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
		at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:178)
		at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106)
		at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79)
		at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
		at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
		at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
		at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
		at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
		at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
		at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
		at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
		at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
		at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
		at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517)
		... 3 more

• The second reconnect attempt then gives rise to the following uncaught exception:

java.lang.IllegalStateException: Unbalanced enter/exit
	at okio.AsyncTimeout.enter(AsyncTimeout.kt:49)
	at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:329)
	at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:427)
	at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:320)
	at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
	at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:178)
	at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106)
	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
	at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)

• This occurs when I attempt to create the websocket either on the callback thread (directly within onFailure()) or from a separate thread. Note that I am using a shared static OkHttpClient instance, as this was the recommended approach.
• The problem does not occur following a successful attempt to the site, only upon start-up if a 503 is immediately encountered.
• I have encountered this under both Java 8 and 17 with okhttp 4.9.3 and 4.10.0.
• The workaround I have found is to schedule the socket creation with a slight delay (>30ms), which avoids this problem.

Sample Code

I was able to reproduce the problem by providing a non-websocket URL that then returns a status code other than 101:

package websocket;

import okhttp3.OkHttpClient;
import okhttp3.Request;
import okhttp3.Response;
import okhttp3.WebSocket;
import okhttp3.WebSocketListener;
import org.jetbrains.annotations.NotNull;
import org.jetbrains.annotations.Nullable;

import java.util.concurrent.TimeUnit;
import java.util.logging.Level;
import java.util.logging.Logger;

public class OkHttpFailureTest {
    private static final Logger logger = Logger.getLogger(OkHttpFailureTest.class.getName());
    private static final OkHttpClient client = new OkHttpClient.Builder()
            .pingInterval(5L, TimeUnit.SECONDS)
            .build();

    private static class ReconnectingClient extends WebSocketListener {
        private final Request request;

        public ReconnectingClient(String url) {
            this.request = new Request.Builder().url(url).build();
        }

        public void connect() {//
            client.newWebSocket(request, this);
        }

        @Override
        public void onFailure(@NotNull WebSocket webSocket, @NotNull Throwable t, @Nullable Response response) {
            logger.log(Level.SEVERE, String.format("onFailure(%s,%s)", t.getMessage(), response), t);
            connect();
        }
    }

    public static void main(String[] args) {
        Thread.setDefaultUncaughtExceptionHandler((t, e) -> {
            logger.log(Level.SEVERE, "Caught " + t, e);
            System.exit(1);
        });

        // Intentionally use a URL that will return a status code other than 101:
        ReconnectingClient client = new ReconnectingClient("http://news.bbc.co.uk");
        client.connect();
    }
}

Any help would be greatly appreciated. Obviously I have the workaround but it would be good to understand if this is a genuine bug, whether I am mis-using the API, or whether the site in question is not following the correct protocol by returning something other than 101 during the initial handshake.

Thanks, Adam.

[swankjesse]

Yikes, yes this is definitely OkHttp's fault. Thanks for the careful test case, that'll make this easier to fix!

[adamparslew]

Great; thanks for confirming. It's worth mentioning that, oddly this only seemed to catch us out when the process first starts (and the host we're attempting to connect to returns 503): Once a successful connection had been made, subsequent socket drop + recovery attempts resulting in 503 do not appear to trigger the same problem. I am not 100% on this though.

[yschimke]

I can't reproduce this, including with the test. Any chance you can put up a draft PR with a test showing failures in CI?

I've even tried using an Interceptor to change the error to a 503, since the site you used no longer fails in that way.

[crysxd]

Also happening on my end with the exact stack trace and using websockets (wrapped with KTOR though). Basicallly when the websocket breaks down I immediately connect it again, causing the issue.

[vanniktech]

I also just ran into this. @yschimke I've got a public repo for you: https://github.com/vanniktech/playground/pull/96 which fails:

➜  kotlin git:(okhttp-7381/unbalanced) gw run
Configuration cache is an incubating feature.
Reusing configuration cache.

> Task :kotlin:run
java.io.IOException: canceled due to java.lang.IllegalStateException: Unbalanced enter/exit
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:530)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1589)
        Suppressed: java.lang.IllegalStateException: Unbalanced enter/exit
                at okio.AsyncTimeout$Companion.scheduleTimeout(AsyncTimeout.kt:231)
                at okio.AsyncTimeout$Companion.access$scheduleTimeout(AsyncTimeout.kt:204)
                at okio.AsyncTimeout.enter(AsyncTimeout.kt:57)
                at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:333)
                at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:427)
                at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:320)
                at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
                at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:178)
                at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106)
                at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79)
                at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
                at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
                at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
                at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
                at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
                at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
                at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
                at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
                at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
                at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
                at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517)
                ... 3 more
Exception in thread "OkHttp Dispatcher" java.lang.IllegalStateException: Unbalanced enter/exit
        at okio.AsyncTimeout$Companion.scheduleTimeout(AsyncTimeout.kt:231)
        at okio.AsyncTimeout$Companion.access$scheduleTimeout(AsyncTimeout.kt:204)
        at okio.AsyncTimeout.enter(AsyncTimeout.kt:57)
        at okio.AsyncTimeout$source$1.read(AsyncTimeout.kt:333)
        at okio.RealBufferedSource.indexOf(RealBufferedSource.kt:427)
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:320)
        at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
        at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:178)
        at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106)
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1589)

[eury-fsl]

vanniktech/playground#96

Any clue why is this hapenning? I'm getting the same issue.

[vanniktech]

Nope. I'm also using the workaround stated above. Basically waiting a few milliseconds.

[yschimke]

I'll take a look at the repro on the weekend. Thanks for providing it. Apologies, but have been battling a different issue with media3 at the moment.

[yschimke]

Found the cause. @swankjesse can probably spot if the reordering is wrong, otherwise I'll try to land with a test this weekend.