Regression: 3.7.0-rc.0 fails at oplog detection

[TwizzyDizzy]

Description:

Since upgrading my testing instance to 3.7.0-rc.0, Rocket.Chat seems to fail to detect whether the Replicaset Oplog is enabled.

I have a single instance, so there is only one MongoDB server and one instance of Rocket.Chat. mongod is in PRIMARY mode as seen below [1].

systemd unit is configured to use the oplog as shown in [2].

I suspect, that this might be related to the changes to app/models/server/models/_BaseDb.js in 3.7.0-rc.0 (diff: 3.6.2...3.7.0-rc.0)

If you need any additional debugging on my side, do not hesitate to get back! :)

Steps to reproduce:

1. Properly configure Rocket.Chat to use the Replicaset Oplog via environment var MONGO_OPLOG_URL
2. start server

Expected behavior:

Oplog detection should connect to the rs-oplog and detect the connection properly

Actual behavior:

ReplicaSet OpLog: Disabled

Server Setup Information:

• Version of Rocket.Chat Server: 3.7.0-rc.0
• Operating System: Linux
• Deployment Method: Ansible
• Number of Running Instances: 1
• DB Replicaset Oplog: configured to be enabled, but not detected properly
• NodeJS Version: 12.18.4 - x64
• MongoDB Version: 3.6.17

Client Setup Information

not relevant

Additional context

See bottom

Relevant logs:

See bottom

[1]

rs0:PRIMARY> rs.status()
{
	"set" : "rs0",
	"date" : ISODate("2020-09-22T09:15:29.796Z"),
	"myState" : 1,
	"term" : NumberLong(47),
	"syncingTo" : "",
	"syncSourceHost" : "",
	"syncSourceId" : -1,
	"heartbeatIntervalMillis" : NumberLong(2000),
	"optimes" : {
		"lastCommittedOpTime" : {
			"ts" : Timestamp(1600766127, 1),
			"t" : NumberLong(47)
		},
		"readConcernMajorityOpTime" : {
			"ts" : Timestamp(1600766127, 1),
			"t" : NumberLong(47)
		},
		"appliedOpTime" : {
			"ts" : Timestamp(1600766127, 1),
			"t" : NumberLong(47)
		},
		"durableOpTime" : {
			"ts" : Timestamp(1600766127, 1),
			"t" : NumberLong(47)
		}
	},
	"members" : [
		{
			"_id" : 0,
			"name" : "127.0.0.1:27017",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 325,
			"optime" : {
				"ts" : Timestamp(1600766127, 1),
				"t" : NumberLong(47)
			},
			"optimeDate" : ISODate("2020-09-22T09:15:27Z"),
			"syncingTo" : "",
			"syncSourceHost" : "",
			"syncSourceId" : -1,
			"infoMessage" : "",
			"electionTime" : Timestamp(1600765815, 1),
			"electionDate" : ISODate("2020-09-22T09:10:15Z"),
			"configVersion" : 39898,
			"self" : true,
			"lastHeartbeatMessage" : ""
		}
	],
	"ok" : 1,
	"operationTime" : Timestamp(1600766127, 1),
	"$clusterTime" : {
		"clusterTime" : Timestamp(1600766127, 1),
		"signature" : {
			"hash" : BinData(0,"XTheg9r1CbMzufZMXmLplqIBPVs="),
			"keyId" : NumberLong("6822964842899439617")
		}
	}
}

[2]

[Service]
Type=simple
Restart=always
StandardOutput=syslog
SyslogIdentifier=RocketChat
User=rocketchat
Group=rocketchat
Environment=MONGO_URL=mongodb://USER:PASSWORD@127.0.0.1:27017/rocketchat
Environment=MONGO_OPLOG_URL=mongodb://USER:PASSWORD@127.0.0.1:27017/local?replSet=rs0&authSource=admin
Environment=ROOT_URL=https://dev-chat.mycompa.ny
Environment=PORT=3000
Environment=DEPLOY_PLATFORM=ansible
WorkingDirectory=/opt/rocketchat
ExecStart=/bin/node --tls-min-v1.2 /opt/rocketchat/bundle/main.js
Environment=NODE_EXTRA_CA_CERTS=/etc/pki/ca-trust/source/anchors/ROOT+ISSUINGCA.crt

[TwizzyDizzy]

Hold on. This issue might still be on my side. Currently doing some additional debugging.

EDIT 1: the actual error, which I must have overlooked the first time, is:

Sep 22 12:10:20 dev-chat RocketChat: not authorized on admin to execute command { replSetGetStatus: 1, lsid: { id: UUID("3941bd2a-05f8-4066-b7d2-91e107b99fe0") }, $clusterTime: { clusterTime: Timestamp(1600769415, 1), signature: { hash: Bi
nData(0, F7107C5295B622083F52D2907B19DF624287B3AD), keyId: 6822964842899439617 } }, $db: "admin" }

Investigation still ongoing.

[sampaiodiego]

thanks for the detailed report @TwizzyDizzy =)

from what I see perhaps we're now executing an admin command (thus requiring admin permissions) while before such permissions weren't required. I'll take a look on this as well. pinging @rodrigok

can you provide extra information on how your mongodb users are set up?

[TwizzyDizzy]

from what I see perhaps we're now executing an admin command (thus requiring admin permissions) while before such permissions weren't required.

Yes, indeed I think the issue may come from that direction.

Here are my users - have in mind, that I have &authSource=admin specified for MONGO_OPLOG_URL.

local collection:

rs0:PRIMARY> use local
switched to db local
rs0:PRIMARY> db.getUsers( {    showCredentials: false, } )
[ ]

admin collection:

rs0:PRIMARY> db.getUsers( {    showCredentials: false, } )
[
	{
		"_id" : "admin.admin",
		"user" : "admin",
		"db" : "admin",
		"customData" : {
			"createdBy" : "Puppet Mongodb_user['User admin on db admin']"
		},
		"roles" : [
			{
				"role" : "clusterAdmin",
				"db" : "admin"
			},
			{
				"role" : "clusterManager",
				"db" : "admin"
			},
			{
				"role" : "clusterMonitor",
				"db" : "admin"
			},
			{
				"role" : "dbAdmin",
				"db" : "admin"
			},
			{
				"role" : "dbAdminAnyDatabase",
				"db" : "admin"
			},
			{
				"role" : "hostManager",
				"db" : "admin"
			},
			{
				"role" : "readAnyDatabase",
				"db" : "admin"
			},
			{
				"role" : "readWrite",
				"db" : "admin"
			},
			{
				"role" : "readWriteAnyDatabase",
				"db" : "admin"
			},
			{
				"role" : "restore",
				"db" : "admin"
			},
			{
				"role" : "root",
				"db" : "admin"
			},
			{
				"role" : "userAdmin",
				"db" : "admin"
			},
			{
				"role" : "userAdminAnyDatabase",
				"db" : "admin"
			}
		]
	},
	{
		"_id" : "admin.backup",
		"user" : "backup",
		"db" : "admin",
		"customData" : {
			"createdBy" : "Puppet Mongodb_user['backup']"
		},
		"roles" : [
			{
				"role" : "backup",
				"db" : "admin"
			}
		]
	},
	{
		"_id" : "admin.oplogger",
		"userId" : UUID("c9253f56-af9d-4d6d-9670-17315b90b386"),
		"user" : "oplogger",
		"db" : "admin",
		"roles" : [
			{
				"role" : "read",
				"db" : "local"
			}
		]
	},
	{
		"_id" : "admin.rocketchat",
		"userId" : UUID("28c3357c-911a-4565-87bd-a88b5a582df3"),
		"user" : "rocketchat",
		"db" : "admin",
		"customData" : {
			"createdBy" : "Puppet Mongodb_user['rocketchat-admin-privs']"
		},
		"roles" : [
			{
				"role" : "clusterMonitor",
				"db" : "admin"
			}
		]
	}
]

The relevant user from MONGO_OPLOG_URL is admin.oplogger:

	{
		"_id" : "admin.oplogger",
		"userId" : UUID("c9253f56-af9d-4d6d-9670-17315b90b386"),
		"user" : "oplogger",
		"db" : "admin",
		"roles" : [
			{
				"role" : "read",
				"db" : "local"
			}
		]
	},

[sampaiodiego]

thanks @TwizzyDizzy .. the new implementation executes admin commands on MONGO_URL if it is compatible with Change Streams (https://docs.mongodb.com/manual/changeStreams/#availability) .. for now you can either set the env var USE_NATIVE_OPLOG to force using old oplog implementation or give admin permissions to the user set on MONGO_URL..

we'll figure out the best approach to this to be backwards compatible.

[TwizzyDizzy]

Hi @sampaiodiego indeed, setting USE_NATIVE_OPLOG to true in my systemd unit [1] restores the old behaviour and shows the oplog as enabled. Thanks for your fast response!

The permission change deserves a closer look later, so I chose the above method to get going :)

Cheers
Thomas

[1]

Environment=USE_NATIVE_OPLOG=true