java.lang.IllegalStateException: Unbalanced enter/exit #7381

adamparslew · 2022-07-13T15:48:52Z

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.

The text was updated successfully, but these errors were encountered:

swankjesse · 2022-07-14T09:50:58Z

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

adamparslew · 2022-07-14T14:34:30Z

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 · 2022-09-10T17:17:51Z

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 · 2022-11-27T08:32:06Z

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.

…lated to this issue: square/okhttp#7381

vanniktech · 2023-04-18T10:56:05Z

I also just ran into this. @yschimke I've got a public repo for you: vanniktech/playground#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 · 2023-05-08T22:26:14Z

vanniktech/playground#96

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

vanniktech · 2023-05-09T13:54:20Z

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

yschimke · 2023-05-09T14:52:57Z

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 · 2023-05-11T21:25:28Z

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

adamparslew added the bug Bug in existing code label Jul 13, 2022

vitorpamplona added a commit to vitorpamplona/amethyst that referenced this issue Jan 21, 2023

Seems to solve constant crashing when reconnecting after a failure re…

0f73111

…lated to this issue: square/okhttp#7381

carlosmuvi-stripe mentioned this issue May 10, 2023

[Android] ImageDecoder: Exception in invokeOnCancellation handler stripe/stripe-android#6698

Merged

yschimke mentioned this issue May 11, 2023

Fix websocket reconnect race condition #7815

Merged

yschimke closed this as completed May 21, 2023

ianbotsf mentioned this issue Apr 3, 2024

OkHttp: Retry on SocketException: Broken pipe smithy-lang/smithy-kotlin#962

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

java.lang.IllegalStateException: Unbalanced enter/exit #7381

java.lang.IllegalStateException: Unbalanced enter/exit #7381

adamparslew commented Jul 13, 2022 •

edited

swankjesse commented Jul 14, 2022

adamparslew commented Jul 14, 2022

yschimke commented Sep 10, 2022

crysxd commented Nov 27, 2022

vanniktech commented Apr 18, 2023

eury-fsl commented May 8, 2023

vanniktech commented May 9, 2023

yschimke commented May 9, 2023

yschimke commented May 11, 2023

java.lang.IllegalStateException: Unbalanced enter/exit #7381

java.lang.IllegalStateException: Unbalanced enter/exit #7381

Comments

adamparslew commented Jul 13, 2022 • edited

Sample Code

swankjesse commented Jul 14, 2022

adamparslew commented Jul 14, 2022

yschimke commented Sep 10, 2022

crysxd commented Nov 27, 2022

vanniktech commented Apr 18, 2023

eury-fsl commented May 8, 2023

vanniktech commented May 9, 2023

yschimke commented May 9, 2023

yschimke commented May 11, 2023

adamparslew commented Jul 13, 2022 •

edited