After upgrade, direct message file upload fails. Getting Bad Request message

Description

Server Setup Information

  • Version of Rocket.Chat Server: 3.5.2
  • Operating System: CentOS Linux release 7.7.1908 (Core)
  • Deployment Method: tar / manual install
  • Number of Running Instances: 1
  • DB Replicaset Oplog:
  • NodeJS Version: v12.18.3
  • MongoDB Version: v4.0.13
  • Proxy: Apache Reverse Proxy
  • Firewalls involved: Firewall is disabled

Any additional Information

Apache Access Log Sample

[Thu Aug 13 14:20:25.238915 2020] [authz_core:debug] [pid 15362] mod_authz_core.c(835): [client 192.168.1.38:63770] AH01628: authorization result: granted (no directives), referer: https://mydomain.com/direct/DxhJ9JdNbw5zZH6J8s5pzzufsdn2CxJfRD
[Thu Aug 13 14:20:25.239007 2020] [proxy:debug] [pid 15362] mod_proxy.c(1123): [client 192.168.1.38:63770] AH01143: Running scheme http handler (attempt 0), referer: https://mydomain.com/direct/DxhJ9JdNbw5zZH6J8s5pzzufsdn2CxJfRD
[Thu Aug 13 14:20:25.239014 2020] [proxy_ajp:debug] [pid 15362] mod_proxy_ajp.c(722): [client 192.168.1.38:63770] AH00894: declining URL http://localhost:3000/sockjs/info?cb=t56y6wls1e, referer: https://mydomain.com/direct/DxhJ9JdNbw5zZH6J8s5pzzufsdn2CxJfRD
[Thu Aug 13 14:20:25.239020 2020] [proxy_fcgi:debug] [pid 15362] mod_proxy_fcgi.c(972): [client 192.168.1.38:63770] AH01076: url: http://localhost:3000/sockjs/info?cb=t56y6wls1e proxyname: (null) proxyport: 0, referer: https://mydomain.com/direct/DxhJ9JdNbw5zZH6J8s5pzzufsdn2CxJfRD
[Thu Aug 13 14:20:25.239030 2020] [proxy_fcgi:debug] [pid 15362] mod_proxy_fcgi.c(975): [client 192.168.1.38:63770] AH01077: declining URL http://localhost:3000/sockjs/info?cb=t56y6wls1e, referer: https://mydomain.com/direct/DxhJ9JdNbw5zZH6J8s5pzzufsdn2CxJfRD
[Thu Aug 13 14:20:25.239040 2020] [proxy:debug] [pid 15362] proxy_util.c(2203): AH00942: HTTP: has acquired connection for (*)
[Thu Aug 13 14:20:25.239047 2020] [proxy:debug] [pid 15362] proxy_util.c(2256): [client 192.168.1.38:63770] AH00944: connecting http://localhost:3000/sockjs/info?cb=t56y6wls1e to localhost:3000, referer: https://mydomain.com/direct/DxhJ9JdNbw5zZH6J8s5pzzufsdn2CxJfRD
[Thu Aug 13 14:20:25.239579 2020] [proxy:debug] [pid 15362] proxy_util.c(2426): [client 192.168.1.38:63770] AH00947: connected /sockjs/info?cb=t56y6wls1e to localhost:3000, referer: https://mydomain.com/direct/DxhJ9JdNbw5zZH6J8s5pzzufsdn2CxJfRD
[Thu Aug 13 14:20:25.239733 2020] [proxy:debug] [pid 15362] proxy_util.c(2793): (111)Connection refused: AH00957: HTTP: attempt to connect to [::1]:3000 (*) failed
[Thu Aug 13 14:20:25.239819 2020] [proxy:debug] [pid 15362] proxy_util.c(2802): AH02824: HTTP: connection established with 127.0.0.1:3000 (*)
[Thu Aug 13 14:20:25.239831 2020] [proxy:debug] [pid 15362] proxy_util.c(2942): AH00962: HTTP: connection complete to [::1]:3000 (localhost)
[Thu Aug 13 14:20:25.243155 2020] [proxy:debug] [pid 15362] proxy_util.c(2218): AH00943: *: has released connection for (*)
[Thu Aug 13 14:20:25.329622 2020] [ssl:debug] [pid 15363] ssl_engine_kernel.c(225): [client 192.168.1.28:63326] AH02034: Initial (No.1) HTTPS request received for child 1 (server mydomain.com:443), referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.329791 2020] [authz_core:debug] [pid 15363] mod_authz_core.c(835): [client 192.168.1.28:63326] AH01628: authorization result: granted (no directives), referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.329899 2020] [proxy:debug] [pid 15363] mod_proxy.c(1123): [client 192.168.1.28:63326] AH01143: Running scheme http handler (attempt 0), referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.329910 2020] [proxy_ajp:debug] [pid 15363] mod_proxy_ajp.c(722): [client 192.168.1.28:63326] AH00894: declining URL http://localhost:3000/sockjs/info?cb=_une4eguuf, referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.329915 2020] [proxy_fcgi:debug] [pid 15363] mod_proxy_fcgi.c(972): [client 192.168.1.28:63326] AH01076: url: http://localhost:3000/sockjs/info?cb=_une4eguuf proxyname: (null) proxyport: 0, referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.329919 2020] [proxy_fcgi:debug] [pid 15363] mod_proxy_fcgi.c(975): [client 192.168.1.28:63326] AH01077: declining URL http://localhost:3000/sockjs/info?cb=_une4eguuf, referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.329928 2020] [proxy:debug] [pid 15363] proxy_util.c(2203): AH00942: HTTP: has acquired connection for (*)
[Thu Aug 13 14:20:25.329935 2020] [proxy:debug] [pid 15363] proxy_util.c(2256): [client 192.168.1.28:63326] AH00944: connecting http://localhost:3000/sockjs/info?cb=_une4eguuf to localhost:3000, referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.330199 2020] [proxy:debug] [pid 15363] proxy_util.c(2426): [client 192.168.1.28:63326] AH00947: connected /sockjs/info?cb=_une4eguuf to localhost:3000, referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.330262 2020] [proxy:debug] [pid 15363] proxy_util.c(2793): (111)Connection refused: AH00957: HTTP: attempt to connect to [::1]:3000 (*) failed
[Thu Aug 13 14:20:25.330341 2020] [proxy:debug] [pid 15363] proxy_util.c(2802): AH02824: HTTP: connection established with 127.0.0.1:3000 (*)
[Thu Aug 13 14:20:25.330354 2020] [proxy:debug] [pid 15363] proxy_util.c(2942): AH00962: HTTP: connection complete to [::1]:3000 (localhost)
[Thu Aug 13 14:20:25.331685 2020] [ssl:debug] [pid 15368] ssl_engine_kernel.c(225): [client 192.168.1.38:63771] AH02034: Initial (No.1) HTTPS request received for child 2 (server mydomain.com:443), referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.331807 2020] [authz_core:debug] [pid 15368] mod_authz_core.c(835): [client 192.168.1.38:63771] AH01628: authorization result: granted (no directives), referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.331900 2020] [proxy:debug] [pid 15368] mod_proxy.c(1123): [client 192.168.1.38:63771] AH01143: Running scheme http handler (attempt 0), referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.331910 2020] [proxy_ajp:debug] [pid 15368] mod_proxy_ajp.c(722): [client 192.168.1.38:63771] AH00894: declining URL http://localhost:3000/sockjs/info?cb=qihzpabkwx, referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.331915 2020] [proxy_fcgi:debug] [pid 15368] mod_proxy_fcgi.c(972): [client 192.168.1.38:63771] AH01076: url: http://localhost:3000/sockjs/info?cb=qihzpabkwx proxyname: (null) proxyport: 0, referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.331918 2020] [proxy_fcgi:debug] [pid 15368] mod_proxy_fcgi.c(975): [client 192.168.1.38:63771] AH01077: declining URL http://localhost:3000/sockjs/info?cb=qihzpabkwx, referer: https://mydomain.com/channel/appdev
[Thu Aug 13 14:20:25.331926 2020] [proxy:debug] [pid 15368] proxy_util.c(2203): AH00942: HTTP: has acquired connection for (*)

Rocket.Chat Log Section

Aug 13 14:20:25 localhost rocketchat: clientAddress: '192.168.1.38',
Aug 13 14:20:25 localhost rocketchat: httpHeaders: {
Aug 13 14:20:25 localhost rocketchat: host: 'localhost:3000',
Aug 13 14:20:25 localhost rocketchat: 'user-agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:68.0) Gecko/20100101 Firefox/68.0',
Aug 13 14:20:25 localhost rocketchat: accept: '*/*',
Aug 13 14:20:25 localhost rocketchat: 'accept-language': 'en-US,en;q=0.5',
Aug 13 14:20:25 localhost rocketchat: 'accept-encoding': 'gzip, deflate, br',
Aug 13 14:20:25 localhost rocketchat: referer: 'https://mydomain.com/direct/DxhJ9JdNbw5zZH6J8s5pzzufsdn2CxJfRD',
Aug 13 14:20:25 localhost rocketchat: 'content-type': 'application/json',
Aug 13 14:20:25 localhost rocketchat: 'x-user-id': 'DxhJ9JdNbw5zZH6J8',
Aug 13 14:20:25 localhost rocketchat: 'x-auth-token': 'HrlhhFVEr97S4HOqD-oHivQBtf7c6OjJwCWg8d82rRP',
Aug 13 14:20:25 localhost rocketchat: 'x-requested-with': 'XMLHttpRequest',
Aug 13 14:20:25 localhost rocketchat: cookie: '_ga=GA1.2.622890059.1583264839; rc_uid=DxhJ9JdNbw5zZH6J8; rc_token=HrlhhFVEr97S4HOqD-oHivQBtf7c6OjJwCWg8d82rRP',
Aug 13 14:20:25 localhost rocketchat: 'x-forwarded-for': '192.168.1.38',
Aug 13 14:20:25 localhost rocketchat: 'x-forwarded-host': 'mydomain.com',
Aug 13 14:20:25 localhost rocketchat: 'x-forwarded-server': 'mydomain.com',
Aug 13 14:20:25 localhost rocketchat: connection: 'close',
Aug 13 14:20:25 localhost rocketchat: 'content-length': '160'
Aug 13 14:20:25 localhost rocketchat: },
Aug 13 14:20:25 localhost rocketchat: userId: 'DxhJ9JdNbw5zZH6J8'
Aug 13 14:20:25 localhost rocketchat: }
Aug 13 14:20:26 localhost rocketchat: null {
Aug 13 14:20:26 localhost rocketchat: id: 'ogqDYWoEez7WCmfNq',
Aug 13 14:20:26 localhost rocketchat: clientAddress: '192.168.1.38',
Aug 13 14:20:26 localhost rocketchat: httpHeaders: {
Aug 13 14:20:26 localhost rocketchat: 'x-forwarded-for': '192.168.1.38',
Aug 13 14:20:26 localhost rocketchat: 'x-forwarded-host': 'mydomain.com',
Aug 13 14:20:26 localhost rocketchat: host: 'localhost:3000',
Aug 13 14:20:26 localhost rocketchat: 'user-agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Rocket.Chat/2.17.7 Chrome/78.0.3904.130 Electron/7.1.10 Safari/537.36',
Aug 13 14:20:26 localhost rocketchat: 'accept-language': 'en-US'
Aug 13 14:20:26 localhost rocketchat: },
Aug 13 14:20:26 localhost rocketchat: userId: null
Aug 13 14:20:26 localhost rocketchat: }

rocketchat.service contents

[Unit]
Description=The Rocket.Chat server
After=network.target remote-fs.target nss-lookup.target nginx.target mongod.target mongod.service
[Service]
ExecStart=/usr/local/bin/node /opt/Rocket.Chat/main.js
StandardOutput=syslog
StandardError=syslog
SyslogIdentifier=rocketchat
User=rocketchat
Environment=MONGO_URL=mongodb://localhost:27017/rocketchat?replicaSet=rocketchatdb MONGO_OPLOG_URL=mongodb://localhost:27017/local?replicaSet=rocketchatdb ROOT_URL=https://mydomain.com/ PORT=3000
[Install]
WantedBy=multi-user.target

Apache Virtual Host Configuration

<VirtualHost *:443>

ServerAdmin admin@mydomain.com
ServerName mydomain.com
ErrorLog /var/log/mydomain.com_error.log
TransferLog /var/log/mydomain.com_access.log
#LogLevel info
LogLevel debug
SSLEngine On
SSLCertificateFile /etc/ssl/certs/newccnycert.pem
SSLCertificateKeyFile /etc/ssl/certs/newccnycertnokey.key
SSLCertificateChainFile /etc/ssl/certs/newccnycert.pem

<Location />
        Order allow,deny
        Allow from all
</Location>

RewriteEngine On
RewriteCond %{HTTP:Upgrade} =websocket [NC]
RewriteRule /(.*)           ws://localhost:3000/$1 [P,L]
RewriteCond %{HTTP:Upgrade} !=websocket [NC]
RewriteRule /(.*)           http://localhost:3000/$1 [P,L]

ProxyPassReverse / http://localhost:3000/
</VirtualHost>

This is what the error looks like from the Rocket.Chat client:

After upgrading to both version 3.5.1 and 3.5.2, I am not able to upload a file via direct message to another user. Whenever I do, I get a “Bad Request” error message.

I have tried changing different settings in rocketchat.service file and in the Apache Proxy, but nothing seems to work. I changed http to https. Used localhost, ip address, domain name and none work.

I do have File Upload enabled in settings.

The files I’ve tried to upload are just images: .jpg, .gif, .png or clipboard paste. I have cleared the list of allowed file types to allow everything, and the problem still happens. I am able to upload fine in a channel, just not in a DM.

I do notice in this line from the log:

[Thu Aug 13 14:20:25.329910 2020] [proxy_ajp:debug] [pid 15363] mod_proxy_ajp.c(722): [client 192.168.1.28:63326] AH00894: declining URL http://localhost:3000/sockjs/info?cb=_une4eguuf, referer: https://mydomain.com/channel/appdev

The referer is https going to http, I don’t know if that has something to do with it.

Before the upgrades, this feature worked fine.

Has anyone experienced something similar? Any idea what setting I might be missing or where else I can look for more clues?

Update. I had been trying this between the same two users. I tried with different users and it works for some users and not for others. This leads me to believe the issue is not with the Apache proxy settings or it would not work for ANY users. I’m still troubleshooting this, but have found no fix as of yet. I’m almost certain if I downgrade the problem will go away since it worked before the upgrade. I will continue and see what I can find.

hello @nitrox007 could you help me in updating rc

@surendrababu.s

I don’t use Docker, but I have backed up and restored my database like this:

Backup

sudo mongodump --out /backup/db/<backup_name>

Restore

sudo mongorestore /backup/db/<backup_name>

After a lot of troubleshooting, I narrowed down the issue to a corrupt user in RC. When I would try to load this user’s profile from the admin interface, I would get “not found”. Because it was not found, it would not allow me to select and/or delete the user. I tested sending/uploading the images between other users, and it seemed to work. To fix it, I deleted the user manually from the database (this is probably not recommended, so use at your on risk if you choose to go this way).

Make sure you create a backup of your database before doing this.

Steps:

mongo
show dbs
use
show collections

db.users.find({username:“user_name”}).pretty()
This will show you the user with the issue

db.users.remove({‘username’:‘user_name’})
This will remove the user

try to view the user again to confirm it’s been removed:

db.users.find({username:“user_name”}).pretty()

After this, restart Apache and Rocketchat services
sudo systemctl restart rocketchat && sudo systemctl restart httpd.service && sudo systemctl status rocketchat && sudo systemctl status httpd.service

If you were logged-in to RC via browser, then make sure to clear cache and cookies before attempting to do the file transfer between users again.