777712 - [OS.File] Warn about file descriptors leaks

Status: RESOLVED FIXED

(Toolkit Graveyard :: OS.File, defect)

Description

[David Teller [:Yoric] - still alive but not very active]

With a little native code, we could easily detect that a file descriptor is finalized instead of being closed by the user. We should do this.

Comment 1

[David Teller [:Yoric] - still alive but not very active]

Actually, for bug 777711, we can do this without native code, if we are willing to wait for thread end before receiving the warning.

Comment 2

[David Teller [:Yoric] - still alive but not very active]

So, to do this, we need to do the following changes:
1. osfile_async_worker.js records the name of each file and directory it opens in OpenedFiles/OpenedDirectoryIterators;
2. osfile_async_front.jsm waits for notification of "web-workers-shutdown" and sends a message "System_shutdown" to the worker;
3. osfile_async_worker.js, upon reception of that message, inspects the name of all files still in OpenedFiles/OpenedDirectoryIterators and, if we are in debug mode, prints them.

As these changes are quite reasonable, marking this bug as mentored.

Comment 3

[Yura Zenevich [:yzen] (please use "needinfo")]

I would like to take this bug.

Comment 4

[David Teller [:Yoric] - still alive but not very active]

Have fun :)

Comment 5

[Yura Zenevich [:yzen] (please use "needinfo")]

Hi David, I have a quick question. The communication between front and its worker is done through the promise worker's post method that formats the arguments in a specific way (e.g. fun, args, id). The async worker itself at the moment only handles messages of that format.

So my question is, did you mean "System_shutdown" would be sent as a plain message (although still wrapped into fun or args yet not referring to any OS.File stuff) and be handled differently from the rest of the messages, or should it be sent similarly to the rest of the messages that are currently deserialized and call method/function on OS.File?

Hopefully ^ makes sense :)

Comment 6

[David Teller [:Yoric] - still alive but not very active]

I would just define a method |Agent.System_shutdown| and use the mechanism in place to transmit the message. Does that make sense?

Comment 7

[Yura Zenevich [:yzen] (please use "needinfo")]

Yes totally, Thanks!

Comment 8

[Yura Zenevich [:yzen] (please use "needinfo")]

Another quick question:

Logging in osfile_async_worker depends on whether DEBUG const is set to true. However I also noticed exports.OS.Shared.DEBUG in osfile_shared_allthreads that seems to be common amongst multiple osfile modules similarly to exports.OS.Shared.LOG. 

In order for me to write tests that test the log warnings, it seems like I would need something that I could set within the test itself such as the OS.Shared.DEBUG flag. Would you have any suggestions in regards to determining whether DEBUG mode is on from within the test?

Thanks again.

Comment 9

[David Teller [:Yoric] - still alive but not very active]

Ah, good point. That's bug 828201. Do you want to work on it first?

Comment 10

[Yura Zenevich [:yzen] (please use "needinfo")]

Certainly, I'll assign it to myself.

Comment 11

[Yura Zenevich [:yzen] (please use "needinfo")]

Hi David, I've been playing around with this one yesterday and I had a couple of questions/about this issue.

Main stumble block I found was actually looking up the "name" of the file and directory iterator that are open. As far as I can tell tell name or full path is not available when you get the file.stat (although the directory iterator entry has that field). So what I tried was utilizing the second "info" argument to ResourceTracker.add. I was putting {path: path} block in there, since it was available in places it was used (in Agent.open and Agent.new_DirectoryIterator). This would let me uniformly access opened resources path whenever I wanted to report them with System_shutdown. What do you think?

I wanted your opinion on the component/place where these opened resources are logged. One approach would be to just LOG them from within the worker. But that means it is practically untestable. Another approach could be actually returning the list of opened resources on System_shutdown from the worker and then LOG on promise's success from within the controller. This would actually be testable, since we can replace LOG with Console.services for testing purposes.

Hopefully I make sense :). Let me know what you think.

Comment 12

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Adding warnings about file descriptors leaks.

Hi David, this is what I meant by my previous post.
There's a caveat in the test: I tried randomly commenting out some of the preceding tests that deal with opening files and creating new Directory iterators and I noticed that the returned list of opened resources differs from time to time. So what it means is that there is a chance of seeing false positives when reporting the logged warnings inside the test.

Comment 13

[Yura Zenevich [:yzen] (please use "needinfo")]

Perhaps, just logging in the worker is simpler but it will most likely be impossible to test.

Comment 14

[David Teller [:Yoric] - still alive but not very active]

(In reply to Yura Zenevich [:yzen] from comment #11)
> Hi David, I've been playing around with this one yesterday and I had a
> couple of questions/about this issue.
> 
> Main stumble block I found was actually looking up the "name" of the file
> and directory iterator that are open. As far as I can tell tell name or full
> path is not available when you get the file.stat (although the directory
> iterator entry has that field).

Correct on both accounts.

> So what I tried was utilizing the second
> "info" argument to ResourceTracker.add. I was putting {path: path} block in
> there, since it was available in places it was used (in Agent.open and
> Agent.new_DirectoryIterator). This would let me uniformly access opened
> resources path whenever I wanted to report them with System_shutdown. What
> do you think?

Yes, |info| was added specifically for that purpose.

> I wanted your opinion on the component/place where these opened resources
> are logged. One approach would be to just LOG them from within the worker.
> But that means it is practically untestable. Another approach could be
> actually returning the list of opened resources on System_shutdown from the
> worker and then LOG on promise's success from within the controller. This
> would actually be testable, since we can replace LOG with Console.services
> for testing purposes.

Good idea.

Comment 15

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 708466 [details] [diff] [review]
Adding warnings about file descriptors leaks.

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

::: toolkit/components/osfile/osfile_async_worker.js
@@ +201,5 @@
> +       System_shutdown: function System_shutdown () {
> +         // Combine both opened files and opened DirectoryIterators into a
> +         // single list.
> +         return listOpenedResources(OpenedFiles).concat(
> +           listOpenedResources(OpenedDirectoryIterators));

In a final patch, I would prefer if files and directories were specified separately.

::: toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
@@ +713,5 @@
> +        if (aMessage.message.indexOf("TEST OS Controller WARNING") < 0) {
> +          return;
> +        }
> +        test.ok(aMessage.message.indexOf("WARNING: File descriptors leaks " +
> +          "detected. The following resources are still open:") >= 0,

Could you check that |EXISTING_FILE| appears in that message?

@@ +727,5 @@
> +    yield iterator.close();
> +
> +    let openedFile = yield OS.File.open(EXISTING_FILE);
> +    toggleDebugTest(true);
> +    Services.obs.notifyObservers(null, "web-workers-shutdown", null);

This might break some stuff. Could you rather add an event (say "test.osfile.web-workers-shutdown") just for the purpose of this test?

Comment 16

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Updated Patch with addressed latest comments.

Comment 17

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 714758 [details] [diff] [review]
Updated Patch with addressed latest comments.

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

Many small things to change, but I like it.

::: toolkit/components/osfile/osfile_async_front.jsm
@@ +138,5 @@
> +  if (opened.length > 0) {
> +    msg += "The following " + type + " are still opened:\n" + opened.join("\n");
> +  }
> +  return msg;
> +};

That sounds a little overcomplicated.
I think you should get rid of |stringifyOpenedResources| and just inline this.

@@ +158,5 @@
> +  });
> +};
> +
> +// Attaching an observer listening to the "web-workers-shutdown".
> +Services.obs.addObserver(OS.Shared.webWorkersShutdownObserver, "web-workers-shutdown", false);

I believe that you should attach this observer to the "test.osfile.web-workers-shutdown", regardless of whether we are currently executing tests. In exchange, keep this observer private.

::: toolkit/components/osfile/osfile_async_worker.js
@@ +122,5 @@
> +      * i.e. the ones still present in its _map.
> +      */
> +     let listOpenedResources = function listOpenedResources(aResourceTracker) {
> +       return [resource.info.path for ([id, resource] of aResourceTracker._map)];
> +     };

Let's make this a method of |ResourceTracker| instead.

@@ +239,5 @@
>         remove: function remove(path) {
>           return File.remove(Type.path.fromMsg(path));
>         },
>         open: function open(path, mode, options) {
> +         path = Type.path.fromMsg(path);

This makes two distinct definitions of |path| with distinct types. Let's give them distinct names.

::: toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
@@ +716,5 @@
> +          }
> +          test.ok(aMessage.message.indexOf("WARNING: File descriptors leaks " +
> +            "detected.") >= 0, "File descriptors leaks are logged correctly.");
> +          test.ok(aMessage.message.indexOf(resource) >= 0,
> +            "Correctly resource is listed in the log.");

"Leaked resource is correctly listed in the log".

@@ +723,5 @@
> +      };
> +      return consoleListener;
> +    }
> +    // Set/Unset testing flags and Services.console listener.
> +    function toggleDebugTest(pref, resource, consoleListener) {

I wouldn't call this arg |pref|.

Comment 18

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Latest patch addressign comments.

Results from the try submission can be found here:

https://tbpl.mozilla.org/?tree=Try&rev=cf330c2a77ab

Comment 19

[Mozilla RelEng Bot]

Try run for cf330c2a77ab is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=cf330c2a77ab
Results (out of 149 total builds):
    exception: 4
    success: 136
    warnings: 9
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-cf330c2a77ab

Comment 20

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 715328 [details] [diff] [review]
Latest patch addressign comments.

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

Looks good to me. Just one trivial nit before landing - no need for another review as far as I'm concerned.

::: toolkit/components/osfile/osfile_async_worker.js
@@ +264,5 @@
>         new_DirectoryIterator: function new_DirectoryIterator(path, options) {
> +         let directoryPath = Type.path.fromMsg(path);
> +         let iterator = new File.DirectoryIterator(directoryPath, options);
> +         return OpenedDirectoryIterators.add(iterator, {
> +           path: directoryPath

Trivial nit: could you please add a comment explaining why we store the path?

Comment 21

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Added missing comment.

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/eac4470ca9f2

Comment 23

[Ryan VanderMeulen [:RyanVM]]

Backed out for xpcshell test failures.
https://hg.mozilla.org/integration/mozilla-inbound/rev/90809831b9f4

https://tbpl.mozilla.org/php/getParsedLog.php?id=19879328&tree=Mozilla-Inbound

TEST-INFO | /builds/slave/talos-slave/test/build/xpcshell/tests/toolkit/modules/tests/xpcshell/test_sqlite.js | running test ...
TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/xpcshell/tests/toolkit/modules/tests/xpcshell/test_sqlite.js | test failed (with xpcshell return code: 3), see following log:
>>>>>>>
resource://gre/modules/osfile/osfile_async_front.jsm:151: ReferenceError: Services is not defined

And a bunch more like it.

Comment 24

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Fixed an issue with Services import.

Here's a try build: https://tbpl.mozilla.org/?tree=Try&rev=cdc7020ff194

Comment 25

[David Teller [:Yoric] - still alive but not very active]

Comment on attachment 715561 [details] [diff] [review]
Fixed an issue with Services import.

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

r=me if tests pass
I'm curious, what happened? Did you run different tests?

Comment 26

[Yura Zenevich [:yzen] (please use "needinfo")]

So services was only loaded conditionally in the osfile_async_front.jsm. And the osfile tests pass when ran directly (profileDir was not there in time). But it looks like for that failing test osfile.jsm is imported when the profile is setup already and thus Services where not imported. With the addition of the observers we now always need to import them.

Comment 27

[Yura Zenevich [:yzen] (please use "needinfo")]

Verified with gbrown that the new try build looks good (re bug 769524).

Comment 28

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/cb220ef54f3d

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/cb220ef54f3d