Custom Integration content_raw possible regression

[cinderblock]

Description:

Custom Integration request.content_raw does not contain request.

Maybe I'm doing something stupid but I can't figure this out.

I'm trying to create a simple custom integration that accepts text/plain content. I cannot get raw request information as expected in content_raw. I seem to get a String with value [object Object].

My first thought was that it was some complex, possibly self referencing object (where I've seen similar issues before), and the implicit toString() was not working as expected. However, inspecting this further, typeof request.content_raw == 'string'. This indicates that something inside Rocket.Chat is not passing along the raw request body correctly.

I have tried multiple Content-Type headers with curl. In no case that I've tried does the content_raw not contain the String [object Object]. Using Content-Type: text/plain, I can see that request.content is an empty object.

I could possibly wrap my plain text as a trivial JSON object to get the data to at least show up in request.content but I don't have very good controls on the process that generates these http requests so I'd rather not.

This might be related to #2543 however I'm betting this was a regression caused by some other change as that issue was getting undefined values for content_raw and that issues seems to have been specifically fixed.

Server Setup Information:

�[34mI20180316-00:17:23.417(3) �[32m➔ �[32m+----------------------------------------------------+ 
�[34mI20180316-00:17:23.418(3) �[32m➔ �[32m|                   SERVER RUNNING                   | 
�[34mI20180316-00:17:23.418(3) �[32m➔ �[32m+----------------------------------------------------+ 
�[34mI20180316-00:17:23.419(3) �[32m➔ �[32m|                                                    | 
�[34mI20180316-00:17:23.419(3) �[32m➔ �[32m|  Rocket.Chat Version: 0.62.2                       | 
�[34mI20180316-00:17:23.419(3) �[32m➔ �[32m|       NodeJS Version: 8.9.4 - x64                  | 
�[34mI20180316-00:17:23.420(3) �[32m➔ �[32m|             Platform: linux                        | 
�[34mI20180316-00:17:23.420(3) �[32m➔ �[32m|         Process Port: 3001                         | 
�[34mI20180316-00:17:23.421(3) �[32m➔ �[32m|             Site URL: https://chat.mydomain.com/  | 
�[34mI20180316-00:17:23.421(3) �[32m➔ �[32m|     ReplicaSet OpLog: Disabled                     | 
�[34mI20180316-00:17:23.422(3) �[32m➔ �[32m|          Commit Hash: 07f0e3f77c                   | 
�[34mI20180316-00:17:23.422(3) �[32m➔ �[32m|        Commit Branch: HEAD                         | 
�[34mI20180316-00:17:23.422(3) �[32m➔ �[32m|                                                    | 
�[34mI20180316-00:17:23.423(3) �[32m➔ �[32m+----------------------------------------------------+ 

• Version of Rocket.Chat Server: 0.62.2
• Operating System: CentOS Linux release 7.4.1708 (Core)
• Deployment Method(snap/docker/tar/etc): tar
• Number of Running Instances: 1
• DB Replicaset Oplog: Disaabled
• Node Version: 8.9.4 - x64
• mongoDB Version: db version v2.6.12

Steps to Reproduce:

1. Create new Integration
2. Modify Script to log content_raw: console.log(request.content_raw)
3. Enable Integration
4. Test Integration (with example curl command that sends JSON)
5. Observe {"success":true} response to curl request

Expected behavior:

1. Raw POST data is printed in logs

Actual behavior:

1. [object Object] is printed in logs

Relevant logs:

�[34mI20180316-00:18:35.234(3) [object Object] 
�[34mI20180316-00:21:39.250(3) [object Object] 
�[34mI20180316-00:22:20.780(3) [object Object] 
�[34mI20180316-00:22:49.181(3) [object Object] 

[cinderblock]

I'm trying to look into this more on my own.

I copied 0.62.2's folder and added a single line to help debug this:

diff -ru Rocket.Chat.0.62.2/programs/server/packages/rocketchat_integrations.js Rocket.Chat.test/programs/server/packages/rocketchat_integrations.js
--- Rocket.Chat.0.62.2/programs/server/packages/rocketchat_integrations.js      2018-03-10 01:34:32.000000000 +0300
+++ Rocket.Chat.test/programs/server/packages/rocketchat_integrations.js        2018-03-19 23:54:07.638384294 +0300
@@ -2369,6 +2369,7 @@
       url_raw: this.request.url,
       url_params: this.urlParams,
       content: this.bodyParams,
+      req: this.request,
       content_raw: this.request._readableState && this.request._readableState.buffer && this.request._readableState.buffer.toString(),
       headers: this.request.headers,
       user: {

(This seems to cause Rocket.Chat to crash on certain changes to the Integration script. Not sure why, but restarting Rocket.Chat makes it come back with the new integration. A little annoying but not preventing exploring these issues.)

With that added line, I can inspect the request and get access to _readableState and its buffer.

Inspecting _readableState object, buffer is a BufferList:

Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: ReadableState {
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: objectMode: false,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: highWaterMark: 16384,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: buffer:
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: BufferList {
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: head: { data: <Buffer 61 73 64 66>, next: null },
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: tail: { data: <Buffer 61 73 64 66>, next: null },
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: length: 1 },
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: length: 4,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: pipes: null,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: pipesCount: 0,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: flowing: null,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: ended: true,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: endEmitted: false,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: reading: false,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: sync: true,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: needReadable: false,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: emittedReadable: true,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: readableListening: false,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: resumeScheduled: false,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: destroyed: false,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: defaultEncoding: 'utf8',
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: awaitDrain: 0,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: readingMore: true,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: decoder: null,
Mar 20 00:14:15 my.chat.server.com rocketchat[15181]: encoding: null }

Searching for BufferList online, I see many implementations like bl or readable-stream which all seem to implement toString(). I however have not been able to figure out which implementation Rocket.Chat is using.

If I, in my "Custom Integration", call .toString() on the BufferList, I get the [object Object] string that was previously returned. So it looks like somehow the toString() override isn't happening as expected.

Note I used the following command to generate the sample request:

$ curl -X POST -H 'Content-Type: text/plain' -d 'asdf' https://chat.mydomain.com/hooks/...

And you can see <Buffer 61 73 64 66> in the request, which corresponds to the asdf ascii.

I'm not familiar with Meteor so I'm not sure where to go from here.

[cinderblock]

I've setup a development copy of Rocket.Chat to test this more.

It looks like the core of the problem, imho, is that Restivus does not attempt to parse data when the request has an unsupported Content-Type. In particular, if the Content-Type is text/plain, I would expect this.bodyParams to contain the decoded string which would also make Rocket.Chat work as expected.

I also see discussions around how Buffer._readableStream is private and not supposed to be readable. Maybe this is something that has changed in recent versions of node?

I've attempted to access request.socket to try and read the data there but the data seems to have all been streamed away.