この記事は ただの集団 Advent Calendar 2019 の20日目の記事です。
先日の ClickHouse Meetup Tokyo 2019 で「監査ログ(audit.log)相当の機能はないの?」 て質問したら system.query_log にあるから見てねということだったので、この記事では設定から出力内容まで見ていきたいと思います。
System Tables - ClickHouse Documentation
ClickHouseについてはGENIEEさんの有名な記事があるので参照ください。
MySQLを捨てClickHouseでレポートAPIのレスポンスを1000倍高速化した話
監査ログ
まず監査ログについて簡単に説明すると、ユーザの行った操作と時間を記録として残すもの。以下の項目を含むログが時系列に出力されたものになります。
- 操作を行った時間
- 実行者
- 操作の内容
system.query_log の内容
テーブル定義をみてみます。監査項目の列に前述の項目の番号を記載しています。ここではclcikhouse-clientの使用のみを考えています。HTTPや他のクライアントを使う場合は他も見ないと実行者の区別をつけられないかもしれません。
ドキュメントにはカラムごとに説明が書いてあるので参照してみてください。
| name | type | 監査項目 |
|---|---|---|
| type | Enum8('QueryStart'=1,'QueryFinish'=2,'ExceptionBeforeStart'=3,'ExceptionWhileProcessing'=4) | |
| event_date | Date | (1) |
| event_time | DateTime | (1) |
| query_start_time | DateTime | (1) |
| query_duration_ms | UInt64 | |
| read_rows | UInt64 | |
| read_bytes | UInt64 | |
| written_rows | UInt64 | |
| written_bytes | UInt64 | |
| result_rows | UInt64 | |
| result_bytes | UInt64 | |
| memory_usage | UInt64 | |
| query | String | (3) |
| exception | String | |
| stack_trace | String | |
| is_initial_query | UInt8 | |
| user | String | (2) |
| query_id | String | |
| address | IPv6 | (2) |
| port | UInt16 | |
| initial_user | String | (2) |
| initial_query_id | String | |
| initial_address | IPv6 | (2) |
| initial_port | UInt16 | |
| interface | UInt8 | |
| os_user | String | |
| client_hostname | String | (2) |
| client_name | String | (2) |
| client_revision | UInt32 | |
| client_version_major | UInt32 | |
| client_version_minor | UInt32 | |
| client_version_patch | UInt32 | |
| http_method | UInt8 | |
| http_user_agent | String | |
| quota_key | String | |
| revision | UInt32 | |
| thread_numbers | Array(UInt32) | |
| os_thread_ids | Array(UInt32) | |
| ProfileEvents.Names | Array(String) | |
| ProfileEvents.Values | Array(UInt64) | |
| Settings.Names | Array(String) | |
| Settings.Values | Array(String) |
type の定義を見ると 処理開始、処理終了、実行前例外、実行中例外 のステータスが出力されるようです。監査ログとして処理の完了失敗まで見れるのは良さそうです。
操作の内容は query を見ればいいでしょう。
操作を行った時間は、event_date、event_timeで実行時間が分かります。 query_start_time も見ておけばリクエストから処理開始までにラグがあったときも拾えそうです。
実行者は、userで大丈夫そうです。
ユーザを共有する場合は、 addressやclient_name、client_host などを見ていけばある程度絞れると思います。しかしユーザの作成や管理をして、userだけ見ればいい環境にしておくほうが健全です。
監査項目意外にもメモリ使用量などメトリクスも取れるようです。
設定方法
デフォルトではquery_logは出力されません。
users.xmlに設定を加えることでユーザごとに出力するかどうか指定できます。ここではdefaultのプロファイルにquery_log出力の設定を行い、そのプロファイルを使うtest_userを作成する設定を行います。
<yandex>
<profiles>
:
<default>
<log_queries>1</log_queries> <!-- query_log出力設定 -->
</default>
</profiles>
:
<users>
<test_user>
:
<profile>default</profile>
</test_user>
</users>
</yandex>
設定後、サーバを再起動すれば反映されます。
query_log自体の設定も可能です。config.xmlにあります。月ごとにパーテションが切られるようです。
<!-- Query log. Used only for queries with setting log_queries = 1. -->
<query_log>
<!-- What table to insert data. If table is not exist, it will be created.
When query log structure is changed after system update,
then old table will be renamed and new table will be created automatically.
-->
<database>system</database>
<table>query_log</table>
<!--
PARTITION BY expr https://clickhouse.yandex/docs/en/table_engines/custom_partitioning_key/
Example:
event_date
toMonday(event_date)
toYYYYMM(event_date)
toStartOfHour(event_time)
-->
<partition_by>toYYYYMM(event_date)</partition_by>
<!-- Interval of flushing data. -->
<flush_interval_milliseconds>7500</flush_interval_milliseconds>
</query_log>
実際のログ
サンプルとして、作成した test_userでローカルにあるクライアントを使って検索を行ったときのログを載せます。
Row 1:
──────
type: QueryStart
event_date: 2019-12-01
event_time: 2019-12-01 11:21:38
query_start_time: 2019-12-01 11:21:38
query_duration_ms: 25
read_rows: 2
read_bytes: 32
written_rows: 0
written_bytes: 0
result_rows: 2
result_bytes: 32
memory_usage: 213712
query: SELECT * FROM ex
exception:
stack_trace:
is_initial_query: 1
user: test_user
query_id: 5a1740b8-c911-4c41-8005-3c582ad17a28
address: ::ffff:127.0.0.1
port: 42404
initial_user: test_user
initial_query_id: 5a1740b8-c911-4c41-8005-3c582ad17a28
initial_address: ::ffff:127.0.0.1
initial_port: 42404
interface: 1
os_user:
client_hostname: bb991ca8883f
client_name: ClickHouse client
client_revision: 54428
client_version_major: 19
client_version_minor: 17
client_version_patch: 2
http_method: 0
http_user_agent:
quota_key:
revision: 54428
thread_numbers: [45,48]
os_thread_ids: [82,94]
ProfileEvents.Names: ['Query','SelectQuery','FileOpen','ReadBufferFromFileDescriptorRead','ReadBufferFromFileDescriptorReadBytes','ReadCompressedBytes','CompressedReadBufferBlocks','CompressedReadBufferBytes','IOBufferAllocs','IOBufferAllocBytes','MarkCacheMisses','CreatedReadBufferOrdinary','DiskReadElapsedMicroseconds','NetworkSendElapsedMicroseconds','SelectedParts','SelectedRanges','SelectedMarks','ContextLock','RWLockAcquiredReadLocks','RealTimeMicroseconds','SoftPageFaults','HardPageFaults']
ProfileEvents.Values: [1,1,4,8,164,104,3,26,8,1049078,2,2,839,4239,1,1,1,19,1,39060,9,4]
Settings.Names: ['use_uncompressed_cache','load_balancing','log_queries','max_memory_usage']
Settings.Values: ['0','random','1','10000000000']
追加機能
v20.11.2.1
ClickHouse release v20.11.2.1, 2020-11-11
New Feature
- errorCodeToName function - return variable name of the error (useful for analyzing query_log and similar). system.errors table - shows how many times errors has been happened (respects system_events_show_zero_values). #16438 (Azat Khuzhin).
- Add log_queries_min_query_duration_ms, only queries slower than the value of this setting will go to query_log/query_thread_log (i.e. something like slow_query_log in mysql). #16529 (Azat Khuzhin).
log-queries-min-query-duration-ms オプションが追加されました。MySQLのSlowQueryログのように遅いクエリのみログに出力するよう設定できます。詳細は ドキュメント を参照してください。
また errorCodeToName 関数が追加されています。エラーコードをメッセージに変換してくれます。クライアントでクエリーを実行してエラーしたときにはエラーメッセージが表示されます。この関数はコードしか出力されないquery_logの調査用にという意図で追加されたようです。
:) SELECT * FROM foo.bar;
Received exception from server (version 20.11.3):
Code: 81. DB::Exception: Received from localhost:9000. DB::Exception: Database foo doesnt exist.
:) SELECT errorCodeToName(81);
┌─errorCodeToName(81)─┐
│ UNKNOWN_DATABASE │
└─────────────────────┘
まとめ
ClickHouseにおける監査ログの内容と設定方法をみてきました。内容は監査ログとして十分そうで、設定も簡単にできます。
ログがDB内に蓄積されますが、ClickHouse自体大量データを扱うDBなのであまり気にしなくてもいいでしょう。デフォルトで月ごとにパーテションもできるので古いログはダンプを取ってS3などに上げてやればよさそうです。