grapqhl-ws/client : malformed query error are swallowed and client simply "completes"

[nomocas]

Hello All,

Client graphql-ws v5.5.0
on nodejs v14.17.0

Server : Hasura v2.0.9

Expected Behaviour
I expect graphql-ws/client to show an error when a query is malformed.

Actual Behaviour
Instead it simply close the connection (complete event) without providing any clue. So, if you do not have access to server's logs : you don't understand why this behaviour happen.

It shows nothing even if I add all possible events handlers in my client. e.g. :

const client = createClient({
       ....
        on: {
            connected: () => {
                debug('connected');
            },
            connecting: () => {
                debug('connecting');
            },
            opened: () => {
                debug('opened');
            },
            closed: () => {
                debug('closed');
            },
            message: (msg) => {
                debug('message', msg);
            },
            ping: (msg) => {
                debug('ping', msg);
            },
            pong: (msg) => {
                debug('pong', msg);
            },
            error: (err) => {
                console.error(err);
            },
        },
        onNonLazyError: (errorOrCloseEvent) => {
            console.error(errorOrCloseEvent);
        },
    });

Debug Information
To reproduce, simply add a typo in your query/subscription and boom : it "completes" instead of throwing.

Thanks for adding proper error handlers in that case.
Clue : in the catch at line 642 (client.ts) : simply rethrow or at least print the error message.

[enisdenjo]

Validation happens on the server, not on the client. Re-throwing the catch on line 642 wont change anything.

Invalid queries are fatal errors; meaning, the connection gets closed immediately and you have the necessary information in the close event. This indeed works and I've added a test case to confirm:

graphql-ws/src/__tests__/client.ts

Lines 433 to 470 in 21e44db

	it('should close socket with error on malformed request', async (done) => {
	expect.assertions(4);
	const { url } = await startTServer();
	const client = createClient({
	url,
	lazy: false,
	retryAttempts: 0,
	onNonLazyError: noop,
	on: {
	closed: (err) => {
	expect((err as CloseEvent).code).toBe(CloseCode.InternalServerError);
	expect((err as CloseEvent).reason).toBe(
	'Syntax Error: Unexpected Name "notaquery".',
	);
	},
	},
	});
	client.subscribe(
	{
	query: 'notaquery',
	},
	{
	next: noop,
	error: (err) => {
	expect((err as CloseEvent).code).toBe(CloseCode.InternalServerError);
	expect((err as CloseEvent).reason).toBe(
	'Syntax Error: Unexpected Name "notaquery".',
	);
	client.dispose();
	done();
	},
	complete: noop,
	},
	);
	});

To get the message, check the error argument of the on.closed callback.

const client = createClient({
       ....
        on: {
            connected: () => {
                debug('connected');
            },
            connecting: () => {
                debug('connecting');
            },
            opened: () => {
                debug('opened');
            },
-           closed: () => {
-               debug('closed');
-           },
+           closed: (err) => {
+               debug('closed', err.code, err.reason);
+          },
            message: (msg) => {
                debug('message', msg);
            },
            ping: (msg) => {
                debug('ping', msg);
            },
            pong: (msg) => {
                debug('pong', msg);
            },
            error: (err) => {
                console.error(err);
            },
        },
        onNonLazyError: (errorOrCloseEvent) => {
            console.error(errorOrCloseEvent);
        },
    });

[enisdenjo]

Can you please share the close code? If its 1000, the issue is related to #244 and is affected by the same problem.

[nomocas]

Indeed, we have now a "closed 4400 Invalid message".

but this is not the server message.

When a add a console log in the catch (line 643) :

I see :
{"type":"error","id":"072366df-a63f-45cc-8afb-e5ea46068ef1","payload":{"errors":[{"extensions":{"path":"$.selectionSet.session.selectionSet.received_paper_voucher","code":"validation-failed"},"message":"field "received_paper_voucher" not found in type: 'session'"}]}}

Which is obviously much more related and clear than a "Invalid message".

[enisdenjo]

You mean line 643 of the build in the lib/ directory, which file exactly? I am looking at line 643 in the source code's client.ts where re-throwing should not fix the issue.

Setting retryAttempts to zero (0) here, should report the error immediately if the close code is 4400. Can you confirm?

[nomocas]

No in the build it's another line as the code have been transpiled before.. but it's the same place.

So in the transpiled client.js file : it's at line 696 where I've added a console.log.

[enisdenjo]

If the close code is 4400, can you please confirm that setting retryAttempts to zero (0) reports the error immediately?

[enisdenjo]

Receiving close code 4400 should fail regardless of retryAttempts since it is considered fatal. Can you share your subscribe code?

[enisdenjo]

I tried sending a malformed query to Hasura Cloud through graphql-ws, fails as expected: immediately. Are you sure you're handling the subscription error callback properly?

[nomocas]

It does not change anything with or without retryAttempts:0.

Here is my subscribeQueue implementation (inspired from your recipes about 'Client usage with AsyncIterator').
In my case, I do not need to be able to do a for-await-of, but I need to check the responses (in order) to do some test at different places in my code.
So it's not a pure AsyncIterator, but it looks like. And again, when query is not malformed, everything is working as expected with it.

export function subscribeQueue<T>(client: Client, payload: SubscribePayload) {
    debug('subscribeQueue:', payload);
    let deferred: {
            resolve: (done: boolean) => void;
            reject: (err: unknown) => void;
        } | null = null,
        error: unknown = null,
        done = false;

    const pending: ExecutionResult<T, unknown>[] = [];

    const dispose = client.subscribe<T>(payload, {
        next: (data) => {
            debug('receive data:', data);
            pending.push(data);
            deferred?.resolve(false);
        },
        error: (err) => {
            debug('error:', err);
            error = err;
            deferred?.reject(error);
        },
        complete: () => {
            debug('complete');
            done = true;
            deferred?.resolve(true);
        },
    });

    return {
        pending,

        dispose,

        async next() {
            debug('subscribeQueue.next');
            if (error) {
                throw error;
            }
            if (done) {
                throw new Error('subscription is done but should not!');
            }
            return pending.length
                ? pending.shift()
                : (await new Promise<boolean>((resolve, reject) => {
                      debug('queue : waiting for next elem(s)!');
                      const timeout = setTimeout(() => {
                          debug('!!!!!!!!!!! Subscription Timeout !!!!!!!!!!!!');
                          error = new Error('Subscription Timeout!');
                          deferred = null;
                          reject(error);
                      }, 5000);

                      deferred = {
                          resolve: (res: boolean) => {
                              debug('deferred.resolve');
                              clearTimeout(timeout);
                              resolve(res);
                          },
                          reject: (reason: unknown) => {
                              debug('deferred.reject');
                              clearTimeout(timeout);
                              reject(reason);
                          },
                      };
                  }))
                ? undefined
                : pending.shift();
        },
    };
}

[enisdenjo]

Do you get the debug('error:', err); log from client.subscribe? Can you share the logs?

[nomocas]

Nope, no error log :

hpk:graphql-ws subscribeQueue: +110ms
hpk:graphql-ws connecting +0ms
hpk:graphql-ws subscribeQueue.next +4ms
hpk:graphql-ws queue : waiting for next elem(s)! +1ms
hpk:graphql-ws opened +10ms
hpk:graphql-ws message { type: 'ping', payload: { message: 'keepalive' } } +3ms
hpk:graphql-ws ping true +0ms
hpk:graphql-ws pong false +0ms
hpk:graphql-ws message { type: 'connection_ack' } +4ms
hpk:graphql-ws connected +0ms
hpk:graphql-ws message { type: 'ping', payload: { message: 'keepalive' } } +0ms
hpk:graphql-ws ping true +0ms
hpk:graphql-ws pong false +0ms
hpk:graphql-ws message { type: 'complete', id: 'cd0ac83b-f94a-40e2-8ae7-e88c77a35e7a' } +10ms
hpk:graphql-ws complete +0ms
hpk:graphql-ws deferred.resolve +1ms
hpk:graphql-ws closed :  code 4400, reason : Invalid message +35ms

[enisdenjo]

Any chance for a repro, at least the backend setup? Whatever I try, I cannot replicate this issue. In my tests, the subscribe error callback gets called every time a close happens.

[nomocas]

Hello Denis,

Here is the repro stuffs :

/docker-compose.yaml

version: "3.7"
services:
  postgres:
    container_name: pg-test
    image: postgres:13.3-alpine
    restart: always
    volumes:
      - db_data:/var/lib/postgresql/data
    environment:
      POSTGRES_PASSWORD: postgrespassword
    ports:
      - "5432:5432"
  graphql-engine:
    container_name: hasura-test
    image: hasura/graphql-engine:v2.0.9
    ports:
      - "8080:8080"
    depends_on:
      - "postgres"
    restart: always
    environment:
      HASURA_PORT: 8080
      HASURA_GRAPHQL_DATABASE_URL: postgres://postgres:postgrespassword@postgres:5432/postgres
      HASURA_GRAPHQL_ADMIN_SECRET: MyReallySuperSecret
      HASURA_GRAPHQL_ENABLE_CONSOLE: "true"
volumes:
  db_data:

/index.ts

import { createClient, SubscribePayload, Client } from "graphql-ws";
import ws, { CloseEvent } from "ws";
import { v4 } from "uuid";
import dbg from "debug";

const debug = dbg("app");

export function createGQLClient(url: string) {
  debug("createGQLClient(%s)", url);
  return createClient({
    url,
    webSocketImpl: ws,
    generateID: () => v4(),
    // retryAttempts: 0, // with or without it
    connectionParams: {
      headers: {
        "x-hasura-admin-secret": "MyReallySuperSecret",
      },
    },
    on: {
      connected: () => {
        debug("connected");
      },
      connecting: () => {
        debug("connecting");
      },
      opened: () => {
        debug("opened");
      },
      closed: (err: unknown) => {
        debug(
          "closed : code %s, reason : %s",
          (err as CloseEvent).code,
          (err as CloseEvent).reason
        );
      },
      message: (msg) => {
        debug("message", msg);
      },
      ping: (msg) => {
        debug("ping", msg);
      },
      pong: (msg) => {
        debug("pong", msg);
      },
      error: (err) => {
        debug("error");
        console.error(err);
      },
    },
    onNonLazyError: (errorOrCloseEvent) => {
      debug("NonLazyError");
      console.error(errorOrCloseEvent);
    },
  });
}

function subscribe(client: Client, payload: SubscribePayload) {
  client.subscribe(payload, {
    next: (data) => {
      debug("receive data:", data);
    },
    error: (err) => {
      debug("error:", err);
    },
    complete: () => {
      debug("complete");
    },
  });
}

subscribe(createGQLClient("ws://localhost:8080/v1/graphql"), {
  query: "subscription foo($bar:String) {  }",
});

/package.json

{
  "name": "test",
  "scripts": {
    "env": "docker compose up",
    "test": "DEBUG=app npx ts-node index.ts"
  },
  "dependencies": {
    "@types/debug": "^4.1.7",
    "@types/uuid": "^8.3.1",
    "@types/ws": "^8.2.0",
    "debug": "^4.3.2",
    "graphql": "^15.6.1",
    "graphql-ws": "^5.5.1",
    "typescript": "^4.4.4",
    "uuid": "^8.3.2",
    "ws": "^8.2.3"
  }
}

Then in a first terminal yarn env which will bootstrap an hasura and its postgres.

Then when env is running, yarn test in another terminal.

Results :

  app createGQLClient(ws://localhost:8080/v1/graphql) +0ms
  app connecting +1ms
  app opened +15ms
  app message { type: 'ping', payload: { message: 'keepalive' } } +2ms
  app ping true +2ms
  app pong false +0ms
  app message { type: 'connection_ack' } +3ms
  app connected +0ms
  app message { type: 'ping', payload: { message: 'keepalive' } } +1ms
  app ping true +0ms
  app pong false +0ms
  app message { type: 'complete', id: 'b338f0db-2a5e-4784-85af-cb17d94c2a7c' } +7ms
  app complete +1ms
  app closed : code 4400, reason : Invalid message +7ms

[nomocas]

If we add a console.log at line 190 in graphql-ws/lib/client.js as console.log('socket.onmessage:', data);

  app createGQLClient(ws://localhost:8080/v1/graphql) +0ms
  app connecting +1ms
  app opened +13ms
socket.onmessage: {"type":"ping","payload":{"message":"keepalive"}}
  app message { type: 'ping', payload: { message: 'keepalive' } } +1ms
  app ping true +2ms
  app pong false +0ms
socket.onmessage: {"type":"connection_ack"}
  app message { type: 'connection_ack' } +1ms
  app connected +0ms
socket.onmessage: {"type":"ping","payload":{"message":"keepalive"}}
  app message { type: 'ping', payload: { message: 'keepalive' } } +0ms
  app ping true +0ms
  app pong false +0ms

socket.onmessage: {"type":"error","id":"9dc4eba2-7042-405d-a6dc-4824d7c7f667","payload":{"errors":[{"extensions":{"path":"$.query","code":"validation-failed"},"message":"not a valid graphql query"}]}}

socket.onmessage: {"type":"complete","id":"9dc4eba2-7042-405d-a6dc-4824d7c7f667"}
  app message { type: 'complete', id: '9dc4eba2-7042-405d-a6dc-4824d7c7f667' } +5ms
  app complete +1ms
  app closed : code 4400, reason : Invalid message +6ms

We see the error from server.
After some checks, the problem appears to come from the fact that it's not recognized as a valid message by the graphql-ws/lib/common.js#isMessage function. When we check the constraints expressed in this function we see :

  case MessageType.Error:
     return hasOwnStringProperty(val, 'id') && areGraphQLErrors(val.payload);

(line 250 and 251 in the source file graphql-ws/src/common.ts)
with graphql-ws/utils#areGraphQLErrors as

export function areGraphQLErrors(obj: unknown): obj is readonly GraphQLError[] {
  return (
    Array.isArray(obj) &&
    // must be at least one error
    obj.length > 0 &&
    // error has at least a message
    obj.every((ob) => 'message' in ob)
  );
}

which could not match the received payload :

{
  "type":"error",
  "id":"9dc4eba2-7042-405d-a6dc-4824d7c7f667",
  "payload":{
      "errors":[
          {"extensions":{"path":"$.query","code":"validation-failed"},"message":"not a valid graphql query"}
      ]
  }
}

Your parser is expecting that payload is directly a GraphqlError[], and hasura provides one wich contains a sub properties errors which is the expected array.

So in fact it's not clear who should follow which payload standard.

Maybe you have an opinion ?

Thanks for following this thread.

[nomocas]

Maybe the solution is to keep the payload as unknown or maybe T extends Record<string, unknown> if we want to keep the constraint that payload must be an object.

Because, even if it could be valuable to have a strictly typed payload, it's dangerous to be too strict in case of error, as it will swallow important information for debug if it does not match (as for the moment) for any reason.
Instead, maybe you could print a warning when payload doesn't match your standard, but never reject it silently as 'Invalid Message'.

As this, we have all the information and we are able to validate the payload on our side, if necessary.

WDYT ?

[enisdenjo]

The problem here, similar to #244, is wrong implementation of the GraphQL over WebSocket Protocol's Error message. See more here: hasura/graphql-engine#7706.

However, thank you for the repro setup, @nomocas, I'll give it a go soon since the subscription should be reporting an error regardless.

[enisdenjo]

Hey @nomocas, there was a bug in the client where a close event was swallowed if the next read message in queue was a Complete message. See more here: 27754b2.

A new release is coming soon, I just want to pack in a few more things. Stay tuned. See: #245 (comment).

Thank you for your insights, they were very helpful!

[enisdenjo]

🎉 This issue has been resolved in version 5.5.2 🎉

The release is available on:

• npm package (@latest dist-tag)
• GitHub release

Your semantic-release bot 📦🚀

[enisdenjo]

v5.5.2 is now out! Please update, @nomocas, and try your malformed query again - the close error should be reported properly.

You still want to keep an eye on hasura/graphql-engine#7706, though. The fix there would keep the connection open and report the error gracefully to the specific problematic subscription.

[nomocas]

Thanks! It works.

But... :) Could we get the problematic payload somewhere ?

The current injected error is the ws.CloseEvent, which continue to hide the real problem, as we are not able to retrieve the payload (wellformed or malformed, anyway) from it. So, it's not anymore silent, but it still opaque.

Also, if we check the timing of the console here, we see that there is a delay between the error detection (on parsing in socket.onmessage), and the final close event. (around 15 ms in this simple setup - much more on real setup). And we continue to see intermediate events.

So, after all, it would be coherent to have the CloseEvent injected in the close handler, with a message as "Invalid message" if the payload is malformed. But to be accurate and transparent, and to allow in-time management of those kind of error, it would be really great to have another Error object, injected at detection time in error handlers only, that provides the problematic payload as information. As a malformed query is a programmatic error, whatever, we should throw and kill the app, then correct the queries, and restart.

Finally, as you, of course, do not have control on all gql engine, and that errors are often badly managed, it would be risky to keep hiding malformed payload. In other words, it will happen. And if we do not understand what is happening, often we'll ask you. ;)

[enisdenjo]

Once Hasura properly implements the Error message with hasura/graphql-engine#7706, you will get the actual validation error gracefully. The "Invalid message" close happens due to improper implementation of the protocol, specifically an invalid message being transmitted (and there is a clause in the protocol exactly describing how to act on invalid messages). I will not change the protocol to accompany malformed messages just because someone does not implement it properly. Please track the issue there.

The "real" graphql-ws library bug in this issue is the swallowed close error, and the fix deployed with 27754b2 will make sure no connection error gets swallowed again.

[nomocas]

I do not ask to change the protocol.

A first question : why it's a ws.CloseEvent object which is injected in the client error handlers ? (And not an Error)

If I check the logs order now (v5.5.2), the error handler is triggered after the close handler, in absolute last position. So we have the proper close event object injected (with proper message) and triggered accordingly to the protocol.
And if I check the protocol, I do not find anywhere about the fact that any errors handlers should receive a CloseEvent precisely. IMHO, the protocol is talking about messages format. Not the way a client should handle errors.

If a client connect to a server that, unfortunately, does not implement the protocol correctly, but returns an object which contains information, I really do not see why the client should hide the payload, which is coming from an object that says type:'error' and provides an id, partially accordingly to the protocol.
Particularly if the reason is Invalid Message.
It should allow instant debug, comparatively to digging in servers log, that we often do not have.

[enisdenjo]

I do not ask to change the protocol.

The only way to read the malformed error message's payload is to modify the protocol simply because it considers messages not described by the protocol as invalid.

To read the payload we have to make one of the following breaking changes in the protocol:

• Allow invalid messages
• Change the Error message structure

why it's a ws.CloseEvent object which is injected in the client error handlers ? (And not an Error)

Because the user should get the first, root most level, error, not a wrap. If the error causer is a CloseEvent, all error handlers should get a CloseEvent.

And if I check the protocol, I do not find anywhere about the fact that any errors handlers should receive a CloseEvent precisely. IMHO, the protocol is talking about messages format. Not the way a client should handle errors.

The protocol should not, and does not, describe how to handle errors either side.

What it does describe is the transport, how it should look like and what the exact format of each message is.

If a client connect to a server that, unfortunately, does not implement the protocol correctly, but returns an object which contains information, I really do not see why the client should hide the payload, which is coming from an object that says type:'error' and provides an id, partially accordingly to the protocol.

Again, if the server, or the client, receives an invalid message - the connection must be terminated.

The lib does not care what the message is, what type, what it holds, or what the context is - if the message is invalid, terminate the connection.

That being said, the client does not even get to the point of interpreting the malformed error message's payload because the connection gets terminated. No handling of messages takes place after the termination, there is no message to handle (because only valid messages are allowed). Keeping this in mind, the first, root most, and only, error here is the CloseEvent.

Once Hasura fixes the format of the error message with hasura/graphql-engine#7706, the connection will not terminate and you will get the focused GraphQLErrors from the error message's payload in the error callback of the relevant subscription.

[nomocas]

Yes : Invalid message means termination through CloseEvent in close handler. No problem with that.
Actual hasura payload should trigger CloseEvent('Invalid Message'). true.

And this will still true if the invalid message is provided, by any way, as convenience, to any developer that encounter it.

What is also true, is that Hasura issues take a long time to be tackled, there is 1.4 K open issues at this moment, and we have really few insight about the road-map. Even if it's one of the biggest project around graphql... So, ok, no choice, we'll wait and see.

And so last try, even a debug mode that, when enabled, print what is happening under the hood ?

Whatever, already thanks for your time.

[enisdenjo]

I mean, this is OSS, you can always fork the repo, apply your changes, yarn build, yarn pack and in your app yarn add ../graphql-ws/package.tgz. 😄