PingPong / Graceful Restart sometimes throwing a fatal error error.

[CristianCiubancan]

For future chads: the error below came frok the fact that the ws connection was not closing with an apropriate status this throwing a fatal error after which the connection could not be reset.

In order to solve this i exported the websocket instance and used it in my index.js where inside a useEffect I would call socket.close(1000, 'normal close') whenever I would get my app in bacground, and on taking the app to foreground I would socket.close(4025, "Client Restart). For now it worked for me. Thanks, have a great day!

Sometimes i am getting the following error:

-on the client side:

Event {
  "code": 1002,
  "isTrusted": false,
  "reason": null,
}

-on the server side:

Internal error emitted on a WebSocket socket. Please check your implementation. RangeError: Invalid WebSocket frame: invalid payload length 
126
    at Receiver.getInfo (C:\Users\ciuba\Desktop\chatapp\server\node_modules\ws\lib\receiver.js:264:16)
    at Receiver.startLoop (C:\Users\ciuba\Desktop\chatapp\server\node_modules\ws\lib\receiver.js:136:22)
    at Receiver._write (C:\Users\ciuba\Desktop\chatapp\server\node_modules\ws\lib\receiver.js:83:10)
    at writeOrBuffer (internal/streams/writable.js:358:12)
    at Receiver.Writable.write (internal/streams/writable.js:303:10)  
    at Socket.socketOnData (C:\Users\ciuba\Desktop\chatapp\server\node_modules\ws\lib\websocket.js:1116:35)
    at Socket.emit (events.js:400:28)
    at Socket.emit (domain.js:475:12)
    at addChunk (internal/streams/readable.js:293:12)
    at readableAddChunk (internal/streams/readable.js:267:9) {        
  code: 'WS_ERR_INVALID_CONTROL_PAYLOAD_LENGTH',
  [Symbol(status-code)]: 1002
}

This is my setup client side implementation:

import {
  ApolloLink,
  Operation,
  FetchResult,
  Observable,
} from "@apollo/client/core";
import { GraphQLError, print } from "graphql";
import { createClient, ClientOptions, Client } from "graphql-ws";
import { host } from "../modules/shared/constants";

class WebSocketLink extends ApolloLink {
  private client: Client;

  constructor(options: ClientOptions) {
    super();
    this.client = createClient(options);
  }

  public request(operation: Operation): Observable<FetchResult> {
    return new Observable((sink) => {
      return this.client.subscribe<FetchResult>(
        { ...operation, query: print(operation.query) },
        {
          next: sink.next.bind(sink),
          complete: sink.complete.bind(sink),
          error: (err) => {
            console.log(err);
            // if (err instanceof Error) {
            //   return sink.error(err);
            // }

            // if (err instanceof CloseEvent) {
            //   return sink.error(
            //     // reason will be available on clean closes
            //     new Error(
            //       `Socket closed with event ${err.code} ${err.reason || ""}`
            //     )
            //   );
            // }

            // return sink.error(
            //   new Error(
            //     (err as GraphQLError[]).map(({ message }) => message).join(", ")
            //   )
            // );
          },
        }
      );
    });
  }
}

export const webSocketLink = () => {
  let activeSocket: any,
    timedOut: any,
    pingSentAt = 0,
    latency = 0;
  let restartRequested = false;
  let restart = () => {
    restartRequested = true;
  };
  return new WebSocketLink({
    url: `${host}/graphql` as string,
    lazy: true,
    retryWait: async function waitForServerHealthyBeforeRetry() {
      await new Promise((resolve) =>
        setTimeout(resolve, 1000 + Math.random() * 3000)
      );
    },
    on: {
      opened: (socket: any) => (activeSocket = socket),
      ping: (received) => {
        if (!received /* sent */) {
          pingSentAt = Date.now();
          timedOut = setTimeout(() => {
            if (activeSocket.readyState === WebSocket.OPEN)
              activeSocket.close(4408, "Request Timeout");
          }, 5_000); // wait 5 seconds for the pong and then close the connection
        }
      },
      pong: (received) => {
        if (received) {
          latency = Date.now() - pingSentAt;
          clearTimeout(timedOut); // pong is received, clear connection close timeout
        }
      },
    },
  });
};

It usually works but sometimes it just throws this error. My guess is that when trying to close the connection and reestablish it the server invalidates the request due to an old subcriber id thus throwing this error.

Any thoughts on where it might originate from or how I might be able to fix it?

Thanks in advance!

And thank you for the great work so far!

EDIT

I looked at the recepie for ping pong again and saw that I was add ing unnecessary retryWait and lazy:true , took that out and added :

 keepAlive: 10000,

now a new error shows on the client side:

Event {
  "isTrusted": false,
  "message": "The operation couldn’t be completed. Connection reset by peer",
}

also i got this one a separate time 👍

Event {
  "isTrusted": false,
  "message": "Error writing to stream",
}

Further explanation after i Take the app to background, leave it there for 20+ seconds , send a message from another device and take the app back to foreground I am not able to receive subscriptions until I move between screens.

Another important thing to mention is that I client.resetStore() everytime i take my app to ferground in order to keep updated with the latest changes. client.resetStore() refetches all active queries (all queries from mounted components), I tried commenting it out and apparently after many tries still got the same error 👍

Event {
  "isTrusted": false,
  "message": "The operation couldn’t be completed. Connection reset by peer",
}

[enisdenjo]

Thanks for reporting, @CristianCiubancan, my time is a bit scarce now, but I will take a look at this as soon as possible.

My guess is that when trying to close the connection and reestablish it the server invalidates the request due to an old subcriber id thus throwing this error.

This is very intentional, restarts will always have subscriptions re-subscribe with the same ID. That behavior should not cause any problems.

---

In the meantime, since you have control over your server, you should absolutely use the server-side WebSocket protocol level pings and pongs, instead of the subprotocol pings and pongs from the recipe.

One of the main reasons why subprotocol pings and pongs exist in the first place is because some servers dont implement the WebSocket protocol pings and pongs (like AWS). For such servers, the subprotocol pings and pongs is simply an escape hatch. Read more here: #201 and here: #117.

Also, please read this comment to understand why client-side pings are not critical.

One more thing you should know is that browsers often pause JavaScript when in background.

WebSocket protocol level pings and pongs are built in all usable servers in graphql-ws (and default to an interval of 12 seconds):

• use/ws
  

  graphql-ws/src/use/ws.ts

  Lines 42 to 49 in 6b14be3

  	/**
  	* The timout between dispatched keep-alive messages. Internally uses the [ws Ping and Pongs]((https://developer.mozilla.org/en-US/docs/Web/API/wss_API/Writing_ws_servers#Pings_and_Pongs_The_Heartbeat_of_wss))
  	* to check that the link between the clients and the server is operating and to prevent the link
  	* from being broken due to idling.
  	*
  	* @default 12_000 // 12 seconds
  	*/
  	keepAlive = 12_000,

  
  

  graphql-ws/src/use/ws.ts

  Lines 98 to 121 in 6b14be3

  	// keep alive through ping-pong messages
  	let pongWait: NodeJS.Timeout | null = null;
  	const pingInterval =
  	keepAlive > 0 && isFinite(keepAlive)
  	? setInterval(() => {
  	// ping pong on open sockets only
  	if (socket.readyState === socket.OPEN) {
  	// terminate the connection after pong wait has passed because the client is idle
  	pongWait = setTimeout(() => {
  	socket.terminate();
  	}, keepAlive);
  	// listen for client's pong and stop socket termination
  	socket.once('pong', () => {
  	if (pongWait) {
  	clearTimeout(pongWait);
  	pongWait = null;
  	}
  	});
  	socket.ping();
  	}
  	}, keepAlive)
  	: null;

• use/fastify-websocket
  

  graphql-ws/src/use/fastify-websocket.ts

  Lines 34 to 41 in 6b14be3

  	/**
  	* The timout between dispatched keep-alive messages. Internally uses the [ws Ping and Pongs]((https://developer.mozilla.org/en-US/docs/Web/API/wss_API/Writing_ws_servers#Pings_and_Pongs_The_Heartbeat_of_wss))
  	* to check that the link between the clients and the server is operating and to prevent the link
  	* from being broken due to idling.
  	*
  	* @default 12_000 // 12 seconds
  	*/
  	keepAlive = 12_000,

  
  

  graphql-ws/src/use/fastify-websocket.ts

  Lines 109 to 132 in 6b14be3

  	// keep alive through ping-pong messages
  	let pongWait: NodeJS.Timeout | null = null;
  	const pingInterval =
  	keepAlive > 0 && isFinite(keepAlive)
  	? setInterval(() => {
  	// ping pong on open sockets only
  	if (socket.readyState === socket.OPEN) {
  	// terminate the connection after pong wait has passed because the client is idle
  	pongWait = setTimeout(() => {
  	socket.terminate();
  	}, keepAlive);
  	// listen for client's pong and stop socket termination
  	socket.once('pong', () => {
  	if (pongWait) {
  	clearTimeout(pongWait);
  	pongWait = null;
  	}
  	});
  	socket.ping();
  	}
  	}, keepAlive)
  	: null;

• use/uWebSockets
  

  graphql-ws/src/use/uWebSockets.ts

  Lines 74 to 81 in 6b14be3

  	/**
  	* The timout between dispatched keep-alive messages. Internally uses the [ws Ping and Pongs]((https://developer.mozilla.org/en-US/docs/Web/API/wss_API/Writing_ws_servers#Pings_and_Pongs_The_Heartbeat_of_wss))
  	* to check that the link between the clients and the server is operating and to prevent the link
  	* from being broken due to idling.
  	*
  	* @default 12_000 // 12 seconds
  	*/
  	keepAlive = 12_000,

  
  

  graphql-ws/src/use/uWebSockets.ts

  Lines 168 to 174 in 6b14be3

  	if (keepAlive > 0 && isFinite(keepAlive)) {
  	client.pingInterval = setInterval(() => {
  	// terminate the connection after pong wait has passed because the client is idle
  	client.pongWaitTimeout = setTimeout(() => socket.close(), keepAlive);
  	socket.ping();
  	}, keepAlive);
  	}

[CristianCiubancan]

unfortunately I don't understand how I might implement subprotocol pings and pongs in my server.
I am using apollo express server :

const main = async () => {
  const conn = await createConnection({
    type: "postgres",
    url: process.env.DATABASE_URL,
    logging: false,
    ssl: __prod__ ? { rejectUnauthorized: false } : false,
    synchronize: true,
    migrations: [path.join(__dirname, "./migrations/*")],
    entities: [User, Chat, ChatMembers, Message, Reader],
  });

  await conn.runMigrations();

  const pubSub = new RedisPubSub({
    connection: process.env.REDIS_URL as any,
  });

  const schema = await buildSchema({
    resolvers: [UserResolver, ChatResolver, MessageResolver],
    pubSub,
  });

  const app = express();
  const RedisStore = connectRedis(session);

  const redisClient = redis;

  app.set("trust proxy", 1);

  app.use(
    cors({
      origin: process.env.CORS_ORIGIN, //asa obijnuia sa fie
      credentials: true,
    })
  );

  const sessionMiddleware = session({
    store: new RedisStore({
      client: redisClient,
      disableTouch: true,
    }),
    name: COOKIE_NAME,
    secret: process.env.SESSION_SECRET,
    resave: false,
    saveUninitialized: false,
    cookie: {
      httpOnly: true,
      sameSite: "lax",
      secure: __prod__, //cookie only works in https
      maxAge: 1000 * 60 * 60 * 24 * 365 * 10, //10 years
    },
  } as any);

  app.use(sessionMiddleware);

  const apolloServer = new ApolloServer({
    schema,
    context: ({ req, res }: MyContext) => ({
      req,
      res,
      redis,
      usersLoader: createUsersLoader(),
      chatsLoader: createChatsLoader(),
      messagesLoader: createMessagesLoader(),
      readerLoader: createReaderLoader(),
      lastMessageLoader: createLastMessageLoader(),
    }),
  });

  app.use(graphqlUploadExpress({ maxFileSize: 10000000, maxFiles: 10 }));
  app.use("/images", express.static(path.join(__dirname, "../images")));
  app.use("/sounds", express.static(path.join(__dirname, "../sounds")));

  await apolloServer.start();
  apolloServer.applyMiddleware({
    app,
    cors: false,
  });

  const server = app.listen(parseInt(process.env.PORT), () => {
    const wsServer = new ws.WebSocketServer({
      
      server,
      path: "/graphql",
    });

    useServer(
      {
        schema,
        context: async (ctx: any) => {
          const promise = new Promise((resolve) => {
            const req = ctx.extra.request as express.Request & {
              session: Session & Partial<SessionData> & { userId?: number };
            };
            const res = {} as any as express.Response;
            sessionMiddleware(req, res, (_: any) => {
              return resolve({ req, res });
            });
          });
          const { req, res } = (await promise) as any;
          return {
            req,
            res,
            redis,
            usersLoader: createUsersLoader(),
            chatsLoader: createChatsLoader(),
            messagesLoader: createMessagesLoader(),
            readerLoader: createReaderLoader(),
            lastMessageLoader: createLastMessageLoader(),
          };
        },
        // onConnect: (ctx) => {
        //   console.log(ctx);
        // },
        // onConnect: (ctx) => {
        //   console.log("Connect", ctx);
        // },
        // onSubscribe: (ctx, msg) => {
        //   console.log("Subscribe", { ctx, msg });
        // },
        // onNext: (ctx, msg, args, result) => {
        //   const { payload } = msg;
        //   // console.debug("Next", { ctx, msg, args, result });
        //   console.log(payload);
        // },
        // onError: (ctx, msg, errors) => {
        //   console.error("Error", { ctx, msg, errors });
        // },
        // onComplete: (ctx, msg) => {
        //   console.log("Complete", { ctx, msg });
        // },
      },
      wsServer
    );
    console.log(
      `🚀 Graphql server ready at http://localhost:4000${apolloServer.graphqlPath}`
    );
  });
};

main();

[enisdenjo]

I am saying you should not use subprotocol pings and pongs. WebSocket pings and pongs are built in, your example has them already working.

You can use Firefox and its dev tools to see them in action (Chrome hides them away).

[CristianCiubancan]

ok cool, sorry for missunderstanding, I kinda intuitively figured that out already as everything was working anyway without ping pong implemented. for now I think everything is working fine with the "batteries included" in graphql-ws for the web, and for react native, my fix works like a charm.

[enisdenjo]

Brilliant! No need to apologize, I am here to help. 😄

[enisdenjo]

Seems like the same problem that caused the server to send too big close frames (#243) was affecting the client. This has been fixed in v5.5.5.

Additionally, with v5.5.5, the original close causing internal client error will be reported to error listeners, instead of the resulting close event. This allows for much better error handling.

@CristianCiubancan could you be so kind and update the version and try again?

[CristianCiubancan]

My react-native clientside still gives me the same errors.
More exactly this one :

Event {
  "isTrusted": false,
  "message": "Error writing to stream",
} 

Even after upgrading to graphql-ws 5.5.5 both on server and client side.

I must add that the errors pointed in the opening only show on client side, the server side errors are no longer printing when those events occour.

As I was saying my fix was to:

• call await sock.close(1000, "normal closure") everytime I take my app to background
• call await sock.close(4205, "Client Restart") everytime I take my app to foreground
  And this works flawlessly without any modifications to the server side

my guess is that closing the connection with the code 4408 makes the connection not reestablishable.

[enisdenjo]

That looks like a react-native specific error, haven't seen it in the browser nor in Node. Something similar to facebook/react-native#26450?

Code 4408 is "connection initialization timeout", meaning, the client failed to introduce itself in time.

I dont follow now, have you managed to fix the issue?

[CristianCiubancan]

yes, In my App.tsx i am listening for app state change and on entering background change I

• call await sock.close(1000, "normal closure") everytime I take my app to background
• call await sock.close(4205, "Client Restart") everytime I take my app to foreground
  this fixes it for me.

[enisdenjo]

Great stuff! Glad you got it working. 😄

[CristianCiubancan]

thank you for your time man, best regards!