Repository: hapijs/hapi (language: javascript)

Issue:
inert + hapi may be leaking file descriptors
#### Support plan

Free plan

* *is this issue currently blocking your project?* (yes/no):  no (actually, sorta... )
* *is this issue affecting a production system?* (yes/no): yes

#### Context

* *node version*: 12.18.4
* *module version with issue*: inert@6.0.3
* *last module version without issue*: unknown
* *environment* (e.g. node, browser, native): node
* *used with* (e.g. hapi application, another framework, standalone, ...): @hapi/hapi@20.1.3
* *any other relevant information*: There may or may not be a conversation about this on the community slack channel: https://hapihour.slack.com/archives/C6CEEUE06/p1622675671016200

#### What are you trying to achieve or the steps to reproduce?

We are serving static files with Hapi and Inert, and we are using up all the file descriptors on the host system.


We are calling:
```js
      const response = h.file(filename, {
        confine: true,
        etagMethod: false,
      });
```

One day some of our microservices suddenly reported errors that the number of file descriptors on their systems were exhausted.

Some more exploration let me to check the number of file descriptors on the linux systems this was running on `ls /proc/${pid}/fd` and I saw these appeared to be incrementing by one for each file.  I then identified that this also happens on my development machine (a mac) using `lsof -p ${pid}`. From here, I began to debug and `console.log()` may way through inert, and gradually found that the `prepare()` routine in Inert's `file.js` is getting called twice on each request.  But only one of the file descriptors are being closed.  The two calls have these stack traces:

```
    at exports.File.open (/Users/demo/project/node_modules/@hapi/inert/lib/fs.js:35:22)
    at async exports.File.openStat (/Users/demo/project/node_modules/@hapi/inert/lib/fs.js:88:9)
    at async Object.internals.prepare (/Users/demo/project/node_modules/@hapi/inert/lib/file.js:111:22)
    at async exports.Manager.execute (/Users/demo/project/node_modules/@hapi/hapi/lib/toolkit.js:105:28)
    at async Object.internals.handler (/Users/demo/project/node_modules/@hapi/hapi/lib/handler.js:46:20)
    at async exports.execute (/Users/demo/project/node_modules/@hapi/hapi/lib/handler.js:31:20)
    at async Request._lifecycle (/Users/demo/project/node_modules/@hapi/hapi/lib/request.js:372:32)
    at async Request._execute (/Users/demo/project/node_modules/@hapi/hapi/lib/request.js:280:9)
```

```
    at exports.File.open (/Users/demo/project/node_modules/@hapi/inert/lib/fs.js:35:22)
    at async exports.File.openStat (/Users/demo/project/node_modules/@hapi/inert/lib/fs.js:88:9)
    at async Object.internals.prepare (/Users/demo/project/node_modules/@hapi/inert/lib/file.js:111:22)
    at async exports.Manager.execute (/Users/demo/project/node_modules/@hapi/hapi/lib/toolkit.js:105:28)
    at async Request._invoke (/Users/demo/project/node_modules/@hapi/hapi/lib/request.js:399:30)
    at async Request._postCycle (/Users/demo/project/node_modules/@hapi/hapi/lib/request.js:470:32)
    at async Request._reply (/Users/demo/project/node_modules/@hapi/hapi/lib/request.js:449:9)
```

What seems to be most relevant is that these are coming from line 280 and 281 in hapi's request.js

```
        await this._lifecycle();
        this._reply();
```

What is interesting is that the call coming from the `_reply()` line gets to `prepare()` in inert, and at that point it has the info in `response.source.file` which was set up by the call coming from the `_lifecycle()` call.  However, this call then overwrites that data with a new call to open().  This appears to be where the leak is happening.

It thus looks to me like adding this to `file.js` in inert (around line 99) would fix the problem.

```
    if (source.file) {
        return response;
    }
```

I am not an expert on the hapi codebase, though, and from the documentation on hapi.dev, it seems like it is expected that prepare() would be opening a file descriptor.  Thus, I do not know if this problem is with inert and hapi, or if there's some aspect of how we are using this that is bad.

I'm happy to do more work to try to identify the problem, and create a PR.  I'd love to get some knowledge knowledge to help me more quickly understand why these calls are happening (I haven't yet debugged deeply into these flows yet)

#### What was the result you got?

65535 file descriptors used over a period of time.

#### What result did you expect?

No leaking file descriptors.



Discussion / hints:
I believe that the cause here is that an `onPreResponse` extension is returning `request.response`, where it probably intends to return `h.continue`.  I was able to modify [this test](https://github.com/hapijs/hapi/blob/525a0f018a8636478aa653a4bc38f06f243b3e5a/test/transmit.js#L91) in hapi concerning file descriptor cleanup to reproduce the error, by adding an extension:
```js
server.ext('onPreResponse', (request, h) => {

    // Issue does not occur if h.continue is returned instead
    return request.response;
});
```

If the `onPreResponse` returned a _new_ file response then the original descriptor would have been closed, but because it's the exact same response I believe it is getting re-`prepare()`'ed (which opens a descriptor) but not `close()`'d.  There is probably a way for hapi to deal with this, which I haven't been able to totally think through yet, but I believe your fix will be to hunt down that `onPreResponse` extension (which may be in a plugin— error-handling/prettifying plugins often use `onPreResponse`) and have it return `h.continue` rather than `request.response`.  Of course there's a chance that this isn't the exact cause for you and you're experiencing something else, but if you could investigate this hunch it would be a great help!
Here is an example of an `onPreResponse` that transforms errors and is careful to return `h.continue` when the error transformation is not applicable:

https://github.com/sholladay/hapi-error-page/blob/5079a3ae135baeb9b45e72cb6ad951c0c8bb2dcc/index.js#L20-L22
@devinivy I got overrun by other tasks yesterday, but looked at this more today. I identified one of our plugins was doing exactly what you predicted (not returning h.continue).  I disabled the plugin, and, voilà!, the duplicate prepare() stopped happening.

While this is definitely a bug in our plugin, and I'll fix that, it does also smell like a bug in hapi.  It seems like if a lifecycle method returns a "new" response, hapi should be calling close() on the response that it is about to discard.  It also seems like this "fix" might also be a breaking change for existing things that inadvertently depend on this behavior (I can't think of anything that would want this behavior...but programmers are creative.

Would you advise that I open an issue on Hapi itself?  I can also look into the hapi code and see if I have ideas for a PR that might fix this.

I haven't looked at the details, but this is definitely a (somewhat serious) bug in either hapi or inert, most likely hapi. Feel free to open a short bug there.
I did some sleuthing, and have some insights into what goes wrong.

A handler that returns a non-symbol response will have [`response.prepare()`](https://github.com/hapijs/hapi/blob/dc2213c880f16ff6853eccc684782ec888326475/lib/toolkit.js#L105) called on it, which then calls the inert [`_prepare()`](https://github.com/hapijs/hapi/blob/dc2213c880f16ff6853eccc684782ec888326475/lib/response.js#L505).

I expect that the call to `response.prepare()` can also have other unintended side-effects. Eg. calling the `_passThrough()` logic twice would [cause `Set-Cookie` headers to be appended twice](https://github.com/hapijs/hapi/blob/dc2213c880f16ff6853eccc684782ec888326475/lib/response.js#L550).

The solution appears to be to add some state, that tracks whether `response.prepare()` has been called, and check it before calling it (or inside the `_prepare()` method). Maybe a `response._state` property, with `'init', 'prepared', 'marshalled', 'closed'` values that must be transitioned in a sequence? None of these methods are supposed to be called twice.

Fix patch:
diff --git a/lib/response.js b/lib/response.js
index 929e8d44a..6bb8044c1 100755
--- a/lib/response.js
+++ b/lib/response.js
@@ -55,10 +55,11 @@ exports = module.exports = internals.Response = class {
 
         this._events = null;
         this._payload = null;                       // Readable stream
-        this._error = null;                         // The boom object when created from an error (used for logging)
+        this._error = options.error || null;        // The boom object when created from an error (used for logging)
         this._contentType = null;                   // Used if no explicit content-type is set and type is known
         this._takeover = false;
         this._statusCode = false;                   // true when code() called
+        this._state = this._error ? 'prepare' : 'init'; // One of 'init', 'prepare', 'marshall', 'close'
 
         this._processors = {
             marshal: options.marshal,
@@ -495,6 +496,10 @@ exports = module.exports = internals.Response = class {
 
     _prepare() {
 
+        Hoek.assert(this._state === 'init');
+
+        this._state = 'prepare';
+
         this._passThrough();
 
         if (!this._processors.prepare) {
@@ -558,10 +563,14 @@ exports = module.exports = internals.Response = class {
 
     async _marshal() {
 
-        let source = this.source;
+        Hoek.assert(this._state === 'prepare');
+
+        this._state = 'marshall';
 
         // Processor marshal
 
+        let source = this.source;
+
         if (this._processors.marshal) {
             try {
                 source = await this._processors.marshal(this);
@@ -638,6 +647,12 @@ exports = module.exports = internals.Response = class {
 
     _close() {
 
+        if (this._state === 'close') {
+            return;
+        }
+
+        this._state = 'close';
+
         if (this._processors.close) {
             try {
                 this._processors.close(this);
diff --git a/lib/toolkit.js b/lib/toolkit.js
index c542ee1fa..c678aa2d9 100755
--- a/lib/toolkit.js
+++ b/lib/toolkit.js
@@ -101,7 +101,7 @@ exports.Manager = class {
 
         if (typeof response !== 'symbol') {
             response = request._core.Response.wrap(response, request);
-            if (!response.isBoom) {
+            if (!response.isBoom && response._state === 'init') {
                 response = await response._prepare();
             }
         }
diff --git a/lib/transmit.js b/lib/transmit.js
index 45a27ad25..0005eedcb 100755
--- a/lib/transmit.js
+++ b/lib/transmit.js
@@ -38,7 +38,9 @@ exports.send = async function (request) {
 internals.marshal = async function (response) {
 
     for (const func of response.request._route._marshalCycle) {
-        await func(response);
+        if (response._state !== 'close') {
+            await func(response);
+        }
     }
 };
 
@@ -72,8 +74,7 @@ internals.fail = async function (request, boom) {
 internals.error = function (request, boom) {
 
     const error = boom.output;
-    const response = new request._core.Response(error.payload, request);
-    response._error = boom;
+    const response = new request._core.Response(error.payload, request, { error: boom });
     response.code(error.statusCode);
     response.headers = Hoek.clone(error.headers);               // Prevent source from being modified
     return response;


Test patch:
diff --git a/test/response.js b/test/response.js
index 2e30f6467..f0757fba6 100755
--- a/test/response.js
+++ b/test/response.js
@@ -1290,6 +1290,37 @@ describe('Response', () => {
             const res = await server.inject('/');
             expect(res.statusCode).to.equal(500);
         });
+
+        it('is only called once for returned responses', async () => {
+
+            let calls = 0;
+            const pre = (request, h) => {
+
+                const prepare = (response) => {
+
+                    ++calls;
+                    return response;
+                };
+
+                return request.generateResponse(null, { prepare });
+            };
+
+            const server = Hapi.server();
+            server.route({
+                method: 'GET',
+                path: '/',
+                options: {
+                    pre: [
+                        { method: pre, assign: 'p' }
+                    ],
+                    handler: (request) => request.preResponses.p
+                }
+            });
+
+            const res = await server.inject('/');
+            expect(res.statusCode).to.equal(204);
+            expect(calls).to.equal(1);
+        });
     });
 
     describe('_tap()', () => {