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

Field names should be quoted in logs

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Logging
    • Labels:
      None
    • ALL
    • Dev Tools 2020-01-13, Dev Tools 2020-01-27, Dev Tools 2020-02-10

      Lack of quoting means it can be impossible to tell what the query actually is.

      Real example:

      2015-11-20T16:46:35.074-0500 I COMMAND  [conn1166] command foo.bar command: find { find: "bar", filter: {  _id: "foobar" }, shardVersion: [ Timestamp 2000|7, ObjectId('564fd7ca4529a9f9b23074ed') ] } planSummary: COLLSCAN keysExamined:0 docsExamined:344866188 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:2694991 nreturned:0 reslen:216 locks:{ Global: { acquireCount: { r: 5389984 } }, Database: { acquireCount: { r: 2694992 } }, Collection: { acquireCount: { r: 2694992 } } } protocol:op_command 1173549ms
      

      Why is this query using a COLLSCAN instead of IDHACK? Because the query is actually on the field " _id".

      Contrived example:
      What's the difference between these queries?

      2015-11-21T22:24:19.430+1100 I COMMAND  [conn29] command test.foo command: find { find: "foo", filter: { abc: 1.0, def: 1.0, a: 1.0 }, shardVersion: [ Timestamp 2000|7, ObjectId('564fd7ca4529a9f9b23074ed') ] } planSummary: IXSCAN { a: "hashed" } keysExamined:4 docsExamined:4 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:211 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms
      2015-11-21T22:26:40.657+1100 I COMMAND  [conn30] command test.foo command: find { find: "foo", filter: { abc: 1.0, def: 1.0, a: 1.0 }, shardVersion: [ Timestamp 2000|7, ObjectId('564fd7ca4529a9f9b23074ed') ] } planSummary: IXSCAN { a: "hashed" } keysExamined:4 docsExamined:4 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:211 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms
      

      They look identical, but were generated by the (very different) queries:

      db.foo.find({abc: 1, def : 1, a:1})
      db.foo.find({'abc: 1.0, def' : 1, a:1})
      

            Assignee:
            henrik.edin@mongodb.com Henrik Edin
            Reporter:
            joanna.cheng@mongodb.com Joanna Cheng
            Votes:
            1 Vote for this issue
            Watchers:
            9 Start watching this issue

              Created:
              Updated:
              Resolved: