[SERVER-20308] Unauthorized query generates partial log line in v3.0 Created: 07/Sep/15  Updated: 06/Dec/22

Status: Backlog
Project: Core Server
Component/s: Logging, Querying
Affects Version/s: 2.6.11, 3.0.6
Fix Version/s: None

Type: Improvement Priority: Minor - P4
Reporter: Joanna Cheng Assignee: Backlog - Query Execution
Resolution: Unresolved Votes: 0
Labels: neweng
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

v3.0.6 sharded cluster


Issue Links:
Depends
Assigned Teams:
Query Execution
Participants:

 Description   
  1. Start up a 3.0.6 sharded cluster

    mlaunch init --sharded 1 --single --auth --port 29070 --smallfiles --config 1
    

  2. Connect to the config server and authenticate
  3. Increase logLevel to 1
  4. Create a new user (modelled on the requirements for Cloud Manager monitoring)

    db.createUser({user:"monitor", pwd:"monitor", roles:[{role:"clusterMonitor", db:"admin"}]})
    

  5. Authenticate as the monitor user and try a query on local.oplog.$main in the config server. It fails, but the log lines are strange

    configsvr> db.oplog.$main.find().sort({$natural:1}).skip(0).limit(-1)
    Error: error: { "$err" : "not authorized for query on local.oplog.$main", "code" : 13 }
    configsvr> show log
    ...
    2015-09-07T16:06:05.447+1000 [conn12] User Assertion: 13:not authorized for query on admin.oplog.$main
    2015-09-07T16:06:05.448+1000 [conn12] assertion 13 not authorized for query on admin.oplog.$main ns:admin.oplog.$main query:{ query: {}, orderby: { $natural: 1.0 } }
    2015-09-07T16:06:05.448+1000 [conn12]  ntoskip:0 ntoreturn:-1
    2015-09-07T16:06:05.448+1000 [conn12] query  keyUpdates:0 exception: not authorized for query on admin.oplog.$main code:13 numYields:0  reslen:91 0ms
    

    specifically the last 2 lines, which look like normal query log lines, except without logging the actual query part

  6. Removing the limit(-1) makes the extra line go away

    configsvr> db.oplog.$main.find().sort({$natural:1}).skip(0)
    ...
    2015-09-07T16:06:49.905+1000 [conn12] User Assertion: 13:not authorized for query on admin.oplog.$main
    2015-09-07T16:06:49.906+1000 [conn12] assertion 13 not authorized for query on admin.oplog.$main ns:admin.oplog.$main query:{ query: {}, orderby: { $natural: 1.0 } }
    2015-09-07T16:06:49.906+1000 [conn12] query  keyUpdates:0 exception: not authorized for query on admin.oplog.$main code:13 numYields:0  reslen:91 0ms
    

  7. Auth as a user that does have permissions to read this collection, and run the original query

    2015-09-07T15:56:47.909+1000 I QUERY    [conn9] query local.oplog.$main query: { query: {}, orderby: { $natural: 1.0 } } planSummary: COLLSCAN ntoskip:0 nscanned:0 nscannedObjects:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:64 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms
    

    ntoreturn is not logged.



 Comments   
Comment by YunHe Wang [ 08/Sep/15 ]

So the "ntoskip" and "ntoreturn" line is part of the same log line as the one above it. It is generated by generateLegacyQueryErrorResponse() in src/mongo/db/instance.cpp when there is an ntoskip or an ntoreturn and an exception happens.

The last line looks like it's generated by src/mongo/db/curop.cpp when the log severity is high enough or the execution takes too long. This is the same file that generates the log line when a user who does have permissions issues the query.

Comment by Joanna Cheng [ 07/Sep/15 ]

A few additions

  • Not limited to local.oplog.$main and any presence of limit() generates the partial log line

    2015-09-07T16:19:45.274+1000 [conn12] User Assertion: 13:not authorized for query on local.system.indexes
    2015-09-07T16:19:45.274+1000 [conn12] assertion 13 not authorized for query on local.system.indexes ns:local.system.indexes query:{}
    2015-09-07T16:19:45.274+1000 [conn12]  ntoskip:0 ntoreturn:5
    2015-09-07T16:19:45.275+1000 [conn12] query  keyUpdates:0 exception: not authorized for query on local.system.indexes code:13 numYields:0  reslen:94 0ms
    

  • Same with a non-zero value of skip

    2015-09-07T16:21:32.498+1000 [conn12] User Assertion: 13:not authorized for query on local.system.indexes
    2015-09-07T16:21:32.498+1000 [conn12] assertion 13 not authorized for query on local.system.indexes ns:local.system.indexes query:{}
    2015-09-07T16:21:32.498+1000 [conn12]  ntoskip:5 ntoreturn:0
    2015-09-07T16:21:32.498+1000 [conn12] query  keyUpdates:0 exception: not authorized for query on local.system.indexes code:13 numYields:0  reslen:94 0ms
    

Generated at Thu Feb 08 03:53:49 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.