MongoDBでセンシティブな情報を含んだクエリがログに出ないようにしたい #mongodb
MongoDBテクニカルサポート担当の山森です。うだるような暑さの中、皆さんいかがお過ごしでしょうか。私の地元では連日36度を記録しており、溶けてしまいそうです。
さて、MongoDBを含めたドキュメントDBは、どのようなデータも柔軟に取り扱うことができます。その中で個人情報などのセンシティブな情報を取り扱うこともあるはずです。そういった場合はデータベース内のデータへのアクセスをより堅牢にすることでしょう。
しかし、実行したクエリの内容がログに出力され、意図せずにデータベースのデータ以外にセンシティブな情報が記録されてしまうことがあります。
MongoDBの公式サポートや、クリエーションライン提供の日本語サポートでは、mongodのログ提供をお願いするケースがよくあります。サポートにmongodのログを提供していただく前に、クエリ内にセンシティブな情報が存在しないか調査し、マスクしてからの提供をお願いしています。しかし、こちらは非常に手間ですよね。
MongoDB Enterprise Advancedでは、機密性の高いデータをログに書き込まないように、事前にマスクしてくれる機能があります。今回はその機能の使い方と、使った結果どうなるのか一緒に見ていきましょう。
クエリがログに記録されてしまうケースとは
MongoDBでは、有名なRDBMSと同様に、Slow queryを記録する機能があります。Slow queryは指定の時間以上に実行時間が経過するとログに記録してくれる機能です。
mongod.confに記載もしくはmongosh上のコマンドで設定します。設定方法は以下のドキュメントを参照してください。
https://www.mongodb.com/docs/manual/reference/method/db.setProfilingLevel/#db.setprofilinglevel--
https://www.mongodb.com/docs/manual/reference/configuration-options/#operationprofiling-options
今回は、センシティブな情報のテストデータを作り、クエリを投げてSlow queryを記録させた後、どのように記録・マスクされるのか見ていきます。
検証環境の構築
今回の検証にあたり、センシティブな情報のテストデータを大量に作る必要があります。そこで活躍するのが、以前に作ったプログラムです。こういうのを一度作っておくとなにかと便利です。Slow queryを出すにはそれなりのデータ数が必要なので、以下のようなデータを100万件ほど放り込んでおきました。
{
"_id": {
"$oid": "6687a0a809ab7dd03e0bf0c2"
},
"username": "FQyFMgO",
"password": "yAkXuXRUxAsXREILqyYSAJmnekCNOAShyUsoGTZFGAraKXUhHA",
"age": 43,
"gender": "male",
"firstname": "Lizzie",
"lastname": "Feil",
"income": 4988
}
このようなデータに対し、Slow queryを出すようなクエリはどのようになものでしょうか。今回もchatGPT君に聞いてみることにしました。
こういう使い方ができるのでchatGPT君は有用ですね。今回は、提案してもらった中から、集計（aggregation）を使ったクエリを使ってみることにしました。以下がそのクエリです。
db.PersonalData_Fake.aggregate([
{ $match: { lastname: "Reichel" } },
{ $group: { _id: null, avgIncome: { $avg: "$income" } } }
])
解説すると、特定の名字（Reichel）のデータの平均年収（avgIncome）を算出するクエリです。インデックスがなければCOLLSCAN（すべてのドキュメントを一通り舐めるクエリ）となるので、確かにSlow queryになりそうです。
Slow queryを記録してみる
では、先ほどのクエリを実行してみましょう。レプリカセット名は「rs0」、データベース名は「PersonalDataBase」、コレクション名は「PersonalData_Fake」です。今回は使用しているMongoDB Server Enterprise Advancedのバージョンは6.0.14です。
まずはセンシティブな情報がマスクされないパターンを見ていきます。クエリを実行してみましょう。以下が実行結果です。avgIncomeが算出されていますね。
Enterprise rs0 [direct: primary] PersonalDataBase> db.PersonalData_Fake.aggregate([
... { $match: { lastname: "Reichel" } },
... { $group: { _id: null, avgIncome: { $avg: "$income" } } }
... ])
[ { _id: null, avgIncome: 2595.7525439407955 } ]
このときのクエリがSlow queryとしてmongod.logに記録されました。以下がそのログです。（MongoDBは、ログもjson形式で記録されます）
少し見ていくのが大変ですが、attrのCommandの部分を見てみてください。pipeline:の部分に実行したクエリが記録されているのがわかります。"lastname": "Reichel"はセンシティブな情報に該当するはずですがばっちりログに出てしまっています。
ちなみにクエリの実行時間は"durationMillis": 319です。こちらは一番下方に記録されています。今回は319ms（>100ms）かかったことがわかります。
{
"t": {
"$date": "2024-07-08T13:25:30.122+09:00"
},
"s": "I",
"c": "COMMAND",
"id": 51803,
"ctx": "conn78",
"msg": "Slow query",
"attr": {
"type": "command",
"ns": "PersonalDataBase.PersonalData_Fake",
"appName": "mongosh 2.2.1",
"command": {
"aggregate": "PersonalData_Fake",
"pipeline": [
{
"$match": {
"lastname": "Reichel"
}
},
{
"$group": {
"_id": null,
"avgIncome": {
"$avg": "$income"
}
}
}
],
"cursor": {},
"lsid": {
"id": {
"$uuid": "43479ac1-8fb0-40cf-8439-04f127c825d7"
}
},
"$clusterTime": {
"clusterTime": {
"$timestamp": {
"t": 1720412649,
"i": 1
}
},
"signature": {
"hash": {
"$binary": {
"base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=",
"subType": "0"
}
},
"keyId": 0
}
},
"$readPreference": {
"mode": "primaryPreferred"
},
"$db": "PersonalDataBase"
},
"planSummary": "COLLSCAN",
"keysExamined": 0,
"docsExamined": 1000000,
"cursorExhausted": true,
"numYields": 1000,
"nreturned": 1,
"queryHash": "ACF5F2E4",
"planCacheKey": "ACF5F2E4",
"queryFramework": "sbe",
"reslen": 280,
"locks": {
"FeatureCompatibilityVersion": {
"acquireCount": {
"r": 1001
}
},
"Global": {
"acquireCount": {
"r": 1001
}
},
"Mutex": {
"acquireCount": {
"r": 1
}
}
},
"readConcern": {
"level": "local",
"provenance": "implicitDefault"
},
"writeConcern": {
"w": "majority",
"wtimeout": 0,
"provenance": "implicitDefault"
},
"storage": {},
"remote": "127.0.0.1:34656",
"protocol": "op_msg",
"durationMillis": 319
}
}
このままではセンシティブな情報もログに記録されてしまうので、マスクする機能を使ってみます。
redactClientLogData を使う
こちらはセンシティブな情報がログに記録されるのを防ぐための機能です。今回のようなケースにおあつらえ向きの機能ですね。機能概要についてはドキュメントも参照してください。
実際に有効にしてみましょう。mongoshから設定します。
実行コマンドは以下の通りです。
db.adminCommand( { setParameter: 1, redactClientLogData : true } )
そして、それを弊社の検証環境で実行してみた結果です。
Enterprise rs0 [direct: primary] PersonalDataBase> db.adminCommand( { setParameter: 1, redactClientLogData : true } )
{
was: false,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1720412789, i: 1 }),
signature: {
hash: Binary.createFromBase64('AAAAAAAAAAAAAAAAAAAAAAAAAAA=', 0),
keyId: Long('0')
}
},
operationTime: Timestamp({ t: 1720412789, i: 1 })
}
ちなみに、現在の設定値を確認するにはgetParameterを使用します。
db.adminCommand({ getParameter: 1, redactClientLogData: 1 })
実行すると、以下のように表示されます。
Enterprise rs0 [direct: primary] PersonalDataBase> db.adminCommand({ getParameter: 1, redactClientLogData: 1 })
{
redactClientLogData: false,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1720412649, i: 1 }),
signature: {
hash: Binary.createFromBase64('AAAAAAAAAAAAAAAAAAAAAAAAAAA=', 0),
keyId: Long('0')
}
},
operationTime: Timestamp({ t: 1720412649, i: 1 })
}
設定が有効な状態で、先ほどと同じクエリを実行してみましょう。
Enterprise rs0 [direct: primary] PersonalDataBase> db.PersonalData_Fake.aggregate([
... { $match: { lastname: "Reichel" } },
... { $group: { _id: null, avgIncome: { $avg: "$income" } } }
... ])
[ { _id: null, avgIncome: 2595.7525439407955 } ]
以下はクエリを実行したときのSlow queryのログです。attrのCommand内のクエリが###でマスクされていることがわかります。
{
"t": {
"$date": "2024-07-08T13:27:29.873+09:00"
},
"s": "I",
"c": "COMMAND",
"id": 51803,
"ctx": "conn78",
"msg": "Slow query",
"attr": {
"type": "command",
"ns": "PersonalDataBase.PersonalData_Fake",
"appName": "mongosh 2.2.1",
"command": {
"aggregate": "###",
"pipeline": [
{
"$match": {
"lastname": "###"
}
},
{
"$group": {
"_id": "###",
"avgIncome": {
"$avg": "###"
}
}
}
],
"cursor": {},
"lsid": {
"id": "###"
},
"$clusterTime": {
"clusterTime": "###",
"signature": {
"hash": "###",
"keyId": "###"
}
},
"$readPreference": {
"mode": "###"
},
"$db": "###"
},
"planSummary": "COLLSCAN",
"keysExamined": 0,
"docsExamined": 1000000,
"cursorExhausted": true,
"numYields": 1000,
"nreturned": 1,
"queryHash": "ACF5F2E4",
"planCacheKey": "ACF5F2E4",
"queryFramework": "sbe",
"reslen": 280,
"locks": {
"FeatureCompatibilityVersion": {
"acquireCount": {
"r": 1001
}
},
"Global": {
"acquireCount": {
"r": 1001
}
},
"Mutex": {
"acquireCount": {
"r": 1
}
}
},
"readConcern": {
"level": "local",
"provenance": "implicitDefault"
},
"writeConcern": {
"w": "majority",
"wtimeout": 0,
"provenance": "implicitDefault"
},
"storage": {},
"remote": "127.0.0.1:34656",
"protocol": "op_msg",
"durationMillis": 294
}
}
クエリを改善したいときにはDatabase Profilerを使おう
マスクされるので、ログを第三者に見てもらうときに便利です。しかし、このままだと実際にSlow queryのクエリを改善するときには不便です。ほかにSlow queryの情報が記録される場所はないのでしょうか。
MongoDBにはDatabase Profilerの機能があります。こちらはデータベースごとに有効にできる機能です。有効にすると、同データベース内に「system.profile」というコレクションが生成されます。
データベース配下で「show collections」を実行するとコレクション一覧が表示されます。system.profileが存在していますね。
Enterprise rs0 [direct: primary] PersonalDataBase> show collections PersonalData_Fake system.profile
Database Profilerを有効にする方法は以下のドキュメントを参照してください。
https://www.mongodb.com/docs/manual/tutorial/manage-the-database-profiler/
それでは、system.profileのコレクション内に、クエリに関する情報がどう記録されるのか見てみましょう。以下は、名字（Reichel）のデータの平均年収（avgIncome）を算出するクエリに関する記録を表示させたものです。
Enterprise rs0 [direct: primary] PersonalDataBase> db.system.profile.find({ "op": "command", "ns": "PersonalDataBase.PersonalData_Fake", "command.aggregate": "PersonalData_Fake", "command.pipeline": [ { "$match": { "lastname": "Reichel" } }, { "$group": { "_id": null, "avgIncome": { "$avg": "$income" } } }] }).pretty().limit(1)
[
{
op: 'command',
ns: 'PersonalDataBase.PersonalData_Fake',
command: {
aggregate: 'PersonalData_Fake',
pipeline: [
{ '$match': { lastname: 'Reichel' } },
{ '$group': { _id: null, avgIncome: { '$avg': '$income' } } }
],
cursor: {},
lsid: { id: UUID('1af1c2ac-5468-4729-ad15-5f3cf6713397') },
'$clusterTime': {
clusterTime: Timestamp({ t: 1720164872, i: 1 }),
signature: {
hash: Binary.createFromBase64('AAAAAAAAAAAAAAAAAAAAAAAAAAA=', 0),
keyId: Long('0')
}
},
'$readPreference': { mode: 'primaryPreferred' },
'$db': 'PersonalDataBase'
},
keysExamined: 0,
docsExamined: 1000000,
cursorExhausted: true,
numYield: 1000,
nreturned: 1,
queryHash: 'ACF5F2E4',
planCacheKey: 'ACF5F2E4',
queryFramework: 'sbe',
locks: {
FeatureCompatibilityVersion: { acquireCount: { r: Long('1002') } },
Global: { acquireCount: { r: Long('1002') } },
Mutex: { acquireCount: { r: Long('1') } }
},
flowControl: {},
readConcern: { level: 'local', provenance: 'implicitDefault' },
writeConcern: { w: 'majority', wtimeout: 0, provenance: 'implicitDefault' },
storage: {
data: {
bytesRead: Long('212603034'),
timeReadingMicros: Long('32142')
}
},
responseLength: 280,
protocol: 'op_msg',
millis: 515,
planSummary: 'COLLSCAN',
ts: ISODate('2024-07-05T07:34:47.809Z'),
client: '127.0.0.1',
appName: 'mongosh 2.2.1',
allUsers: [],
user: ''
}
]
こちらには実行したクエリ内容も含めてしっかり記録されています。通常時、Slow queryはマスクありでmongodのログに記録させ、実際にクエリ改善を行うときはsystem.profileにある情報を見ながらやるのがよさそうです。
この記事が皆さんの参考になれば幸いです。
