OPAのDecision Logsを使ってログを残す

OPA

Open Policy Agent (以下OPA）で様々なPolicyの判断をするにあたって、ログをどのように残すのかが気になってきました。

OPAを初めて聞いた、あるいはあまり知らない場合は以下の記事を参考にしていただければ！

kenfdev.hateblo.jp

ログを残す方法としてOPAではDecision Logsという仕組みがあるのがわかりました。

www.openpolicyagent.org

実際に使ってみたのでどんな感じなのかというのを紹介します。

TL;DR

この記事のサンプルコードのリポジトリを以下に置いてますので、docker-compose upでお試しできます！

github.com

Decision Logsの仕組み

Decision Logsの仕組みはシンプルで、OPAの設定ファイルで指定したLog ServiceにPOSTしてくれます。流れとしては下図の通り。

f:id:kenev:20190623083920p:plain

百聞は一見に如かずなので、実際に簡単なサンプルコードで見てみます！

OPAにはcurlでリクエストして、Log Serviceには超シンプルなNode.jsのサーバーを使います。

f:id:kenev:20190623111521p:plain

Policyの準備

まずはPolicyを作ります。policy.regoというファイルで、下のようなuser == "john"であればtrueになるallowというルールを定義しておきます。

# policy.rego
package foo

default allow = false
allow {
  input.user == "john"
}

Policyが正常に使えるか見てみます。まずはdockerコマンドで立ち上げ。

docker run -p 8181:8181 -v $(pwd):/workspace openpolicyagent/opa run --server /workspace/policy.rego

今回作ったPolicyはpackage foo配下のallowルールになるのでエンドポイントは/v1/data/foo/allowになります。curlで下のようにリクエストしてみると：

$ curl -XPOST -d '{ "input": { "user": "john" } }' http://localhost:8181/v1/data/foo/allow
{"result":true}

結果が{ "result": true }で返ってきているのが確認できます。

Mockサーバーの準備

ログを受け取れるように簡単なAPIサーバーをNode.jsで作ります。server.jsとして下のNode.jsサーバーを作ります。

// server.js
const express = require('express');
const bodyParser = require('body-parser')

const app = express();
const port = 3000;

app.use(bodyParser.json())

app.post('/logs', (request, response) => {
  console.log(JSON.stringify(request.body, null, 2));
  response.sendStatus(200);
});

app.listen(port, err => {
  if (err) {
    return console.log('something bad happened', err);
  }

  console.log(`server is listening on ${port}`);
});

これはポート3000で待ち受けてPOST /logsエンドポイントを公開しているサーバーになります。POST /logsを受け取るとログをconsole.logに出力して、レスポンスは200を返すようにしています。

OPAの設定

Logサービスはできたので、次にOPA側のDecision Logsの設定を加えてログが送信されるようにします。

まず、OPAには設定ファイルを--configオプションとして渡すことができます。以下、公式ドキュメントで詳しく記載されています。

www.openpolicyagent.org

設定ファイルはYAMLで書き、Decision Logsを有効化するには以下のような設定にします。

# config.yml
services:
  logger:
    url: http://logger:3000/

decision_logs:
  service: logger
  reporting:
    min_delay_seconds: 5
    max_delay_seconds: 10

OPAはdecision_logs.serviceに設定したサービスのエンドポイントに下の形でログを送信します。

POST /logs[/<partition_name>] HTTP/1.1
Content-Encoding: gzip
Content-Type: application/json

デフォルトで/logsになるのですが、/logs配下の別の場所にリクエストを飛ばしたければ設定ファイルのdecision_logs.partition_nameに値を設定します。

decision_logs.min_delay_seconds, decision_logs.max_delay_secondsが若干わかりづらいのですが、上の設定であれば、5秒毎にログを送信して、送信失敗した場合は送信間隔が最大10秒になるまではリトライしてくれるという内容になります。

delay_secondsの挙動についてはドキュメントだと曖昧だったのでコードで確認しました

検証

ではOPAとLog用のServiceが立ち上がるようにdocker-compose.ymlを作ります。

version: '3'

services:
  logger:
    build: ./logger
    image: logger
  opa:
    image: openpolicyagent/opa:0.13.0
    ports:
      - 8181:8181
    volumes:
      - .:/workspace
    command: ["run", "--server", "-c", "/workspace/config.yml", "/workspace/policy.rego"]

docker-compose upで起動します。

先程同様にOPAにリクエストしてみましょう！

curl -XPOST -d '{ "input": { "user": "john" } }' http://localhost:8181/v1/data/foo/allow

結果は以下のように返ってくるのがわかります。

{
  "decision_id":"79f24c2d-ce6a-4da1-8d2f-bd0b3c23a690",
  "result":true
}

docker-composeのログを見るとNode.jsのサーバーとOPAもログを出力しているのがわかります。

logger_1  | [
logger_1  |   {
logger_1  |     "labels": {
logger_1  |       "id": "abc47ac3-ab0a-4e4f-9ba2-316af7b2c9b4",
logger_1  |       "version": "0.13.0"
logger_1  |     },
logger_1  |     "decision_id": "79f24c2d-ce6a-4da1-8d2f-bd0b3c23a690",
logger_1  |     "path": "foo/allow",
logger_1  |     "input": {
logger_1  |       "user": "john"
logger_1  |     },
logger_1  |     "result": true,
logger_1  |     "requested_by": "172.18.0.1:59272",
logger_1  |     "timestamp": "2019-08-10T00:30:01.4419929Z",
logger_1  |     "metrics": {
logger_1  |       "timer_rego_module_compile_ns": 18600,
logger_1  |       "timer_rego_module_parse_ns": 32800,
logger_1  |       "timer_rego_query_compile_ns": 214200,
logger_1  |       "timer_rego_query_eval_ns": 90700,
logger_1  |       "timer_rego_query_parse_ns": 1098600,
logger_1  |       "timer_server_handler_ns": 1691000
logger_1  |     }
logger_1  |   }
logger_1  | ]
opa_1     | {"level":"info","msg":"Logs uploaded successfully.","plugin":"decision_logs","time":"2019-08-10T00:30:01Z"}

Decision Logが送信されているのがわかります！これでOPAがどのようなインプットでどのような判断を下したのかというログを残していくことができることがわかりました。

機密データのMasking

それでは、Decision Logsについてもう一歩先に進んでみます。

例えば以下のようなリクエストをOPAに投げたとします。

curl -XPOST -d '{ "input": { "user": "john", "password": "secret" } }' http://localhost:8181/v1/data/foo/allow

このときのDecision Logは以下のようになります。

logger_1  | [
logger_1  |   {
logger_1  |     "labels": {
logger_1  |       "id": "abc47ac3-ab0a-4e4f-9ba2-316af7b2c9b4",
logger_1  |       "version": "0.13.0"
logger_1  |     },
logger_1  |     "decision_id": "64475260-33ec-4d29-b375-afb61a2b2624",
logger_1  |     "path": "foo/allow",
logger_1  |     "input": {
logger_1  |       "password": "secret",
logger_1  |       "user": "john"
logger_1  |     },
logger_1  |     "result": true,
logger_1  |     "requested_by": "172.18.0.1:59276",
logger_1  |     "timestamp": "2019-08-10T00:35:55.2005304Z",
logger_1  |     "metrics": {
...
logger_1  |     }
logger_1  |   }
logger_1  | ]

おもいっきり"password": "secret"が出力されているのが確認できます。

"input": {
  "password": "secret",
  "user": "john"
}

このように機密性の高いデータがinputに含まれている場合に、それが平文でログに残されていくのは穏やかな状況ではないですよね。そういう情報を隠せるようにOPAのDecision LogsにはMaskする機能があります。

仕組みとしては比較的シンプルで、OPA自身がDecision Logを送信する前に（デフォルトでは）data.system.log.maskのルールを評価します。その結果に応じて情報を消します（Maskします）。これもさっそく実装してみます。

mask.regoというファイルを作って、中身を以下のようにします。

# mask.rego
package system.log

mask["/input/password"]

これはsystem.logパッケージのmaskルールを作ったことになり、OPA上のルールとしてはdata.system.log.maskに配置することになります。maskルールの中身（mask[<ここ>]）にはJSON Pointerを記述することができて、そこに消したい（Maskしたい）情報へのパスを記述します。上の例であればinput.passwordの内容をログから消したいのでmask["/input/password"]と記述します。

あとはこのmask.regoを起動時に読み込んでおけば大丈夫です。docker-compose.ymlのcommandを編集しておきます。

# docker-compose.yml
version: '3'

services:
# ...
  opa:
# ...
    command: ["run", "--server", "-c", "/workspace/config.yml", "/workspace/policy.rego", "/workspace/mask.rego"]

それではもう一度サービスを再起動（docker-compose down && docker-compose up）してみてリクエストしてみます！

curl -XPOST -d '{ "input": { "user": "john", "password": "secret" } }' http://localhost:8181/v1/data/foo/allow

Decision Logsを見るとinputからpasswordが消えているのがわかります！消されたものに関してはerasedの中にログが残るのも確認できます。

logger_1  | [
logger_1  |   {
logger_1  |     "labels": {
logger_1  |       "id": "734fe644-cfa9-4fed-9b87-dd11edbd4c8e",
logger_1  |       "version": "0.13.0"
logger_1  |     },
logger_1  |     "decision_id": "9bbf532b-b7f8-49b9-a8fd-2711c24ece70",
logger_1  |     "path": "foo/allow",
logger_1  |     "input": {
logger_1  |       "user": "john"
logger_1  |     },
logger_1  |     "result": true,
logger_1  |     "erased": [
logger_1  |       "/input/password"
logger_1  |     ],
logger_1  |     "requested_by": "172.18.0.1:54560",
logger_1  |     "timestamp": "2019-08-10T00:46:02.994297Z",
logger_1  |     "metrics": {
logger_1  |       "timer_rego_module_compile_ns": 18800,
logger_1  |       "timer_rego_module_parse_ns": 1723900,
logger_1  |       "timer_rego_query_compile_ns": 248100,
logger_1  |       "timer_rego_query_eval_ns": 206800,
logger_1  |       "timer_rego_query_parse_ns": 2582800,
logger_1  |       "timer_server_handler_ns": 5260600
logger_1  |     }
logger_1  |   }
logger_1  | ]

このように、Decision LogsのMaskingができることも確認できました。MaskのルールはRegoで書かれているので、ルールの中身を書くことでさらにMaskする条件を絞っていくこともできます。

例えば（こんなルールは無いでしょうけど）userがjohnのときだけMaskしたい場合は、下のようなMaskルールを書くことができます。

package system.log

mask["/input/password"] {
  input.user == "john"
}

v0.13.0から使えるようになったConsole Decision Logger

この記事を書いている途中でOPAのv0.13.0がリリースされました！そしてその中でタイムリーにDecision LogsにConsole Decision Loggerという機能が追加されました。今までDecision Logsを見るには上のようにLoggerを別サービスで用意しておく必要がありましたが、v0.13.0からは標準出力してくれるようになりました！！これは開発時にはかなりうれしい機能になります。

さっそくこれも試してみます。2種類やり方があります。

config.ymlで指定

config.ymlは以下のようになります。（削除する場所がわかりやすいように元々の設定をコメントアウトしています）

# 必要なのはdecision_logs.console = trueのみ！

# services:
#   logger:
#     url: http://logger:3000/

decision_logs:
  console: true
  # service: logger
  # reporting:
  #   min_delay_seconds: 5
  #   max_delay_seconds: 10
起動引数で指定

OPAの起動引数に含めるやり方でも大丈夫です。

opa run --server --set decision_logs.console=true

今回の例であればdocker-compose.ymlを以下のように変えて、config.ymlを使わないようにすることもできます。

version: '3'
# ...
  opa:
    image: openpolicyagent/opa:0.13.0
 # ...
    command: ["run", "--server", "--set", "decision_logs.console=true", "/workspace/policy.rego", "/workspace/mask.rego"]

Console Decision Loggerを検証

では、再びサービスを再起動（docker-compose down && docker-compose up）してリクエストしてみます！

curl -XPOST -d '{ "input": { "user": "john", "password": "secret" } }' http://localhost:8181/v1/data/foo/allow

今回はLoggerサービスではなく、OPA自身のサービスに注目すると：

opa_1  | {"decision_id":"2bb5bd90-856b-4ba7-87db-d995b96d3cca","erased":["/input/password"],"input":{"user":"john"},"labels":{"id":"d54018d5-6700-437f-829e-6fa24210972c","version":"0.13.0"},"level":"info","metrics":{"timer_rego_module_compile_ns":17900,"timer_rego_module_parse_ns":18300,"timer_rego_query_compile_ns":209900,"timer_rego_query_eval_ns":78600,"timer_rego_query_parse_ns":823000,"timer_server_handler_ns":1331300},"msg":"Decision Log","path":"foo/allow","requested_by":"172.27.0.1:45836","result":true,"time":"2019-08-10T21:44:21Z","timestamp":"2019-08-10T21:44:21.378772Z"}

1行にまとめられてるのでちょっとみづらいですが、OPAのログにDecision Logが標準出力されているのがわかります！これはさり気なく結構うれしい新機能だと思います。開発時に積極的に使っていきたいです！

修正方法については以下PRにもしています。

github.com

まとめ

  • OPAではDecision Logs機能を使うことでどういうインプットでどういう判断をしたかログを残すことができる
  • Decision LogsにはMask機能があるのでログを残しておきたくない情報（パスワードなど）を消すことができる
  • v0.13.0からはConsole Decision Loggerが追加されて、Decision Logsが容易に見れるようになった

おまけ

JSON Pointerと配列に関するドキュメントの記述がちょっとわかりにくかったのでプチContributionしました！

github.com