Okhttp: Recover gracefully from Thread.interrupt()

Created on 7 Oct 2015  Â·  36Comments  Â·  Source: square/okhttp

Using 2.5.0 and excessive / unnecessary close() calls I still get a StrictMode error. I notice the glide folk had an issue logged that looked similar. Both are using an ExecutorService. Perhaps this just boils down to just 'Android / StrictMode' and can be simply ignored - rfc.

    {
        mCacheControl = new CacheControl.Builder()
                .maxStale(90, TimeUnit.DAYS)
                .maxAge(3, TimeUnit.DAYS)
                .build();
    }

    public byte[] getData(String url) throws IOException {
        Request request = new Request.Builder()
                .cacheControl(mCacheControl)
                .url(url)
                .build();

        byte[] result = null;
        Response resp = null;

        try {
            resp = mClient.newCall(request).execute();
            if (resp.body().contentType() != null) {
                result = resp.body().bytes();
                resp.body().close();
            }
        } catch (Exception e) {
            if (resp != null && resp.body() != null) {
                try {
                    resp.body().close();
                } catch (IOException e2) {
                    Timber.e(e2, "Potential leak - cannot close body");
                }
            }
        } finally {
            if (resp != null && resp.body() != null) {
                try {
                    resp.body().close();
                } catch (IOException e) {
                    Timber.e(e, "Potential leak - cannot close body");
                }
            }
        }
        return result;
    }

E/StrictMode(32187): A resource was acquired at attached stack trace but never released. See java.io.Closeable for information on avoiding resource leaks.
E/StrictMode(32187): java.lang.Throwable: Explicit termination method 'close' not called
E/StrictMode(32187):    at dalvik.system.CloseGuard.open(CloseGuard.java:184)
E/StrictMode(32187):    at com.android.org.conscrypt.OpenSSLSocketImpl.startHandshake(OpenSSLSocketImpl.java:287)
E/StrictMode(32187):    at com.squareup.okhttp.Connection.connectTls(Connection.java:235)
E/StrictMode(32187):    at com.squareup.okhttp.Connection.connectSocket(Connection.java:199)
E/StrictMode(32187):    at com.squareup.okhttp.Connection.connect(Connection.java:172)
E/StrictMode(32187):    at com.squareup.okhttp.Connection.connectAndSetOwner(Connection.java:367)
E/StrictMode(32187):    at com.squareup.okhttp.OkHttpClient$1.connectAndSetOwner(OkHttpClient.java:128)
E/StrictMode(32187):    at com.squareup.okhttp.internal.http.HttpEngine.connect(HttpEngine.java:328)
E/StrictMode(32187):    at com.squareup.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:245)
E/StrictMode(32187):    at com.squareup.okhttp.Call.getResponse(Call.java:267)
E/StrictMode(32187):    at com.squareup.okhttp.Call$ApplicationInterceptorChain.proceed(Call.java:224)
E/StrictMode(32187):    at com.squareup.okhttp.Call.getResponseWithInterceptorChain(Call.java:195)
E/StrictMode(32187):    at com.squareup.okhttp.Call.execute(Call.java:79)
E/StrictMode(32187):    at uk.organisation.samples.gis.http.DownloaderImpl.getData(DownloaderImpl.java:88)
E/StrictMode(32187):    at uk.organisation.samples.gis.layers.MapLayer.getTile(MapLayer.java:156)
E/StrictMode(32187):    at com.gis.android.map.TiledServiceLayer$1.run(SourceFile:412)
E/StrictMode(32187):    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422)
E/StrictMode(32187):    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
E/StrictMode(32187):    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
E/StrictMode(32187):    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
E/StrictMode(32187):    at java.lang.Thread.run(Thread.java:818)
bug enhancement
Source
picture snodnipper

Most helpful comment

I think as has been pointed out, ExcutorService uses thread interrupts to encourage threads to stop what they are doing. ExecutorService is pretty core to Java. It would be unclean to not support thread interrupts, and it would be wrong to run into errors because of thread interrupts.

I think, perhaps unfortunately, you have to deal with interrupts because it is such a core part of the language. Ideally waits/reads/writes would all stop when interrupted (perhaps similar to a read/write timeout, could you just treat them the same?). If not that ideal solution then at the very least you pretty much have to not run into errors when threads are interrupted as that is core to any logic being executed in java.

Finally I will mention that many devs would probably be super happy if okhttp supported interrupts, the ability to ask a thread to stop without needing to restart the JVM is a very nice very useful property.

@yschimke updated since you re-opened for discussion.

picture LukeButters on 30 Mar 2020
👍3

All 36 comments

Can fix.

swankjesse picture swankjesse on 31 Oct 2015

@dave-r12 this looks tricky. Interested?

swankjesse picture swankjesse on 8 Jan 2016

Hah, nice. @snodnipper do you recall/know if at least one exception is being thrown on any of your HTTP calls? I think this is a connection leak within OkHttp itself so your excessive close calls may not be necessary. I noted 2 possible leak sites, one relating to hitting the max follow up threshold (which has since been addressed) and the other around HTTP authentication.

dave-r12 picture dave-r12 on 10 Jan 2016

Excellent, thanks @dave-r12 for taking a look.

From memory, I was downloading several million files. This demo project has a crude outline.

It takes the visible area of a map and calculates the URLs to fetch. I probably then created an ExecutorService to download several concurrently and over the few million tiles I probably got a few of those errors.

re: "at least one exception is being thrown" - possibly some of the HTTP calls failed given the number of tiles.

I note that in my demo project I am not using SSL (I am using OSM) as the source...whereas the code that generated the problem was connecting to an https endpoint in reference to your HTTP authentication thoughts.

Just for good measure, I note that the demo project gets the following exception on a screen rotation. I assume it is a separate issue.

01-12 18:29:56.212  1419  1427 E StrictMode: java.lang.Throwable: Explicit termination method 'close' not called
01-12 18:29:56.212  1419  1427 E StrictMode:    at dalvik.system.CloseGuard.open(CloseGuard.java:180)
01-12 18:29:56.212  1419  1427 E StrictMode:    at java.io.FileOutputStream.<init>(FileOutputStream.java:89)
01-12 18:29:56.212  1419  1427 E StrictMode:    at okio.Okio.appendingSink(Okio.java:182)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.internal.io.FileSystem$1.appendingSink(FileSystem.java:59)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.internal.DiskLruCache.newJournalWriter(DiskLruCache.java:301)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.internal.DiskLruCache.readJournal(DiskLruCache.java:293)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.internal.DiskLruCache.initialize(DiskLruCache.java:220)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.internal.DiskLruCache.get(DiskLruCache.java:422)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.Cache.get(Cache.java:184)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.Cache$1.get(Cache.java:139)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:226)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.Call.getResponse(Call.java:267)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.Call$ApplicationInterceptorChain.proceed(Call.java:224)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.Call.getResponseWithInterceptorChain(Call.java:195)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.squareup.okhttp.Call.execute(Call.java:79)
01-12 18:29:56.212  1419  1427 E StrictMode:    at uk.co.snodnipper.okhttp.issue1903.DownloaderImpl.getData(DownloaderImpl.java:114)
01-12 18:29:56.212  1419  1427 E StrictMode:    at uk.co.snodnipper.okhttp.issue1903.MapboxLayer.getTile(MapboxLayer.java:117)
01-12 18:29:56.212  1419  1427 E StrictMode:    at com.esri.android.map.TiledServiceLayer$1.run(SourceFile:412)
01-12 18:29:56.212  1419  1427 E StrictMode:    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:423)
01-12 18:29:56.212  1419  1427 E StrictMode:    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
01-12 18:29:56.212  1419  1427 E StrictMode:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
01-12 18:29:56.212  1419  1427 E StrictMode:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
01-12 18:29:56.212  1419  1427 E StrictMode:    at java.lang.Thread.run(Thread.java:818)
snodnipper picture snodnipper on 12 Jan 2016

Thanks, and cool demo app BTW. I'm also seeing that StrictMode message. It's been quite awhile since I've done development on Android, so please correct me if I'm wrong here. I think part of the problem is that your are creating an OkHttpClient and Cache each time the MainActivity is created. From the wiki:

Most applications should call new OkHttpClient() exactly once, configure it with their cache, and use that same instance everywhere.

I don't think it's surprising this message is getting logged. I'm also wondering if a similar scenario is happening regarding your StrictMode message for the socket.

dave-r12 picture dave-r12 on 12 Jan 2016

So I have updated the demo to only create the OkHttpClient once - you are quite correct. We certainly do not seem to get the issue so frequently now...but I am still getting it in my logcat. For example:

01-13 06:49:35.869 24377 24404 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/13/4062/2745.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.025 24377 24407 E DownloaderImpl: ! WE HAVE DATA http://a.tile.openstreetmap.org/13/4064/2744.png
01-13 06:49:36.032 24377 24427 E DownloaderImpl: ! WE HAVE DATA http://a.tile.openstreetmap.org/13/4063/2745.png
01-13 06:49:36.037 24377 24406 E DownloaderImpl: ! WE HAVE DATA http://a.tile.openstreetmap.org/13/4063/2744.png
01-13 06:49:36.060 24377 24407 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/13/4064/2743.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.077 24377 24406 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/13/4063/2743.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.085 24377 24427 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/13/4062/2743.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.161 24377 24404 E DownloaderImpl: ! WE HAVE DATA http://a.tile.openstreetmap.org/13/4062/2745.png
01-13 06:49:36.176 24377 24404 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/13/4061/2743.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.263 24377 24407 E DownloaderImpl: ! WE HAVE DATA http://a.tile.openstreetmap.org/13/4064/2743.png
01-13 06:49:36.282 24377 24407 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/13/4065/2743.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.317 24377 24406 E DownloaderImpl: ! WE HAVE DATA http://a.tile.openstreetmap.org/13/4063/2743.png
01-13 06:49:36.334 24377 24406 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/13/4065/2744.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.364 24377 24427 E DownloaderImpl: ! GOSH - NO DATA http://a.tile.openstreetmap.org/13/4062/2743.png.  Key: 18eef60661cf25ecd72f7d2355d4d3ae
01-13 06:49:36.372 24377 24385 E StrictMode: A resource was acquired at attached stack trace but never released. See java.io.Closeable for information on avoiding resource leaks.
01-13 06:49:36.372 24377 24385 E StrictMode: java.lang.Throwable: Explicit termination method 'close' not called
01-13 06:49:36.372 24377 24385 E StrictMode:    at dalvik.system.CloseGuard.open(CloseGuard.java:180)
01-13 06:49:36.372 24377 24385 E StrictMode:    at java.io.FileOutputStream.<init>(FileOutputStream.java:89)
01-13 06:49:36.372 24377 24385 E StrictMode:    at java.io.FileOutputStream.<init>(FileOutputStream.java:72)
01-13 06:49:36.372 24377 24385 E StrictMode:    at okio.Okio.sink(Okio.java:176)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.internal.io.FileSystem$1.sink(FileSystem.java:49)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.internal.DiskLruCache$Editor.newSink(DiskLruCache.java:875)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.Cache$CacheRequestImpl.<init>(Cache.java:431)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.Cache.put(Cache.java:240)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.Cache.access$000(Cache.java:131)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.Cache$1.put(Cache.java:142)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.internal.http.HttpEngine.maybeCache(HttpEngine.java:546)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.internal.http.HttpEngine.readResponse(HttpEngine.java:820)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.Call.getResponse(Call.java:268)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.Call$ApplicationInterceptorChain.proceed(Call.java:224)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.Call.getResponseWithInterceptorChain(Call.java:195)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.squareup.okhttp.Call.execute(Call.java:79)
01-13 06:49:36.372 24377 24385 E StrictMode:    at uk.co.snodnipper.okhttp.issue1903.DownloaderImpl.getData(DownloaderImpl.java:114)
01-13 06:49:36.372 24377 24385 E StrictMode:    at uk.co.snodnipper.okhttp.issue1903.MapboxLayer.getTile(MapboxLayer.java:117)
01-13 06:49:36.372 24377 24385 E StrictMode:    at com.esri.android.map.TiledServiceLayer$1.run(SourceFile:412)
01-13 06:49:36.372 24377 24385 E StrictMode:    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:423)
01-13 06:49:36.372 24377 24385 E StrictMode:    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
01-13 06:49:36.372 24377 24385 E StrictMode:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
01-13 06:49:36.372 24377 24385 E StrictMode:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
01-13 06:49:36.372 24377 24385 E StrictMode:    at java.lang.Thread.run(Thread.java:818)
01-13 06:49:36.408 24377 24405 E DownloaderImpl: ! GOSH - NO DATA http://a.tile.openstreetmap.org/13/4062/2744.png.  Key: e5172912fdfaf1eb1b6ccc9a6270d51f
01-13 06:49:36.439 24377 24404 E DownloaderImpl: ! GOSH - NO DATA http://a.tile.openstreetmap.org/13/4061/2743.png.  Key: ca185223ed31db7e493561796fac8212
01-13 06:49:36.505 24377 24405 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/14/8126/5490.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.505 24377 24427 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/14/8127/5491.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e
01-13 06:49:36.507 24377 24404 E DownloaderImpl: ! ONLINE - fetch http://a.tile.openstreetmap.org/14/8127/5492.png from uk.co.snodnipper.okhttp.issue1903.DownloaderImpl@46dd60e

With regard to the original code that generated the errors, it was almost certainly using a Dagger Singleton instance. I will try and find some time find / execute the code again with OkHttp.

snodnipper picture snodnipper on 13 Jan 2016

Alright, thanks. I'll see if I can take a look

dave-r12 picture dave-r12 on 13 Jan 2016

I believe I've been able to reproduce a variant of the original exception, but I think it's separate from what you are doing. Here is the repo, https://github.com/dave-r12/okhttp-racing-leak

dave-r12 picture dave-r12 on 14 Jan 2016

It looks like there was a fair bit of refactoring work around ConnectionPool and StreamAllocation since OkHttp 2.5. @snodnipper is it possible for you to upgrade to OkHttp3? The leaks I mentioned have already been identified and fixed.

The other thing I found was in reference to your issue #1903 about using Thread.interrupt() & InterruptedIOException not playing nice with OkHttp. For whatever reason, I can't trigger this on the desktop (I think we'd need to dive into the JDK source to understand why.) But it does seem to trigger on Android reliably. If you interrupt a thread while it is in the middle of a request, it will leak the connection (it also requires a domain with 1 DNS entry.) I've updated the demo app I created which replicates the issue reliably. Can anyone else confirm this?

dave-r12 picture dave-r12 on 15 Jan 2016

For what it’s worth, we haven’t paid much attention or interest to Thread.interrupt(). It’s an awkward API and we prefer cancel instead.

swankjesse picture swankjesse on 16 Jan 2016

I updated the map app to OkHttp 3.0.1 and received the following output:

01-17 20:36:32.139  4512  4549 E StrictMode: java.lang.Throwable: Explicit termination method 'end' not called
01-17 20:36:32.139  4512  4549 E StrictMode:    at dalvik.system.CloseGuard.open(CloseGuard.java:180)
01-17 20:36:32.139  4512  4549 E StrictMode:    at java.util.zip.Inflater.<init>(Inflater.java:82)
01-17 20:36:32.139  4512  4549 E StrictMode:    at java.util.zip.ZipFile.getInputStream(ZipFile.java:343)
01-17 20:36:32.139  4512  4549 E StrictMode:    at java.util.jar.JarFile.getInputStream(JarFile.java:390)
01-17 20:36:32.139  4512  4549 E StrictMode:    at libcore.net.url.JarURLConnectionImpl.getInputStream(JarURLConnectionImpl.java:222)
01-17 20:36:32.139  4512  4549 E StrictMode:    at java.net.URL.openStream(URL.java:470)
01-17 20:36:32.139  4512  4549 E StrictMode:    at java.lang.ClassLoader.getResourceAsStream(ClassLoader.java:444)
01-17 20:36:32.139  4512  4549 E StrictMode:    at java.lang.Class.getResourceAsStream(Class.java:1169)
01-17 20:36:32.139  4512  4549 E StrictMode:    at com.esri.android.map.MapView$a.a(SourceFile:3321)
01-17 20:36:32.139  4512  4549 E StrictMode:    at com.esri.android.map.MapView$a.b(SourceFile:3311)
01-17 20:36:32.139  4512  4549 E StrictMode:    at com.esri.android.map.MapView$a.a(SourceFile:3277)
01-17 20:36:32.139  4512  4549 E StrictMode:    at com.esri.android.map.MapView$a.a(SourceFile:3229)
01-17 20:36:32.139  4512  4549 E StrictMode:    at com.esri.android.map.MapView$7.run(SourceFile:3114)
01-17 20:36:32.139  4512  4549 E StrictMode:    at android.os.Handler.handleCallback(Handler.java:739)
01-17 20:36:32.139  4512  4549 E StrictMode:    at android.os.Handler.dispatchMessage(Handler.java:95)
01-17 20:36:32.139  4512  4549 E StrictMode:    at android.os.Looper.loop(Looper.java:148)
01-17 20:36:32.139  4512  4549 E StrictMode:    at android.app.ActivityThread.main(ActivityThread.java:5417)
01-17 20:36:32.139  4512  4549 E StrictMode:    at java.lang.reflect.Method.invoke(Native Method)
01-17 20:36:32.139  4512  4549 E StrictMode:    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
01-17 20:36:32.139  4512  4549 E StrictMode:    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
01-17 20:36:32.149  4512  4549 E StrictMode: A resource was acquired at attached stack trace but never released. See java.io.Closeable for information on avoiding resource leaks.
01-17 20:36:32.149  4512  4549 E StrictMode: java.lang.Throwable: Explicit termination method 'close' not called
01-17 20:36:32.149  4512  4549 E StrictMode:    at dalvik.system.CloseGuard.open(CloseGuard.java:180)
01-17 20:36:32.149  4512  4549 E StrictMode:    at java.io.FileOutputStream.<init>(FileOutputStream.java:89)
01-17 20:36:32.149  4512  4549 E StrictMode:    at java.io.FileOutputStream.<init>(FileOutputStream.java:72)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okio.Okio.sink(Okio.java:176)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.internal.io.FileSystem$1.sink(FileSystem.java:49)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.internal.DiskLruCache$Editor.newSink(DiskLruCache.java:863)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.Cache$CacheRequestImpl.<init>(Cache.java:437)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.Cache.put(Cache.java:250)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.Cache.access$000(Cache.java:136)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.Cache$1.put(Cache.java:148)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.internal.http.HttpEngine.maybeCache(HttpEngine.java:389)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.internal.http.HttpEngine.readResponse(HttpEngine.java:633)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.RealCall.getResponse(RealCall.java:241)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.RealCall$ApplicationInterceptorChain.proceed(RealCall.java:198)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:160)
01-17 20:36:32.149  4512  4549 E StrictMode:    at okhttp3.RealCall.execute(RealCall.java:57)
01-17 20:36:32.149  4512  4549 E StrictMode:    at uk.co.snodnipper.okhttp.issue1903.DownloaderImpl.getData(DownloaderImpl.java:116)
01-17 20:36:32.149  4512  4549 E StrictMode:    at uk.co.snodnipper.okhttp.issue1903.MapboxLayer.getTile(MapboxLayer.java:117)
01-17 20:36:32.149  4512  4549 E StrictMode:    at com.esri.android.map.TiledServiceLayer$1.run(SourceFile:412)
01-17 20:36:32.149  4512  4549 E StrictMode:    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:423)
01-17 20:36:32.149  4512  4549 E StrictMode:    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
01-17 20:36:32.149  4512  4549 E StrictMode:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
01-17 20:36:32.149  4512  4549 E StrictMode:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
01-17 20:36:32.149  4512  4549 E StrictMode:    at java.lang.Thread.run(Thread.java:818)

I'll check out your okhttp-racing-leak project in a moment.

snodnipper picture snodnipper on 17 Jan 2016

And you are certain that the problem is not in your code? Also that first
trace is not OkHttp.

On Sun, Jan 17, 2016, 3:53 PM Ollie Snowden [email protected]
wrote:

I updated the map app to OkHttp 3.0.1 and received the following output:

01-17 20:36:32.139 4512 4549 E StrictMode: java.lang.Throwable: Explicit
termination method 'end' not called
01-17 20:36:32.139 4512 4549 E StrictMode: at
dalvik.system.CloseGuard.open(CloseGuard.java:180)
01-17 20:36:32.139 4512 4549 E StrictMode: at
java.util.zip.Inflater.(Inflater.java:82)
01-17 20:36:32.139 4512 4549 E StrictMode: at
java.util.zip.ZipFile.getInputStream(ZipFile.java:343)
01-17 20:36:32.139 4512 4549 E StrictMode: at
java.util.jar.JarFile.getInputStream(JarFile.java:390)
01-17 20:36:32.139 4512 4549 E StrictMode: at
libcore.net.url.JarURLConnectionImpl.getInputStream(JarURLConnectionImpl.java:222)
01-17 20:36:32.139 4512 4549 E StrictMode: at
java.net.URL.openStream(URL.java:470)
01-17 20:36:32.139 4512 4549 E StrictMode: at
java.lang.ClassLoader.getResourceAsStream(ClassLoader.java:444)
01-17 20:36:32.139 4512 4549 E StrictMode: at
java.lang.Class.getResourceAsStream(Class.java:1169)
01-17 20:36:32.139 4512 4549 E StrictMode: at
com.esri.android.map.MapView$a.a(SourceFile:3321)
01-17 20:36:32.139 4512 4549 E StrictMode: at
com.esri.android.map.MapView$a.b(SourceFile:3311)
01-17 20:36:32.139 4512 4549 E StrictMode: at
com.esri.android.map.MapView$a.a(SourceFile:3277)
01-17 20:36:32.139 4512 4549 E StrictMode: at
com.esri.android.map.MapView$a.a(SourceFile:3229)
01-17 20:36:32.139 4512 4549 E StrictMode: at
com.esri.android.map.MapView$7.run(SourceFile:3114)
01-17 20:36:32.139 4512 4549 E StrictMode: at
android.os.Handler.handleCallback(Handler.java:739)
01-17 20:36:32.139 4512 4549 E StrictMode: at
android.os.Handler.dispatchMessage(Handler.java:95)
01-17 20:36:32.139 4512 4549 E StrictMode: at
android.os.Looper.loop(Looper.java:148)
01-17 20:36:32.139 4512 4549 E StrictMode: at
android.app.ActivityThread.main(ActivityThread.java:5417)
01-17 20:36:32.139 4512 4549 E StrictMode: at
java.lang.reflect.Method.invoke(Native Method)
01-17 20:36:32.139 4512 4549 E StrictMode: at
com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
01-17 20:36:32.139 4512 4549 E StrictMode: at
com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
01-17 20:36:32.149 4512 4549 E StrictMode: A resource was acquired at
attached stack trace but never released. See java.io.Closeable for
information on avoiding resource leaks.
01-17 20:36:32.149 4512 4549 E StrictMode: java.lang.Throwable: Explicit
termination method 'close' not called
01-17 20:36:32.149 4512 4549 E StrictMode: at
dalvik.system.CloseGuard.open(CloseGuard.java:180)
01-17 20:36:32.149 4512 4549 E StrictMode: at
java.io.FileOutputStream.(FileOutputStream.java:89)
01-17 20:36:32.149 4512 4549 E StrictMode: at
java.io.FileOutputStream.(FileOutputStream.java:72)
01-17 20:36:32.149 4512 4549 E StrictMode: at okio.Okio.sink(Okio.java:176)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.internal.io.FileSystem$1.sink(FileSystem.java:49)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.internal.DiskLruCache$Editor.newSink(DiskLruCache.java:863)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.Cache$CacheRequestImpl.(Cache.java:437)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.Cache.put(Cache.java:250)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.Cache.access$000(Cache.java:136)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.Cache$1.put(Cache.java:148)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.internal.http.HttpEngine.maybeCache(HttpEngine.java:389)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.internal.http.HttpEngine.readResponse(HttpEngine.java:633)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.RealCall.getResponse(RealCall.java:241)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.RealCall$ApplicationInterceptorChain.proceed(RealCall.java:198)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:160)
01-17 20:36:32.149 4512 4549 E StrictMode: at
okhttp3.RealCall.execute(RealCall.java:57)
01-17 20:36:32.149 4512 4549 E StrictMode: at
uk.co.snodnipper.okhttp.issue1903.DownloaderImpl.getData(DownloaderImpl.java:116)
01-17 20:36:32.149 4512 4549 E StrictMode: at
uk.co.snodnipper.okhttp.issue1903.MapboxLayer.getTile(MapboxLayer.java:117)
01-17 20:36:32.149 4512 4549 E StrictMode: at
com.esri.android.map.TiledServiceLayer$1.run(SourceFile:412)
01-17 20:36:32.149 4512 4549 E StrictMode: at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:423)
01-17 20:36:32.149 4512 4549 E StrictMode: at
java.util.concurrent.FutureTask.run(FutureTask.java:237)
01-17 20:36:32.149 4512 4549 E StrictMode: at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
01-17 20:36:32.149 4512 4549 E StrictMode: at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
01-17 20:36:32.149 4512 4549 E StrictMode: at
java.lang.Thread.run(Thread.java:818)

I'll check out your okhttp-racing-leak project in a moment.

—
Reply to this email directly or view it on GitHub
https://github.com/square/okhttp/issues/1902#issuecomment-172379525.

JakeWharton picture JakeWharton on 17 Jan 2016

great @dave-r12 - your demo seems to reproduce the original issue. I received the following:

01-17 21:13:55.337  7562 15625 E MainActivity: IOException, can't close: java.io.InterruptedIOException
01-17 21:13:56.117  7562 16155 E MainActivity: Failed HTTP Request
01-17 21:13:56.734  7562 15643 E MainActivity: IOException, can't close: java.io.InterruptedIOException
01-17 21:13:57.874  7562 16155 E MainActivity: Failed HTTP Request
01-17 21:13:59.325  7562 16155 E MainActivity: Failed HTTP Request
01-17 21:14:00.106  7562 16155 E MainActivity: Failed HTTP Request
01-17 21:14:04.621  7562  7570 E StrictMode: A resource was acquired at attached stack trace but never released. See java.io.Closeable for information on avoiding resource leaks.
01-17 21:14:04.621  7562  7570 E StrictMode: java.lang.Throwable: Explicit termination method 'close' not called
01-17 21:14:04.621  7562  7570 E StrictMode:    at dalvik.system.CloseGuard.open(CloseGuard.java:180)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.android.org.conscrypt.OpenSSLSocketImpl.startHandshake(OpenSSLSocketImpl.java:288)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.Connection.connectTls(Connection.java:235)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.Connection.connectSocket(Connection.java:199)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.Connection.connect(Connection.java:172)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.Connection.connectAndSetOwner(Connection.java:367)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.OkHttpClient$1.connectAndSetOwner(OkHttpClient.java:128)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.internal.http.HttpEngine.connect(HttpEngine.java:328)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:245)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.Call.getResponse(Call.java:267)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.Call$ApplicationInterceptorChain.proceed(Call.java:224)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.Call.getResponseWithInterceptorChain(Call.java:195)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.squareup.okhttp.Call.execute(Call.java:79)
01-17 21:14:04.621  7562  7570 E StrictMode:    at com.example.droberge.racingleak.MainActivity$3.run(MainActivity.java:88)
01-17 21:14:06.093  7562 15669 E MainActivity: IOException, can't close: java.io.InterruptedIOException
01-17 21:14:06.367  7562 15686 E MainActivity: IOException, can't close: java.io.InterruptedIOException

Given that you said "[t]he leaks I mentioned have already been identified and fixed" does this mean this issue can be closed?

@JakeWharton - I will have a go at simplifying the Map demo code, which is essentially a quick 'n dirty adapter for the closed source ESRI SDK (executing my OkHttp code with ThreadPoolExecutor / Futures that are cancelled when out of screen).

snodnipper picture snodnipper on 17 Jan 2016

I believe Okhttp doesn't handle very well with Interrupted.

I think you should remove

resp.body() != null

checks

iNoles picture iNoles on 18 Jan 2016

@snodnipper from my perspective, the takeaways are:

  • Double check the application isn't accidentally leaking a connection
  • Try to migrate away from using Thread.interrupt() and instead use Call.cancel()

Given Jesse's comment above, I'm reluctant to research this one further. It feels like mixing Thread.interrupt() with OkHttp is asking for trouble. It's a bit unfortunate that the map library forced your hand, but maybe they provide some hooks to implement your own strategy?

dave-r12 picture dave-r12 on 18 Jan 2016

Thanks folks. I can raise another issue if the map code still generates an exception under intended use.

  1. regarding thread interrupts (InterruptedException), I guess that could be dealt with as a feature request.

Essentially, it is probably fair to say that many will be using ExecutorService and Futures. Folk may use future.cancel(boolean mayInterruptIfRunning), which could deep down be executing an OkHttp call and throw an InterruptedException.

Clearly corrupting the cache is undesirable (https://github.com/square/okhttp/issues/1903) _but_ better support for InterruptedException might help with clean-up / possible StrictMode violations.

  1. Perhaps we could create some documentation to say that ‘Future.cancel(true)’ is not supported and provide a recommended pattern - even if that is Future.cancel(false) and PR welcome for the moment.
snodnipper picture snodnipper on 18 Jan 2016
❤1

Is this planned to get implemented? We have to disable strict mode in our app due to this bug?

h0jeZvgoxFepBQ2C picture h0jeZvgoxFepBQ2C on 9 May 2018

Don't use Thread.interrupt() ?

swankjesse picture swankjesse on 9 May 2018

@swankjesse Interruption is the standard way to interrupt long-running tasks in Java. In our WebDriver tests (WD recently switched to OkHttp), we had to switch back to ApacheHttp for this very reason. It's unfeasible to somehow pierce through multiple layers to get to the Call.

dagguh picture dagguh on 21 May 2018

@dagguh yeah, but Thread.interrupt() assumes one thread per in-flight HTTP request. This isn’t strictly the case, especially with HTTP/2.

swankjesse picture swankjesse on 24 May 2018

Thread.interrupt() does not assume anything about HTTP. It's just a hint that the caller wants to abort the task being done by the thread. The task itself defines how it interprets interruption. Some ignore it, some gracefully and quickly abort.
In the case of OkHttp, it would be great to handle interruption at least when using HTTP/1.1. And the case of HTTP/2, in the future we could abort all multiplexed connections managed by the thread.

dagguh picture dagguh on 26 May 2018

Interrupting a thread in the middle of a blocking I/O call is likely to leave things in an inconsistent state, particularly when considering the variety of platforms (Android, JVM) and socket types (TCP, JVM SSL, native SSL). So I don't think it's safe to assume that we can handle client interrupts predictably in this way.

I think you have a valid point about HTTP/1.1, it should be handled relatively cleanly if interruptions do occur. Probably the same for HTTP/2, all streams using the same connection are eventually errored, but the client left in a decent state.

yschimke picture yschimke on 26 May 2018

It's also problematic if thread interruption works differently for HTTP/1 and HTTP/2; we've worked hard to encapsulate those differences.

swankjesse picture swankjesse on 26 May 2018
👍2

In a related discussion from Apache folks, it's concluded that:

The notion of a current thread and what exactly an interrupted flag represents in a managed environment is simply semantically unclear. Low level component of a generic transport library ought not make any assumptions about thread management.

dagguh picture dagguh on 3 Dec 2019

Closing, any framework usage of OkHttp should hook into clean cancel calls, and connection pool etc.

yschimke picture yschimke on 29 Mar 2020

I think as has been pointed out, ExcutorService uses thread interrupts to encourage threads to stop what they are doing. ExecutorService is pretty core to Java. It would be unclean to not support thread interrupts, and it would be wrong to run into errors because of thread interrupts.

I think, perhaps unfortunately, you have to deal with interrupts because it is such a core part of the language. Ideally waits/reads/writes would all stop when interrupted (perhaps similar to a read/write timeout, could you just treat them the same?). If not that ideal solution then at the very least you pretty much have to not run into errors when threads are interrupted as that is core to any logic being executed in java.

Finally I will mention that many devs would probably be super happy if okhttp supported interrupts, the ability to ask a thread to stop without needing to restart the JVM is a very nice very useful property.

@yschimke updated since you re-opened for discussion.

LukeButters picture LukeButters on 30 Mar 2020
👍3

For discussion. Will close if we decide not to support.

yschimke picture yschimke on 30 Mar 2020

In a related discussion from Apache folks, it's concluded that:

The notion of a current thread and what exactly an interrupted flag represents in a managed environment is simply semantically unclear. Low level component of a generic transport library ought not make any assumptions about thread management.

OTOH the caller's thread is clearly defined. If the lib does multithreading underneath, it could still respect the interruptability of the caller thread and propagate it further down the layers.

dagguh picture dagguh on 30 Mar 2020

ought not make any assumptions about thread management.

indeed, it can not be assumed that interrupt wont be called.

LukeButters picture LukeButters on 31 Mar 2020

Keep your chin up, this can be done :)

I think that any existing IO/concurrency/locking call are all things that can already fail (e.g. lock timed out, some IO error). I think also the network failures is stuff you already have to deal with.

Interrupts really give you an opportunity to see what happens when those fail, it is easy to cause a thread to be interrupted making it easier to see what happens when an exception is thrown at some location or silent failure happens (sigh java).

Since interrupts are easy to cause it should be easy to test which results in making it easier to move toward better support of interrupts.

I don't think the final two sentences are useful in this situation, that isn't the case. I suspect it would be closer to:
Patient: "I get sick when a virus infects me."
Doctor: "Just don't get a virus."
Narrator: Unfortunately patient lives in the JVM and so can not avoid being infected by a thread interrupt.

LukeButters picture LukeButters on 1 Apr 2020

As far as I know the only code that isn't interrupt-friendly is the response cache.

swankjesse picture swankjesse on 1 Apr 2020
👍2

It might make sense to improve okhttp with interrupts bit by bit rather than try to make it all work in a single PR.

LukeButters picture LukeButters on 1 Apr 2020

Deleting my objections then.

yschimke picture yschimke on 1 Apr 2020

Assuming someone submits a PR, which components need to remain?

  • working after resume
  • non-corrupted

out of:

  • Client
  • ConnectionPool
  • Dispatcher
  • Connection (H1.1/H2)
  • Active Stream
  • Streams on same connection
  • Response
  • Cache
  • TaskRunner.INSTANCE

FWIW this still surprises me because of an expectation that we need to be aware of things like InterruptedIOException.bytesTransferred, if we want something like a Connection to allow a consumer of a single stream to be interrupted and recover.

yschimke picture yschimke on 1 Apr 2020
👍1

My preference is that interrupting an OkHttp call is as similar as possible to canceling the call. The call itself is over, but it shouldn’t leak resources or leave shared features like the connection pool or cache in an inconsistent state.

We don’t do anything about InterruptedIOException.bytesTransferred. It might be possible to integrate that in Okio so the Buffer has the right state after an interrupted operation.

swankjesse picture swankjesse on 1 Apr 2020
❤1 👍1

Basic behaviour confirmed in test https://github.com/square/okhttp/pull/5937

We should add further tests in response to specific bugs. I don't think we currently cover all cases.

yschimke picture yschimke on 11 Apr 2020
❤1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

rfc2822 picture rfc2822  Â·  3Comments
maoai-xianyu picture maoai-xianyu  Â·  3Comments
yschimke picture yschimke  Â·  3Comments
TheLester picture TheLester  Â·  3Comments
lyf571321556 picture lyf571321556  Â·  3Comments