Kucoin: wait for welcome message before sending subscription requests

[WoutervDijk]

Exchange
Kucoin

Subscription type
L3orderbook

Describe the bug
For some reason if I try to connect to the kucoin L3 orderbook it will often not send any updates at all. However, this bug is very inconsistent, sometimes it will connect and stream updates other times it won't at all.

To Reproduce
Run the following code in a AWS instance close to kucoin, like ap-northeast-1

/**
 * Prototype for maintaining a Level 3 order book for Kucoin according
 * to the instructions defined here:
 * https://docs.kucoin.com/#full-matchengine-data-level-3
 *
 * This technique uses a Map to store orders. It has efficient updates
 * but will be slow for performing tip of book or snapshot operations.
 *
 * # Example
 * ```javascript
 * */
const ccxws = require("ccxws");
const KucoinOrderBook = require("ccxws/src/orderbooks/KucoinOrderBook");
let market = {id: "BTC-USDT", base: "BTC", quote: "USDT"};
markets=[market, {id: "AMPL-USDT", base: "AMPL", quote: "USDT"}, {id: "SXP-USDT", base: "SXP", quote: "USDT"}]
for (let market of markets) {
    let updates = [];
    let ob;
    const client = new ccxws.Kucoin();
    client.subscribeLevel3Updates(market);
    client.on("l3snapshot", async (snapshot) => {
        console.log("length before", updates.length)
        await sleep(5000);
        if (updates.length === 0){
            console.log("Update length 0 wait longer");
            await sleep(5000);
        }
        console.log("updates after", updates.length);
        ob = new KucoinOrderBook(snapshot, updates);
        console.log("running ", market.id);
    });
    client.on("l3update", update => {
        // enqueue updates until snapshot arrives
        if (!ob) {
            updates.push(update);
            return;
        }
        // validate the sequence and exit if we are out of sync
        if (ob.sequenceId + 1 !== update.sequenceId) {
            console.log(`out of sync, expected ${ob.sequenceId + 1}, got ${update.sequenceId}`);
            //process.exit(1);
        }
        // apply update
        ob.update(update);
    });
}
function sleep(ms) {
    return new Promise(resolve => setTimeout(resolve, ms));
}

The exact error I get is as follow:
(node:120179) UnhandledPromiseRejectionWarning: Error: Missing update or Must queue updates prior to snapshot, which is the real problem
The weirdest thing is, is that it does work at my home computer (Europe), but my latency is also very high here. However, using an AWS instance it will only connect sometimes?!?!? It might be because the snapshot call is too fast after trying to connect but I have no idea tbh.
This especially happens when I try to run multiple coins at the same time (using a new ccxws object for each). Especially the SXP/USDT pair seems to fail often.
Could we maybe add a function which retries connecting to the socket if no updates start streaming?
EDIT:
I am actually thinking that it might just be Kucoin servers that are a little broken, perhaps a function to reconnect with the socket would suffice.

Second EDIT:
This is the exact output of the error I meant:

length before 0
length before 21
updates after 181
running  SXP-USDT
Update length 0 wait longer
updates after 1416
(node:121384) UnhandledPromiseRejectionWarning: Error: Missing update
    at new KucoinOrderBook (node_modules/ccxws/src/orderbooks/KucoinOrderBook.js:85:15)
    at KucoinClient.<anonymous> (test.js:29:14)
(Use `node --trace-warnings ...` to show where the warning was created)
(node:121384) UnhandledPromiseRejectionWarning: Unhandled promise rejection. 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(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
(node:121384) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
updates after 0
(node:121384) UnhandledPromiseRejectionWarning: Error: Must queue updates prior to snapshot
    at new KucoinOrderBook (node_modules/ccxws/src/orderbooks/KucoinOrderBook.js:59:13)
    at KucoinClient.<anonymous> (test.js:29:14)
(node:121384) UnhandledPromiseRejectionWarning: Unhandled promise rejection. 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(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)

[bmancini55]

Thanks for submitting the issue. Those errors occur in the prototype l3 orderbook when it receives a snapshot but can't properly replay queued updates (either because there are no updates yet or the update stream started after the snapshot's sequence time period).

https://github.com/altangent/ccxws/blob/master/src/orderbooks/KucoinOrderBook.js#L59 and
https://github.com/altangent/ccxws/blob/master/src/orderbooks/KucoinOrderBook.js#L85

The issue is result of a race condition in how the snapshot is obtained from REST. If the update stream starts before the REST response is obtained everything is ok. But it is possible that the REST request for the snapshot is initiated prior to the update stream starting which would result in the above errors.

https://github.com/altangent/ccxws/blob/master/src/exchanges/kucoin-client.js#L237

Coding wise, a hacky fix for this is adding a small delay to the sending of the REST request. The proper fix is sending the REST request only after we've successfully subscribed to the update stream.

In the interim, you can monkey patch a delay into _requestLevel3Snapshot. Something like:

const REST_DELAY_MS = 50
client._originalRequestLevel3Snapshot = client._requestLevel3Snapshot;
client._requestLevel3Snapshot = market => setTimeout(() => client._originalRequestLevel3Snapshot(market), REST_DELAY_MS);

Unfortunately there is no option to disable the REST request in Kucoin like there is other clients. If so, you could disable the automatic REST request and initiate the REST request after you're seen the first l3update event for a market. The gotcha is that if there is a disconnection you will need to re-fetch the REST request once the socket is connected again.

[WoutervDijk]

Thank you for your fast response @bmancini55. But I am not really sure whether this is the bug I had in mind (I think it is a different one). I outlined the problem incorrectly in my post, so let me explain it in a different way. In the current code I have used (note I edited it in the original post) in case we receive our snapshot I wait for 5 seconds before processing the orderbook. So I don't think the race condition bug is valid. After those 5 seconds I check whether the updates length is 0 (so we didn't receive any updates), and wait for another 5 seconds to see if updates would start streaming. But even after those 5 seconds, updates still don't start streaming updates after 0. So I am afraid that sometimes the websocket won't connect to kucoins api??

[bmancini55]

Ah ok, I should have read the description more carefully. So you're not getting updates at all in certain circumstances? If so you can add a log message here to see whether the subscription is being ack'd or has an error:
https://github.com/altangent/ccxws/blob/master/src/exchanges/kucoin-client.js#L282

The code should probably emit an error event if it receives an error message.

[WoutervDijk]

Yes, that is exactly the case. No updates at all in some cases.
I have added the log and in case I receive no updates then I also do not receive an ack. Furthermore, no error is emitted as well (at that location).

[bmancini55]

Interesting, do you get a connected event?

[WoutervDijk]

On line 46 I added the following this._wss.on("connected", () => console.log("connected"));. And I can confirm that is does emit a connected event, but no ack is received.

[WoutervDijk]

Any update @bmancini55 ?

[bmancini55]

Hi @WoutervDijk, I haven't had a chance to dig into it yet.

You want to log anything that comes down the socket at the beginning of the _processMessage method. There might be a message that is being missed.

[bmancini55]

@WoutervDijk I wasn't able to reproduce locally but I made a few changes to the client to improve reliability of message sends. Let me know if you're still seeing the issue after updating: https://github.com/altangent/ccxws/releases/tag/v0.37.7

[WoutervDijk]

@bmancini55 thank you very much for your response. It did unfortunately not solve the problem. I will have a look at it this weekend and log everything _processmessage and see if I can find something. What OS were you using and which Node version when you tested it?

[bmancini55]

Bummer. I'm running node v12.10 on macOS and Pop_OS. Couldn't get it to reproduce on either.

[WoutervDijk]

This might be a fault in my OS (Ubuntu) or Nodejs. I have downgraded to Node 12 (latest) and it is working for now. I'll close the issue.

[WoutervDijk]

@bmancini55 I think I found the error. If you enable tcp_fastopen (on your OS) then for some reason Kucoin won't open a connection all the time! Anyway we can disable that with a particular call in the websocket (when we open the connection) library? Then people can keep tcp_fastopen enabled on their system, without this bug. I know it is possible in C++. Thanks

EDIT: My hypothesis seems incorrect. I will look at it tomorrow