subscribe to WebSocket v2 failed if sent too soon after connect

[WudsyWudsyWudsy]

This is regarding the new WebSocket v2 Beta.

I had to add a two second delay between the on ‘connect’ event and subscribing to consistently subscribe (and hence receive messages) from the WebSocket.

socket.on('connect', function(){
      setTimeout(function() {
          socket.emit('subscribe', request)
      }, 2000)
});

If I do not, only about one in ten attempts to connect result in me receiving messages.

My testing is below…

I found that I was not receiving any messages, played with code a lot, got frustrated trying everything, finally got messages. Reset application, exact same code, this time no messages. Try another 20 times, finally get another set of messages.

I wrote a loop that attempts to create a new connection every 10 seconds. Log of attempts and results below:

2019-04-09 16:57:12 Creating socket 0 2019-04-09 16:57:13 Socket 0 attempting to connect 2019-04-09 16:57:22 Creating socket 1 2019-04-09 16:57:23 Socket 1 attempting to connect 2019-04-09 16:57:32 Creating socket 2 2019-04-09 16:57:33 Socket 2 attempting to connect 2019-04-09 16:57:42 Creating socket 3 2019-04-09 16:57:43 Socket 3 attempting to connect 2019-04-09 16:57:43 Socket 3 got a message 2019-04-09 16:57:46 Socket 3 got a message 2019-04-09 16:57:47 Socket 3 got a message 2019-04-09 16:57:48 Socket 3 got a message 2019-04-09 16:57:50 Socket 3 got a message 2019-04-09 16:57:51 Socket 3 got a message 2019-04-09 16:57:52 Creating socket 4 2019-04-09 16:57:53 Socket 3 got a message 2019-04-09 16:57:53 Socket 4 attempting to connect 2019-04-09 16:57:53 Socket 3 got a message 2019-04-09 16:57:56 Socket 3 got a message 2019-04-09 16:57:58 Socket 3 got a message 2019-04-09 16:57:59 Socket 3 got a message 2019-04-09 16:58:01 Socket 3 got a message 2019-04-09 16:58:02 Creating socket 5 2019-04-09 16:58:02 Socket 3 got a message 2019-04-09 16:58:03 Socket 5 attempting to connect 2019-04-09 16:58:04 Socket 3 got a message 2019-04-09 16:58:05 Socket 3 got a message 2019-04-09 16:58:06 Socket 3 got a message

As you can see attempt 3 was successful and I received messages. However attempts 0, 1, 2, 4 and 5 never get a message back.

The code is completely untouched between attempts. Its just a loop running the same function.

Even when I give it half an hour and try again, I get the same results.

I then changed the code so that it would only create one connection, but if it didn’t receive any messages in ten seconds, it would resend the subscribe message

2019-04-09 17:10:59 Creating socket 0 2019-04-09 17:10:59 Socket 0 connected 2019-04-09 17:10:59 Socket 0 sending subscribe 2019-04-09 17:11:09 Socket 0 resending subscribe 2019-04-09 17:11:09 Socket 0 got a message

I tried this about ten times, every time it worked the second attempt to subscribe, once it worked the first.

I then changed this to a two second delay, removed the original subscription (so now the first time it tries is two seconds after connection), and returned to a loop of new connections every 10 seconds.

2019-04-09 17:15:09 Creating socket 0 2019-04-09 17:15:09 Socket 0 connected 2019-04-09 17:15:11 Socket 0 sending subscribe 2019-04-09 17:15:12 Socket 0 got a message - logging for socket 0 has been stopped 2019-04-09 17:15:19 Creating socket 1 2019-04-09 17:15:19 Socket 1 connected 2019-04-09 17:15:21 Socket 1 sending subscribe 2019-04-09 17:15:23 Socket 1 got a message - logging for socket 1 has been stopped 2019-04-09 17:15:29 Creating socket 2 2019-04-09 17:15:29 Socket 2 connected 2019-04-09 17:15:31 Socket 2 sending subscribe 2019-04-09 17:15:34 Socket 2 got a message - logging for socket 2 has been stopped 2019-04-09 17:15:39 Creating socket 3 2019-04-09 17:15:40 Socket 3 connected 2019-04-09 17:15:42 Socket 3 sending subscribe 2019-04-09 17:15:43 Socket 3 got a message - logging for socket 3 has been stopped 2019-04-09 17:15:49 Creating socket 4 2019-04-09 17:15:49 Socket 4 connected 2019-04-09 17:15:51 Socket 4 sending subscribe 2019-04-09 17:15:54 Socket 4 got a message - logging for socket 4 has been stopped

This ran for about 40 cycles with 100% success rate.

[martin-nginio]

Hi @WudsyWudsyWudsy

Thanks for trying the new WebSocket feed.

I'm sorry our initial throttling for client WebSockets was very aggressive. This has been changed today and we now only throttle connections and not subscription events(you should be able to make up to 3 connections per 10 seconds per IP successfully). Also, now, upon a successful connection you will receive an immediate heartbeat message.

Apart from throttling, we also noticed some intermittently delay in new connections (after few attempts) probably due to using CloudFlare that our team is investigating now. I will get back to you once there is improvement this.

Please also note that our team has considered using standard WebSocket (standard WebSocket protocol instead of socket.io implementation) so it's possible the final version will be delivered via WebSocket only. If that happens we will update the sample codes in different languages )

Thanks again for your feedback.

[WudsyWudsyWudsy]

Hey @martin-nginio

Just confirming still the same issues today. Looking forward to update from CloudFlare.

Without two second delay:

2019-04-10 15:23:57 Creating socket 0 2019-04-10 15:24:07 Socket 0 no messages in 9.9 seconds - subscribe failed 2019-04-10 15:24:07 Creating socket 1 2019-04-10 15:24:17 Socket 1 no messages in 9.9 seconds - subscribe failed 2019-04-10 15:24:17 Creating socket 2 2019-04-10 15:24:27 Socket 2 no messages in 9.9 seconds - subscribe failed 2019-04-10 15:24:27 Creating socket 3 2019-04-10 15:24:37 Socket 3 no messages in 9.9 seconds - subscribe failed 2019-04-10 15:24:37 Creating socket 4 2019-04-10 15:24:47 Socket 4 no messages in 9.9 seconds - subscribe failed 2019-04-10 15:24:47 Creating socket 5 2019-04-10 15:24:57 Socket 5 no messages in 9.9 seconds - subscribe failed 2019-04-10 15:24:57 Creating socket 6 2019-04-10 15:24:58 Socket 6 got a message 2019-04-10 15:25:07 Creating socket 7 2019-04-10 15:25:17 Socket 7 no messages in 9.9 seconds - subscribe failed 2019-04-10 15:25:17 Creating socket 8 2019-04-10 15:25:18 Socket 8 got a message 2019-04-10 15:25:27 Creating socket 9 2019-04-10 15:25:37 Socket 9 no messages in 9.9 seconds - subscribe failed 2019-04-10 15:25:37 Creating socket 10 2019-04-10 15:25:38 Socket 10 got a message

7/10 failed.

With two second delay

2019-04-10 15:26:42 Creating socket 0 2019-04-10 15:26:44 Socket 0 got a message 2019-04-10 15:26:52 Creating socket 1 2019-04-10 15:26:54 Socket 1 got a message 2019-04-10 15:27:02 Creating socket 2 2019-04-10 15:27:04 Socket 2 got a message 2019-04-10 15:27:12 Creating socket 3 2019-04-10 15:27:14 Socket 3 got a message 2019-04-10 15:27:22 Creating socket 4 2019-04-10 15:27:24 Socket 4 got a message 2019-04-10 15:27:32 Creating socket 5 2019-04-10 15:27:34 Socket 5 got a message 2019-04-10 15:27:42 Creating socket 6 2019-04-10 15:27:44 Socket 6 got a message 2019-04-10 15:27:52 Creating socket 7 2019-04-10 15:27:54 Socket 7 got a message 2019-04-10 15:28:02 Creating socket 8 2019-04-10 15:28:04 Socket 8 got a message 2019-04-10 15:28:12 Creating socket 9 2019-04-10 15:28:14 Socket 9 got a message 2019-04-10 15:28:22 Creating socket 10 2019-04-10 15:28:24 Socket 10 got a message

0/10 failed.

As far as changing to standard WebSocket, I would absolutely support this move. Currently in the process of trying to hack it in myself ;)

[martin-nginio]

Thanks for sharing.

Our team has been running some concurrent testing in order to validate the socket connections and also subscription workflows.

3-4 out of 10 new connections (if they created at the same time) can subscribe successfully after sending socket.emit (immediately and with no delay). Those connections start to receiveheartbeatmessage successfully. For the rest of the sockets in test, they are closed by the backend due to throttle logic that is legitimate from what we can see. For those sockets with no valid subscription, re-attempting the connection logic by callingsocket.connect()and then followed bysocket.emit` (immediately after a successful connection) should solve the issue.

We used higher numbers for testing and the behavior was consistent with above which seems legitimate. We expect API traders to maintain a single connection in most use cases as there is now flexibility for changing subscriptions dynamically. It's possible that we may also enforce a limited number of connections per IP in the future.

We are happy to further look into the specific scenario you mentioned which is easier if you can can share the test scripts with our dev team (in case if your scenarios are different to what our team has tested so far).

I will update you on WebSocket implementation.

Thanks.

[WudsyWudsyWudsy]

My aim isn't to have multiple connections, I am only looping for because I am having issues connecting on my first go. Additionally, between each attempted connection I am waiting 10 seconds so none of my attempts should be throttled if I understand correctly.

Just to clarify, if I turn my computer off, wait an hour, come back, boot up, and try a single connection without the delay before socket.emit there is an approximately 80% chance the connection will never receive a message.

More specifically; if I run your example code, there is an approximately 80% chance I will never get a message.

[martin-nginio]

so if I understand you correctly, you are running your a single tests multiple times ( not parallel). Let me get back to as our team will re-produce and validate this scenario.

Thanks.

[WudsyWudsyWudsy]

That is correct. Single attempted connection, wait 10 seconds, if I have not got any messages yet, try again. You should be able to see this from the time stamps.

Sorry for any confusion!

I will attach my test code when I get home in a few hours.

You can however repeat the test by using the example code provided in the how to.

1) Wait 1 hour, don't use Internet or computer at all, no connection

2) Run the example connection code - 80% chance you will never get any messages back, 20% chance you will.

If I add a two second delay, I get around this.

[WudsyWudsyWudsy]

Most simple example below. Run this just once and it fails to get any messages in 10 seconds about 80+% of the time (heartbeat should be nearly instant).

Change instantSubscription to false and it works 100% of the time...

(function createSocket () {
  // if instantSubscription is false bot will wait two seconds 
  // after onConnect to attempt to subscribe
  const instantSubscription = true
  // timeOutTime is how long the bot will wait for any messages
  // before declaring the subscription a failure
  const timeOutTime = 10000 // ms

  console.log(printDate(), 'Creating socket')
  socket = require('socket.io-client')('https://socket.btcmarkets.net', {
    secure: true,
    transports: ['websocket'],
    upgrade: false,
    path: '/v2'
  })

  let request = {
    marketIds: ['tick', 'heartbeat'],
    channels: ['BTC-AUD']
  }

  let callback

  socket.on('connect', function(){
    console.log(printDate(), 'Socket connected')
    if (instantSubscription) {
      console.log(printDate(), 'Socket sending subscribe')
      socket.emit('subscribe', request)
    } else {
      setTimeout(function() {
        console.log(printDate(), 'Socket sending subscribe')
        socket.emit('subscribe', request)
      }, 2000)
    }

    callback = setTimeout(function() {
      console.log(printDate(), 'Socket received no messages in', (timeOutTime / 1000), 'seconds - subscribe failed')
      socket.disconnect()
    }, timeOutTime)
  })

  socket.on('message', function(data){
    console.log(printDate(), 'Socket received a message - subscribe passed - yay!')
    clearTimeout(callback)
    socket.disconnect()
  })

  socket.on('error', function(err){
    console.log(printDate(), 'Socket', err)
  })

  socket.on('disconnect', function(){
    console.log(printDate(), 'Socket disconnected')
  })
})()

function printDate (date = new Date()) {
  // print the date in human readable format
  return date.getFullYear() + '-' + (date.getMonth() + 1).toString().padStart(2, '0') + '-' + date.getDate().toString().padStart(2, '0') + ' ' + date.getHours().toString().padStart(2, '0') + ':' + date.getMinutes().toString().padStart(2, '0') + ':' + date.getSeconds().toString().padStart(2, '0')
}

[martin-nginio]

Thanks for sharing your test script.

Please note that we have updated the backend and now using WebSocket standard instead of socket.io. We will update the docs and sample client code and also will be running your tests against the new WebSocket implementation.

Thanks.

[martin-nginio]

I made some small changes to port your code to WebSocket (instead of socket.io) and it seems to be working fine if you run it multiple times.

Please let us know if you come across any further issues.

Thanks.

const WebSocket = require('ws');

(function createSocket () {
  // if instantSubscription is false bot will wait two seconds 
  // after onConnect to attempt to subscribe
  const instantSubscription = true
  // timeOutTime is how long the bot will wait for any messages
  // before declaring the subscription a failure
  const timeOutTime = 10000 // ms

  console.log(printDate(), 'Creating socket')

  const request = {
    channels: ['tick', 'heartbeat'],
    marketIds: ['BTC-AUD'],
    messageType: 'subscribe'
  };

  let callback;

   const ws = new WebSocket('wss://socket.btcmarkets.net/v2');

  ws.on('open', function open() {
    console.log(printDate(), 'Socket connected');
    if (instantSubscription) {
      console.log(printDate(), 'Socket sending subscribe');
      ws.send(JSON.stringify(request));

    } else {
      setTimeout(function() {
        console.log(printDate(), 'Socket sending subscribe with timeout');
        ws.send(JSON.stringify(request));
      }, 2000);
    }

    callback = setTimeout(function() {
      console.log(printDate(), 'Socket received no messages in', (timeOutTime / 1000), 'seconds - subscribe failed')
      ws.close();
    }, timeOutTime)  

  });

  ws.on('message', function incoming(data) {
    console.log(printDate(), 'Socket received a message - subscribe passed - yay!')
    clearTimeout(callback)
    ws.close()
  });

  ws.on('error', function(err){
    console.log(printDate(), 'Socket', err)
  })

  ws.on('close', function(){
    console.log(printDate(), 'Socket disconnected')
  })

})()

function printDate (date = new Date()) {
  // print the date in human readable format
  return date.getFullYear() + '-' + (date.getMonth() + 1).toString().padStart(2, '0') + '-' + date.getDate().toString().padStart(2, '0') + ' ' + date.getHours().toString().padStart(2, '0') + ':' + date.getMinutes().toString().padStart(2, '0') + ':' + date.getSeconds().toString().padStart(2, '0')
}

[WudsyWudsyWudsy]

Working perfectly!

2019-04-12 11:07:26 Creating socket 0 2019-04-12 11:07:26 Socket 0 connected 2019-04-12 11:07:26 Socket 0 received a message - subscribe passed - yay! 2019-04-12 11:07:26 Socket 0 disconnected 2019-04-12 11:07:36 Creating socket 1 2019-04-12 11:07:36 Socket 1 connected 2019-04-12 11:07:36 Socket 1 received a message - subscribe passed - yay! 2019-04-12 11:07:36 Socket 1 disconnected 2019-04-12 11:07:46 Creating socket 2 2019-04-12 11:07:46 Socket 2 connected 2019-04-12 11:07:46 Socket 2 received a message - subscribe passed - yay! 2019-04-12 11:07:46 Socket 2 disconnected 2019-04-12 11:07:56 Creating socket 3 2019-04-12 11:07:56 Socket 3 connected 2019-04-12 11:07:56 Socket 3 received a message - subscribe passed - yay! 2019-04-12 11:07:56 Socket 3 disconnected 2019-04-12 11:08:06 Creating socket 4 2019-04-12 11:08:06 Socket 4 connected 2019-04-12 11:08:06 Socket 4 received a message - subscribe passed - yay! 2019-04-12 11:08:06 Socket 4 disconnected 2019-04-12 11:08:16 Creating socket 5 2019-04-12 11:08:16 Socket 5 connected 2019-04-12 11:08:16 Socket 5 received a message - subscribe passed - yay! 2019-04-12 11:08:16 Socket 5 disconnected

Cheers for getting this fixed, and converting to standard ws.