Propagate "peek" and "finish" errors as error response

[matthieusieben]

Fixes #4172

[kanongil]

Looks good. Just needs a few tweaks.

[matthieusieben]

I don't think the failing tests are related to the changes of this PR.

[kanongil]

LGTM.

[kanongil]

CI errors are due to hapijs/lab#997.

[matthieusieben]

Any idea on when this could land, @kanongil ?

[matthieusieben]

As workaround, one can currently do:

request.raw.req.emit('error', unauthorized('Corrupted payload'))

as in:

server.ext('onRequest', (request, h) => {
  const hash = createHash('sha512')

  request.events.on('peek', (chunk, encoding) => {
    hash.update(chunk, encoding)
  })

  request.events.on('finish', () => {
    const payloadDigest = hash.digest('base64')
    if (payloadDigest !== getDigestHeader(request, 'sha512')) {
      /**
       * @hack Until we can throw from the 'finish' listener
       * @see {@link https://github.com/hapijs/hapi/pull/4173}
       */
      request.raw.req.emit('error', Boom.unauthorized('Corrupted payload'))
      // throw unauthorized('Corrupted payload')
    }
  })  
});

[devinivy]

This is nice, I think I do like the behavior. Thanks for the contribution. Two notes here:

1. I see there's only one class shared by both request and response peeking. Perhaps we should add tests for response peeking to demonstrate that we understand the effect that this change has there. Seems like it could be more complex than request peeking.
2. This is a pretty hot code path (when there are event handlers), and I don't have a sense for what kind of effect this might have on performance. Does anyone have interest in doing some benchmarking so that we know what to expect if we land this? I foresee many microticks with those awaits and I'm curious just how much they might add-up in the middle of request and response streaming.

[matthieusieben]

I started writing some tests but encountered the following issue with server.inject(): #4182

[kanongil]

Given the performance considerations that @devinivy brought up, I am no longer certain that this should be patched. I might defer to my original stance, which was that it is a fatal programming error, if an event handler throws.

Looking at podium itself, and the usage across the hapijs org, it is apparent that handling thrown errors is mostly a non-consideration. The two other modules that use it, catbox and beam, both call the emitter without handling the returned promise, resulting in an unhandledRejection emit on process.

For hapi itself, the emit() promise is only handled for the server start and stop events. Every other usage is presently unhandled. I would in fact consider any await of the returned promise to be a bug, since the application flow should not delay to handle any fallout of an event. emit() is by its nature a fire and forget thing.

All-in-all, the conclusion seems to be that hapi should stop awaiting start and stop events (breaking change), and podium should have an optimization pass to not return a promise (breaking change), and that this PR is unfortunately not appropriate.

.

[matthieusieben]

Regarding the performance issues, you know that node's stream heavily rely on micro tasks internally, right? And that this change has indeed the potential to slow down request processing, but only if the dev is not careful during the peek & finally.

It is kinda sad that there is no clean way to fix #4172. (Ie. Preventing any processing of the request payload, in an auth scheme).

Also, what is the point of having a podium at all (instead of node's event emitter) if not for being able to await listeners execution?

I use hapi quite a lot and love how it is so easily extendable and plug & play. I really fell like this decision is a move backwards.

For example, being able to execute all async setup tasks during start is so elegant and efficient (all tasks run in parallel). I don't really understand how a PR adding extendability made you rethink everything in the opposite direction

[kanongil]

What is the point of having a podium at all (instead of node's event emitter) if not for being able to await listeners execution?

Podium contains channels and tags, that allow filtering and more efficient processing. The registration step prevents emitting mistyped event names. It also ensures that all emitters are called on an emit(), even if one throws (though it is up to the application to handle such a throw). The promise returned from emit() is not even part of the documented API.

For example, being able to execute all async setup tasks during start is so elegant and efficient (all tasks run in parallel).

It is still possible to stall a start() / stop(), you just need to use the exts onPreStart / onPostStop, which will have slightly different timing, but are more powerful, since you can control the order they are run in.

FYI, your contribution has helped us gain insight into a part that is not clearly handled. A clarification can go either way, and in this case it seems more consistent to do something other than you proposed.

[kanongil]

FYI, if podium is changed to not emit async, you will likely be able to solve your #4172 issue with:

    request.events.once('finish', () => {

        if (digest !== hash.digest('base64')) {
            request.raw.req.destroy(throw new Boom.badData('nice error message'));
        }
    });

[matthieusieben]

I did some benchmarking to see the impact of microtasks. Here are my conclusions:

Computer

macOS Catalina 10.15.7 (19H15)
MacBook Pro (13-inch, 2019, Four Thunderbolt 3 ports)
2,8 GHz Intel Core i7 quad core
16 Go 2133 MHz LPDDR3

server.js

const Hapi = require('.');
const noop = () => {};
const server = Hapi.server({ port: 8080 });

server.route({
  method: 'POST',
  path: '/',
  handler: (request, h) => h.response(null)
});

server.ext('onRequest', (request, h) => {
  if (request.query.peek === "1") request.events.on('peek', noop);
  if (request.query.finish === "1") request.events.on('finish', noop);
  return h.continue;
});

server.start()

benchmark.js

const Stream = require('stream');
const Http = require('http');
const noop = () => {}

class TestStream extends Stream.Readable {
  constructor(chunks, chunkSize = undefined) {
    super({ highWaterMark: chunkSize, autoDestroy: true, objectMode: false })
    this.chunks = chunks
  }
  _read(size) {
    if (this.chunks--) this.push(Buffer.alloc(size))
    else this.push(null)
  }
}

const mesure = (qs) => new Promise((resolve, reject) => {
  const req = Http.request({
    protocol: 'http:',
    host: "127.0.0.1",
    port: 8080,
    method: 'POST',
    path: `/?${qs}`,
  }, (res) => {
    res.on('error', end);
    res.on('data', noop);
    res.on('end', end);
  });

  const end = (err) => {
    const diff = process.hrtime(start)
    if (err) reject(err)
    else resolve(diff[0] * 1e9 + diff[1])
  }
  const stream = new TestStream(100000, 1)
  const start = process.hrtime()
  stream.pipe(req)
});

const suite = async () => ({
  'no-tap': (await mesure('peek=0&finish=0')) / 1e6,
  'finish': (await mesure('peek=0&finish=1')) / 1e6,
  'peek': (await mesure('peek=1&finish=0')) / 1e6,
});


const benchmark = async (count = 10) => {
  let result = await suite()
  for (let i = 0; i <= count; i++) {
    const newResult = await suite()
    for (const key in newResult) result[key] += newResult[key]
  }
  for (const key in result) result[key] /= count
  return result
};

benchmark(100).then(console.log)

The idea is to compare the following behavours:

• No listeners (this will disable tapping the request stream)
• Finish listener only (tap enabled. no microtasks generated by peek listeners)
• Peek listeners only (tap enabled. several microtasks generated by peek listeners)

The bench script is generating a stream payload composed of 100 000 chunks, to try and trigger the peek listeners a lot of times. This corresponds to the number of times peek would happen during a transfer of 1,6384 GB of data (readable stream's default highWaterMark is 16384 bytes). The server.js script can easily be adapted to check that the number of chunks (= calls to peek listeners) correspond to that value.

Here are the results:

  no-tap: 378.2443061600001 ms (avg)
  finish: 370.87199968999994 ms (avg)
  peek: 377.50655967 ms (avg)

As you can see (and this comes as a surprise), enabling tapping proves to actually improve performances (at lease when using small data chunks). Enabling peeking causes an increase of 6.6 mili-seconds for every 100 000 chunks of data. The impact of micro tasks seems very dim to me...

[kanongil]

In my mind, this is no longer a performance issue, but an conceptual emit() should never be awaited on issue.

The provided benchmark is not really appropriate, as there is not apparent what is really benchmarked here. It just shows that the difference is too small to detect in relation to the request processing itself (which does not surprise me). Given that this will waste much time waiting for IO, there is no way to determine the actual CPU load of the change.