IllegalStateException thrown from AsyncTimeout in Android 4.4.2

[jorgeper]

I added a comment on 1842 since it seems like the same problem.

I am getting lots of reports on Android 4.4.2 of IllegalStateException thrown from a call to close on the stream we get through getInputStream(). We use OkHttp 3.9.0 through the HttpURLConnection interface.

Our crashing thread's code is fairly straightforward: opens the connection, gets the input stream, reads it and saves it to a file in 8k chunks, and closes the connection.

The call to close the input thread is throwing (stack below, same as 1842), but it is also possible (and I think more likely) that a read from the input stream is throwing before that. Unfortunately, our code calls close() on a finally block without storing a suppressed exception that may have been thrown by the reads of the stream, which is what I suspect is happening.

We run this code in 1 out of 4 threads from a pool, but these threads all get different connections and different input streams, which never hand out. So unless there's some caching/pooling under the covers, I don't think this would be a bug in our app code's multi-threaded use of the input stream. At any rate, from the reports, I see this where no more than 1 of our threads is involved.

This leaves me suspecting that there's something in 4.4.2 different, that may be causing the internal OkHttp thread to read in parallel to our thread (perhaps a timeout kicks in that case?). One difference I saw in the debugger is that 4.4.2 uses HTTP 1.1 connections, whereas other later versions use HTTP 2.

I spent quite a bit of time browsing the OkHttp code trying to look for what could cause this, but I couldn't figure this out.

Any ideas would be very appreciated.

06-24 12:50:54.425 10001 16298 E AndroidRuntime: java.lang.IllegalStateException: Unbalanced enter/exit
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.okio.AsyncTimeout.enter(AsyncTimeout.java:62)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.okio.AsyncTimeout$2.read(AsyncTimeout.java:209)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.okio.RealBufferedSource.indexOf(RealBufferedSource.java:306)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.okio.RealBufferedSource.indexOf(RealBufferedSource.java:300)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:196)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.internal.http.HttpConnection$ChunkedSource.readChunkSize(HttpConnection.java:476)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.internal.http.HttpConnection$ChunkedSource.read(HttpConnection.java:460)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.internal.Util.skipAll(Util.java:176)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.internal.Util.discard(Util.java:158)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.internal.http.HttpConnection$ChunkedSource.close(HttpConnection.java:499)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.okio.RealBufferedSource.close(RealBufferedSource.java:374)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at com.android.okhttp.okio.RealBufferedSource$1.close(RealBufferedSource.java:362)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at java.io.FilterInputStream.close(FilterInputStream.java:64)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at java.util.zip.InflaterInputStream.close(InflaterInputStream.java:252)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at java.util.zip.GZIPInputStream.close(GZIPInputStream.java:125)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at okio.Okio$2.close(SourceFile:145)
06-24 12:50:54.425 10001 16298 E AndroidRuntime: at okio.RealBufferedSource.close(SourceFile:363)

[swankjesse]

FYI, this stacktrace is not using OkHttp 3.10. The com.android in the package means it’s the device’ built-in copy of OkHttp 2.x.

You can get 3.10 with the URL connection interface like so:
http://square.github.io/okhttp/3.x/okhttp-urlconnection/okhttp3/OkUrlFactory.html#createURLStreamHandler-java.lang.String-

[jorgeper]

my bad, I pasted the wrong stack from 1842. This is the one I am getting on 3.9

java.lang.IllegalStateException: Unbalanced enter/exit
at okio.AsyncTimeout.enter(AsyncTimeout.java:73)
at okio.AsyncTimeout$2.read(AsyncTimeout.java:235)
at okio.RealBufferedSource.read(RealBufferedSource.java:46)
at okhttp3.internal.http1.Http1Codec$AbstractSource.read(Http1Codec.java:352)
at okhttp3.internal.http1.Http1Codec$FixedLengthSource.read(Http1Codec.java:396)
at okhttp3.internal.Util.skipAll(Util.java:175)
at okhttp3.internal.Util.discard$5166UQR9DSNL6RRLE9HMAEQ99HL62TJ15TQN8QBC5THMURJ3ELP74PBEEGNL8QBDCLAMSQBK7CKLK___0(Util.java:157)
at okhttp3.internal.http1.Http1Codec$FixedLengthSource.close(Http1Codec.java:413)
at okio.RealBufferedSource.close(RealBufferedSource.java:455)
at okio.RealBufferedSource$1.close(RealBufferedSource.java:443)

[swankjesse]

Which device? Are you using D8? We’ve seen VM correctness problem on 4.4.2.

[jorgeper]

Thank you, indeed, it seems this is correlated with switching to D8. This is happening in a fairly wide selection of devices. Are you referring to #3641 ?

[swankjesse]

Yup.

[swankjesse]

Dupe of #3641