1019009 - Detect unclosed Cursors in SQLiteBridge/MatrixBlobCursor

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Data Providers, enhancement)

Description

[Gian-Carlo Pascutto [:gcp]]

As a follow-up to bug 1018089, it would be good to extend the SQLiteBridge class and the Cursors class it uses (MatrixBlobCursor) to automatically detect unclosed Cursors, just like the built-in Android SQLiteCursor class does.

I believe this is possible by adding a boolean to the MatrixBlobCursor class that remembers if "close()" has been called, and then detecting in finalize() (called when the Cursor gets forcibly garbage-collected) whether the close method has in fact been called before. If it was never called, then we issue a warning with a stacktrace.

Background on detecting this in finalize;
http://stackoverflow.com/questions/158174/why-would-you-ever-implement-finalize

Background on why we'd want this:
Because SQLiteBridge *currently* doesn't keep the underlying SQLite query handle, leaking them isn't a big deal yet. But I can imagine we might improve SQLiteBridge at some point and this becomes an issue in the future. On top of that, AbstractCursor, on which MatrixBlobCursor is built, at least seems to deregisters/notify content observers on close: https://github.com/android/platform_frameworks_base/blob/master/core/java/android/database/AbstractCursor.java#L145

Comment 1

[Gian-Carlo Pascutto [:gcp]]

Note that adding "finalize" to a class does come with overhead, so we probably only want to do this in debug builds.

Comment 2

[Epransky]

Attachment: Bug-1019009.patch

Did what we discussed over IRC.  I couldn't figure out how to add this only for debug builds as you suggested, but I'm submitting the patch anyways. If you can assist me on how to do this last part, let me know. Otherwise, let me know if my patch is ok besides this.  Thanks!

Comment 3

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8442299 [details] [diff] [review]
Bug-1019009.patch

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

::: mobile/android/base/sqlite/MatrixBlobCursor.java
@@ +329,5 @@
> +
> +    @Override
> +    protected void finalize() {
> +        super.finalize();
> +        Log.e(LOGTAG, "Cursor finalized without closing the database");

This unconditionally prints a warning whenever the class is garbage collected, so you'll get the warning whether the Cursor is closed or not.

Comment 4

[Gian-Carlo Pascutto [:gcp]]

As for detecting you're in a debug build and printing the warning only in that case, see: http://stackoverflow.com/questions/1743683/distinguishing-development-mode-and-release-mode-environment-settings-on-android

Comment 5

[Epransky]

Attachment: Bug-1019009.patch

Right on. I think this works better.  Is this all I need to check for debug builds then? It looks like this is all we need to do based on the more current answer.

Comment 6

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8443313 [details] [diff] [review]
Bug-1019009.patch

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

::: mobile/android/base/sqlite/MatrixBlobCursor.java
@@ +16,5 @@
>   */
>  
>  package org.mozilla.gecko.sqlite;
>  
> +import org.mozilla.fennec_User.BuildConfig;

The package named is determined at build time, and can be org.mozilla.firefox, firefox_beta, fennec or fennec_name_of_the_user_building. So this won't work. The direct workaround would be to change this file to a preprocessed file (.in) and use @ANDROID_PACKAGE_NAME@. That said, I think this BuildConfig is generated by some Android build tools that don't actually run (yet) for a Firefox for Android build, so the whole approach doesn't work.

See comments below for a simpler solution.

@@ +329,5 @@
>      }
> +
> +    @Override
> +    protected void finalize() {
> +        if (BuildConfig.DEBUG) {

So I'm afraid that turns out to only be available if certain Android build tools run that we don't seem to be using in Firefox. Oops. The other solution here would've worked: http://stackoverflow.com/questions/1743683/distinguishing-development-mode-and-release-mode-environment-settings-on-android/3204444#3204444

But I did some more digging and found this, which looks perfect for our use:
http://dxr.mozilla.org/mozilla-central/source/mobile/android/base/AppConstants.java.in#161

@@ +330,5 @@
> +
> +    @Override
> +    protected void finalize() {
> +        if (BuildConfig.DEBUG) {
> +            if (!super.mClosed) {

You only need to use super here if you're hiding the mClosed field. MatrixBlobCursor has no mClosed field of its own, so this isn't needed. In any case, using the getter method (isClosed) is probably better OOP style as it'll work even if the internals of AbstractCursor change.

@@ +331,5 @@
> +    @Override
> +    protected void finalize() {
> +        if (BuildConfig.DEBUG) {
> +            if (!super.mClosed) {
> +                Log.e(LOGTAG, "Cursor finalized without closing the database");

What has the database being open got to do with our Cursor? :-)

Comment 7

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8443313 [details] [diff] [review]
Bug-1019009.patch

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

Should've been r- as there's some more issues to tackle.

Comment 8

[Epransky]

Gotchya.  I thought since this was available in SDK version 17+ that it would be valid.  I'm having a tough time with the other method because I'm not sure how to retrieve an kind of Context in MatrixBlobCursor.  I need a Context to get a PackageManager and check what the PackageName is and if it's debuggable. Is there a way to work around this which I'm missing that isn't super convoluted?

All of your other comments make sense and I'll edit them in a new patch once you can help me with the debuggable check.  I can do the first method you suggested also but it seems a little messier and not ideal... Thanks

Comment 9

[Gian-Carlo Pascutto [:gcp]]

>I'm having a tough time with the other method because I'm not sure how to retrieve an kind of Context in MatrixBlobCursor.

You're right that this is non-obvious. I think here you'd need GeckoAppShell.getContext(). But don't use this method! I was maybe not clear enough in my comment but AppConstants.DEBUG_BUILD already gives us exactly what we want to know in an easy manner, right there in our own source, so we don't need to bother with looking up whether we're a debug build ourselves. I didn't realize we already had that DEBUG_BUILD boolean available when I pointed you to the StackOverflow topic.

Comment 10

[Epransky]

Attachment: Bug-1019009.patch

Yeah, it was late last night and now I understand your previous comment - I didn't look at the dxr link! Let me know if my stack trace warning makes more sense now.  Thanks!

Comment 11

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8443639 [details] [diff] [review]
Bug-1019009.patch

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

Looks good, with two minor edits. 

The description on top of your patch is wrong though: "added a warning to stack trace". Log.e will just put a an error message in the Android log, not a stack trace. The error message is enough for now, knowing there is a problem with a cursor is already an excellent start.

Note that because finalize is called by the Android GC, printing a stack trace wouldn't tell us anything useful about the code that failed to close the cursor anyway. Doing this is quite a bit more complicated and maybe something for a follow-up bug. See for example how Android itself does it: https://github.com/android/platform_frameworks_base/blob/dbc51de44fe4f9a7f81528204250de32ec405d39/core/java/android/database/sqlite/SQLiteCursor.java#L259 which is basically having the Cursor remember a bunch of stuff about the last SQL query made with it etc.

Can you test your patch? Like, find a few places that are using SQLiteBridge/MatrixBlobCursor, remove the close() calls, and see if new warnings appear?

::: mobile/android/base/sqlite/MatrixBlobCursor.java
@@ +39,5 @@
>   * A mutable cursor implementation backed by an array of {@code Object}s. Use
>   * {@link #newRow()} to add rows. Automatically expands internal capacity
>   * as needed.
>   */
> +public class MatrixBlobCursor extends AbstractCursor{

You accidentally deleted a space here, causing this line to show up as changed by this patch even though the change is irrelevant.

@@ +331,5 @@
> +    @Override
> +    protected void finalize() {
> +        if (AppConstants.DEBUG_BUILD) {
> +            if (!isClosed()) {
> +                Log.e(LOGTAG, "Cursor finalized without closing itself and unregistering ContentObservers and ContenResolvers");

Well, the latter is something that AbstractCursor ends up doing, and the Cursor doesn't close itself, that's up to the programmer. So I'd tweak the wording here to just "Cursor finalized without being closed".

Comment 12

[Epransky]

(In reply to Gian-Carlo Pascutto [:gcp] from comment #11)
> Comment on attachment 8443639 [details] [diff] [review]
> Bug-1019009.patch
> 
> Review of attachment 8443639 [details] [diff] [review]:
> -----------------------------------------------------------------

> The description on top of your patch is wrong though: "added a warning to
> stack trace". Log.e will just put a an error message in the Android log, not
> a stack trace. The error message is enough for now, knowing there is a
> problem with a cursor is already an excellent start.

You're right.  I thought the Log was what you meant.  I looked into it and I can change this to actually add a stacktrace if it's better.  Let me know.  For now, I just changed the description of the patch.

> 
> Note that because finalize is called by the Android GC, printing a stack
> trace wouldn't tell us anything useful about the code that failed to close
> the cursor anyway. Doing this is quite a bit more complicated and maybe
> something for a follow-up bug. See for example how Android itself does it:
> https://github.com/android/platform_frameworks_base/blob/
> dbc51de44fe4f9a7f81528204250de32ec405d39/core/java/android/database/sqlite/
> SQLiteCursor.java#L259 which is basically having the Cursor remember a bunch
> of stuff about the last SQL query made with it etc.

It looks like we could print this kind of info as well in our warning.  Should we?
> 
> Can you test your patch? Like, find a few places that are using
> SQLiteBridge/MatrixBlobCursor, remove the close() calls, and see if new
> warnings appear?
> 

I'm still a little unclear about how testing is supposed to go down. I read about Robocop but I still don't quite get what it does and when/if it's relevant.  

Besides that, I couldn't find where MatrixBlobCursor's or AbstractCursor's close() method was called.  Is it actually being closed before garbage collection?  In short, I'm really not sure how to test this properly.

> You accidentally deleted a space here, causing this line to show up as
> changed by this patch even though the change is irrelevant.
> 

See patch

ntObservers and ContenResolvers");
> 
> Well, the latter is something that AbstractCursor ends up doing, and the
> Cursor doesn't close itself, that's up to the programmer. So I'd tweak the
> wording here to just "Cursor finalized without being closed".

See patch

Comment 13

[Epransky]

Attachment: Bug-1019009.patch

See Comment #12

Comment 14

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8444031 [details] [diff] [review]
Bug-1019009.patch

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

LGTM. You probably want your commit message to explain what you actually did rather than how you implemented it, as we can see the implementation in the patch. I'll fix it up when I check in your patch.

Comment 15

[Gian-Carlo Pascutto [:gcp]]

>It looks like we could print this kind of info as well in our warning.  Should we?

Well, that would be very nice, but it looks significantly more complicated as you need to track all those things at the moment the Cursor is created, and hardly suitable for a [good first bug]. That said if you want to give it a shot, go right ahead!

>I'm still a little unclear about how testing is supposed to go down. I read about Robocop but I still don't quite get what it does and when/if it's relevant.  

I didn't mean writing an automated test (which Robocop is), I meant testing your code on your own device and/or emulator, just to see if it's actually doing anything.

>Besides that, I couldn't find where MatrixBlobCursor's or AbstractCursor's close() method was called.  

Most code will probably just be using the base class interface (Cursor) and calling "close()" on that. The first comment in this bug (https://bugzilla.mozilla.org/show_bug.cgi?id=1019009#c0https://bugzilla.mozilla.org/show_bug.cgi?id=1019009#c0) points to another bug where Close was missing on a MatrixBlobCursor, and it's in fact the reason why I made this bug. You basically want to look at whoever is using SQLiteBridge, as that is the one that creates the MatrixBlobCursors.

Comment 16

[Gian-Carlo Pascutto [:gcp]]

Tested it by backing out bug 1018089, and syncing a new Firefox profile to my Firefox Account.

https://hg.mozilla.org/integration/mozilla-inbound/rev/15b3563a6c46

Comment 17

[Epransky]

(In reply to Gian-Carlo Pascutto [:gcp] from comment #15)

> That said if you want to give it
> a shot, go right ahead!

I'll pass on it now in the interest of closing this bug, but I could tackle it in another bug if you think it's worth it...
> 

> I didn't mean writing an automated test (which Robocop is), I meant testing
> your code on your own device and/or emulator, just to see if it's actually
> doing anything.

OK, I see what you did for test in the following comment.

> Most code will probably just be using the base class interface (Cursor) and
> calling "close()" on that. The first comment in this bug
> (https://bugzilla.mozilla.org/show_bug.cgi?id=1019009#c0https://bugzilla.
> mozilla.org/show_bug.cgi?id=1019009#c0) points to another bug where Close
> was missing on a MatrixBlobCursor, and it's in fact the reason why I made
> this bug. You basically want to look at whoever is using SQLiteBridge, as
> that is the one that creates the MatrixBlobCursors.

In bug 1018089, the fix only adds a close() to a simple Cursor object and not a MatrixBlobCursor from what I can see. The only class which uses a MatrixBlobCursor is here: https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/db/PasswordsProvider.java#287 and it doesn't close it (which I guess the GC will do anyways).  Otherwise, other classes which have SQLiteBridge don't even close this object except for https://mxr.mozilla.org/mozilla-central/source/mobile/android/base/db/SQLiteBridgeContentProvider.java and the SQLitBridge class only ever closes the Cursor class.

Can you sort out my confusion here because I think I may not be following the logic correctly? If it's not an issue, let me know because I think I'm getting off on a tangent which isn't directly related to this particular bug. Thanks!

Comment 18

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/15b3563a6c46

Comment 19

[Gian-Carlo Pascutto [:gcp]]

>the fix only adds a close() to a simple Cursor object and not a MatrixBlobCursor from what I can see.

Your OOP fundamentals are a bit rusty :)
http://docs.oracle.com/javase/tutorial/java/IandI/polymorphism.html

The "close()" is a virtual method call (as are all method calls in Java by default).

Comment 20

[Epransky]

(In reply to Gian-Carlo Pascutto [:gcp] from comment #19)

> The "close()" is a virtual method call (as are all method calls in Java by
> default).

Thanks for the tip. I just missed how the internalQuery method actually initializes cursor as MatrixBlobCursor subclass.  Anyways, thanks for the help on this bug!