[SERVER-32640] killCursors auditing messages are duplicated or incomplete Created: 10/Jan/18  Updated: 30/Oct/23  Resolved: 05/Mar/21

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: None
Fix Version/s: 5.0.0

Type: Bug Priority: Major - P3
Reporter: Ian Boros Assignee: Sergey Galtsev (Inactive)
Resolution: Fixed Votes: 0
Labels: query-44-grooming
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File StackTraces.txt    
Issue Links:
Issue split
split to SERVER-55014 KillCursors operation is not audited ... Closed
Backwards Compatibility: Minor Change
Operating System: ALL
Sprint: Security 2021-02-22, Security 2021-03-08
Participants:

 Description   

Run a mongod with auditing on:
mongod --auditDestination console --setParameter auditAuthorizationSuccess=true

Then start up a shell and insert some data:

    db.audit.drop()
    for (var i = 0; i < 100; i++) {
        assert.writeOK(db.audit.insert({_id: i}));
    }
 
    let query;
    let cursorId;

Then, run a find() command and then kill the cursor associated with it:

    query = db.audit.find().batchSize(1);
    cursorId = query._cursor._cursorid;
    assert.neq(cursorId, NumberLong(0));
 
    cmdRes = db.runCommand({killCursors: db.audit.getName(), cursors: [cursorId]});

You will see three audit messages:

{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T12:23:53.675-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 46976 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "test.audit", "args" : { "killCursors" : "audit", "cursors" : [ { "$numberLong" : "18214762657" } ], "$db" : "test" } }, "result" : 0 }
{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T12:23:53.675-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 46976 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "test.audit", "args" : { "killCursors" : "audit", "cursorId" : { "$numberLong" : "18214762657" } } }, "result" : 0 }
{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T12:23:53.676-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 46976 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "test.audit", "args" : { "killCursors" : "audit", "cursorId" : { "$numberLong" : "18214762657" } } }, "result" : 0 }

Now try it with aggregate():

    query = db.audit.aggregate([{$limit: 500}], {cursor: {batchSize: 1}})
    cursorId = query._cursorid;
    assert.neq(cursorId, NumberLong(0));
 
    cmdRes = db.runCommand({killCursors: db.audit.getName(), cursors: [cursorId]});

You will again see three messages. However, the ns field of the second message is empty!

{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T12:22:08.695-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 46976 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "test.audit", "args" : { "killCursors" : "audit", "cursors" : [ { "$numberLong" : "8130617323690985931" } ], "$db" : "test" } }, "result" : 0 }
{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T12:22:08.695-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 46976 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "", "args" : { "killCursors" : "", "cursorId" : { "$numberLong" : "8130617323690985931" } } }, "result" : 0 }
{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T12:22:08.697-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 46976 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "test.audit", "args" : { "killCursors" : "audit", "cursorId" : { "$numberLong" : "8130617323690985931" } } }, "result" : 0 }

Now do the same for listCollections.

    // Create some temporary collections
    db.createCollection("tempColA");
    db.createCollection("tempColB");
    cmdRes = db.runCommand({listCollections: 1, cursor: {batchSize: 1}});
    cursorId = cmdRes.cursor.id
    cmdRes = db.runCommand({killCursors: db.audit.getName(), cursors: [cursorId]});

Again you will see three audit messages, and the second has an empty ns field.

{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T15:12:18.282-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 47118 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "test.audit", "args" : { "killCursors" : "audit", "cursors" : [ { "$numberLong" : "8828860051368457912" } ], "$db" : "test" } }, "result" : 0 }
{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T15:12:18.283-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 47118 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "", "args" : { "killCursors" : "", "cursorId" : { "$numberLong" : "8828860051368457912" } } }, "result" : 43 }
{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-10T15:12:18.283-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 47118 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "test.audit", "args" : { "killCursors" : "audit", "cursorId" : { "$numberLong" : "8828860051368457912" } } }, "result" : 43 }

Running killCursors on a find while using the shell with --readMode=legacy will produce only one audit message:
./mongo --readMode=legacy

query = db.audit.find().batchSize(1);
query.close();

{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-11T13:42:41.397-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 55612 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "test.audit", "args" : { "killCursors" : "audit", "cursorId" : { "$numberLong" : "13009096037" } } }, "result" : 0 }

On an aggregate (with readMode legacy) it will produce one audit message, but with a missing namespace:

query = db.audit.aggregate([{$limit: 500}], {cursor: {batchSize: 1}})
query.close()

{ "atype" : "authCheck", "ts" : { "$date" : "2018-01-11T13:45:28.706-0500" }, "local" : { "ip" : "127.0.0.1", "port" : 30000 }, "remote" : { "ip" : "127.0.0.1", "port" : 55612 }, "users" : [], "roles" : [], "param" : { "command" : "killCursors", "ns" : "", "args" : { "killCursors" : "", "cursorId" : { "$numberLong" : "9177271237534965986" } } }, "result" : 0 }



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

Author:

{'name': 'Sergey Galtsev', 'email': 'sergey.galtsev@mongodb.com', 'username': 'brushless-glitch'}

Message: SERVER-32640 migrate cursor kill audit into authorization check
Branch: master
https://github.com/mongodb/mongo/commit/f2060e3a81f74a6fc96ef040eade41d48dcd5c7d

Comment by Githook User [ 05/Mar/21 ]

Author:

{'name': 'Sergey Galtsev', 'email': 'sergey.galtsev@mongodb.com', 'username': 'brushless-glitch'}

Message: SERVER-32640 migrate cursor kill audit into authorization check
Branch: master
https://github.com/10gen/mongo-enterprise-modules/commit/088c8da0b633fc6c9d3f6c12b7b2fa4665114437

Comment by Sergey Galtsev (Inactive) [ 19/Feb/21 ]

I reproduced scenario on 3.6.

I reproduced duplicating events on master, but not an empty ns, so it seems that this specific issue is gone. Will be working on deduplication only

Comment by Ian Boros [ 18/Feb/21 ]

sergey.galtsev My guess is that I was running 3.6 or a development version of 4.0.

 

A lot of the cursor management code has been refactored in the last three years so I would not be surprised if some of these issues have just gone away.

Comment by Sergey Galtsev (Inactive) [ 18/Feb/21 ]

ian.boros I am trying to reproduce your steps and not all results match your write-up. Do you happen to recall what version were you using when you ran the commands? I would like to make sure I can fully reproduce the issue before fixing it, so that I can know I am not missing anything

Comment by Davi Ottenheimer [ 20/Feb/18 ]

does not appear critical as workarounds do exist and audit could still be done on cursor actions, even though less convenient. appears to be more of a quality bug that needs ns to be filled in to ensure audit functioning consistently across operations.

Comment by Ian Whalen (Inactive) [ 19/Jan/18 ]

Moving this to the Platforms team because the Query team doesn't know how to triage it. They are happy to help with implementation if it is important.

Generated at Thu Feb 08 04:30:50 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.