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

Mismatched createIndex logs on mongos vs mongods with floating point expireAfterSeconds

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Works as Designed
    • Priority: Icon: Minor - P4 Minor - P4
    • None
    • Affects Version/s: None
    • Component/s: None
    • None
    • Storage Execution
    • ALL
    • Hide 
      >  mlaunch --shards 2 --replicaset --nodes 2 --binarypath <localPath>/.local/m/versions/7.3.0/bin
...
> mongosh
> [direct: mongos] test> db.myColl.createIndex({created: 1}, {expireAfterSeconds: 10.23})

      mongos.log: "expireAfterSeconds":10.23

      {"t":{"$date":"2024-07-09T17:31:02.269-05:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn30","msg":"Slow query","attr":{"type"    :"command","isFromUserConnection":true,"ns":"test.myColl","collectionType":"normal","appName":"mongosh 2.2.0","command":{"createIndexes    ":"myColl","indexes":[{"expireAfterSeconds":10.23,"name":"created_1","key":{"created":1}}],"lsid":{"id":{"$uuid":"2588dcb2-8ff2-4ace-a8    62-a8c6659eb07a"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1720564257,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAA    AAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test"},"catalogCacheDatabaseLookupDurationMillis":1,"catalogCacheCollectionL    ookupDurationMillis":7,"numYields":0,"reslen":447,"locks":{},"readConcern":{"level":"local","provenance":"implicitDefault"},"remote":"1    27.0.0.1:56622","protocol":"op_msg","remoteOpWaitMillis":98,"durationMillis":189}}

      mongod.log (rs1): "expireAfterSeconds": 10

      {"t":{"$date":"2024-07-09T17:31:02.223-05:00"},"s":"I",  "c":"REPL",     "id":7360101, "ctx":"conn51","msg":"Wrote oplog entry for crea    teIndexes","attr":{"namespace":"test.$cmd","uuid":{"uuid":{"$uuid":"0889e21a-a69d-40ba-a89c-5cfa97d019cb"}},"opTime":{"ts":{"$timestamp    ":{"t":1720564262,"i":12}},"t":1},"object":{"createIndexes":"myColl","v":2,"key":{"created":1},"name":"created_1","expireAfterSeconds": 10}}}

       

      Show
      >  mlaunch --shards 2 --replicaset --nodes 2 --binarypath <localPath>/.local/m/versions/7.3.0/bin ... > mongosh > [direct: mongos] test> db.myColl.createIndex({created: 1}, {expireAfterSeconds: 10.23}) mongos.log: "expireAfterSeconds":10.23 { "t" :{ "$date" : "2024-07-09T17:31:02.269-05:00" }, "s" : "I" , "c" : "COMMAND" , "id" :51803, "ctx" : "conn30" , "msg" : "Slow query" , "attr" :{ "type" : "command" , "isFromUserConnection" : true , "ns" : "test.myColl" , "collectionType" : "normal" , "appName" : "mongosh 2.2.0" , "command" :{ "createIndexes " : "myColl" , "indexes" :[{ "expireAfterSeconds" :10.23, "name" : "created_1" , "key" :{ "created" :1}}], "lsid" :{ "id" :{ "$uuid" : "2588dcb2-8ff2-4ace-a8 62-a8c6659eb07a" }}, "$clusterTime" :{ "clusterTime" :{ "$timestamp" :{ "t" :1720564257, "i" :1}}, "signature" :{ "hash" :{ "$binary" :{ "base64" : "AAAAAA AAAAAAAAAAAAAAAAAAAAA=" , "subType" : "0" }}, "keyId" :0}}, "$db" : "test" }, "catalogCacheDatabaseLookupDurationMillis" :1, "catalogCacheCollectionL ookupDurationMillis" :7, "numYields" :0, "reslen" :447, "locks" :{}, "readConcern" :{ "level" : "local" , "provenance" : "implicitDefault" }, "remote" : "1 27.0.0.1:56622" , "protocol" : "op_msg" , "remoteOpWaitMillis" :98, "durationMillis" :189}} mongod.log (rs1): "expireAfterSeconds": 10 { "t" :{ "$date" : "2024-07-09T17:31:02.223-05:00" }, "s" : "I" ,   "c" : "REPL" ,     "id" :7360101, "ctx" : "conn51" , "msg" : "Wrote oplog entry for crea    teIndexes" , "attr" :{ "namespace" : "test.$cmd" , "uuid" :{ "uuid" :{ "$uuid" : "0889e21a-a69d-40ba-a89c-5cfa97d019cb" }}, "opTime" :{ "ts" :{ "$timestamp    " :{ "t" :1720564262, "i" :12}}, "t" :1}, "object" :{ "createIndexes" : "myColl" , "v" :2, "key" :{ "created" :1}, "name" : "created_1" , "expireAfterSeconds" : 10}}}  
    • Execution Team 2024-08-19

      On mongos, if a user runs

      db.myColl.createIndex({created: 1}, {expireAfterSeconds: 10.23})

      the slow query log shows 'expireAfterSeconds' : 10.23

      However, the mongod logs report the index is created with 'expireAfterSeconds':10.

      This is minor, but could be misleading when debugging index inconsistencies. Especially for tools relying on $listCatalog, which truncates 'expireAfterSeconds' to an integer in 7.3, but preserves the floating point value in 6.0.

      It would be nice to log a warning when the 'expireAfterSeconds' is truncated to an integer - or have the 'slow query' logs for a single command reflect consistent TTL fields through mongos and mongod. 

            Assignee:
            haley.connelly@mongodb.com Haley Connelly
            Reporter:
            haley.connelly@mongodb.com Haley Connelly
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: