[SERVER-26325] Log redaction does not show query shape when slow queries are logged Created: 26/Sep/16  Updated: 19/Nov/16  Resolved: 07/Oct/16

Status: Closed
Project: Core Server
Component/s: Security
Affects Version/s: None
Fix Version/s: 3.4.0-rc1

Type: Bug Priority: Major - P3
Reporter: Osmar Olivo Assignee: Spencer Jackson
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Platforms 2016-10-10
Participants:

 Description   

Log redaction is supposed to redact out sensitive lines and when possible, show the query shape, redacting only the values but displaying the keys. Currently this is not the case and everything is redacted out every time.



 Comments   
Comment by Spencer Jackson [ 07/Oct/16 ]

The new outputs look like this:

2016-10-07T18:09:38.153-0400 I NETWORK  [conn1] received client metadata from 127.0.0.1:37322 conn1: { application: { name: "MongoDB Shell"
}, driver: { name: "MongoDB Internal Client", version: "3.4.0-rc0-60-gbe34a50" }, os: { type: "Linux", name: "NAME="Arch Linux"", architectu
re: "x86_64", version: "Kernel 4.7.6-1-ARCH" } }
^[[A^[[C2016-10-07T18:09:53.020-0400 I COMMAND  [conn1] command test.col appName: "MongoDB Shell" command: insert { insert: "###", document$
: [ { _id: "###", data: "###" } ], ordered: "###" } ninserted:1 keysInserted:1 numYields:0 reslen:29 locks:{ Global: { acquireCount: { r: 3$
 w: 3 } }, Database: { acquireCount: { w: 2, W: 1 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_command 16ms
n2016-10-07T18:10:11.582-0400 I COMMAND  [conn1] command test.col appName: "MongoDB Shell" command: find { find: "###", filter: { data: "##$
" } } planSummary: ### keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:120 locks:{ Global: { acquireCount: {
r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 1ms
2016-10-07T18:10:52.638-0400 I WRITE    [conn1] update test.col appName: "MongoDB Shell" query: { data: "###" } planSummary: ### update: { $
tad: "###" } keysExamined:0 docsExamined:1 nMatched:1 nModified:1 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: {
acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 1ms
2016-10-07T18:10:52.639-0400 I COMMAND  [conn1] command test.$cmd appName: "MongoDB Shell" command: update { update: "###", updates: [ { q:
{ data: "###" }, u: { atad: "###" }, multi: "###", upsert: "###" } ], ordered: "###" } numYields:0 reslen:44 locks:{ Global: { acquireCount$
 { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_command 1ms
2016-10-07T18:11:03.876-0400 I -        [conn1] end connection 127.0.0.1:37322 (1 connection now open)
2016-10-07T18:11:09.837-0400 I NETWORK  [thread1] connection accepted from 127.0.0.1:37324 #2 (1 connection now open)
2016-10-07T18:11:09.838-0400 I NETWORK  [conn2] received client metadata from 127.0.0.1:37324 conn2: { application: { name: "MongoDB Shell"
}, driver: { name: "MongoDB Internal Client", version: "3.4.0-rc0-60-gbe34a50" }, os: { type: "Linux", name: "NAME="Arch Linux"", architect$
re: "x86_64", version: "Kernel 4.7.6-1-ARCH" } }
2016-10-07T18:11:15.259-0400 I COMMAND  [conn2] command test.col appName: "MongoDB Shell" command: find { find: "###", filter: { data: "###$
 } } planSummary: ### keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:0 reslen:81 locks:{ Global: { acquireCount: { r$
 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 1ms
2016-10-07T18:11:42.313-0400 I WRITE    [conn2] update test.col appName: "MongoDB Shell" query: { data: "###" } planSummary: ### update: { $
tad: "###" } keysExamined:0 docsExamined:2 nMatched:1 nModified:1 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: {
acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 1ms

Comment by Githook User [ 07/Oct/16 ]

Author:

{u'username': u'spencerjackson', u'name': u'Spencer Jackson', u'email': u'spencer.jackson@mongodb.com'}

Message: SERVER-26325: Show redacted slow operation report when redaction enabled
Branch: master
https://github.com/mongodb/mongo/commit/4d825b60b071dfc166ce6a92ee71519af586a81b

Comment by Daniel Pasette (Inactive) [ 27/Sep/16 ]

It can be very tricky to trust that a std:string has been properly redacted at the layer below. We'll have to comment this exception to the rule carefully.

Comment by Osmar Olivo [ 27/Sep/16 ]

If I run a query with log redaction enabled and sloms set to -1 as shown below

mongod --redactClientLogData --fork
 
 
mongo 
> db.setProfilingLevel(0, -1)
> db.test.find({something : 1})

this is what is output to the logs.

2016-09-22T22:00:41.547+0000 I COMMAND  [conn1] ###
2016-09-22T22:00:41.549+0000 I COMMAND  [conn1] ###

Comment by Spencer Jackson [ 27/Sep/16 ]

The slow query report is redacted to '###'. This can be observed by ramping up the logging, and running a query. This is because the report is redacted in instance.cpp, after it has been generated, where it is a std::string. We should pipe the redaction flags down through MutableBSON, so we can be more selective and expose the query shape.

Comment by Daniel Pasette (Inactive) [ 27/Sep/16 ]

Please give a repro case

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