Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-74264

Incorrect $$NOW behavior in projection of find

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 7.0.0-rc0, 6.3.0-rc2
    • Affects Version/s: 6.3.0-rc0
    • Component/s: None
    • None
    • Fully Compatible
    • ALL
    • v6.3, v6.0
    • Hide

      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")
}

       

      Show
      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" ) }  
    • QE 2023-03-06, QE 2023-03-20, QE 2023-04-03

      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.

            Assignee:
            zixuan.zhuang@mongodb.com Zixuan Zhuang
            Reporter:
            militsa.sotirova@mongodb.com Militsa Sotirova
            Votes:
            0 Vote for this issue
            Watchers:
            12 Start watching this issue

              Created:
              Updated:
              Resolved: