[SERVER-29989] BSON field 'OperationSessionInfo.$logicalTime' is a duplicate field Created: 05/Jul/17  Updated: 27/Oct/23  Resolved: 17/Aug/17

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

Type: Bug Priority: Major - P3
Reporter: Misha Tyulenev Assignee: Misha Tyulenev
Resolution: Gone away Votes: 0
Labels: PM-221
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Sharding 2017-07-31, Sharding 2017-08-21
Participants:

 Description   

While running patch with causal consistency set to true by default got this error

[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.180+0000 assert: [40413] != [73] are not equal : Expected failure code did not match actual in command result: {
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.181+0000 	"ok" : 0,
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.181+0000 	"errmsg" : "BSON field 'OperationSessionInfo.$logicalTime' is a duplicate field",
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.181+0000 	"code" : 40413,
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.181+0000 	"codeName" : "Location40413",
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.181+0000 	"$logicalTime" : {
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.182+0000 		"clusterTime" : Timestamp(1499278149, 2),
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.182+0000 		"signature" : {
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.182+0000 			"hash" : BinData(0,"ih/XXAirsRLy+ar0M3Ut9wDmC7c="),
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.182+0000 			"keyId" : NumberLong("6439350411403984900")
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.182+0000 		}
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.183+0000 	},
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.183+0000 	"operationTime" : Timestamp(1499278149, 2)
[js_test:commands_namespace_parsing] 2017-07-05T18:09:09.183+0000 } : undefined

Investigated, testing the fix.
The code running the command on mongos propagates the response from mongod and adds cluster time without check: https://github.com/mongodb/mongo/blob/r3.5.9/src/mongo/s/commands/strategy.cpp#L133
This also happens when mongod sends the request to a another shard: https://github.com/mongodb/mongo/blob/r3.5.9/src/mongo/db/service_entry_point_mongod.cpp#L267

The proposed fix is to skip appending cluster time if its already there in https://github.com/mongodb/mongo/blob/r3.5.9/src/mongo/rpc/metadata/logical_time_metadata.cpp#L105. Will use the greatest of both cluster times



 Comments   
Comment by Misha Tyulenev [ 13/Jul/17 ]

jack.mulrow I found other cases when it duplicates the clusterTime - when mongod sends a command to config shard. So with that Im going to change the approach and
1. copy the greatest cluster time it seems there is no way around it
2. Move this code to the LogicalTimeMetadata::writeToMetadata
Updated the description per this

Comment by Kaloian Manassiev [ 10/Jul/17 ]

OK cool. Then I am going to make it 3.5 Required because it seems serious enough to warrant that.

Comment by Misha Tyulenev [ 10/Jul/17 ]

kaloian.manassiev Its not the test fixing issue. The problem is that somewhere in OP_MSG the @logicalTime added twice - this is not correct it should be one top level $logicalTime which is the greatest. Once its fixed the error will go away

Comment by Kaloian Manassiev [ 10/Jul/17 ]

Did this error message change because we started using the IDL parser? Also, what is the impact of this - is it a matter of fixing a test only or there's an internal dependency?

I am moving it out of the iteration, because it is Needs Triage.

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