Premature close?

[mschwartz]

I am porting a server application from Node to Deno and the WebSocket behavior is unexpected.

The simplest program I've tried opens a WebSocket and prints messages received via on('message'...).

The connection is being made to a hubitat home automation controller. The hubitat periodically sends a message over the WebSocket and those are printed. After about 2-3 minutes, the on('close' method is called and there are no more messages received.

I have an on('ping' callback installed and it seems that is being called immediately before the close.

The error passed to close callback is 1002, which is socket closed, I believe.

I am thinking that maybe your client/server talk to each other without fail, but you client doesn't talk to existing and well tested servers? Hubitat software is Java based.

1598396994391 ws connected!
1598397042870 ws message { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
1598397043834 ws message { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
1598397044853 ws message { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
1598397045852 ws message { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
1598397102811 ws message { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
1598397103876 ws message { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
1598397104836 ws message { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
1598397105848 ws message { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
1598397111404 ws ping Uint8Array(0) []

[mschwartz]

import { WebSocket } from "https://deno.land/x/[email protected]/mod.ts";

const log = (...args: any) => {
  console.log(Date.now(), ...args);
};

const main = async () => {
  const ws = new WebSocket('ws://hubitat/eventsocket');
  ws.on("open", () => {
    log("ws connected!");
  });
  ws.on("error", (err: any) => {
    log('ws error', err);
  });
  ws.on("ping", (err: any) => {
    log('ws ping', err);
  });
  ws.on("close", (err: any) => {
    log('ws close', err);
  });
  ws.on('message', (message: any) => {
    log('ws message', message);
  });
};

main();

[mschwartz]

Side note: no retry/reconnect option?

[ryo-ma]

Thank you for the issue. The problem is to not return pong when you got the ping. Because 1002 is a protocol error.

https://tools.ietf.org/html/rfc6455#section-5.5.2

I should support to return pong in this library when the client got a ping.

[ryo-ma]

I made a mistake. I have confirmed to return pong in this library now. Can you try ws of std library? Whether occurs same problem.

https://deno.land/[email protected]/ws

[mschwartz]

I saw no pong() method in the API, or I would have returned it in the on('ping', ... handler myself 👍

I can look at the other API, but this is going to be the preferred one for most people, I think.

[ryo-ma]

Yes, there is not pong() method in deno std ws library too. And then I am using the ws of deno std library for my library. But I have confirmed to return pong in the deno std ws code. https://deno.land/[email protected]/ws/mod.ts#L274

Can you try the following code?

import {
  connectWebSocket,
  isWebSocketCloseEvent,
  isWebSocketPingEvent,
  isWebSocketPongEvent,
} from "https://deno.land/[email protected]/ws/mod.ts";
import { encode } from "https://deno.land/[email protected]/encoding/utf8.ts";
import { BufReader } from "https://deno.land/[email protected]/io/bufio.ts";
import { TextProtoReader } from "https://deno.land/[email protected]/textproto/mod.ts";
import { blue, green, red, yellow } from "https://deno.land/[email protected]/fmt/colors.ts";

const endpoint = "ws://hubitat/eventsocket";
/** simple websocket cli */

  
const sock = await connectWebSocket(endpoint);
console.log(green("ws connected! (type 'close' to quit)"));
for await (const msg of sock) {
      if (typeof msg === "string") {
        console.log(yellow(`< ${msg}`));
      } else if (isWebSocketPingEvent(msg)) {
        console.log(blue("< ping"));
      } else if (isWebSocketPongEvent(msg)) {
        console.log(blue("< pong"));
      } else if (isWebSocketCloseEvent(msg)) {
        console.log(red(`closed: code=${msg.code}, reason=${msg.reason}`));
      }
}

[mschwartz]

This is using deno in a docker container. Using the code in the previous comment as you requested.

Dockerfile:

FROM hayd/deno:1.0.0
WORKDIR /app
USER deno
ADD . /app
# These are passed as deno arguments when run with docker:
CMD ["run", "--allow-net", "main.ts"]

Download https://deno.land/[email protected]/node/_util/_util_types.ts
Download https://deno.land/[email protected]/encoding/utf8.ts
Download https://deno.land/[email protected]/io/bufio.ts
Download https://deno.land/[email protected]/async/mod.ts
Download https://deno.land/[email protected]/http/_io.ts
Download https://deno.land/[email protected]/bytes/mod.ts
Download https://deno.land/[email protected]/async/deferred.ts
Download https://deno.land/[email protected]/async/delay.ts
Download https://deno.land/[email protected]/async/mux_async_iterator.ts
Download https://deno.land/[email protected]/async/pool.ts
Download https://deno.land/[email protected]/textproto/mod.ts
Download https://deno.land/[email protected]/http/http_status.ts
Download https://deno.land/[email protected]/_util/has_own_property.ts
Download https://deno.land/[email protected]/io/ioutil.ts
Download https://deno.land/[email protected]/hash/sha1.ts
Download https://deno.land/[email protected]/_util/has_own_property.ts
Download https://deno.land/[email protected]/io/ioutil.ts
Download https://deno.land/[email protected]/hash/sha1.ts
Download https://deno.land/[email protected]/http/_io.ts
Download https://deno.land/[email protected]/async/deferred.ts
Download https://deno.land/[email protected]/_util/assert.ts
Download https://deno.land/[email protected]/bytes/mod.ts
Download https://deno.land/[email protected]/http/server.ts
Download https://deno.land/[email protected]/http/http_status.ts
Download https://deno.land/[email protected]/async/mod.ts
Download https://deno.land/[email protected]/async/delay.ts
Download https://deno.land/[email protected]/async/mux_async_iterator.ts
Download https://deno.land/[email protected]/async/pool.ts
error: TS2345 [ERROR]: Argument of type '{ depth: any; iterableLimit: any; compact: boolean; sorted: boolean; }' is not assignable to parameter of type 'InspectOptions'.
  Object literal may only specify known properties, and 'iterableLimit' does not exist in type 'InspectOptions'.
    iterableLimit: opts.iterableLimit ?? 100,
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    at https://deno.land/[email protected]/node/util.ts:11:5

[mschwartz]

Also, I have deno installed natively in WSL2/Arch Linux and it errors if I try to deno upgrade.

[mschwartz]

Your code runs in deno installed natively on my iMac. Same failure :(

ws connected! (type 'close' to quit)
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Office Dimmer", "value" : "on", "unit" : "null", "deviceId" : 11, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Office Dimmer was turned on [digital]"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Office Dimmer", "value" : "off", "unit" : "null", "deviceId" : 11, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Office Dimmer was turned off [digital]"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< { "source" : "DEVICE", "name" : "switch", "displayName" : "Outdoor Lights", "value" : "off", "unit" : "null", "deviceId" : 98, "hubId" : 0, "installedAppId" : 0, "descriptionText" : "Outdoor Lights is off"}
< ping
closed: code=1002, reason=Client MUST mask all frames (RFC-6455: Section 5.1)

[ryo-ma]

Thank you for running the code. I thought that this problem is occurred by deno std code.

The following error is the problem that is a low layer.

Client MUST mask all frames (RFC-6455: Section 5.1)

I recommend that you should open an issue in the deno repository. https://github.com/denoland/deno

[mschwartz]

Done.

[ryo-ma]

@mschwartz Released v1.4 May be fixed this problem.

https://github.com/denoland/deno/issues/7231#issuecomment-691450148

[UserJHansen]

Should be closed due to inactivity