762064 - java.lang.Throwable: Explicit termination method 'end' not called @ SuggestClient.query(SuggestClient.java:78)

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Aaron Train [:aaronmt]]

E/StrictMode( 1853): A resource was acquired at attached stack trace but never released. See java.io.Closeable for information on avoiding resource leaks.
E/StrictMode( 1853): java.lang.Throwable: Explicit termination method 'end' not called
E/StrictMode( 1853): 	at dalvik.system.CloseGuard.open(CloseGuard.java:184)
E/StrictMode( 1853): 	at java.util.zip.Inflater.<init>(Inflater.java:82)
E/StrictMode( 1853): 	at java.util.zip.GZIPInputStream.<init>(GZIPInputStream.java:96)
E/StrictMode( 1853): 	at java.util.zip.GZIPInputStream.<init>(GZIPInputStream.java:81)
E/StrictMode( 1853): 	at libcore.net.http.HttpEngine.initContentStream(HttpEngine.java:515)
E/StrictMode( 1853): 	at libcore.net.http.HttpEngine.readResponse(HttpEngine.java:808)
E/StrictMode( 1853): 	at libcore.net.http.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:274)
E/StrictMode( 1853): 	at libcore.net.http.HttpURLConnectionImpl.getInputStream(HttpURLConnectionImpl.java:168)
E/StrictMode( 1853): 	at libcore.net.http.HttpsURLConnectionImpl.getInputStream(HttpsURLConnectionImpl.java:270)
E/StrictMode( 1853): 	at org.mozilla.gecko.SuggestClient.query(SuggestClient.java:78)
E/StrictMode( 1853): 	at org.mozilla.gecko.AwesomeBar$4$1.doInBackground(AwesomeBar.java:193)
E/StrictMode( 1853): 	at org.mozilla.gecko.AwesomeBar$4$1.doInBackground(AwesomeBar.java:191)
E/StrictMode( 1853): 	at android.os.AsyncTask$2.call(AsyncTask.java:264)
E/StrictMode( 1853): 	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:305)
E/StrictMode( 1853): 	at java.util.concurrent.FutureTask.run(FutureTask.java:137)
E/StrictMode( 1853): 	at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:208)
E/StrictMode( 1853): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1076)
E/StrictMode( 1853): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:569)
E/StrictMode( 1853): 	at java.lang.Thread.run(Thread.java:856)

--
Tested via
Asus Transformer Prime TF201
20120606065339
http://hg.mozilla.org/integration/mozilla-inbound/rev/7d817c805af5

Comment 1

[Brian Nicholson (:bnicholson)]

Attachment: patch

From Inflater.java:

    public Inflater(boolean noHeader) {
        streamHandle = createStream(noHeader);
        guard.open("end");
    }

It looks like this is getting cancelled between createStream() and the following end call (since SuggestClient.query() is running inside of an AsyncTask, which can be interrupted at any time). If we synchronize the calls to getInputStream() and cancel(), this should prevent the task from getting interrupted here.

Another small bug I noticed looking at this: the HttpURLConnection is created outside of the try/finally block:

    HttpURLConnection urlConnection = (HttpURLConnection) url.openConnection();
    try { 
        ...
    } finally {
        urlConnection.disconnect();
    }

If the AsyncTask gets cancelled immediately after the URL connection is created and before entering the try/finally block, the connection will not be disconnected. I moved this to the inside of the try block.

Comment 2

[Brian Nicholson (:bnicholson)]

Attachment: patch v2

Actually, the 'guard.open("end");' has nothing to do with closing the stream and is simply responsible for reporting that end() hasn't been explicitly called; I suppose this means the native call to 'streamHandle = createStream(noHeader);' is getting interrupted.

Also, the previous patch isn't a robust solution since mSuggestClient could change between creating the AsyncTask and the call to cancel(). Maybe we should just ignore this; the task will rarely be interrupted at this exact place, and when it is, it should still generally be cleaned up in Inflater's finalize().

Aaron, are you able to reproduce this? Have you seen this more than once?

Comment 3

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 632037 [details] [diff] [review]
patch v2

>             } finally {
>                 urlConnection.disconnect();
>             }

I think we need to test for a null connection here.

>+                if (urlConnection != null)
>                   urlConnection.disconnect();

Comment 4

[Brian Nicholson (:bnicholson)]

(In reply to Mark Finkle (:mfinkle) from comment #3)
> 
> I think we need to test for a null connection here.

Thanks...had that in the first patch, but apparently I was a bit too careless with qcrefresh.

Comment 5

[Brian Nicholson (:bnicholson)]

Attachment: Close InputStream in SuggestClient

I can reproduce this easily on Galaxy Nexus by quickly typing on the keyboard. Closing the InputStream seems to fix the error, though I don't know why it's necessary. The example at [1] doesn't mention closing the InputStream, and it's used in several places [2][3] that don't call close().

[1] http://developer.android.com/reference/java/net/HttpURLConnection.html
[2] http://grepcode.com/file/repository.grepcode.com/java/ext/com.google.android/android/4.0.1_r1/android/net/wifi/WifiWatchdogStateMachine.java#349
[3] http://grepcode.com/file/repository.grepcode.com/java/ext/com.google.android/android-apps/4.0.3_r1/com/example/android/samplesync/client/NetworkUtilities.java#237

Comment 6

[Brad Lassey [:blassey] (use needinfo?)]

Comment on attachment 633332 [details] [diff] [review]
Close InputStream in SuggestClient

Review of attachment 633332 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/SuggestClient.java
@@ -78,5 @@
> -                InputStream in = new BufferedInputStream(urlConnection.getInputStream());
> -                json = convertStreamToString(in);
> -            } finally {
> -                urlConnection.disconnect();
> -            }

why not keep this try-finally here?

Comment 7

[Brad Lassey [:blassey] (use needinfo?)]

Comment on attachment 633332 [details] [diff] [review]
Close InputStream in SuggestClient

Review of attachment 633332 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/SuggestClient.java
@@ -78,5 @@
> -                InputStream in = new BufferedInputStream(urlConnection.getInputStream());
> -                json = convertStreamToString(in);
> -            } finally {
> -                urlConnection.disconnect();
> -            }

looks like neither the HttpURLConnection nor the input stream are needed beyond this point

Comment 8

[Brian Nicholson (:bnicholson)]

(In reply to Brad Lassey [:blassey] from comment #6)
> Comment on attachment 633332 [details] [diff] [review]
> Close InputStream in SuggestClient
> 
> Review of attachment 633332 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: mobile/android/base/SuggestClient.java
> @@ -78,5 @@
> > -                InputStream in = new BufferedInputStream(urlConnection.getInputStream());
> > -                json = convertStreamToString(in);
> > -            } finally {
> > -                urlConnection.disconnect();
> > -            }
> 
> why not keep this try-finally here?

It's already in a try block, and there's no point in recovering if an error is caught there (since the JSON will just be null), so I figured it would be cleaner to merge them rather than have nested trys.

Comment 9

[Brian Nicholson (:bnicholson)]

Attachment: Close InputStream in SuggestClient, v2

keep try/finally block

Comment 10

[Brian Nicholson (:bnicholson)]

http://hg.mozilla.org/integration/mozilla-inbound/rev/3b3c745e9bca

Comment 11

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/3b3c745e9bca

Comment 12

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/f3c2734016bd
https://hg.mozilla.org/mozilla-central/rev/03cd608177cc
https://hg.mozilla.org/mozilla-central/rev/dfced0e2fdaf
https://hg.mozilla.org/mozilla-central/rev/81cf04b16eb1

Comment 13

[Matt Brubeck (:mbrubeck)]

(In reply to Ed Morley [:edmorley] from comment #12)
> https://hg.mozilla.org/mozilla-central/rev/f3c2734016bd
> https://hg.mozilla.org/mozilla-central/rev/03cd608177cc
> https://hg.mozilla.org/mozilla-central/rev/dfced0e2fdaf
> https://hg.mozilla.org/mozilla-central/rev/81cf04b16eb1

These were mis-labeled and are actually from bug 754335.