Fix new messages not appearing in chat list (!1146) · Merge requests · gitter / webapp

Eric Eastwood requested to merge feature/1894-fix-new-messages-not-appearing-in-chat-list into develop May 07, 2018

Fix new messages not appearing in chat list by serializing the ObjectId to a string in the bayeux-events-bridge before publishing it to faye
Update faye/bayeux-cluster logging to actually log fatal errors and report errors
Adds npm start -- --inspect-node so you debug with familiar browser devtools and step through the code
Update @gitterhq/env@0.34.0 for https://gitlab.com/gitlab-org/gitter/env/merge_requests/10
Update @gitterhq/faye@1.1.0-j(from gitter-faye) for https://gitlab.com/gitlab-org/gitter/faye/merge_requests/1

Investigation

Redis

I looked directly at the Redis store to make sure the subscriptions were being saved and accounted for

$ npm install redis-commander -g
$ redis-commander
# Visit http://localhost:8081/
# Look at the `fr:` prefixed entries (defined here, https://gitlab.com/gitlab-org/gitter/webapp/blob/c3b8126074edaef9c20793c4d910e9f4c1720aa9/server/web/bayeux/cluster.js#L45)

Websocket/faye server

I could see that there wasn't any .../chatMessages frames client-side. When things are working normally, we get a downstream frame that looks like this,

[
  {
    "channel": "/api/v1/rooms/556b681e15522ed4b3e1357f/chatMessages",
    "data": {
      "operation": "create",
      "model": {
        "id": "5af09cf797f07c7e13768675",
        "text": "nnbn",
        "html": "nnbn",
        "sent": "2018-05-07T18:37:43.077Z",
        "fromUser": {
          "id": "55b214df0fc9f982beaad275",
          "username": "EricTroupeTester",
          "displayName": "Eric Eastwood",
          "url": "/EricTroupeTester",
          "avatarUrl": "https://avatars-03.gitter.im/gh/uv/4/EricTroupeTester",
          "avatarUrlSmall": "https://avatars1.githubusercontent.com/u/13482600?v=4&s=60",
          "avatarUrlMedium": "https://avatars1.githubusercontent.com/u/13482600?v=4&s=128",
          "v": 183,
          "gv": "4"
        },
        "unread": true,
        "readBy": 0,
        "urls": [],
        "mentions": [],
        "issues": [],
        "meta": [],
        "v": 1
      }
    },
    "id": "5c47",
    "ext": {
      "c": 7
    }
  }
]

I was able to debug that websocket frames weren't getting sent from the server with the faye monitoring hooks. There wasn't any publish .../chatMessages when a message was sent.

Add to server/web/bayeux/cluster.js

/* */
server.on('handshake', function(clientId) {
  console.log(`handshake: ${clientId}`);
});
server.on('subscribe', function(clientId, channel) {
  console.log(`subscribe: ${clientId} ${channel}`);
});
server.on('unsubscribe', function(clientId, channel) {
  console.log(`unsubscribe: ${clientId} ${channel}`);
});
server.on('publish', function(clientId, channel, data) {
  console.log(`publish: ${clientId} ${channel} ${JSON.stringify(data)}`);
});
server.on('disconnect', function(clientId) {
  console.log(`disconnect: ${clientId}`);
});
/* */

`mongoose` dependency

~~From some debugging, it looks like the mongoose schema.post('save', ...) hooks are not firing.~~

~~Relevant code: modules/persistence-utils/lib/mongoose-utils.js#L73-77-> server/services/persistence-service-events.js#L29-33~~

~~There is an issue around hooks that @andrewn created for mongoose@>=4.8.0 but we are using mongoose@4.6.8 😕~~

Testing locally, I am seeing our tests around the hook functionality is failing with mongoose@4.6.8, modules/persistence-utils/test/mongoose-utils-test.js. You can try it out npm run mocha -- modules/persistence-utils/test/mongoose-utils-test.js Update: I verified I was using mongoose@4.6.8 previously and now but now it is all of the sudden working 🤔

But it appears to pass in CI, https://gitlab.com/gitlab-org/gitter/webapp/-/jobs/66957916 (search for attachNotificationListenersToSchema)

mongoose dependency progression

mongoose@4.5.3 (current prod) ->
mongoose@4.10.8(https://gitlab.com/gitlab-org/gitter/webapp/merge_requests/1064) ->
mongoose4.6.8(https://gitlab.com/gitlab-org/gitter/webapp/merge_requests/1067 and current master), reverted back to 4.6.8 because of https://github.com/Automattic/mongoose/issues/5438

Back to the Websocket/faye server

The following errors were being hidden away because we didn't have proper logging setup. I'm not sure what caused the change where trying to JSON.stringify(someMongooseModel) will throw errors about the ObjectId buffers. There has been various updates to BSON things in mongo@2.2.x, https://github.com/mongodb/node-mongodb-native/blob/344d1f5a18291a262e74f0addb40710f4d443926/HISTORY.md

Error: invalid ObjectId, ObjectId.id must be either a string or a Buffer, but is [{"type":"Buffer","data":[]}]
	at ObjectID.toHexString (gitlab\webapp\node_modules\mongoose\node_modules\bson\lib\bson\objectid.js:73:11)
	at ObjectID.toJSON (gitlab\webapp\node_modules\mongoose\node_modules\bson\lib\bson\objectid.js:174:15)
	at Object.stringify (native)
	at Object.publish (gitlab\webapp\node_modules\@gitterhq\faye-redis\faye-redis.js:270:28)
	at Object.publish (gitlab\webapp\node_modules\gitter-faye\javascript\engines\proxy.js:108:25)
	at Object._handle (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\server.js:109:30)
	at Object.<anonymous> (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\server.js:78:14)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:33:39)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:36:23)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:36:23)
	at Object.extension.incoming (gitlab/webapp/server/web/bayeux/extension.js:66:16)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:38:43)
	at Object.extension.incoming (gitlab/webapp/server/web/bayeux/extension.js:66:16)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:38:43)
	at Object.extension.incoming (gitlab/webapp/server/web/bayeux/extension.js:66:16)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:38:43)
	at Object.extension.incoming (gitlab/webapp/server/web/bayeux/extension.js:70:16)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:38:43)
	at Object.incoming (gitlab/webapp/server/web/bayeux/logging.js:45:5)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:38:43)
	at Object.pipeThroughExtensions (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:41:5)
	at Object.process (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\server.js:77:12)
	at Object.request (gitlab\webapp\node_modules\gitter-faye\javascript\transport\node_local.js:13:19)
	at Object.sendMessage (gitlab\webapp\node_modules\gitter-faye\javascript\transport\transport.js:41:60)
	at Object._sendEnvelope (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\dispatcher.js:128:40)
	at Object.sendMessage (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\dispatcher.js:106:10)
	at Object.<anonymous> (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\client.js:341:24)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:33:39)
	at Object.outgoing (gitlab/webapp/server/web/bayeux/super-client.js:12:5)
	at pipe (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:39:43)
	at Object.pipeThroughExtensions (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\extensible.js:41:5)
	at Object._sendMessage (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\client.js:334:10)
	at Object.<anonymous> (gitlab\webapp\node_modules\gitter-faye\javascript\protocol\client.js:299:12)
	at gitlab\webapp\node_modules\gitter-faye\javascript\mixins\deferrable.js:22:49
	at _invoke (gitlab\webapp\node_modules\gitter-faye\javascript\util\promise.js:70:15)
	at Immediate.<anonymous> (gitlab\webapp\node_modules\gitter-faye\javascript\util\promise.js:63:22)
	at runCallback (timers.js:672:20)
	at tryOnImmediate (timers.js:645:5)
	at processImmediate [as _immediateCallback] (timers.js:617:5)

Error: invalid ObjectId, ObjectId.id must be either a string or a Buffer, but is [{"type":"Buffer","data":[]}]
	at ObjectID.toHexString (C:\\Users\\MLM\\Documents\\GitLab\\webapp\\node_modules\\mongoose\\node_modules\\bson\\lib\\bson\\objectid.js:73:11)
	at ObjectID.toJSON (C:\\Users\\MLM\\Documents\\GitLab\\webapp\\node_modules\\mongoose\\node_modules\\bson\\lib\\bson\\objectid.js:174:15)
	at Object.stringify (native)
	at stringifyInternal (gitlab/webapp/server/web/bayeux/cluster.js:141:21)
	at Object.faye.stringify (gitlab/webapp/server/web/bayeux/cluster.js:157:12)
	at Object.toJSON (gitlab/gitter-faye/javascript/faye.js:130:17)
	at gitlab/gitter-faye/javascript/mixins/logging.js:25:25
	at RegExp.[Symbol.replace] (native)
	at RegExp.[Symbol.replace] (native)
	at String.replace (native)
	at Object.writeLog (gitlab/gitter-faye/javascript/mixins/logging.js:23:32)
	at Object.Faye_Logging.(anonymous function) [as debug] (gitlab/gitter-faye/javascript/mixins/logging.js:50:14)
	at Object.publish (gitlab/gitter-faye-redis/faye-redis.js:268:18)
	at Object.publish (gitlab/gitter-faye/javascript/engines/proxy.js:109:25)
	at Object._handle (gitlab/gitter-faye/javascript/protocol/server.js:109:30)
	at Object.<anonymous> (gitlab/gitter-faye/javascript/protocol/server.js:78:14)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:32:39)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:35:23)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:35:23)
	at Object.extension.incoming (gitlab/webapp/server/web/bayeux/extension.js:66:16)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:37:27)
	at Object.extension.incoming (gitlab/webapp/server/web/bayeux/extension.js:66:16)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:37:27)
	at Object.extension.incoming (gitlab/webapp/server/web/bayeux/extension.js:66:16)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:37:27)
	at Object.extension.incoming (gitlab/webapp/server/web/bayeux/extension.js:70:16)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:37:27)
	at Object.incoming (gitlab/webapp/server/web/bayeux/logging.js:45:5)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:37:27)
	at Object.pipeThroughExtensions (gitlab/gitter-faye/javascript/protocol/extensible.js:40:5)
	at Object.process (gitlab/gitter-faye/javascript/protocol/server.js:77:12)
	at Object.request (gitlab/gitter-faye/javascript/transport/node_local.js:13:19)
	at Object.sendMessage (gitlab/gitter-faye/javascript/transport/transport.js:41:60)
	at Object._sendEnvelope (gitlab/gitter-faye/javascript/protocol/dispatcher.js:128:40)
	at Object.sendMessage (gitlab/gitter-faye/javascript/protocol/dispatcher.js:106:10)
	at Object.<anonymous> (gitlab/gitter-faye/javascript/protocol/client.js:331:24)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:32:39)
	at Object.outgoing (gitlab/webapp/server/web/bayeux/super-client.js:12:5)
	at pipe (gitlab/gitter-faye/javascript/protocol/extensible.js:38:27)
	at Object.pipeThroughExtensions (gitlab/gitter-faye/javascript/protocol/extensible.js:40:5)
	at Object._sendMessage (gitlab/gitter-faye/javascript/protocol/client.js:328:10)
	at Object.<anonymous> (gitlab/gitter-faye/javascript/protocol/client.js:298:12)
	at gitlab/gitter-faye/javascript/mixins/deferrable.js:22:49
	at _invoke (gitlab/gitter-faye/javascript/util/promise.js:70:15)
	at Immediate.<anonymous> (gitlab/gitter-faye/javascript/util/promise.js:63:22)
	at runCallback (timers.js:672:20)
	at tryOnImmediate (timers.js:645:5)
	at processImmediate [as _immediateCallback] (timers.js:617:5)

Closes https://gitlab.com/gitlab-org/gitter/webapp/issues/1894

Edited May 08, 2018 by Eric Eastwood

Fix new messages not appearing in chat list

Investigation

Redis

Websocket/faye server

mongoose dependency

Back to the Websocket/faye server

Merge request reports

`mongoose` dependency