Spire v1.0.2から利用できるのAuditLogについて

SPIREにAudit Logを出力する機能が追加されています。
v1.0.2から導入されました。

仕様についてのドキュメントも用意されています。

https://github.com/spiffe/spire/blob/main/doc/auditlog.md


Audit Logを出力するにはserver.confに `audit_log_enabled`を設定すること。(デフォルトはfalse)
これを設定すると通常のログにAuditログも合わせて出力されます。

- type: audit
  - 固定値
- request_id
  - リクエストを一意に特定するためのuuid
- status
  - リクエストが成功したかどうかを示す error or success
- status_code
  - gRPCのステータスコード
- status_message
  - クライアントに返却されたエラーメッセージ

# Audit Logの歴史

2019年10月のこのIssueから始まりました。

https://github.com/spiffe/spire/issues/1207

2021年3月にこのIssueは動き始め、、以下のような議論が行われています。

- Batchオペレーションのログが場合によって膨大になる
- 参照系のログにはそこまで興味がない
- 普通のログに混ぜるか、別のログにするか
- ProposalはGoogle Docsで用意されている。
  - https://docs.google.com/document/d/1A0z01oj3YmO-3i3J8dgUPNafTawUarFIqKudeqt_fCw/edit
    - AttestAgent,RenewAgentのAuditがNot Sureになっているので、実装を確認する必要あり。
    - 基本的に更新系でAuditログを出す方針
    - SVID APIについても Not sureが並んでいる。
    - 実装方針について3通りの方法が提案されている
      - Log Based
        - →これが実装された方式のようだ
        - →バッチ系は含まれるそれぞれのエントリごとの出力を出すと書かれている
      - Audit Log Service
        - →実装されていない
        - →DBと連携してAuditログを保存する方式
      - Audit log Plugin
        - →ログを残すための仕組みをプラガブルにする方式

# 実装

泥臭く処理の各所にAuditログを出力する処理を入れている。
（抜け漏れがありそう・・）
ログについてもテストがしっかり書かれているのは良い。

Auditログを仕込んでいるPRは下記。APIの種類ごとにPRがわけられている。

- [Add audit log to bundle service #2297](https://github.com/spiffe/spire/pull/2297)
  - Auditログを残すための簡単なライブラリを作っている。 pkg/server/api/audit/audit.go
  - pkg/server/api/rpccontext/audit.go によりrpccontextから簡単にAuditログを出力できるようになっている。この処理を要所要所に埋め込んでいる。
  - pkg/server/api/middleware/audit.go で、GRPCがエラーを返した際のauditログを一括で処理している。
  - AuditログはInfoレベルで出力される。
  - CountBundles, GetBundleなど参照系でもAuditログを出している。
  - バッチ系のリクエストはバッチに含まれるエントリごとにAuditログを出している。
- [Add audit logs to Sever's agent service #2391](https://github.com/spiffe/spire/pull/2391)
- [Add auditlog to entry endpoints #2394](https://github.com/spiffe/spire/pull/2394)
  - Auditログを出力する関数を少し改造している。
- [Add auditlog to svid endpoints #2396](https://github.com/spiffe/spire/pull/2396)
- 全体を通して
  - 参照系でもAuditログを出している。

# 実際の動作を見てみる

ヘルスチェックした様子

```
INFO[0061] API accessed                                  caller_gid=20 caller_path=/XXXXX/spire-server caller_uid=503 method=GetBundle request_id=9b4f72e3-73eb-45e3-bdb8-96bf20ee4827 service=bundle.v1.Bundle status=success subsystem_name=api trust_domain_id=example.org type=audit
```

tokenを払い出した時

```
INFO[0096] API accessed                                  caller_gid=20 caller_path=/XXXXX/spire-server caller_uid=503 method=CreateJoinToken request_id=e66c9ad0-e7b3-4bdc-9167-243a5dbb9e89 service=agent.v1.Agent spiffe_id="spiffe://example.org/myagent" status=success subsystem_name=api ttl=600 type=audit
```

agentをjoinさせてみる。

```
INFO[0156] Agent attestation request completed           address="127.0.0.1:49177" agent_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" caller_addr="127.0.0.1:49177" method=AttestAgent node_attestor_type=join_token request_id=683e5097-8b77-43c0-a9cf-eca4428608bb service=agent.v1.Agent subsystem_name=api
INFO[0156] API accessed                                  agent_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" caller_addr="127.0.0.1:49177" method=AttestAgent node_attestor_type=join_token request_id=683e5097-8b77-43c0-a9cf-eca4428608bb service=agent.v1.Agent status=success subsystem_name=api type=audit
INFO[0156] API accessed                                  caller_addr="127.0.0.1:49177" method=GetBundle request_id=8cc31f97-1c76-4160-8c4d-0590d137b37f service=bundle.v1.Bundle status=success subsystem_name=api trust_domain_id=example.org type=audit
INFO[0156] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetAuthorizedEntries request_id=32d86d26-5688-4702-81c9-58633c562862 service=entry.v1.Entry status=success subsystem_name=api type=audit
INFO[0156] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetBundle request_id=8a12a46d-4f00-4020-93cc-3824e8c167d9 service=bundle.v1.Bundle status=success subsystem_name=api trust_domain_id=example.org type=audit
DEBU[0156] Signed X509 SVID                              expiration="2021-09-03T02:32:48Z" spiffe_id="spiffe://example.org/myagent" subsystem_name=ca
INFO[0156] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" csr=2fda2dafae350f544fd5d704c04d3d59bb15b64a0e974cf428e733a32d7e0786 entry_id=f3f9535d-3812-433f-ae12-164ef375cc49 expires_at=1630636368 method=BatchNewX509SVID request_id=0dc25b03-3208-4208-a3d8-219b517f02ba service=svid.v1.SVID status=success subsystem_name=api type=audit
INFO[0161] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetAuthorizedEntries request_id=5a17ddb2-256a-4661-a044-45760fb73262 service=entry.v1.Entry status=success subsystem_name=api type=audit
INFO[0161] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetBundle request_id=19d23194-c32e-4b8a-886d-68a5a1da68b6 service=bundle.v1.Bundle status=success subsystem_name=api trust_domain_id=example.org type=audit
INFO[0166] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetAuthorizedEntries request_id=9b4231ca-d688-4f9f-93d8-be5d83621a6e service=entry.v1.Entry status=success subsystem_name=api type=audit
INFO[0166] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetBundle request_id=14cc2ed8-c630-4a89-bf6d-a96d0bf79273 service=bundle.v1.Bundle status=success subsystem_name=api trust_domain_id=example.org type=audit
INFO[0171] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetAuthorizedEntries request_id=6a5f8a60-53ca-47f1-a86d-a3ee9cb0bf52 service=entry.v1.Entry status=success subsystem_name=api type=audit
INFO[0171] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetBundle request_id=1de286a8-8248-4337-9802-fa6eeb291846 service=bundle.v1.Bundle status=success subsystem_name=api trust_domain_id=example.org type=audit
INFO[0176] API accessed                                  caller_addr="127.0.0.1:49178" caller_id="spiffe://example.org/spire/agent/join_token/e0807b93-e9cb-4f24-8c57-4452e05ba24d" method=GetAuthorizedEntries request_id=af26940d-a9f7-4f6b-878f-cac92ace478c service=entry.v1.Entry status=success subsystem_name=api type=audit
```

誤ったtokenでjoinしようとしてみる。

```
INFO[0001] API accessed                                  caller_gid=20 caller_path=/XXXXX/spire-server caller_uid=503 method=GetBundle request_id=70de5edf-cd43-4350-a578-a597cc4f83fc service=bundle.v1.Bundle status=success subsystem_name=api trust_domain_id=example.org type=audit
ERRO[0007] Invalid argument: failed to attest: join token does not exist or has already been used  caller_addr="127.0.0.1:50293" method=AttestAgent node_attestor_type=join_token request_id=dd5b120c-4b8d-4e6b-8ff5-34796329cfa8 service=agent.v1.Agent subsystem_name=api
INFO[0007] API accessed                                  caller_addr="127.0.0.1:50293" method=AttestAgent node_attestor_type=join_token request_id=dd5b120c-4b8d-4e6b-8ff5-34796329cfa8 service=agent.v1.Agent status=error status_code=InvalidArgument status_message="failed to attest: join token does not exist or has already been used" subsystem_name=api type=audit
```

エラーの時も正しくAuditログが出ていることが確認できる。

# まとめ

SPIREのようなセキュリティ要件と直結するソフトウェアの監査というのは非常に大切です。今までもログに多くの情報が出ていましたが、今回のようにAuditログという形で一定のポリシーを持って監査ログを出すようになったことで、SPIREを本番環境で運用していく際の懸念点が一つ払拭されたように思いました。