Slow query insert logs success after duplicate key

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Unresolved
    • Priority: Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • Storage Execution
    • ALL
    • Hide
      > db.setProfilingLevel(1, { slowms: 0 });  // Log all queries as slow querys
      > db.createCollection("users")
      > db.users.createIndex({ email: 1 }, { unique: true })
      > userDoc = { email: "alice@example.com", name: "Alice" }
      > session.getDatabase(db.getName()).users.insert(userDoc)
      // Reports success
      > session.getDatabase(db.getName()).users.insert(userDoc)
      // Reports E11000 duplicate key error collection: test.users index: email_1 dup key: { email: "alice@example.com" }
      ....
      // Slow query logs. 
      // First insert: ninserted 1
      {"t":{"$date":"2025-09-17T13:01:49.093-05:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn28","msg":"Slow query","attr":{"type":"command","ns":"test.users","appName":"mongosh 2.5.1","command":{"insert":"users","documents":[{"email":"alice@example.com","name":"Alice","_id":{"$oid":"68caf78d2ee4a2979b4fa64c"}}],"ordered":true,"lsid":{"id":{"$uuid":"7a5eb408-41e8-40d9-9c04-e6d2d229ebcd"}},"txnNumber":1,"$clusterTime":{"clusterTime":{"$timestamp":{"t":1758132082,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"primaryPreferred"},"$db":"test"},"totalOplogSlotDurationMicros":149,"ninserted":1,"keysInserted":2,"numYields":0,"reslen":230,"locks":{"ParallelBatchWriterMode":{"acquireCount":{"r":3}},"FeatureCompatibilityVersion":{"acquireCount":{"r":5,"w":2}},"ReplicationStateTransition":{"acquireCount":{"w":6}},"Global":{"acquireCount":{"r":5,"w":2}},"Database":{"acquireCount":{"r":2,"w":2}},"Collection":{"acquireCount":{"r":2,"w":2}}},"flowControl":{"acquireCount":1},"readConcern":{"provenance":"implicitDefault"},"writeConcern":{"w":"majority","wtimeout":0,"provenance":"implicitDefault"},"waitForWriteConcernDurationMillis":13,"storage":{},"remote":"127.0.0.1:52614","protocol":"op_msg","durationMillis":17}}
      
      // Second insert: ninserted: 0
      {"t":{"$date":"2025-09-17T13:01:51.685-05:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn28","msg":"Slow query","attr":{"type":"command","ns":"test.users","appName":"mongosh 2.5.1","command":{"insert":"users","documents":[{"email":"alice@example.com","name":"Alice","_id":{"$oid":"68caf78f2ee4a2979b4fa64d"}}],"ordered":true,"lsid":{"id":{"$uuid":"7a5eb408-41e8-40d9-9c04-e6d2d229ebcd"}},"txnNumber":2,"$clusterTime":{"clusterTime":{"$timestamp":{"t":1758132109,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"primaryPreferred"},"$db":"test"},"totalOplogSlotDurationMicros":280,"ninserted":0,"numYields":0,"reslen":466,"locks":{"ParallelBatchWriterMode":{"acquireCount":{"r":1}},"FeatureCompatibilityVersion":{"acquireCount":{"r":2,"w":1}},"ReplicationStateTransition":{"acquireCount":{"w":4}},"Global":{"acquireCount":{"r":2,"w":1}},"Database":{"acquireCount":{"w":1}},"Collection":{"acquireCount":{"w":1}}},"flowControl":{"acquireCount":1},"readConcern":{"level":"
      
      Show
      > db.setProfilingLevel(1, { slowms: 0 }); // Log all queries as slow querys > db.createCollection( "users" ) > db.users.createIndex({ email: 1 }, { unique: true }) > userDoc = { email: "alice@example.com" , name: "Alice" } > session.getDatabase(db.getName()).users.insert(userDoc) // Reports success > session.getDatabase(db.getName()).users.insert(userDoc) // Reports E11000 duplicate key error collection: test.users index: email_1 dup key: { email: "alice@example.com" } .... // Slow query logs. // First insert: ninserted 1 { "t" :{ "$date" : "2025-09-17T13:01:49.093-05:00" }, "s" : "I" , "c" : "COMMAND" , "id" :51803, "ctx" : "conn28" , "msg" : "Slow query" , "attr" :{ "type" : "command" , "ns" : "test.users" , "appName" : "mongosh 2.5.1" , "command" :{ "insert" : "users" , "documents" :[{ "email" : "alice@example.com" , "name" : "Alice" , "_id" :{ "$oid" : "68caf78d2ee4a2979b4fa64c" }}], "ordered" : true , "lsid" :{ "id" :{ "$uuid" : "7a5eb408-41e8-40d9-9c04-e6d2d229ebcd" }}, "txnNumber" :1, "$clusterTime" :{ "clusterTime" :{ "$timestamp" :{ "t" :1758132082, "i" :1}}, "signature" :{ "hash" :{ "$binary" :{ "base64" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=" , "subType" : "0" }}, "keyId" :0}}, "$readPreference" :{ "mode" : "primaryPreferred" }, "$db" : "test" }, "totalOplogSlotDurationMicros" :149, "ninserted" :1, "keysInserted" :2, "numYields" :0, "reslen" :230, "locks" :{ "ParallelBatchWriterMode" :{ "acquireCount" :{ "r" :3}}, "FeatureCompatibilityVersion" :{ "acquireCount" :{ "r" :5, "w" :2}}, "ReplicationStateTransition" :{ "acquireCount" :{ "w" :6}}, "Global" :{ "acquireCount" :{ "r" :5, "w" :2}}, "Database" :{ "acquireCount" :{ "r" :2, "w" :2}}, "Collection" :{ "acquireCount" :{ "r" :2, "w" :2}}}, "flowControl" :{ "acquireCount" :1}, "readConcern" :{ "provenance" : "implicitDefault" }, "writeConcern" :{ "w" : "majority" , "wtimeout" :0, "provenance" : "implicitDefault" }, "waitForWriteConcernDurationMillis" :13, "storage" :{}, "remote" : "127.0.0.1:52614" , "protocol" : "op_msg" , "durationMillis" :17}} // Second insert: ninserted: 0 { "t" :{ "$date" : "2025-09-17T13:01:51.685-05:00" }, "s" : "I" , "c" : "COMMAND" , "id" :51803, "ctx" : "conn28" , "msg" : "Slow query" , "attr" :{ "type" : "command" , "ns" : "test.users" , "appName" : "mongosh 2.5.1" , "command" :{ "insert" : "users" , "documents" :[{ "email" : "alice@example.com" , "name" : "Alice" , "_id" :{ "$oid" : "68caf78f2ee4a2979b4fa64d" }}], "ordered" : true , "lsid" :{ "id" :{ "$uuid" : "7a5eb408-41e8-40d9-9c04-e6d2d229ebcd" }}, "txnNumber" :2, "$clusterTime" :{ "clusterTime" :{ "$timestamp" :{ "t" :1758132109, "i" :1}}, "signature" :{ "hash" :{ "$binary" :{ "base64" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=" , "subType" : "0" }}, "keyId" :0}}, "$readPreference" :{ "mode" : "primaryPreferred" }, "$db" : "test" }, "totalOplogSlotDurationMicros" :280, "ninserted" :0, "numYields" :0, "reslen" :466, "locks" :{ "ParallelBatchWriterMode" :{ "acquireCount" :{ "r" :1}}, "FeatureCompatibilityVersion" :{ "acquireCount" :{ "r" :2, "w" :1}}, "ReplicationStateTransition" :{ "acquireCount" :{ "w" :4}}, "Global" :{ "acquireCount" :{ "r" :2, "w" :1}}, "Database" :{ "acquireCount" :{ "w" :1}}, "Collection" :{ "acquireCount" :{ "w" :1}}}, "flowControl" :{ "acquireCount" :1}, "readConcern" :{ "level" :"
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      While inside a session, inserting a document which violates a unique index constraint will cause the shell to report the error, but the slow query logs will report the operation was successful with ninserted: 0.

            Assignee:
            Unassigned
            Reporter:
            Haley Connelly
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated: