Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: abort and headers already sent errors for the rest api #5722

Merged
merged 8 commits into from
Jul 14, 2023
Merged

fix: abort and headers already sent errors for the rest api #5722

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
68c5e2e
Fix the validator abort error
nazarhussain Jun 30, 2023
ba6b116
Fix abort error
nazarhussain Jul 13, 2023
11134a2
Update the request handling for headers
nazarhussain Jul 14, 2023
476e7ea
Update the request handling for headers
nazarhussain Jul 14, 2023
e467e63
Improve the check on the error
nazarhussain Jul 14, 2023
175fcb4
Fix prittier error
nazarhussain Jul 14, 2023
7ce0c92
Revert the changes for the validator handler
nazarhussain Jul 14, 2023
513396f
Revert the changes for the validator handler
nazarhussain Jul 14, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 10 additions & 1 deletion packages/api/src/beacon/server/events.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import {ChainForkConfig} from "@lodestar/config";
import {ErrorAborted} from "@lodestar/utils";
import {Api, ReqTypes, routesData, getEventSerdes} from "../routes/events.js";
import {ServerRoutes} from "../../utils/server/index.js";
import {ServerApi} from "../../interfaces.js";
Expand Down Expand Up @@ -36,6 +37,9 @@ export function getRoutes(config: ChainForkConfig, api: ServerApi<Api>): ServerR
await new Promise<void>((resolve, reject) => {
void api.eventstream(req.query.topics, controller.signal, (event) => {
try {
// If the request is already aborted, we don't need to send any more events.
if (req.raw.destroyed) return;
Copy link
Contributor Author

@nazarhussain nazarhussain Jul 14, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This check will try to avoid headers already sent scenario. Though that edge case is very tricky to reproduce. I tried a lot of ticks but was not able to produce it locally.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are you sure this handles all cases where this can happen, I was think maybe to check res.raw.headersSent before setting hearders but would also have to look into this more if that the correct condition to check for

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

headers already sent error occurred, when you try to write to a response, which related request is completed. That completion can be because request was aborted, or server already finished writing response and closed the stream with res.end().

I can't see the later case happens in our code, as we write the response only from one place. So the only case left in my mind is the first one, so this condition will cover it.

If you can find a way to reproduce headers already sent scenario manually, please share then we can test.

Copy link
Member

@nflaig nflaig Jul 14, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Based on the stack trace in the issue, the error is not caused by us setting headers but something fastify does.

Looks like here res.writeHead, might be an issue on fastify or related to us not closing correcty.

But res.raw.write looks like a good candidate that could be causing this. If we are sure this does not cause unwanted side effects the change looks good.

If you can find a way to reproduce headers already sent scenario manually

I just saw this once or twice on my end over a period of several months and it was reported by a user once. Seems to be highly timing specific, I tried to reproduce it consistently but no luck so far

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't see any side effects for this change.

Copy link
Member

@nflaig nflaig Jul 20, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@nazarhussain I was going through logs from sim tests and it looks like the error still happens there.

[node-1-cl-lodestar] [8460]: Eph 6/0 2.220[node-1-cl-lodestar] �[31merror�[39m: uncaughtException: Cannot set headers after they are sent to the client
Error: Cannot set headers after they are sent to the client
    at new NodeError (node:internal/errors:405:5)
    at ServerResponse.setHeader (node:_http_outgoing:648:11)
    at ServerResponse.writeHead (node:_http_server:381:21)
    at onSendEnd (/home/runner/actions-runner/_work/lodestar/lodestar/node_modules/fastify/lib/reply.js:597:7)
    at onSendHook (/home/runner/actions-runner/_work/lodestar/lodestar/node_modules/fastify/lib/reply.js:530:5)
    at fallbackErrorHandler (/home/runner/actions-runner/_work/lodestar/lodestar/node_modules/fastify/lib/error-handler.js:127:3)
    at handleError (/home/runner/actions-runner/_work/lodestar/lodestar/node_modules/fastify/lib/error-handler.js:61:5)
    at onErrorHook (/home/runner/actions-runner/_work/lodestar/lodestar/node_modules/fastify/lib/reply.js:743:5)
    at Reply.send (/home/runner/actions-runner/_work/lodestar/lodestar/node_modules/fastify/lib/reply.js:133:5)
    at defaultErrorHandler (/home/runner/actions-runner/_work/lodestar/lodestar/node_modules/fastify/lib/error-handler.js:92:9) Cannot set headers after they are sent to the client
Error: Cannot set headers after they are sent to the client

See node-1-cl-lodestar.log from this sim tests run. This error seems to happen quite frequently in sim tests.

I would suggest we revert this change here as it does not solve the issue. It might also be a bug in fastify and not directly solvable on our end.

Edit: I created an issue to keep track of this


const data = eventSerdes.toJson(event);
res.raw.write(serializeSSEEvent({event: event.type, data}));
} catch (e) {
Expand All @@ -49,7 +53,12 @@ export function getRoutes(config: ChainForkConfig, api: ServerApi<Api>): ServerR
// The client may disconnect and we need to clean the subscriptions.
req.raw.once("close", () => resolve());
req.raw.once("end", () => resolve());
req.raw.once("error", (err) => reject(err));
req.raw.once("error", (err) => {
if ((err as unknown as {code: string}).code === "ECONNRESET") {
Copy link
Member

@nflaig nflaig Jul 14, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I reviewed our code and did some research on how EventSource behaves. It looks like we are closing this correctly on the client by calling .close().

It is invoking both the close and error event on the server, this is a bit strange to me but it looks like that's how EventSource works, it doesn't gracefully close for some reason.

Another thing is that usually this would be handled by fastify which also just ignore errors with code ECONNRESET, see https://github.com/fastify/fastify/blob/cc347d7c0b4266097b61b126158b797878668353/fastify.js#L667C23-L667C33

But since the event API is not handled by fastify we need to do it ourselves and applying same pattern sounds good to me.

We might even consider just resolving here instead of rejecting with abort error but I guess if this error is not logged due to it being ignored upstream this is also fine.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I feel we should abort here on ECONNRESET and let the higher level stack handle that error, as it's currently doing. Once we have more resources to knew if the reset was actually abort or gracefully closed by client then we can decide to resolve the later scenario.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, sounds good to me 👍

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is invoking both the close and error event on the server, this is a bit strange to me but it looks like that's how EventSource works, it doesn't gracefully close for some reason.

This might be related to

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is also simliar to issue reported here

return reject(new ErrorAborted());
}
return reject(err);
});
});

// api.eventstream will never stop, so no need to ever call `res.raw.end();`
Expand Down
4 changes: 2 additions & 2 deletions packages/cli/src/cmds/validator/signers/index.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -86,7 +86,7 @@ export async function getSignersFromArgs(
const needle = showProgress({
total: keystoreDefinitions.length,
frequencyMs: KEYSTORE_IMPORT_PROGRESS_MS,
signal: signal,
signal,
progress: ({ratePerSec, percentage, current, total}) => {
logger.info(
`${percentage.toFixed(0)}% of keystores imported. current=${current} total=${total} rate=${(
Expand Down Expand Up @@ -119,7 +119,7 @@ export async function getSignersFromArgs(
const needle = showProgress({
total: keystoreDefinitions.length,
frequencyMs: KEYSTORE_IMPORT_PROGRESS_MS,
signal: signal,
signal,
progress: ({ratePerSec, percentage, current, total}) => {
logger.info(
`${percentage.toFixed(0)}% of local keystores imported. current=${current} total=${total} rate=${(
Expand Down