[SERVER-74264] Incorrect $$NOW behavior in projection of find Created: 22/Feb/23  Updated: 29/Oct/23  Resolved: 21/Mar/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 6.3.0-rc0
Fix Version/s: 7.0.0-rc0, 6.3.0-rc2

Type: Bug Priority: Major - P3
Reporter: Militsa Sotirova Assignee: Zixuan Zhuang
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Related
related to SERVER-75125 Complete TODO listed in SERVER-74264 Closed
related to SERVER-75158 Complete TODO listed in SERVER-74264 Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v6.3
Steps To Reproduce:

Start up a mongod on master with featureFlagSbeFull enabled. (Note that we do not see this behavior when the flag is not enabled.) Here is an example of the commands I used to get this behavior:

MongoDB Enterprise > db.coll.insert({a: 1})
WriteResult({ "nInserted" : 1 })
MongoDB Enterprise > db.coll.findOne({}, {time: "$$NOW"})
{
 "_id" : ObjectId("63f62adf1fd77f966273945c"),
 "time" : ISODate("2023-02-22T14:47:19.636Z")
}
MongoDB Enterprise > d = new Date()
ISODate("2023-02-22T14:47:43.620Z")
MongoDB Enterprise > db.coll.findOne({}, {time: "$$NOW"})
{
 "_id" : ObjectId("63f62adf1fd77f966273945c"),
 "time" : ISODate("2023-02-22T14:47:19.636Z")
}

I called new Date() between the two find commands to show that time had indeed passed before I ran the second one.

Example where the projected field name differs (time1 and time2) and the time is different:

MongoDB Enterprise > db.coll.findOne({}, {time1: "$$NOW"})
{
 "_id" : ObjectId("63f62adf1fd77f966273945c"),
 "time1" : ISODate("2023-02-22T15:06:32.161Z")
}
MongoDB Enterprise > d = new Date()
ISODate("2023-02-22T15:06:34.900Z")
MongoDB Enterprise > db.coll.findOne({}, {time2: "$$NOW"})
{
 "_id" : ObjectId("63f62adf1fd77f966273945c"),
 "time2" : ISODate("2023-02-22T15:06:41.043Z")
}

 

Sprint: QE 2023-03-06, QE 2023-03-20, QE 2023-04-03
Participants:

 Description   

When featureFlagSbeFull is enabled, $$NOW evaluates to the same value across two consecutive find commands when it is present in the projection part of the command (for example, db.coll.findOne({}, {time: "$$NOW"})).

I suspect that this is because when we cache the plan for the first query to use for the second, we save the actual value that $$NOW evaluates to, not a reference to it. Looking at the log printed at this point, running an example similar to the one below - the log printed for the first find command is 

{"t":{"$date":"2023-02-22T14:41:01.364+00:00"},"s":"D5", "c":"QUERY",    "id":4822860, "ctx":"conn1","msg":"SBE plan","attr":{
 
"slots":"$$RESULT=s6 env: { s2 = Nothing (SEARCH_META), s3 = 1677076861360 (NOW), s1 = TimeZoneDatabase(Asia/Tbilisi...Etc/GMT-9) (timeZoneDB) }",
 
"stages":"[3] limit 1 \n[2] project [s6 = traverseP(s4, lambda(l1.0) { makeBsonObj(MakeObjSpec(keep, [\"_id\"], [\"time\"]), l1.0, Date(1677076861360)) }, Nothing)] \n[1] scan s4 s5 none none none none [] @\"6c666eb7-d3b2-4e60-a48c-0b63d00fd393\" true false "
}}

and the log printed for the second one is 

{"t":{"$date":"2023-02-22T14:41:04.367+00:00"},"s":"D5", "c":"QUERY",    "id":4822860, "ctx":"conn1","msg":"SBE plan","attr":{
 
"slots":"$$RESULT=s6 env: { s2 = Nothing (SEARCH_META), s3 = 1677076864366 (NOW), s1 = TimeZoneDatabase(Asia/Tbilisi...Etc/GMT-9) (timeZoneDB) }",
 
"stages":"[3] limit 1 \n[2] project [s6 = traverseP(s4, lambda(l1.0) { makeBsonObj(MakeObjSpec(keep, [\"_id\"], [\"time\"]), l1.0, Date(1677076861360)) }, Nothing)] \n[1] scan s4 s5 none none none none [] @\"6c666eb7-d3b2-4e60-a48c-0b63d00fd393\" true false "
}} 

You can see that in the second log the value of $$NOW in the env is (correctly) later than that of the first log but the value used in the stages field is still the value from the first log.

Another reason I suspect this is because of how we are storing the value in the plan cache is that when we run the same commands but change the projected field name so that it is different in the second one, we see that value of $$NOW changes (since we wouldn't be able to use the cached plan from the first command). See the second example in the steps to reproduce.

This may also be the behavior for other system variables.



 Comments   
Comment by Githook User [ 21/Mar/23 ]

Author:

{'name': 'Zixuan Zhuang', 'email': 'zixuan.zhuang@mongodb.com', 'username': 'leozzx'}

Message: SERVER-74264 Backport to 6.3
Branch: v6.3
https://github.com/mongodb/mongo/commit/0f6baedfbb04cd0f1434d091b5ff9e23a6da15c9

Comment by Githook User [ 20/Mar/23 ]

Author:

{'name': 'Zixuan Zhuang', 'email': 'zixuan.zhuang@mongodb.com', 'username': 'leozzx'}

Message: SERVER-74264 Fix incorrect $$NOW behavior in projection of find
Branch: master
https://github.com/mongodb/mongo/commit/8a524486d458d0fad010d4821423f3a77780ee50

Generated at Thu Feb 08 06:26:57 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.