[OS.File] Warn about file descriptors leaks

RESOLVED FIXED in mozilla22

Status

()

Toolkit
OS.File
RESOLVED FIXED
6 years ago
5 years ago

People

(Reporter: Yoric, Assigned: yzen)

Tracking

unspecified
mozilla22
Points:
---
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [mentor=Yoric][lang=js])

Attachments

(1 attachment, 4 obsolete attachments)

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.
Actually, for bug 777711, we can do this without native code, if we are willing to wait for thread end before receiving the warning.
OS: Mac OS X → All
Hardware: x86 → All
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.
Whiteboard: [mentor=Yoric][lang=js]
(Assignee)

Comment 3

5 years ago
I would like to take this bug.
(Assignee)

Updated

5 years ago
Assignee: nobody → yura.zenevich
Have fun :)
(Assignee)

Comment 5

5 years ago
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 :)
Flags: needinfo?(dteller)
I would just define a method |Agent.System_shutdown| and use the mechanism in place to transmit the message. Does that make sense?
Flags: needinfo?(dteller)
(Assignee)

Comment 7

5 years ago
Yes totally, Thanks!
(Assignee)

Comment 8

5 years ago
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.
Ah, good point. That's bug 828201. Do you want to work on it first?
(Assignee)

Comment 10

5 years ago
Certainly, I'll assign it to myself.
(Assignee)

Updated

5 years ago
Depends on: 828201
(Assignee)

Comment 11

5 years ago
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.
(Assignee)

Comment 12

5 years ago
Created attachment 708466 [details] [diff] [review]
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.
Attachment #708466 - Flags: feedback?(dteller)
(Assignee)

Comment 13

5 years ago
Perhaps, just logging in the worker is simpler but it will most likely be impossible to test.
(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 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?
Attachment #708466 - Flags: feedback?(dteller) → feedback+
(Assignee)

Comment 16

5 years ago
Created attachment 714758 [details] [diff] [review]
Updated Patch with addressed latest comments.
Attachment #708466 - Attachment is obsolete: true
Attachment #714758 - Flags: feedback?(dteller)
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|.
Attachment #714758 - Flags: feedback?(dteller) → feedback+
(Assignee)

Comment 18

5 years ago
Created attachment 715328 [details] [diff] [review]
Latest patch addressign comments.

Results from the try submission can be found here:

https://tbpl.mozilla.org/?tree=Try&rev=cf330c2a77ab
Attachment #714758 - Attachment is obsolete: true
Attachment #715328 - Flags: review?(dteller)

Comment 19

5 years ago
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/yura.zenevich@gmail.com-cf330c2a77ab
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?
Attachment #715328 - Flags: review?(dteller) → review+
(Assignee)

Comment 21

5 years ago
Created attachment 715513 [details] [diff] [review]
Added missing comment.
Attachment #715328 - Attachment is obsolete: true
(Assignee)

Updated

5 years ago
Keywords: checkin-needed
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.
(Assignee)

Comment 24

5 years ago
Created attachment 715561 [details] [diff] [review]
Fixed an issue with Services import.

Here's a try build: https://tbpl.mozilla.org/?tree=Try&rev=cdc7020ff194
Attachment #715513 - Attachment is obsolete: true
Attachment #715561 - Flags: review?(dteller)
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?
Attachment #715561 - Flags: review?(dteller) → review+
(Assignee)

Comment 26

5 years ago
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.
(Assignee)

Comment 27

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

Updated

5 years ago
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/cb220ef54f3d
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla22
You need to log in before you can comment on or make changes to this bug.