[SERVER-32845] Arbiter fails when receiving an isMaster command with a $clusterTime Created: 22/Jan/18  Updated: 02/Mar/18  Resolved: 02/Mar/18

Status: Closed
Project: Core Server
Component/s: Replication, Sharding
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Jeffrey Yemin Assignee: Misha Tyulenev
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-32639 Arbiters in standalone replica sets c... Closed
Problem/Incident
causes PYTHON-1471 test_replica_set_client.TestReplicaSe... Closed
Operating System: ALL
Steps To Reproduce:

Tested with MongoDB version 3.7.1-60-gb251fd6
Start a replica set with 2 members and an arbiter, with authentication enabled

Send an isMaster command with no $clusterTime to the arbiter
Send a second isMaster command to the arbiter with the $clusterTime that the previous isMaster command returned.

On 3.6.0 this succeeds. On 3.7.1-60-gb251fd6 it fails.

Sprint: Sharding 2018-02-26, Sharding 2018-03-12
Participants:

 Description   

An arbiter fails when receiving an isMaster command with a $clusterTime with the following response:

{ 
   "operationTime" : { "$timestamp" : { "t" : 1516663477, "i" : 1 } }, 
   "ok" : 0.0, 
   "errmsg" : "Cache Reader No keys found for HMAC that is valid for time: { ts: Timestamp(1516663477, 1) } with id: 0", 
   "code" : 211, 
   "codeName" : "KeyNotFound", 
   "$clusterTime" : { 
       "clusterTime" : { "$timestamp" : { "t" : 1516663477, "i" : 1 } }, 
       "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, 
                              "keyId" : { "$numberLong" : "0" } } }
}



 Comments   
Comment by Misha Tyulenev [ 02/Mar/18 ]

Same as SERVER-32639

Comment by Shane Harvey [ 26/Feb/18 ]

I can reproduce this on the current MacOS latest build:

MongoDB shell version v3.7.2-169-g67d04f1
git version: 67d04f1a286b23ea824bdfb7042462d7da1b515d
OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016
allocator: system
modules: enterprise
build environment:
    distarch: x86_64
    target_arch: x86_64

Start a replica set with authentication and an arbiter. Then connect directly to the arbiter:

$ mongo 'mongodb://localhost:27019/'
MongoDB shell version v3.6.2
connecting to: mongodb://localhost:27019/
MongoDB server version: 3.7.2-169-g67d04f1
WARNING: shell and server versions do not match
Error while trying to show server startup warnings: Cache Reader No keys found for HMAC that is valid for time: { ts: Timestamp(1519682766, 1) } with id: 0
Note: Cannot determine if automation is active
> db.adminCommand({isMaster:1})
{
	"operationTime" : Timestamp(1519682766, 1),
	"ok" : 0,
	"errmsg" : "Cache Reader No keys found for HMAC that is valid for time: { ts: Timestamp(1519682766, 1) } with id: 0",
	"code" : 211,
	"codeName" : "KeyNotFound",
	"$clusterTime" : {
		"clusterTime" : Timestamp(1519682766, 1),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	}
}

Without sending an lsid the isMaster succeeds. I demonstrated this by using a 3.4.0 shell which does not add $clusterTime to commands:

$ mongodb-osx-x86_64-enterprise-3.4.0/bin/mongo  'mongodb://localhost:27019/'
MongoDB shell version v3.4.0
connecting to: mongodb://localhost:27019/
MongoDB server version: 3.7.2-169-g67d04f1
WARNING: shell and server versions do not match
MongoDB Enterprise e624e6b9-40e4-423c-aa84-c85cabb7853a:ARBITER> db.adminCommand({isMaster:1})
{
	"hosts" : [
		"localhost:27017",
		"localhost:27018"
	],
	"arbiters" : [
		"localhost:27019"
	],
	"setName" : "e624e6b9-40e4-423c-aa84-c85cabb7853a",
	"setVersion" : 1,
	"ismaster" : false,
	"secondary" : false,
	"primary" : "localhost:27017",
	"arbiterOnly" : true,
	"me" : "localhost:27019",
	"lastWrite" : {
		"opTime" : {
			"ts" : Timestamp(1519682756, 1),
			"t" : NumberLong(2)
		},
		"lastWriteDate" : ISODate("2018-02-26T22:05:56Z"),
		"majorityOpTime" : {
			"ts" : Timestamp(1519682756, 1),
			"t" : NumberLong(2)
		},
		"majorityWriteDate" : ISODate("2018-02-26T22:05:56Z")
	},
	"maxBsonObjectSize" : 16777216,
	"maxMessageSizeBytes" : 48000000,
	"maxWriteBatchSize" : 100000,
	"localTime" : ISODate("2018-02-26T22:06:01.969Z"),
	"logicalSessionTimeoutMinutes" : 30,
	"minWireVersion" : 0,
	"maxWireVersion" : 7,
	"readOnly" : false,
	"ok" : 1,
	"operationTime" : Timestamp(1519682756, 1)
}

Comment by Bernie Hackett [ 22/Feb/18 ]

I suspect that PYTHON-1471 is another instance of this, but I've been unable to reproduce it locally. The test fails consistently in Evergreen.

Comment by Jeffrey Yemin [ 23/Jan/18 ]

I can't reproduce it with 3.6.2-45-gb86dc5e.

Comment by Daniel Pasette (Inactive) [ 23/Jan/18 ]

jeff, can you check on 3.6.3-pre?

Comment by Jeffrey Yemin [ 23/Jan/18 ]

Also, note what happens when connecting to the arbiter via the shell:

~$ mongo localhost:27019
MongoDB shell version v3.6.0
connecting to: mongodb://localhost:27019/test
MongoDB server version: 3.7.1-60-gb251fd6
WARNING: shell and server versions do not match
Error while trying to show server startup warnings: Cache Reader No keys found for HMAC that is valid for time: { ts: Timestamp(1516670897, 1) } with id: 0
Note: Cannot determine if automation is active
>

Generated at Thu Feb 08 04:31:28 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.