[SERVER-61790] Inserting to custom collection in "local" database on secondary yields writeConcernError with PrimarySteppedDown(189) Created: 30/Nov/21  Updated: 27/Oct/23  Resolved: 31/Mar/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 5.0.0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jeremy Mikola Assignee: Vesselina Ratcheva (Inactive)
Resolution: Gone away Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-58898 Prevent writing to "local" db from wa... Closed
Related
is related to PHPC-1878 Unexpected primary step down when tes... Closed
Operating System: ALL
Sprint: Replication 2022-01-10, Replication 2022-01-24, Replication 2022-02-07, Repl 2022-02-21, Repl 2022-03-07, Repl 2022-03-21, Repl 2022-04-04
Participants:

 Description   

I assume this is related to the implicit default write concern in MongoDB 5.0+, despite the docs saying that write concerns will be ignored for the "local" database.

Consider the following mongo shell session, from a direct connection to a secondary member within a three-member replica set (no arbiter).

MongoDB Enterprise repl0:SECONDARY> rs.status()
{
	"set" : "repl0",
	"date" : ISODate("2021-11-29T23:58:43.564Z"),
	"myState" : 2,
	"term" : NumberLong(3),
	"syncSourceHost" : "localhost:27018",
	"syncSourceId" : 1,
	"heartbeatIntervalMillis" : NumberLong(2000),
	"majorityVoteCount" : 2,
	"writeMajorityCount" : 2,
	"votingMembersCount" : 3,
	"writableVotingMembersCount" : 3,
	"optimes" : {
		"lastCommittedOpTime" : {
			"ts" : Timestamp(1638230323, 1),
			"t" : NumberLong(3)
		},
		"lastCommittedWallTime" : ISODate("2021-11-29T23:58:43.279Z"),
		"readConcernMajorityOpTime" : {
			"ts" : Timestamp(1638230323, 1),
			"t" : NumberLong(3)
		},
		"appliedOpTime" : {
			"ts" : Timestamp(1638230323, 1),
			"t" : NumberLong(3)
		},
		"durableOpTime" : {
			"ts" : Timestamp(1638230323, 1),
			"t" : NumberLong(3)
		},
		"lastAppliedWallTime" : ISODate("2021-11-29T23:58:43.279Z"),
		"lastDurableWallTime" : ISODate("2021-11-29T23:58:43.279Z")
	},
	"lastStableRecoveryTimestamp" : Timestamp(1638230271, 1),
	"members" : [
		{
			"_id" : 0,
			"name" : "localhost:27017",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 2813,
			"optime" : {
				"ts" : Timestamp(1638230322, 1),
				"t" : NumberLong(3)
			},
			"optimeDurable" : {
				"ts" : Timestamp(1638230322, 1),
				"t" : NumberLong(3)
			},
			"optimeDate" : ISODate("2021-11-29T23:58:42Z"),
			"optimeDurableDate" : ISODate("2021-11-29T23:58:42Z"),
			"lastHeartbeat" : ISODate("2021-11-29T23:58:42.808Z"),
			"lastHeartbeatRecv" : ISODate("2021-11-29T23:58:42.873Z"),
			"pingMs" : NumberLong(0),
			"lastHeartbeatMessage" : "",
			"syncSourceHost" : "",
			"syncSourceId" : -1,
			"infoMessage" : "",
			"electionTime" : Timestamp(1638227503, 1),
			"electionDate" : ISODate("2021-11-29T23:11:43Z"),
			"configVersion" : 1,
			"configTerm" : 3
		},
		{
			"_id" : 1,
			"name" : "localhost:27018",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 2813,
			"optime" : {
				"ts" : Timestamp(1638230322, 1),
				"t" : NumberLong(3)
			},
			"optimeDurable" : {
				"ts" : Timestamp(1638230322, 1),
				"t" : NumberLong(3)
			},
			"optimeDate" : ISODate("2021-11-29T23:58:42Z"),
			"optimeDurableDate" : ISODate("2021-11-29T23:58:42Z"),
			"lastHeartbeat" : ISODate("2021-11-29T23:58:42.808Z"),
			"lastHeartbeatRecv" : ISODate("2021-11-29T23:58:43.417Z"),
			"pingMs" : NumberLong(0),
			"lastHeartbeatMessage" : "",
			"syncSourceHost" : "localhost:27017",
			"syncSourceId" : 0,
			"infoMessage" : "",
			"configVersion" : 1,
			"configTerm" : 3
		},
		{
			"_id" : 2,
			"name" : "localhost:27019",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 2814,
			"optime" : {
				"ts" : Timestamp(1638230323, 1),
				"t" : NumberLong(3)
			},
			"optimeDate" : ISODate("2021-11-29T23:58:43Z"),
			"syncSourceHost" : "localhost:27018",
			"syncSourceId" : 1,
			"infoMessage" : "",
			"configVersion" : 1,
			"configTerm" : 3,
			"self" : true,
			"lastHeartbeatMessage" : ""
		}
	],
	"ok" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1638230323, 1),
		"signature" : {
			"hash" : BinData(0,"klt6L8rDyJJW2C/QLGz//VJelBE="),
			"keyId" : NumberLong("7036133351224246275")
		}
	},
	"operationTime" : Timestamp(1638230323, 1)
}
MongoDB Enterprise repl0:SECONDARY> use local
switched to db local
MongoDB Enterprise repl0:SECONDARY> db.foo.insert({x:1})
WriteResult({
	"nInserted" : 1,
	"writeConcernError" : {
		"code" : 189,
		"codeName" : "PrimarySteppedDown",
		"errmsg" : "Primary stepped down while waiting for replication",
		"errInfo" : {
			"writeConcern" : {
				"w" : "majority",
				"wtimeout" : 0,
				"provenance" : "implicitDefault"
			}
		}
	}
})



 Comments   
Comment by Vesselina Ratcheva (Inactive) [ 31/Mar/22 ]

Fixed by SERVER-58898 in 5.0.3+. Users should consider upgrading.

Comment by Jeremy Mikola [ 28/Mar/22 ]

vesselina.ratcheva: I just reproduced this using a two-member replica set running with 5.0.2 binaries. Both mongods were started from a command line using parameters shown below by ps aux. After starting those processes, I ran rs.initiate() and rs.add() on one host to create the replica set and add the second node. See below:

$ ps aux |grep mongod
jmikola   367083  1.5  0.5 1854944 92456 ?       Sl   Mar23 108:38 5.0.2/bin/mongod --port 27050 --dbpath /tmp/mongo50 --logpath /tmp/mongo50.log --replSet rs0 --setParameter featureFlagDotsAndDollars=true --setParameter enableTestCommands=1 --setParameter transactionLifetimeLimitSeconds=5 --fork
jmikola   367214  1.5  0.5 1824924 93080 ?       Sl   Mar23 110:46 5.0.2/bin/mongod --port 27051 --dbpath /tmp/mongo50b --logpath /tmp/mongo50b.log --replSet rs0 --setParameter featureFlagDotsAndDollars=true --setParameter enableTestCommands=1 --setParameter transactionLifetimeLimitSeconds=5 --fork
jmikola   749276  0.0  0.0   9032   720 pts/3    S+   14:25   0:00 grep --color=auto mongod
 
[beaker: ~] $ mongo --port 27051
MongoDB shell version v5.0.2
connecting to: mongodb://127.0.0.1:27051/?compressors=disabled&gssapiServiceName=mongodb
Implicit session: session { "id" : UUID("a75e7f6c-b54c-46bc-a9b6-c4cd2ae3c110") }
MongoDB server version: 5.0.2
================
Warning: the "mongo" shell has been superseded by "mongosh",
which delivers improved usability and compatibility.The "mongo" shell has been deprecated and will be removed in
an upcoming release.
We recommend you begin using "mongosh".
For installation instructions, see
https://docs.mongodb.com/mongodb-shell/install/
================
---
The server generated these startup warnings when booting: 
        2022-03-23T18:37:30.961-04:00: Access control is not enabled for the database. Read and write access to data and configuration is unrestricted
        2022-03-23T18:37:30.961-04:00: This server is bound to localhost. Remote systems will be unable to connect to this server. Start the server with --bind_ip <address> to specify which IP addresses it should serve responses from, or with --bind_ip_all to bind to all interfaces. If this behavior is desired, start the server with --bind_ip 127.0.0.1 to disable this warning
---
MongoDB Enterprise rs0:SECONDARY> rs.status()
{
	"set" : "rs0",
	"date" : ISODate("2022-03-28T18:25:34.012Z"),
	"myState" : 2,
	"term" : NumberLong(1),
	"syncSourceHost" : "localhost:27050",
	"syncSourceId" : 0,
	"heartbeatIntervalMillis" : NumberLong(2000),
	"majorityVoteCount" : 2,
	"writeMajorityCount" : 2,
	"votingMembersCount" : 2,
	"writableVotingMembersCount" : 2,
	"optimes" : {
		"lastCommittedOpTime" : {
			"ts" : Timestamp(1648491931, 1),
			"t" : NumberLong(1)
		},
		"lastCommittedWallTime" : ISODate("2022-03-28T18:25:31.373Z"),
		"readConcernMajorityOpTime" : {
			"ts" : Timestamp(1648491931, 1),
			"t" : NumberLong(1)
		},
		"appliedOpTime" : {
			"ts" : Timestamp(1648491931, 1),
			"t" : NumberLong(1)
		},
		"durableOpTime" : {
			"ts" : Timestamp(1648491931, 1),
			"t" : NumberLong(1)
		},
		"lastAppliedWallTime" : ISODate("2022-03-28T18:25:31.373Z"),
		"lastDurableWallTime" : ISODate("2022-03-28T18:25:31.373Z")
	},
	"lastStableRecoveryTimestamp" : Timestamp(1648491911, 1),
	"members" : [
		{
			"_id" : 0,
			"name" : "localhost:27050",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 416871,
			"optime" : {
				"ts" : Timestamp(1648491931, 1),
				"t" : NumberLong(1)
			},
			"optimeDurable" : {
				"ts" : Timestamp(1648491931, 1),
				"t" : NumberLong(1)
			},
			"optimeDate" : ISODate("2022-03-28T18:25:31Z"),
			"optimeDurableDate" : ISODate("2022-03-28T18:25:31Z"),
			"lastHeartbeat" : ISODate("2022-03-28T18:25:32.046Z"),
			"lastHeartbeatRecv" : ISODate("2022-03-28T18:25:33.127Z"),
			"pingMs" : NumberLong(0),
			"lastHeartbeatMessage" : "",
			"syncSourceHost" : "",
			"syncSourceId" : -1,
			"infoMessage" : "",
			"electionTime" : Timestamp(1648075020, 2),
			"electionDate" : ISODate("2022-03-23T22:37:00Z"),
			"configVersion" : 3,
			"configTerm" : 1
		},
		{
			"_id" : 1,
			"name" : "localhost:27051",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 416884,
			"optime" : {
				"ts" : Timestamp(1648491931, 1),
				"t" : NumberLong(1)
			},
			"optimeDate" : ISODate("2022-03-28T18:25:31Z"),
			"syncSourceHost" : "localhost:27050",
			"syncSourceId" : 0,
			"infoMessage" : "",
			"configVersion" : 3,
			"configTerm" : 1,
			"self" : true,
			"lastHeartbeatMessage" : ""
		}
	],
	"ok" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1648491931, 1),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	},
	"operationTime" : Timestamp(1648491931, 1)
}
MongoDB Enterprise rs0:SECONDARY> use local
switched to db local
MongoDB Enterprise rs0:SECONDARY> db.foo.insert({x:1})
WriteResult({
	"nInserted" : 1,
	"writeConcernError" : {
		"code" : 189,
		"codeName" : "PrimarySteppedDown",
		"errmsg" : "Primary stepped down while waiting for replication",
		"errInfo" : {
			"writeConcern" : {
				"w" : "majority",
				"wtimeout" : 0,
				"provenance" : "implicitDefault"
			}
		}
	}
})
MongoDB Enterprise rs0:SECONDARY>

Generated at Thu Feb 08 05:53:19 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.