req.multipart() does not await for all multipartfield handler async functions?

[BobbyWibowo]

Edit:

Actual description of the issue is in this reply: #100 (comment)

---

Original:

I did not notice this before since I initially was just doing things such as piping file's ReadStream into a WriteStream, which basically ends almost immediately as the ReadStream itself finishes

But after I start playing with some Transform stream that needs slightly longer time than usual, I finally notice that req.multipart appears to resolve almost immediately, even if there's a MultipartField handler async function still working in the background

Suppose the following code snippets

routes.post('/api/upload', async (req, res) => {

  console.log('1')

  await req.multipart(busboyConfig, async field => {
    await new Promise(resolve => setTimeout(() => resolve(), 5000))
    console.log('2')
  }

  console.log('3')
  res.status(200).end()
}
})

Console output would be:

1
3
< request ended here, then 5 seconds-ish later... >
2

[BobbyWibowo]

It appears that it will only await if the handler function explicitly returns a Promise, because the code internally checks if it's an instanceof Promise, which async function is not

[kartikk221]

Calling an async function synchronously should always return a Promise which then resolves to the actual value returned from the async function?

[BobbyWibowo]

Yeah, it was an invalid assumption on my part due to rather messy attempts at trying to pinpoint the root cause lmao

[kartikk221]

No problem, I'll try and recreate the issue with the snippets you provided and keep tests for those that trigger an error, so this doesn't occur again in future.

[BobbyWibowo]

Ah, my bad, it wasn't that it did not await
It did await properly with that example code in the original post

Instead, from what I can tell, req.multipart resolves early when field.file.stream has been consumed by the first Transform/Writable stream I piped it into, even though the handler function is still supposed to await for the remaining destination streams if any

So assuming I have multi-step pipes:

field.file.stream
  .pipe(destStream1)
  .pipe(destStream2)

req.multipart() somehow resolves after destStream1 has finished consuming the stream, even though destStream2 is still doing it things

[kartikk221]

Interesting, I'll add a test for multiple pipes and see If I can recreate/properly await all streaming operations before continuing to the next iteration.

[BobbyWibowo]

Hi there, just wondering, is there an internal timeout of 10s somewhere?

Suppose I only pipe the incoming file.read.stream to a regular WriteStream to write to a file, but I choose to "hold" the Promise within req.multipart() for about 20s after WriteStream:finish before resolving the Promise, I notice that after only about 10s, the client's connection will simply drop with no error code (0) nor payload

And every once in a while, other than only dropping, the handler for that specific route will also get triggered again for that exact same Request, scratches head

Inspecting the client browser's network inspector, client never attempted to re-send the request after the connection drop, so it was just some voodoo thingies going on in the server side for some reason

[kartikk221]

Ah, my bad, it wasn't that it did not await It did await properly with that example code in the original post

Instead, from what I can tell, req.multipart resolves early when field.file.stream has been consumed by the first Transform/Writable stream I piped it into, even though the handler function is still supposed to await for the remaining destination streams if any

So assuming I have multi-step pipes:

field.file.stream
  .pipe(destStream1)
  .pipe(destStream2)

req.multipart() somehow resolves after destStream1 has finished consuming the stream, even though destStream2 is still doing it things

So ideally for this scenario, you should return a Promise to the multipart handler synchronously then manually call the resolve() once all of your layered pipes have finished. Since HyperExpress does not have a reference to all of your layered pipes, it only can wait for the exposed file stream to finish piping into it's immediate destination.

[BobbyWibowo]

So ideally for this scenario, you should return a Promise to the multipart handler synchronously then manually call the resolve() once all of your layered pipes have finished.

That was actually what I had been doing too
It's just that, for some odd reasons, req.multipart() would resolve first, even though the Promise handler that was supposed to wait for both 2 destStreams was still working in the background

I logged both destStreams' end-like events, and req.multipart() would somehow resolve immediately after destStream1's end-like event, even though the Promise handler was still waiting for destStream2's
I even confirmed the Promise itself was still working in the background and had not yet been resolved, cause a few seconds after req.multipart() has resolved and subsequently finalize the Request (i.e. the amount of time it takes for destStream2 to work), it will still properly log destStream2's end-like event, and the Promise's own resolve

Unfortunately I've also stopped using the passthrough stream (destStream1) altogether (as I've just mentioned in the other comment), so pursuing that issue specifically is no longer worth it, imho

[kartikk221]

Would you be able to provide the client-side payload you were sending to the snippet in the code snippet in your original post above to the /api/upload endpoint?

[kartikk221]

Hi there, just wondering, is there an internal timeout of 10s somewhere?

While there is no built-in request timeout anywhere in HyperExpress, there is a hard-coded security inactivity timeout of ~10 seconds built into uWebsockets.js which is likely what you are experiencing here. Essentially if the socket does not send or receive any content for 10 seconds then uWebsockets.js will automatically timeout the request. See https://github.com/uNetworking/uWebSockets/blob/5eb463580913486493d97a410d354a2085681147/src/HttpContext.h#L43-L44

And every once in a while, other than only dropping, the handler for that specific route will also get triggered again for that exact same Request, scratches head

This would be really weird / shouldn't even be possible but add the following snippet to your route:

// Add a random UUID to each request to "track" it
if (!request.id) request.id = crypto.randomUUID();
console.log('Received Request ' + request.id);

Then try to see If the same UUID is logged to console twice which would signify that HyperExpress called the route handler with the same Request/Response objects.

[BobbyWibowo]

While there is no built-in request timeout anywhere in HyperExpress, there is a hard-coded security inactivity timeout of ~10 seconds built into uWebsockets.js which is likely what you are experiencing here. Essentially if the socket does not send or receive any content for 10 seconds then uWebsockets.js will automatically timeout the request. See https://github.com/uNetworking/uWebSockets/blob/5eb463580913486493d97a410d354a2085681147/src/HttpContext.h#L43-L44

Ah, I see
Oh well, it's fine
Me randomly testing the 20s hold thingy was only as an attempt to pinpoint the issue I was having anyways
There were other unrelated technical issues, that was causing the passthrough streamer I was piping incoming data into, to sometimes hang for that amount of time or longer
I've since found a better solution for my use case that should not ever cause requests to hang like that (tldr; it was the passthrough streamer that was bad)

Then try to see If the same UUID is logged to console twice which would signify that HyperExpress called the route handler with the same Request/Response objects.

I will get back to you on this in a bit

[BobbyWibowo]

I managed to replicate the behavior, but it happens very very rarely
I'd say the chance is like once every 20 to 30 tries

[16:55:02.060] [57b647aa-753a-482d-be32-fa8f45144716] /api/upload
[16:55:02.060] [57b647aa-753a-482d-be32-fa8f45144716] Request.raw.uuid = 57b647aa-753a-482d-be32-fa8f45144716
[16:55:02.060] [57b647aa-753a-482d-be32-fa8f45144716] Request.headers.uuid = fad9e11b-20ea-4ffd-a857-6d23acbd547e
[16:55:02.061] [57b647aa-753a-482d-be32-fa8f45144716] await req.multipart()
[16:55:02.063] [57b647aa-753a-482d-be32-fa8f45144716] readStream.pipe(writeStream)
[16:55:02.065] [57b647aa-753a-482d-be32-fa8f45144716] writeStream:finish, delaying for 20s…
[16:55:13.061] [e0cb73c5-5db7-47d9-bca7-80f0444913be] /api/upload
[16:55:13.061] [e0cb73c5-5db7-47d9-bca7-80f0444913be] Request.raw.uuid = e0cb73c5-5db7-47d9-bca7-80f0444913be
[16:55:13.061] [e0cb73c5-5db7-47d9-bca7-80f0444913be] Request.headers.uuid = fad9e11b-20ea-4ffd-a857-6d23acbd547e
[16:55:13.062] [e0cb73c5-5db7-47d9-bca7-80f0444913be] await req.multipart()
[16:55:13.064] [e0cb73c5-5db7-47d9-bca7-80f0444913be] readStream.pipe(writeStream)
[16:55:13.069] [e0cb73c5-5db7-47d9-bca7-80f0444913be] writeStream:finish, delaying for 20s…
[16:55:22.066] [57b647aa-753a-482d-be32-fa8f45144716] req.multipart() resolved
[16:55:22.069] [57b647aa-753a-482d-be32-fa8f45144716] res.json()
[16:55:33.069] [e0cb73c5-5db7-47d9-bca7-80f0444913be] req.multipart() resolved
[16:55:33.072] [e0cb73c5-5db7-47d9-bca7-80f0444913be] res.json()

The UUID in the [] brackets is the one set on Request.uuid ONLY IF it has not been set before
Request.raw.uuid will be set to be the same as Request.uuid ONLY IF it has not been set before either

It appears that Request.raw.uuid is always identical with Request.uuid, which likely means that the underlying uWebsockets.js request object is also fresh when it happens

Request.headers.uuid is an UUID generated on the client's side, only when a file is first selected to be uploaded, which will then be added into the POST request's header
It's supposed to be always unique, even when selecting the same exact file multiple times
Which likely means that, at least, the file buffer being sent from the client is the exact same, thus meaning either the client re-sends the exact same request after 10s of silence, or something else

Then inspecting the relevant request further in Firefox's dev tools, it indeed only logged that the request only happened once, however I found something interesting in the Timing chart

The other attempts I did, did not have the 10s period of being "blocked"
I can only guess that Firefox somehow inferred that the initial request was not successful, but somehow interpreted it in a way that made it decide to re-send the request after 10s, I assume because the initial request was dropped by uWebSockets.js' hard-coded timeout
Unfortunately I don't actually know the specifics to confirm said guess

[kartikk221]

Yeah, this seems to be a case of the Browser retrying the request because it detected an abrupt close from uWebsockets.js rather than a proper response with a status code, headers etc. Also, I remember uWebsockets.js developer stating that with HTTP all incoming data must be received before outgoing data can be sent, so that can also be the reason why you can't have a "proper" request end while there is still content being sent to the server.