Split request.info.responded to responded and completed. Closes hapij…

…s#3901

API.md

@@ -4755,6 +4755,8 @@ Request information:
 
 - `acceptEncoding` - the request preferred encoding.
 
+- `completed` - request processing completion timestamp (`0` is still processing).
+
 - `cors` - request CORS information (available only after the `'onRequest'` extension point as CORS
   is configured per-route and no routing decisions are made at that point in the request
   lifecycle), where:
@@ -4775,7 +4777,7 @@ Request information:
 
 - `remotePort` - remote client port.
 
-- `responded` - request response timestamp (`0` is not responded yet).
+- `responded` - request response timestamp (`0` is not responded yet or response failed when `completed` is set).
 
 Note that the `request.info` object is not meant to be modified.
 

lib/request.js

@@ -425,8 +425,6 @@ exports = module.exports = internals.Request = class {
 
     _finalize() {
 
-        this.info.responded = Date.now();
-
         if (this.response &&
             this.response.statusCode === 500 &&
             this.response._error) {
@@ -445,6 +443,7 @@ exports = module.exports = internals.Request = class {
             this.response._close(this);
         }
 
+        this.info.completed = Date.now();
         this._core.events.emit('response', this);
         this._core.queue.release();
     }
@@ -459,7 +458,7 @@ exports = module.exports = internals.Request = class {
             this.response._close(this);
         }
 
-        if (this.info.responded) {
+        if (this.info.completed) {
             if (response._close) {
                 response._close(this);
             }
@@ -564,7 +563,8 @@ internals.info = function (core, req) {
 
         acceptEncoding: null,
         cors: null,
-        responded: 0
+        responded: 0,
+        completed: 0
     };
 
     if (core.requestCounter.value > core.requestCounter.max) {

lib/transmit.js

@@ -45,11 +45,7 @@ internals.marshal = async function (request) {
 
 internals.fail = async function (request, boom) {
 
-    const error = boom.output;
-    const response = new Response(error.payload, request);
-    response._error = boom;
-    response.code(error.statusCode);
-    response.headers = Hoek.clone(error.headers);               // Prevent source from being modified
+    const response = internals.error(boom, request);
     request.response = response;                                // Not using request._setResponse() to avoid double log
 
     try {
@@ -61,8 +57,8 @@ internals.fail = async function (request, boom) {
         // Failed to marshal an error - replace with minimal representation of original error
 
         const minimal = {
-            statusCode: error.statusCode,
-            error: Http.STATUS_CODES[error.statusCode],
+            statusCode: response.statusCode,
+            error: Http.STATUS_CODES[response.statusCode],
             message: boom.message
         };
 
@@ -73,6 +69,17 @@ internals.fail = async function (request, boom) {
 };
 
 
+internals.error = function (boom, request) {
+
+    const error = boom.output;
+    const response = new Response(error.payload, request);
+    response._error = boom;
+    response.code(error.statusCode);
+    response.headers = Hoek.clone(error.headers);               // Prevent source from being modified
+    return response;
+};
+
+
 internals.transmit = function (response) {
 
     const request = response.request;
@@ -264,14 +271,16 @@ internals.end = function (env, event, err) {
 
     const { request, stream, team } = env;
 
-    if (!team) {                                                                // Used instead of cleaning up emitter listeners
+    if (!team) {                                                        // Used instead of cleaning up emitter listeners
         return;
     }
 
     env.team = null;
 
-    if (event === 'close' &&
-        request.raw.res.finished) {
+    if (request.raw.res.finished) {
+        if (event !== 'aborted') {
+            request.info.responded = Date.now();
+        }
 
         team.attend();
         return;
@@ -281,41 +290,24 @@ internals.end = function (env, event, err) {
         request.raw.res.destroy();
         Response.drain(stream);
     }
-    else if (event) {
-        err = new Boom(`Request ${event}`, { statusCode: request.route.settings.response.disconnectStatusCode });
-    }
 
-    if (err) {
-        const error = Boom.boomify(err);
-        request._setResponse(error);
+    err = err || new Boom(`Request ${event}`, { statusCode: request.route.settings.response.disconnectStatusCode });
+    const error = internals.error(Boom.boomify(err), request);
+    request._setResponse(error);
 
-        if (request.raw.res[Config.symbol]) {
-            request.raw.res.statusCode = error.output.statusCode;
-            request.raw.res[Config.symbol].result = error.output.payload;      // Force injected response to error
-        }
+    if (request.raw.res[Config.symbol]) {
+        request.raw.res.statusCode = error.statusCode;
+        request.raw.res[Config.symbol].result = error.source;       // Force injected response to error
     }
 
-    if (!request.raw.res.finished &&
-        event !== 'aborted') {
-
-        request.raw.res.end();
+    if (event) {
+        request._log(['response', 'error', event]);
     }
-
-    if (event ||
-        err) {
-
-        if (request._events) {
-            request._events.emit('disconnect');
-        }
-
-        if (event) {
-            request._log(['response', 'error', event]);
-        }
-        else {
-            request._log(['response', 'error'], err);
-        }
+    else {
+        request._log(['response', 'error'], err);
     }
 
+    request.raw.res.end();                                          // Triggers injection promise resolve
     team.attend();
 };
 

test/request.js

@@ -809,6 +809,7 @@ describe('Request', () => {
             await server.inject('/');
             const [request] = await log;
             expect(request.info.responded).to.be.min(request.info.received);
+            expect(request.info.completed).to.be.min(request.info.responded);
             expect(request.response.source).to.equal('ok');
             expect(request.response.statusCode).to.equal(200);
         });

test/toolkit.js

@@ -48,13 +48,13 @@ describe('Toolkit', () => {
                 await server.register(Inert);
                 const handler = (request, h) => {
 
-                    return h.file('./package.json').code(499);
+                    return h.file('./package.json').code(999);
                 };
 
                 server.route({ method: 'GET', path: '/file', handler });
 
                 const res = await server.inject('/file');
-                expect(res.statusCode).to.equal(499);
+                expect(res.statusCode).to.equal(999);
                 expect(res.payload).to.contain('hapi');
                 expect(res.headers['content-type']).to.equal('application/json; charset=utf-8');
                 expect(res.headers['content-length']).to.exist();

test/transmit.js

@@ -597,13 +597,8 @@ describe('transmission', () => {
                     }
 
                     this.isDone = true;
-
                     this.push('success');
-
-                    setImmediate(() => {
-
-                        this.emit('error', new Error());
-                    });
+                    setImmediate(() => this.emit('error', new Error()));
                 };
 
                 return stream;
@@ -618,7 +613,9 @@ describe('transmission', () => {
             expect(res.result.message).to.equal('An internal server error occurred');
 
             const [request] = await log;
-            expect(request.response.output.statusCode).to.equal(500);
+            expect(request.response.statusCode).to.equal(500);
+            expect(request.info.completed).to.be.above(0);
+            expect(request.info.responded).to.equal(0);
         });
 
         it('handles stream errors on the response after the response has been piped (http)', async () => {
@@ -642,11 +639,17 @@ describe('transmission', () => {
             };
 
             const server = Hapi.server();
+            const log = server.events.once('response');
             server.route({ method: 'GET', path: '/', handler });
 
             await server.start();
             await expect(Wreck.request('GET', 'http://localhost:' + server.info.port + '/')).to.reject();
             await server.stop();
+
+            const [request] = await log;
+            expect(request.response.statusCode).to.equal(500);
+            expect(request.info.completed).to.be.above(0);
+            expect(request.info.responded).to.equal(0);
         });
 
         it('matches etag header list value', async () => {
@@ -1100,10 +1103,16 @@ describe('transmission', () => {
             };
 
             const server = Hapi.server();
+            const log = server.events.once('response');
             server.route({ method: 'GET', path: '/stream', handler: (request, h) => h.response(new ErrStream(request)).bytes(0) });
 
             const res = await server.inject({ url: '/stream', headers: { 'Accept-Encoding': 'gzip' } });
             expect(res.statusCode).to.equal(499);
+
+            const [request] = await log;
+            expect(request.response.statusCode).to.equal(499);
+            expect(request.info.completed).to.be.above(0);
+            expect(request.info.responded).to.equal(0);
         });
 
         it('does not truncate the response when stream finishes before response is done', async () => {