[SERVER-27934] Config Server Optime difference from rs.status() output Created: 07/Feb/17  Updated: 26/Apr/19  Resolved: 16/Feb/17

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

Type: Bug Priority: Minor - P4
Reporter: Wei Shan Ang Assignee: Kelsey Schubert
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

FreeBSD 11 64bit, MongoDB 3.2.11


Attachments: Text File config server oplog.txt    
Backwards Compatibility: Minor Change
Operating System: ALL
Steps To Reproduce:

1. Deploy config server in CSRS.
2. Query the replication status via replSetGetStatus

Participants:

 Description   

Hi all!

I think I found a bug when querying for config server optime via replSetGetStatus command somehow.

config.rs0:SECONDARY> rs.status()
{
	"set" : "config.rs0",
	"date" : ISODate("2017-02-07T13:35:02.792Z"),
	"myState" : 2,
	"term" : NumberLong(25),
	"syncingTo" : "config1",
	"configsvr" : true,
	"heartbeatIntervalMillis" : NumberLong(2000),
	"members" : [
		{
			"_id" : 3,
			"name" : "config2:27019",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 7358,
			"optime" : {
				"ts" : Timestamp(1486474501, 4),
				"t" : NumberLong(25)
			},
			"optimeDate" : ISODate("2017-02-07T13:35:01Z"),
			"syncingTo" : "config1:27019",
			"configVersion" : 14,
			"self" : true
		},
		{
			"_id" : 4,
			"name" : "config1:27019",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 7356,
			"optime" : {
				"ts" : Timestamp(1486474501, 4),
				"t" : NumberLong(25)
			},
			"optimeDate" : ISODate("2017-02-07T13:35:01Z"),
			"lastHeartbeat" : ISODate("2017-02-07T13:35:02.516Z"),
			"lastHeartbeatRecv" : ISODate("2017-02-07T13:35:02.515Z"),
			"pingMs" : NumberLong(0),
			"electionTime" : Timestamp(1486467112, 1),
			"electionDate" : ISODate("2017-02-07T11:31:52Z"),
			"configVersion" : 14
		},
		{
			"_id" : 5,
			"name" : "config3:27019",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 7355,
			"optime" : {
				"ts" : Timestamp(1486474501, 4),
				"t" : NumberLong(25)
			},
			"optimeDate" : ISODate("2017-02-07T13:35:01Z"),
			"lastHeartbeat" : ISODate("2017-02-07T13:35:02.764Z"),
			"lastHeartbeatRecv" : ISODate("2017-02-07T13:35:02.576Z"),
			"pingMs" : NumberLong(190),
			"syncingTo" : "config1:27019",
			"configVersion" : 14
		}
	],
	"ok" : 1
}

If you see the above, the optime on the primary is 1486474501, which is the actual last entry in the oplog. However, when I query the config server using replSetGetStatus (pymongo), it shows the uptime instead.

[{u'uptime': 7362,
   u'configVersion': 14,
   u'optime': {
      u'ts': Timestamp(1486474506, 1),
      u't': 25L
      },
   u'name': u'config2:27019',
   u'self': True,
   u'optimeDate': datetime.datetime(2017, 2, 7, 13, 35, 6),
   u'syncingTo': u'config1:27019',
   u'state': 2,
   u'health': 1.0,
   u'stateStr': u'SECONDARY',
   u'_id': 3},
{u'uptime': 7360,
   u'configVersion': 14,
   u'optime': {
      u'ts': Timestamp(1486474506, 1),
      u't': 25L
   },
   u'name': u'config1:27019',
   u'pingMs': 0L,
   u'optimeDate': datetime.datetime(2017, 2, 7, 13, 35, 6),
   u'electionTime': Timestamp(1486467112, 1),
   u'electionDate': datetime.datetime(2017, 2, 7, 11, 31, 52),
   u'state': 1,
   u'health': 1.0,
   u'stateStr': u'PRIMARY',
   u'lastHeartbeatRecv': datetime.datetime(2017, 2, 7, 13, 35, 6, 522000),
   u'_id': 4,
   u'lastHeartbeat': datetime.datetime(2017, 2, 7, 13, 35, 6, 522000)},
{u'uptime': 7359,
   u'configVersion': 14,
   u'optime': {
      u'ts': Timestamp(1486474504, 1),
      u't': 25L
      },
   u'name': u'config3:27019',
   u'pingMs': 190L,
   u'optimeDate': datetime.datetime(2017, 2, 7, 13, 35, 4),
   u'syncingTo': u'config1',
   u'state': 2,
   u'health': 1.0,
   u'stateStr': u'SECONDARY',
   u'lastHeartbeatRecv': datetime.datetime(2017, 2, 7, 13, 35, 4, 771000),
   u'_id': 5,
   u'lastHeartbeat': datetime.datetime(2017, 2, 7, 13, 35, 4, 959000)}]

This only happens on CSRS config server replica sets.

Thanks!



 Comments   
Comment by Ian Whalen (Inactive) [ 26/Apr/19 ]

Switching "Drivers Changes Needed" from "Maybe" to "Not Needed" since this was closed as something other than Fixed.

Comment by Kelsey Schubert [ 16/Feb/17 ]

Hi weishan,

Thanks for the additional information. From your responses, I do not see anything to indicate a bug in the MongoDB server. If another write was performed, it is expected that the optime would change between calls to rs.status(). If you would like us to continue to investigate, would you please a reproduction that guarantees that the optime should be the same?

For MongoDB-related support discussion please post on the mongodb-user group or Stack Overflow with the mongodb tag. A question like this involving more discussion would be best posted on the mongodb-users group. Users there may be able to help explain this behavior or guide you to construct a reproduction to help our investigation.

Thank you,
Thomas

Comment by Wei Shan Ang [ 08/Feb/17 ]

Hi Mark,

I have just reattach the output again to show the issue better. Yesterday, I did a failover as we were doing some maintenance. After that, I found out the issue has reversed. Now, the optime of rs.status() output is valid but the output in replSetGetStatus stays the same.

Comment by Mark Agarunov [ 07/Feb/17 ]

Hello weishan,

Thank you for the report. Looking over the output you've provided, I don't seem to see the behavior you're describing. With rs.status() the optime is showing:

"ts" : Timestamp(1486474501, 4)

And in the pymongo/replSetGetStatus output it's showing:

u'ts': Timestamp(1486474504, 1),

which is only a few seconds after the optime from the mongo shell. The output of both appears to be the same; both show uptime and optime. If I am misunderstanding the issue you are describing, please let me know and we'll continue debugging.

Thanks,
Mark

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