Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Recover gracefully from Thread.interrupt() #1902

Closed
snodnipper opened this issue Oct 7, 2015 · 36 comments
Closed

Recover gracefully from Thread.interrupt() #1902

snodnipper opened this issue Oct 7, 2015 · 36 comments
Labels
bug Bug in existing code enhancement Feature not a bug
Milestone

Comments

@snodnipper
Copy link
Contributor

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)
@swankjesse swankjesse added the bug Bug in existing code label Oct 31, 2015
@swankjesse swankjesse added this to the 2.6 milestone Oct 31, 2015
@swankjesse
Copy link
Collaborator

Can fix.

@swankjesse swankjesse modified the milestones: 2.7, 2.6 Nov 22, 2015
@swankjesse swankjesse modified the milestones: 3.0, 2.7 Dec 15, 2015
@JakeWharton JakeWharton modified the milestones: 3.0, 3.1 Dec 23, 2015
@swankjesse
Copy link
Collaborator

@dave-r12 this looks tricky. Interested?

@dave-r12
Copy link
Collaborator

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.

@snodnipper
Copy link
Contributor Author

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)

@dave-r12
Copy link
Collaborator

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.

@snodnipper
Copy link
Contributor Author

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.

@dave-r12
Copy link
Collaborator

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

@dave-r12
Copy link
Collaborator

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
Copy link
Collaborator

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?

@swankjesse
Copy link
Collaborator

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.

@snodnipper
Copy link
Contributor Author

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.

@JakeWharton
Copy link
Collaborator

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 notifications@github.com
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
#1902 (comment).

@snodnipper
Copy link
Contributor Author

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).

@iNoles
Copy link
Contributor

iNoles commented Jan 18, 2016

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

I think you should remove

resp.body() != null

checks

@dave-r12
Copy link
Collaborator

@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?

@snodnipper
Copy link
Contributor Author

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 (Cache stops being written to when java.io.InterruptedIOException: thread interrupted #1903) but better support for InterruptedException might help with clean-up / possible StrictMode violations.

  2. 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.

@swankjesse swankjesse modified the milestones: 3.4, 3.3 May 21, 2016
@swankjesse swankjesse changed the title StrictMode - Explicit termination method 'close' not called Recover gracefully from Thread.interrupt() Jul 1, 2016
@swankjesse swankjesse added this to the 3.5 milestone Jul 1, 2016
@dagguh
Copy link

dagguh commented May 21, 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.

@swankjesse
Copy link
Collaborator

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

@dagguh
Copy link

dagguh commented May 26, 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.

@yschimke
Copy link
Collaborator

yschimke commented May 26, 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.

@swankjesse
Copy link
Collaborator

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

@dagguh
Copy link

dagguh commented Dec 3, 2019

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.

@yschimke
Copy link
Collaborator

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

@LukeButters
Copy link

LukeButters commented Mar 29, 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.

@yschimke yschimke reopened this Mar 29, 2020
@yschimke
Copy link
Collaborator

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

@dagguh
Copy link

dagguh commented Mar 30, 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.

@LukeButters
Copy link

LukeButters commented Mar 30, 2020

ought not make any assumptions about thread management.

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

@LukeButters
Copy link

LukeButters commented Mar 31, 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.

@swankjesse
Copy link
Collaborator

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

@LukeButters
Copy link

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

@yschimke
Copy link
Collaborator

yschimke commented Apr 1, 2020

Deleting my objections then.

@yschimke
Copy link
Collaborator

yschimke commented Apr 1, 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.

@swankjesse
Copy link
Collaborator

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.

@yschimke
Copy link
Collaborator

Basic behaviour confirmed in test #5937

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

icbaker pushed a commit to androidx/media that referenced this issue May 9, 2022
Relates to square/okhttp#3146. This was from #71.

There is a draft PR https://github.com/square/okhttp/pull/7185/files which documents OkHttp's ideal handling of cancellation including interrupts.

But a few key points

1) This is a target state, and OkHttp does not currently handle interrupts correctly.  In the past this has been identified, and the advice is to avoid interrupts on Http threads, see discussion on square/okhttp#1902. Also an attempt at a fix here square/okhttp#7023 which wasn't in a form to land.

2) Even with this fixed, it is likely to never be optimal, because of OkHttp sharing a socket connection for multiple inflight requests.

From square/okhttp#7185

```
Thread.interrupt() is Clumsy
----------------------------

`Thread.interrupt()` is Java's built-in mechanism to cancel an in-flight `Thread`, regardless of
what work it's currently performing.

We recommend against using `Thread.interrupt()` with OkHttp because it may disrupt shared resources
including HTTP/2 connections and cache files. In particular, calling `Thread.interrupt()` may cause
unrelated threads' call to fail with an `IOException`.
```

This PR leaves the Loader/DataSource thread parked on a countdown latch, while this may seem wasteful and an additional context switch. However in practice the response isn't returned until the Http2Connection and Http2Reader have a response from the server and these means effectively parking in a `wait()` statement here https://github.com/square/okhttp/blob/9e039e94123defbfd5f11dc64ae146c46b7230eb/okhttp/src/jvmMain/kotlin/okhttp3/internal/http2/Http2Stream.kt#L140

PiperOrigin-RevId: 446652468
icbaker pushed a commit to google/ExoPlayer that referenced this issue May 9, 2022
Relates to square/okhttp#3146. This was from androidx/media#71.

There is a draft PR https://github.com/square/okhttp/pull/7185/files which documents OkHttp's ideal handling of cancellation including interrupts.

But a few key points

1) This is a target state, and OkHttp does not currently handle interrupts correctly.  In the past this has been identified, and the advice is to avoid interrupts on Http threads, see discussion on square/okhttp#1902. Also an attempt at a fix here square/okhttp#7023 which wasn't in a form to land.

2) Even with this fixed, it is likely to never be optimal, because of OkHttp sharing a socket connection for multiple inflight requests.

From square/okhttp#7185

```
Thread.interrupt() is Clumsy
----------------------------

`Thread.interrupt()` is Java's built-in mechanism to cancel an in-flight `Thread`, regardless of
what work it's currently performing.

We recommend against using `Thread.interrupt()` with OkHttp because it may disrupt shared resources
including HTTP/2 connections and cache files. In particular, calling `Thread.interrupt()` may cause
unrelated threads' call to fail with an `IOException`.
```

This PR leaves the Loader/DataSource thread parked on a countdown latch, while this may seem wasteful and an additional context switch. However in practice the response isn't returned until the Http2Connection and Http2Reader have a response from the server and these means effectively parking in a `wait()` statement here https://github.com/square/okhttp/blob/9e039e94123defbfd5f11dc64ae146c46b7230eb/okhttp/src/jvmMain/kotlin/okhttp3/internal/http2/Http2Stream.kt#L140

PiperOrigin-RevId: 446652468
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Bug in existing code enhancement Feature not a bug
Projects
None yet
Development

No branches or pull requests

9 participants