search

dotansimha / graphql-yoga

🧘 Rewrite of a fully-featured GraphQL Server with focus on easy setup, performance & great developer experience. The core of Yoga implements WHATWG Fetch API and can run/deploy on any JS environment.
https://the-guild.dev/graphql/yoga-server
MIT License
8.14k stars 562 forks source link

[ERR_HTTP_HEADERS_SENT] Cannot write headers after they are sent to the client #3099

Open gajus opened 8 months ago

gajus commented 8 months ago

Describe the bug

[22:36:15.758]   0ms error %@contra/contra-api: unhandledRejection
error:
  code:    ERR_HTTP_HEADERS_SENT
  message: Cannot write headers after they are sent to the client
  name:    Error
  stack:
    """
      Error [ERR_HTTP_HEADERS_SENT]: Cannot write headers after they are sent to the client
          at ServerResponse.writeHead (node:_http_server:345:11)
          at safeWriteHead (/srv/node_modules/.pnpm/fastify@4.24.3/node_modules/fastify/lib/reply.js:556:9)
          at onSendEnd (/srv/node_modules/.pnpm/fastify@4.24.3/node_modules/fastify/lib/reply.js:595:5)
          at wrapOnSendEnd (/srv/node_modules/.pnpm/fastify@4.24.3/node_modules/fastify/lib/reply.js:549:5)
          at next (/srv/node_modules/.pnpm/fastify@4.24.3/node_modules/fastify/lib/hooks.js:293:7)
          at handleResolve (/srv/node_modules/.pnpm/fastify@4.24.3/node_modules/fastify/lib/hooks.js:310:5)
          at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    """

Added console.trace to try to catch it.

Trace: header
    at Reply.header (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:247:11)
    at Reply.headers (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:274:10)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:60:19)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Trace: header
    at Reply.header (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:247:11)
    at Reply.headers (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:274:10)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:60:19)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Trace: header
    at Reply.header (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:247:11)
    at Reply.headers (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:274:10)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:60:19)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Trace: send
    at Reply.send (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:134:11)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:71:26)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Trace: header
    at Reply.header (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:247:11)
    at setCookies (/srv/node_modules/.pnpm/@fastify+cookie@9.1.0/node_modules/@fastify/cookie/plugin.js:80:15)
    at Object.fastifyCookieOnSendHandler (/srv/node_modules/.pnpm/@fastify+cookie@9.1.0/node_modules/@fastify/cookie/plugin.js:109:5)
    at next (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/hooks.js:299:30)
    at onSendHookRunner (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/hooks.js:321:3)
    at onSendHook (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:537:5)
    at Reply.send (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:161:7)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:71:26)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)

Our setup is pretty basic:

import { createContext } from './createContext.js';
import { AuthenticationError, ForbiddenError } from '@contra/errors';
import { type DatabasePool } from '@contra/slonik';
import { type Configuration } from '@contra/temporary-common/types.js';
import { useSchema } from '@envelop/core';
import { useParserCache } from '@envelop/parser-cache';
import { useValidationCache } from '@envelop/validation-cache';
import { renderGraphiQL } from '@graphql-yoga/render-graphiql';
import { FastifyReply, FastifyRequest } from 'fastify';
import { fastifyPlugin } from 'fastify-plugin';
import { GraphQLError, type GraphQLSchema } from 'graphql';
import { createYoga, maskError } from 'graphql-yoga';
import { type Redis } from 'ioredis';
import { randomUUID } from 'node:crypto';
import lru from 'tiny-lru';

export const createGraphqlPlugin = fastifyPlugin<{
  configuration: Configuration;
  pool: DatabasePool;
  redis: Redis;
  schema: GraphQLSchema;
}>(async (fastify, options) => {
  const DAY = 24 * 60 * 60 * 1_000;

  type ServerContext = {
    reply: FastifyReply;
    request: FastifyRequest;
  };

  const yoga = createYoga<ServerContext>({
    context: ({ request }) => {
      return createContext({
        configuration: options.configuration,
        pool: options.pool,
        redis: options.redis,
        request,
      });
    },
    graphqlEndpoint: '/',
    maskedErrors: options.configuration['error-masking']
      ? {
          maskError: (error, message, isDevelopment) => {
            // We don't know what this error, therefore using the default masking function
            if (!(error instanceof GraphQLError)) {
              return maskError(error, message, isDevelopment);
            }

            const originalError = error?.originalError as
              | (Error & {
                  code?: string;
                  extensions?: Record<string, any>;
                })
              | undefined;

            const uid = randomUUID();

            // Authentication/authorization errors are expected, so we don't mask or report them either
            if (
              originalError instanceof AuthenticationError ||
              originalError instanceof ForbiddenError
            ) {
              return new GraphQLError(
                originalError.message,
                error.nodes,
                error.source,
                error.positions,
                error.path,
                null,
                { code: originalError.code, uid },
              );
            }

            return maskError(error, message, isDevelopment);
          },
        }
      : false,
    plugins: [
      useSchema(options.schema),
      useParserCache({
        documentCache: lru(10_000, DAY),
      }),
      useValidationCache({
        cache: lru(10_000, DAY),
      }),
    ],
    renderGraphiQL,
    schema: options.schema,
  });

  void fastify.route({
    handler: async (request, reply) => {
      const response = await yoga.handleNodeRequest(request, {
        reply,
        request,
      });

      reply.headers({
        ...Object.fromEntries(response.headers.entries()),
        'x-contra-release-version':
          options.configuration['release-version'] ?? 'n/a',
      });

      if (reply.sent) {
        console.trace('already sent 1');
      }

      reply.status(response.status);

      if (reply.sent) {
        console.trace('already sent 2');
      }

      return reply.send(response.body);
    },
    method: ['GET', 'POST', 'OPTIONS'],
    url: yoga.graphqlEndpoint,
  });
});

This error appeared only after trying to migrate from Helix to Yoga.

Your Example Website or App

N/A

Steps to Reproduce the Bug or Issue

N/A

Expected behavior

N/A

Screenshots or Videos

No response

Platform

N/A

Additional context

No response

ardatan commented 8 months ago

Could you disable your cookie plugin and try again?

gajus commented 8 months ago

Not really, because the tests that are failing are for authorized user. So everything would fail even before it gets to it.

For what it is worth, we are just using "@fastify/cookie": "^9.1.0",.

I could patch the plugin if you see anything wrong with it.

For what it is worth, I looked at the plugin and nothing looks off.

https://github.com/fastify/fastify-cookie/blob/efea6715583149fdc7a591ca831047a84e3b80ce/plugin.js#L72

gajus commented 8 months ago

I am not convinced that it is coming from the cookie plugin either. For instance, this crash does not refer to the cookie plugin.

[00:56:47.931]   1ms debug @slonik: query execution result
connectionId:  727761d2
executionTime: 1ms
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
poolId:        65570a6c
queryId:       810e1260
reqId:         b9fe139a-df04-4e66-bf47-468d26e75b94
rowCount:      1
Trace: header
    at Reply.header (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:247:11)
    at Reply.headers (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:274:10)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:60:19)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Trace: header
    at Reply.header (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:247:11)
    at Reply.headers (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:274:10)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:60:19)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Trace: header
    at Reply.header (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:247:11)
    at Reply.headers (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:274:10)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:60:19)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Trace: send
    at Reply.send (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:134:11)
    at Object.handler (file:///srv/apps/contra-api/dist/contra-api/factories/createGraphqlPlugin.js:71:26)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[00:56:47.932]   1ms debug %@contra/contra-api: The existing session was not changed, leaving it as is
hook:       onSend
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
plugin:     fastify-session
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
sessionId:  8gXnlS9ivKbRprUiJEjOt
[00:56:47.937]   5ms error %@contra/contra-api: unhandled request handler error
error:
  code:    ERR_STREAM_PREMATURE_CLOSE
  message: Premature close
  name:    Error
  stack:
    """
      Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
          at Readable.onclose (node:internal/streams/end-of-stream:154:30)
          at Readable.emit (node:events:515:28)
          at Readable.emit (node:domain:488:12)
          at emitCloseNT (node:internal/streams/destroy:132:10)
          at process.processTicksAndRejections (node:internal/process/task_queues:81:21)
    """
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
Trace: send
    at Reply.send (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:134:11)
    at Object.<anonymous> (file:///srv/apps/contra-api/dist/contra-api/factories/createFastifyApp.js:70:34)
    at handleError (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/error-handler.js:65:18)
    at onErrorHook (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:781:5)
    at Proxy.<anonymous> (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:669:9)
    at Proxy.<anonymous> (node:internal/util:534:12)
    at Readable.onclose (node:internal/streams/end-of-stream:153:25)
    at Readable.emit (node:events:515:28)
    at Readable.emit (node:domain:488:12)
    at emitCloseNT (node:internal/streams/destroy:132:10)
[00:56:47.938]   1ms debug %@contra/contra-api: The existing session was not changed, leaving it as is
hook:       onSend
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
plugin:     fastify-session
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
sessionId:  8gXnlS9ivKbRprUiJEjOt
Trace: send
    at Reply.send (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:134:11)
    at /srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/wrapThenable.js:25:15
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[00:56:47.938]   0ms debug %@contra/contra-api: The existing session was not changed, leaving it as is
hook:       onSend
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
plugin:     fastify-session
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
sessionId:  8gXnlS9ivKbRprUiJEjOt
[00:56:47.938]   0ms warn  %@contra/contra-api: Reply was already sent, did you forget to "return reply" in the "/" (POST) route?
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
[00:56:47.939]   1ms error %@contra/contra-api: unhandledRejection
error:
  code:    ERR_HTTP_HEADERS_SENT
  message: Cannot write headers after they are sent to the client
  name:    Error
  stack:
    """
      Error [ERR_HTTP_HEADERS_SENT]: Cannot write headers after they are sent to the client
          at ServerResponse.writeHead (node:_http_server:345:11)
          at safeWriteHead (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:560:9)
          at onSendEnd (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:599:5)
          at wrapOnSendEnd (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:553:5)
          at next (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/hooks.js:293:7)
          at handleResolve (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/hooks.js:310:5)
          at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    """
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
[00:56:47.940]   1ms info  @lightship: received request to shutdown the service
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
[00:56:47.940]   0ms debug @lightship: running 1 shutdown handler(s)
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
[00:56:47.940]   0ms info  %@contra/contra-api: gracefully shutting down contra-api
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/user-profile/inline-editing/inline-editing_1.spec.ts
  project:
  testCase: empty states
  uid:      98f4ba9a-7ead-4bc8-9c15-a466a51c11ee
reqId:      b9fe139a-df04-4e66-bf47-468d26e75b94
This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason:
Error [ERR_HTTP_HEADERS_SENT]: Cannot write headers after they are sent to the client
    at ServerResponse.writeHead (node:_http_server:345:11)
    at safeWriteHead (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:560:9)
    at onSendEnd (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:599:5)
    at wrapOnSendEnd (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:553:5)
    at next (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/hooks.js:293:7)
    at handleResolve (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/hooks.js:310:5)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[00:56:47.943]   3ms debug @slonik: client connection is closed and removed from the client pool
ardatan commented 8 months ago

Then could you help us to reproduce it because error stack traces look too cryptic for us to understand the problem?

gajus commented 8 months ago

Annoyingly I was not able to replicate it locally yet, so cannot provide that or fix it. But I am working on it.

gajus commented 8 months ago

I am still trying to understand what is happening here, but it looks like it happens after there is an unhandled rejection:

[03:16:11.343]   2ms debug %@contra/contra-api: The existing session was not changed, leaving it as is
hook:       onSend
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/dashboard/contractor/portfolio-viewers.spec.ts
  project:
  testCase: can navigate to viewers page with more than 5 viewers, share profile and go back to dashboard
  uid:      a9b64b8e-0345-4754-a53d-0f9033ca14db
plugin:     fastify-session
reqId:      36ce1ecc-0522-4d11-913b-faa1fed74925
sessionId:  UM3S7ehut8A6-0TSYCD0z
error handler Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
    at Readable.onclose (node:internal/streams/end-of-stream:154:30)
    at Readable.emit (node:events:515:28)
    at Readable.emit (node:domain:488:12)
    at emitCloseNT (node:internal/streams/destroy:132:10)
    at process.processTicksAndRejections (node:internal/process/task_queues:81:21) {
  code: 'ERR_STREAM_PREMATURE_CLOSE'
} false
[03:16:11.348]   5ms error %@contra/contra-api: unhandled request handler error
error:
  code:    ERR_STREAM_PREMATURE_CLOSE
  message: Premature close
  name:    Error
  stack:
    """
      Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
          at Readable.onclose (node:internal/streams/end-of-stream:154:30)
          at Readable.emit (node:events:515:28)
          at Readable.emit (node:domain:488:12)
          at emitCloseNT (node:internal/streams/destroy:132:10)
          at process.processTicksAndRejections (node:internal/process/task_queues:81:21)
    """
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/dashboard/contractor/portfolio-viewers.spec.ts
  project:
  testCase: can navigate to viewers page with more than 5 viewers, share profile and go back to dashboard
  uid:      a9b64b8e-0345-4754-a53d-0f9033ca14db
reqId:      36ce1ecc-0522-4d11-913b-faa1fed74925
Trace: send
    at Reply.send (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:134:11)
    at Object.<anonymous> (file:///srv/apps/contra-api/dist/contra-api/factories/createFastifyApp.js:71:34)
    at handleError (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/error-handler.js:65:18)
    at onErrorHook (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:781:5)
    at Proxy.<anonymous> (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:669:9)
    at Proxy.<anonymous> (node:internal/util:534:12)
    at Readable.onclose (node:internal/streams/end-of-stream:153:25)
    at Readable.emit (node:events:515:28)
    at Readable.emit (node:domain:488:12)
    at emitCloseNT (node:internal/streams/destroy:132:10)
[03:16:11.349]   1ms debug %@contra/contra-api: The existing session was not changed, leaving it as is
hook:       onSend
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/dashboard/contractor/portfolio-viewers.spec.ts
  project:
  testCase: can navigate to viewers page with more than 5 viewers, share profile and go back to dashboard
  uid:      a9b64b8e-0345-4754-a53d-0f9033ca14db
plugin:     fastify-session
reqId:      36ce1ecc-0522-4d11-913b-faa1fed74925
sessionId:  UM3S7ehut8A6-0TSYCD0z
Trace: send
    at Reply.send (/srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/reply.js:134:11)
    at /srv/node_modules/.pnpm/fastify@4.24.3_patch_hash=lcbqiye6cxjewuoghmhivz2pjm/node_modules/fastify/lib/wrapThenable.js:25:15
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[03:16:11.349]   0ms debug %@contra/contra-api: The existing session was not changed, leaving it as is
hook:       onSend
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/dashboard/contractor/portfolio-viewers.spec.ts
  project:
  testCase: can navigate to viewers page with more than 5 viewers, share profile and go back to dashboard
  uid:      a9b64b8e-0345-4754-a53d-0f9033ca14db
plugin:     fastify-session
reqId:      36ce1ecc-0522-4d11-913b-faa1fed74925
sessionId:  UM3S7ehut8A6-0TSYCD0z
[03:16:11.349]   0ms warn  %@contra/contra-api: Reply was already sent, did you forget to "return reply" in the "/" (POST) route?
playwright:
  file:     /home/github/actions-runner/_work/gaia/gaia/apps/contra-web-app/tests/e2e/dashboard/contractor/portfolio-viewers.spec.ts
  project:
  testCase: can navigate to viewers page with more than 5 viewers, share profile and go back to dashboard
  uid:      a9b64b8e-0345-4754-a53d-0f9033ca14db
reqId:      36ce1ecc-0522-4d11-913b-faa1fed74925

This is our error handler:

  console.error('error handler', error, reply.sent);

  if (
    [
      'ECONNRESET',
      'FST_ERR_CTP_EMPTY_JSON_BODY',
      'FST_ERR_CTP_INVALID_MEDIA_TYPE',
    ].includes(error.code)
  ) {
    request.log.debug(
      {
        error: serializeError(error),
      },
      'Returning 400 status code for invalid payload',
    );

    return reply.status(400).send();
  }

  captureException(error);

  request.log.error(
    {
      error: serializeError(error),
    },
    'unhandled request handler error',
  );

  if (onUnhandledError) {
    onUnhandledError();
  }

  if (reply.sent) {
    request.log.error('reply already sent, not sending 500');

    return null;
  }

  return reply.status(500).send({
    error: 'An unknown error has occurred.',
    requestId: request.id,
  });
});

As seen from logs, it looks like Yoga attempted to send a reply even though it was handled by the setErrorHandler, i.e. setErrorHandler already sent a response. Trying to replicate this in a smaller example now.

ardatan commented 8 months ago

Sorry but this is not helpful enough for us to debug the issue. We need a proper reproduction like I said above.

gajus commented 8 months ago

I don't know what the underlying issue is, but the issue is def with graphql-yoga / Fastify interoperability.

I realized that Yoga response itself is a readable stream, and given that I don't use readable streams elsewhere, I tried to buffer the response. Turns out that fixes the issue, i.e.

- return reply.send(response.body);
+ const buffers = [];
+ 
+ for await (const data of response.body) {
+   buffers.push(data);
+ }
+ 
+ reply.send(Buffer.concat(buffers));
+ 
+ return reply;

Hope this helps others.

gajus commented 8 months ago

Will leave this open since it is an issue with Yoga / Fastify compatibility.

ardatan commented 8 months ago

Instead of return reply.send, it should be reply.send and return reply like here already; https://github.com/dotansimha/graphql-yoga/blob/main/examples/fastify/src/app.ts#L90

Urigo commented 8 months ago

is there something we could add on the Yoga-Fastify docs to make sure people know how to use it properly?

kingston commented 2 months ago

@gajus I encountered this issue in our E2E tests which were pretty bad since it pretty much triggered the entire Node server to crash on a premature close with @fastify/session. After a bit of digging, I figured out that using handleNodeRequestAndResponse instead of handleNodeRequest fixes this issue. It looks like this was released in Graphql Yoga 5.3.0.

    const response = await graphQLServer.handleNodeRequestAndResponse(
      request,
      reply,
      {
        req: request,
        reply,
      },
    );
gajus commented 2 months ago

Thanks for this. Just deployed this change – so far looking really good!