🔊 Warn when messages are sent before the v1.1 handshake

At the moment, it's possible for messages to be sent before the client-
server handshake.

Sending messages before the handshake has happened has undefined
behaviour, and can result in errors such as in:
#605

We can't just ignore these messages, because old clients might
potentially be on v1.0 of the client-server protocol, in which the
server informs the client when it's ready, but not the other way around,
so it's impossible to know when a client should be considered "ready",
and its messages acceptable.

Instead, we add a warning for clients on v1.1 who have sent a message
before their handshake. In order to aid with debugging, we keep track of
the first message received, and log it when the handshake is received
(which means that v1.0 clients will never get such a warning).

lib/agent.js

@@ -58,6 +58,11 @@ function Agent(backend, stream) {
   // active, and it is passed to each middleware call
   this.custom = {};
 
+  // The first message received over the connection. Stored to warn if messages
+  // are being sent before the handshake.
+  this._firstReceivedMessage = null;
+  this._handshakeReceived = false;
+
   // Send the legacy message to initialize old clients with the random agent Id
   this.send(this._initMessage(ACTIONS.initLegacy));
 }
@@ -394,6 +399,7 @@ Agent.prototype._handleMessage = function(request, callback) {
   try {
     var errMessage = this._checkRequest(request);
     if (errMessage) return callback(new ShareDBError(ERROR_CODE.ERR_MESSAGE_BADLY_FORMED, errMessage));
+    this._checkFirstMessage(request);
 
     switch (request.a) {
       case ACTIONS.handshake:
@@ -855,6 +861,20 @@ Agent.prototype._handlePresenceData = function(presence) {
   });
 };
 
+Agent.prototype._checkFirstMessage = function(request) {
+  if (this._handshakeReceived) return;
+  if (!this._firstReceivedMessage) this._firstReceivedMessage = request;
+
+  if (request.a === ACTIONS.handshake) {
+    this._handshakeReceived = true;
+    if (this._firstReceivedMessage.a !== ACTIONS.handshake) {
+      logger.warn('Unexpected message received before handshake', this._firstReceivedMessage);
+    }
+    // Release memory
+    this._firstReceivedMessage = null;
+  }
+};
+
 function createClientOp(request, clientId) {
   // src can be provided if it is not the same as the current agent,
   // such as a resubmission after a reconnect, but it usually isn't needed

package.json

@@ -22,7 +22,8 @@
     "ot-json1": "^0.3.0",
     "rich-text": "^4.1.0",
     "sharedb-legacy": "npm:sharedb@=1.1.0",
-    "sinon": "^9.2.4"
+    "sinon": "^9.2.4",
+    "sinon-chai": "^3.7.0"
   },
   "files": [
     "lib/",

test/agent.js

@@ -0,0 +1,74 @@
+var Backend = require('../lib/backend');
+var logger = require('../lib/logger');
+var sinon = require('sinon');
+var StreamSocket = require('../lib/stream-socket');
+var expect = require('chai').expect;
+var ACTIONS = require('../lib/message-actions').ACTIONS;
+var Connection = require('../lib/client/connection');
+var LegacyConnection = require('sharedb-legacy/lib/client').Connection;
+
+describe('Agent', function() {
+  var backend;
+
+  beforeEach(function() {
+    backend = new Backend();
+  });
+
+  afterEach(function(done) {
+    backend.close(done);
+  });
+
+  describe('handshake', function() {
+    it('warns when messages are sent before the handshake', function(done) {
+      var socket = new StreamSocket();
+      var stream = socket.stream;
+      backend.listen(stream);
+      sinon.spy(logger, 'warn');
+      socket.send(JSON.stringify({a: ACTIONS.subscribe, c: 'dogs', d: 'fido'}));
+      var connection = new Connection(socket);
+      socket._open();
+      connection.once('connected', function() {
+        expect(logger.warn).to.have.been.calledOnceWithExactly(
+          'Unexpected message received before handshake',
+          {a: ACTIONS.subscribe, c: 'dogs', d: 'fido'}
+        );
+        done();
+      });
+    });
+
+    it('does not warn when messages are sent after the handshake', function(done) {
+      var socket = new StreamSocket();
+      var stream = socket.stream;
+      var agent = backend.listen(stream);
+      sinon.spy(logger, 'warn');
+      var connection = new Connection(socket);
+      socket._open();
+      connection.once('connected', function() {
+        socket.send(JSON.stringify({a: ACTIONS.subscribe, c: 'dogs', d: 'fido'}));
+        expect(logger.warn).not.to.have.been.called;
+        expect(agent._firstReceivedMessage).to.be.null;
+        done();
+      });
+    });
+
+    it('does not warn for clients on protocol v1.0', function(done) {
+      backend.use('receive', function(request, next) {
+        var error = null;
+        if (request.data.a === ACTIONS.handshake) error = new Error('Unexpected handshake');
+        next(error);
+      });
+      var socket = new StreamSocket();
+      var stream = socket.stream;
+      backend.listen(stream);
+      sinon.spy(logger, 'warn');
+      socket.send(JSON.stringify({a: ACTIONS.subscribe, c: 'dogs', d: 'fido'}));
+      var connection = new LegacyConnection(socket);
+      socket._open();
+      connection.get('dogs', 'fido').fetch(function(error) {
+        if (error) return done(error);
+        expect(logger.warn).not.to.have.been.called;
+        done();
+      });
+    });
+  });
+});

test/setup.js

@@ -1,5 +1,9 @@
 var logger = require('../lib/logger');
 var sinon = require('sinon');
+var sinonChai = require('sinon-chai');
+var chai = require('chai');
+
+chai.use(sinonChai);
 
 if (process.env.LOGGING !== 'true') {
   // Silence the logger for tests by setting all its methods to no-ops