Answering to long running threads fails with 400 error

[Gummikavalier]

Description:

When trying to answer to some long running threads that have other messages in between on the channel, posting a reply in the thread pane fails with message error message '400 error' on the top right corner of the interface.

The state of the thread stays broken until the user scrolls up the channel (not the thread) view so long that the original message becomes visible (at the latest). After this users can post messages again to the thread.

Steps to reproduce:

1. Create a normal thread on the channel with reasonable amount of activity.
2. Discuss using thread for few days using RocketChat's normal web interface. Normal new messages are required in between the replies on the channel.
3. At some point users get a red '400 error' in the top right corner of the interface any time they try to post a reply to the same thread.

Expected behavior:

Should work as usual without error messages.

Actual behavior:

No screenshot yet, I'll apply one when I get one of the threads to fail again.

Server Setup Information:

• Version of Rocket.Chat Server: 1.0.2
• Operating System: CentOS 7
• Deployment Method: tar
• Number of Running Instances: 20
• DB Replicaset Oplog: enabled
• NodeJS Version: v8.11.4
• MongoDB Version: 3.4

Additional context

The first time we saw this problem was after we had deleted and recreated a channel that already had references (links) on the other channel. On that other channel with references to original people started having '400 error' problems. However, we get these errors on any thread, and not just on the threads that had references to the recreated channel.

Relevant logs:

These get logged on our server every time the error happens:

May 09 13:05:31 removed_from_log rocketchat[1734]: Exception while invoking method 'joinRoom' { Error: Match error: Expected string, got null
May 09 13:05:31 removed_from_log rocketchat[1734]: at check (packages/check/match.js:36:17)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.joinRoom (app/lib/server/methods/joinRoom.js:10:3)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.methodsMap.(anonymous function) (app/lib/server/lib/debug.js:73:34)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.methodMap.(anonymous function) (packages/rocketchat_monitoring.js:2731:30)
May 09 13:05:31 removed_from_log rocketchat[1734]: at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1767:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at DDP._CurrentMethodInvocation.withValue (packages/ddp-server/livedata_server.js:719:19)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1304:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at DDPServer._CurrentWriteFence.withValue (packages/ddp-server/livedata_server.js:717:46)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1304:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Promise (packages/ddp-server/livedata_server.js:715:46)
May 09 13:05:31 removed_from_log rocketchat[1734]: at new Promise ()
May 09 13:05:31 removed_from_log rocketchat[1734]: at Session.method (packages/ddp-server/livedata_server.js:689:23)
May 09 13:05:31 removed_from_log rocketchat[1734]: at packages/ddp-server/livedata_server.js:559:43
May 09 13:05:31 removed_from_log rocketchat[1734]: message: 'Match error: Expected string, got null',
May 09 13:05:31 removed_from_log rocketchat[1734]: path: '',
May 09 13:05:31 removed_from_log rocketchat[1734]: sanitizedError:
May 09 13:05:31 removed_from_log rocketchat[1734]: { Error: Match failed [400]
May 09 13:05:31 removed_from_log rocketchat[1734]: at errorClass. (packages/check/match.js:91:27)
May 09 13:05:31 removed_from_log rocketchat[1734]: at new errorClass (packages/meteor.js:725:17)
May 09 13:05:31 removed_from_log rocketchat[1734]: at check (packages/check/match.js:36:17)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.joinRoom (app/lib/server/methods/joinRoom.js:10:3)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.methodsMap.(anonymous function) (app/lib/server/lib/debug.js:73:34)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.methodMap.(anonymous function) (packages/rocketchat_monitoring.js:2731:30)
May 09 13:05:31 removed_from_log rocketchat[1734]: at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1767:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at DDP._CurrentMethodInvocation.withValue (packages/ddp-server/livedata_server.js:719:19)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1304:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at DDPServer._CurrentWriteFence.withValue (packages/ddp-server/livedata_server.js:717:46)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1304:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Promise (packages/ddp-server/livedata_server.js:715:46)
May 09 13:05:31 removed_from_log rocketchat[1734]: at new Promise ()
May 09 13:05:31 removed_from_log rocketchat[1734]: at Session.method (packages/ddp-server/livedata_server.js:689:23)
May 09 13:05:31 removed_from_log rocketchat[1734]: at packages/ddp-server/livedata_server.js:559:43
May 09 13:05:31 removed_from_log rocketchat[1734]: isClientSafe: true,
May 09 13:05:31 removed_from_log rocketchat[1734]: error: 400,
May 09 13:05:31 removed_from_log rocketchat[1734]: reason: 'Match failed',
May 09 13:05:31 removed_from_log rocketchat[1734]: details: undefined,
May 09 13:05:31 removed_from_log rocketchat[1734]: message: 'Match failed [400]',
May 09 13:05:31 removed_from_log rocketchat[1734]: errorType: 'Meteor.Error' },
May 09 13:05:31 removed_from_log rocketchat[1734]: errorType: 'Match.Error' }
May 09 13:05:31 removed_from_log rocketchat[1734]: Sanitized and reported to the client as: { Error: Match failed [400]
May 09 13:05:31 removed_from_log rocketchat[1734]: at errorClass. (packages/check/match.js:91:27)
May 09 13:05:31 removed_from_log rocketchat[1734]: at new errorClass (packages/meteor.js:725:17)
May 09 13:05:31 removed_from_log rocketchat[1734]: at check (packages/check/match.js:36:17)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.joinRoom (app/lib/server/methods/joinRoom.js:10:3)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.methodsMap.(anonymous function) (app/lib/server/lib/debug.js:73:34)
May 09 13:05:31 removed_from_log rocketchat[1734]: at MethodInvocation.methodMap.(anonymous function) (packages/rocketchat_monitoring.js:2731:30)
May 09 13:05:31 removed_from_log rocketchat[1734]: at maybeAuditArgumentChecks (packages/ddp-server/livedata_server.js:1767:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at DDP._CurrentMethodInvocation.withValue (packages/ddp-server/livedata_server.js:719:19)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1304:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at DDPServer._CurrentWriteFence.withValue (packages/ddp-server/livedata_server.js:717:46)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Meteor.EnvironmentVariable.EVp.withValue (packages/meteor.js:1304:12)
May 09 13:05:31 removed_from_log rocketchat[1734]: at Promise (packages/ddp-server/livedata_server.js:715:46)
May 09 13:05:31 removed_from_log rocketchat[1734]: at new Promise ()
May 09 13:05:31 removed_from_log rocketchat[1734]: at Session.method (packages/ddp-server/livedata_server.js:689:23)
May 09 13:05:31 removed_from_log rocketchat[1734]: at packages/ddp-server/livedata_server.js:559:43
May 09 13:05:31 removed_from_log rocketchat[1734]: isClientSafe: true,
May 09 13:05:31 removed_from_log rocketchat[1734]: error: 400,
May 09 13:05:31 removed_from_log rocketchat[1734]: reason: 'Match failed',
May 09 13:05:31 removed_from_log rocketchat[1734]: details: undefined,
May 09 13:05:31 removed_from_log rocketchat[1734]: message: 'Match failed [400]',
May 09 13:05:31 removed_from_log rocketchat[1734]: errorType: 'Meteor.Error' }
May 09 13:05:31 removed_from_log rocketchat[1734]: undefined undefined

[Gummikavalier]

Ah, should be fixed already by #14402 in RC 1.0.3.

Closing.