Response event for aborted requests has status code 200 and doesn't call native `response.end`

dnechay commented 3 years ago

Support plan

is this issue currently blocking your project? (yes/no): no
is this issue affecting a production system? (yes/no): no

Context

node version: 12.13.1, 14.15.1
module version with issue: 19.2.0, 20.0.1, 20.1.2 (maybe others)
last module version without issue: unsure
environment (e.g. node, browser, native): node
used with (e.g. hapi application, another framework, standalone, ...): hapi-application, another framework
any other relevant information: similar to https://github.com/hapijs/hapi/issues/4072

What are you trying to achieve or the steps to reproduce?

const Hapi = require('@hapi/hapi');

const server = Hapi.server({
  host: 'localhost',
  port: 8080,
});

server.route({
  method: 'GET',
  path: '/abort-test',
  handler: async function() {
    return new Promise(function (resolve) {
      setTimeout(function () {
        resolve('OK');
      }, 4000);
    });
  },
})

server.events.on('request', (request, event) => {
  console.log(`Event: ${JSON.stringify(event)}`);
});

server.events.on('response', (request) => {
  console.log(`Response Status Code: ${request.response.statusCode}`);
});

server.start();
console.log(`Server running at: ${server.info.uri}`);

curl --max-time 1 http://localhost:8080/abort-test

What was the result you got?

Server running at: http://localhost:8080
Event: {"request":"<SHORTENED>","timestamp":1584125752386,"tags":["request","error","abort"],"channel":"internal"}
Response Status Code: 200

Native node.js response.end isn't called.

What result did you expect?

response.end called, response status code to be 499.

Additional info

We're using opentelemetry.js to collect metrics from our application, it has a module that automatically collects HTTP metrics by wrapping native node's http and https modules. It works fine with usual HTTP requests to our hapi-app, but when a request is aborted on a client side - it doesn't collect metrics. I assume that it's because Hapi.js doesn't call native response.end for aborted requests, which is wrapped with opentelemetry module. It works fine with native node.js HTTP service (because it calls response.end even for aborted requests). So it would be nice to get some help and understand if there a bug in Hapi request abort mechanism or should we deal some specific way with aborted requests to be able to collect metrics in this case.

devinivy commented 3 years ago

I started digging into this and wanted to share what I've learned so far in case anyone else wants to take a look as well.

In short, I was able to confirm the issue. I have been most focused on seeing the correct 499 status code and logged response. When a lifecycle step is in progress, a response from that step was able to overwrite hapi's "Request aborted" response. Additionally, it was waiting for the in-progress lifecycle step to complete before emitting 'response', which seems unnecessary.

The fix I found was to call _reply() once the abort response is set, which in turn triggers finalization of that response. This left a line uncovered, so I started working on covering that line. The case that now covers this line is a response 'close' event (without a request 'abort') in the middle of the request lifecycle. When that triggered finalization, a hard error occurred because hapi anticipated a response to have been set. I didn't fix this issue, and you can reproduce it by running the tests. I haven't thought through exactly how this should be handled yet, but if anyone has ideas about it feel free to share!

https://github.com/hapijs/hapi/compare/master...devinivy:fix-4244

kanongil commented 3 years ago

I am looking into this as part of an upcoming PR that revises some of the stream transmit logic.

During my refactor I was encountering issues around aborted requests, and had a hard time figuring out how to handle them. Thanks for the hint regarding the call to _reply(). That was the "missing link", as the underlying issue is that Hapi does not support calling setResponse() during the transmission (after the headers have been sent), and you need to use _reply(err) to change the response.

devinivy commented 3 years ago

Awesome, I am glad you found this work and that it was useful. I agree that it does feel like time to revise some of the transmit and abort logic. Thanks for digging into it!

RobYed commented 1 year ago

Any news on this? It still seems to be an issue. We are running hapi v21.1.0 and aborted requests still log 200 and do not seem to end the request. In our case this is particularly disadvantageous, since cancelled requests are supposed to end a stream. This is currently not the case, so streams continue to run in the background without any benefit (request handler of our streaming api).

hapijs / hapi