Node-solid-server: File descriptors are being left open

[justinwb]

Over the course of several days on a production server, we observed a steady increase in the number of open file descriptors associated with the node-solid-server process, until it reached the per-process limit, at which point node-solid-server stopped accepting new requests and needed to be restarted.

A few key points to note:

The vast majority of open descriptors are of type REG (regular file), with 93% of those being the profile card file. For example:

node    20481 root  305r      REG              259,1     2406   267569 /var/solid/justin.inrupt.net/profile/card

It's important to note that they were not all profile/card. For example, there are also instances of others, such as:

• settings/prefs.ttl
• RandomChat/index.ttl
• public/friends/person/uuid/index.ttl
• profile/photograph.png
• favicon.ico
• public/Dokieli/index.html
• pubilc/test.txt

So while MOST of them were rdf files, not all of them were.

Descriptors associated with a given resource are not re-used when that resource is requested again.
For example, there were 26 open descriptors for /var/solid/justin.inrupt.net/profile/card.

[timbl]

Can you compare with the proportion of all requests which are for a profile card? Was that in fact just the distribution of requests?
If you look at the length of the log, what proportion of requests end up leaving a FD open?

[konobi]

@kjetilk mentioned this issue to me and I'd like to help out on the node debugging, tracing, analysis side. I'm rather new to solid but if you have a test scenario/replication available for this issue, I can get rolling pretty quickly.

[justinwb]

@konobi great thanks for jumping on this! the good news is that from what we've seen, this happens consistently, and so it's really just a matter of narrowing down the spot in the code where the resource is getting opened and not closed cleanly.

I think the right way to track this down is to start with a server that has no other activity aside from your own, then get a node debugging session going and step through different request workflows in solid-ui, using lsof to list and count the files that are being opened and closed, to isolate cases where descriptors are abandoned in the open state.

Based on the volume of growth that we're seeing on the production servers, this is happening on a 1:1 basis with every request, so our guess is that this happens on less common workflows. For example, if every GET on the profile/card was not releasing the resource this would be a much more apparent problem. It may be that this is only happening on updates, or only by certain panes in solid-ui (like the editor pane).

That's the high-level view. Let me know if that's enough to get going or if you need more detail. Happy to dive in and provide more if needed!

[konobi]

I've been able to replicate the file descriptor leak pretty easily, just refresh the page on "https:///profile/card#me" and you'll get an additional fd after each request. Am attempting to go through the debugger stepwise, but Promises really make that an exercise.

I had hoped to get a coredump from the server by using abort-on-uncaught-exception and reducing the ulimit file count to about 30 or so and forcing it out, but it appears that that exception is actually getting caught somewhere.

[konobi]

Okay... I've traced the culprit down to https://github.com/solid/node-solid-server/blob/master/lib/ldp.js#L438-L466

The leaked file descriptor is coming from the fs.createReadStream usage here. It looks like there may be a cycle here due to the stream object being passed around in one of the "on" event handlers for the same stream object. I'll try getting a fix worked out soon, after some time away from a screen.

[justinwb]

Great progress @konobi. Keep us posted!