[Core] aborted$ stream defined in core/server/http/router/request.ts doesn't work in some cases

[alexwizp]

This is a follow-up PR issue for #125069 because we didn't find the answer.

Summary

I made similar changes in two places, for some reason it works in examples but doesn't work in TSVB

TSVB:
To play just open any TSVB visualization and see console.
Expected: I expect to see 'tsvb: abort is not working' in console

Screen.Recording.2022-02-09.at.4.11.49.PM.mov

Examples:

1. Go to app /app/searchExamples/search
2. Scroll to the end of page and execute Request from low-level client on the server

Screen.Recording.2022-02-09.at.4.09.15.PM.mov

[elasticmachine]

Pinging @elastic/kibana-core (Team:Core)

[pgayvallet]

Analysis

I initially though this was related to the basePath proxy, but the behavior is the exact same when running with no-base-path, I quickly excluded this option.

Then, I used #125069 to try to understand the differences between the working and non-working scenarios.

My conclusion is that it's failing for requests having a payload:

• I adapted the working scenario to use a POST request, the aborted event still fires
• I adapted the working scenario to use a POST request and sending a body payload, the aborted event never fires
• I adapted the working scenario to use a PUT request, the aborted event still fires
• I adapted the working scenario to use a PUT request and sending a body payload, the aborted event never fires
• I adapted the failing scenario to remove the body payload, the aborted event fires.

Then, I wanted to see if the problem was in our internal observers, or deeper, so I adapted KibanaRequest to expose the raw request via _request, and checked if request._request.raw.req.aborted was properly set to true for scenarios where the event does not fire. It does not, which strongly tend to indicate that the problem is in the underlying implementation rather that core's code.

I then adapted this test:

kibana/src/core/server/http/integration_tests/request.test.ts

Line 169 in 4681a80

it('emits once and completes when request aborted', async () => {

To use a POST request with payload instead of the current GET, and I confirmed that the test went red (because the observable does not emit). Interesting though, in some case only: the payload needs to be validated/parsed for the test to fail.

With this request:

const incomingRequest = supertest(innerServer.listener)
          .post('/')
          .send({ hello: 'dolly' })

this fails:

 router.post(
            { path: '/', validate: { body: schema.any() } },

but this passes:

 router.post(
            { path: '/', validate: false },

So it likely has something to do with the low level request's payload accessing, parsing, or associated route configuration.

I checked where we were using the value of route.validate, and the only place apart from where we're we doing our own validation/parsing is in this: validOptions function:

kibana/src/core/server/http/router/router.ts

Lines 187 to 197 in 3c8fa52

	const body = shouldNotHavePayload
	? undefined
	: {
	// If it's not a GET (requires payload) but no body validation is required (or no body options are specified),
	// We assume the route does not care about the body => use the memory-cheapest approach (stream and no parsing)
	output: !shouldValidateBody ? ('stream' as const) : undefined,
	parse: !shouldValidateBody ? false : undefined,
	// User's settings should overwrite any of the "desired" values
	...options.body,
	};

So I played with the route.options.body value to see which ones were switching the test from green to red, and the conclusion is that it's body.output:

• When body.output is stream (which is what we use when we're not validating the body payload) the test passes
• When body.output is undefined, defaulting to data (which is what we use when we're validating the body payload) the test fails

So, somehow, HAPI's RouteOptions.payload.output has an impact on whether the aborted event on the underlying nodejs http module's request's aborted event fires or not when the client-side request is aborted. When HAPI reads the body payloads to generates the associated data in memory, somehow this causes the aborted event to not fire...

Not sure how to progress further. We should probably try to create a reproduction scenario with a plain HAPI server to confirm our observations.

Side note - the aborted event is deprecated

As a (long) side note, the aborted event is deprecated starting on node v16.12.0 (https://nodejs.org/docs/latest-v16.x/api/http.html#event-abort), meaning that at some point, we will be forced to use close instead, and this event doesn't make a distinction between requests that were canceled and requests that were properly completed (this is the event we're currently using for KibanaRequest.events.complete$.

Given that we will be forced at some point in time to remove usage of this aborted event anyway, I wonder if we shouldn't just go the pragmatic road and:

• deprecated KibanaRequest.events.aborted$ aborted in favor of KibanaRequest.events.completed$
• change the underlying implementation to have both observable use the exact same source until we totally get rid of the deprecation one

This means that our API consumers will not be able to make the distinction between requests that were canceled and requests that were completed, but given our usage of aborted$, I'm not sure this is really problematic, as from my understanding, we're mostly (exclusively?) using it to perform cancelation of the underlying ES requests in case of cancelation from the client-side, so having the event fire when the client-side request is completed shouldn't really be a problem.

We can also try to understand what the problem is in the underlying implementation, but given that this aborted event is deprecated for removal anyway, I wonder if that's really worth it.

WDYT?

[pgayvallet]

I isolated the problem in a test case that is using HAPI's Server directly

import { Server } from '@hapi/hapi';
import supertest from 'supertest';

const delay = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms));

const deferred = <T = unknown>(): {
  promise: Promise<T>;
  resolve: (value: T) => void;
  reject: (error: any) => void;
} => {
  let resolve: (value: T) => void;
  let reject: (error: any) => void;
  const promise = new Promise<T>((_resolve, _reject) => {
    resolve = _resolve;
    reject = _reject;
  });
  return {
    promise,
    resolve: resolve!,
    reject: reject!,
  };
};

describe('aborted event bug', () => {
  let server: Server;
  let request: supertest.SuperTest<supertest.Test>;

  beforeEach(() => {
    server = new Server({
      host: '127.0.0.1',
      port: 6666,
    });
    request = supertest('http://127.0.0.1:6666');
  });

  afterEach(async () => {
    await server.stop();
  });

  const runTest = async (options: { output: 'stream' | 'data' }) => {
    let abortedReceived = false;
    const { promise: responseClosedPromise, resolve: responseClosedResolve } = deferred<void>();

    server.route({
      method: 'POST',
      path: '/test',
      options: {
        payload: {
          output: options.output,
        },
      },
      handler: async (req, h) => {
        req.raw.req.on('aborted', () => { // same with req.events.on('disconnect'
          abortedReceived = true;
        });
        req.raw.res.on('close', () => {
          responseClosedResolve();
        });

        await delay(3000);
        return h.response('foo');
      },
    });

    await server.start();

    const incomingRequest = request.post('/test').send({ hello: 'dolly' }).end();
    setTimeout(() => incomingRequest.abort(), 100);

    await responseClosedPromise;

    expect(abortedReceived).toEqual(true);
  };

  // pass
  it('should work with `options.payload.output=stream`', async () => {
    await runTest({ output: 'stream' });
  });

  // fail
  it('should work with `options.payload.output=data`', async () => {
    await runTest({ output: 'data' });
  });
});

at this point I think the next step is to open an issue upstream

[pgayvallet]

Opened hapijs/hapi#4339

[pgayvallet]

More context from hapijs/hapi#4315

It seems that http.IncomingMessage no longer emits 'aborted' events once the payload has been delivered

Also it seems that node is considering that as working as intended, as nodejs/node#40775 was closed.

[pgayvallet]

Currently working on a workaround based on a suggestion found in nodejs/node#40775. It seems to be passing the tests, I should open a PR shortly. cc @flash1293 @alexwizp