この記事では、Quarkusベースとなったバージョン17以降のKeycloakが出力するログについて解説します。どういうわけか、比較的充実したKeycloakの公式ドキュメントに、ログの設定についての記述はほとんど記載がありませんでした...ということで以前このような記事を書きましたが、Keycloakがバージョン17からQuarkusベースとなって大幅に変わってしまったので、新たに記事を書くことにしました。
この記事を書く際に使用したバージョンはQuarkusベースの17.0.0～19.0.2ですが、17と18/19でログ出力の制御方法が変わっています。それに加えて、20以降のバージョンでも仕様が変わる可能性があることに、注意して下さい。
はじめに
Webアプリケーションがファイルに出力するログには主に以下があります。
- デバッグログ：トラブルシューティングを主目的としたログ
- アクセスログ：クライアントからのアクセス状況を記録するログ
- 監査ログ：監査を目的としたログ
いずれのログも、バージョン17以降のKeycloakはデフォルトでファイルには出力しません。INFOレベル以上のデバッグログと一部の監査ログをコンソール（標準出力）に出力しますが、アクセスログはコンソールにも出力しません。なお、Keycloakではデバッグログを「サーバーログ」という呼び方をしているので、以降は「サーバーログ」と表記します。また、監査ログは「監査イベント」としてDBにレコードを登録にすることもできます（ファイルに出力するのではなくDBに登録する方が一般的です）。
バージョン17より前では、サーバーログを次の2つの設定ファイルで制御していましたが、これらのファイルはバージョン17からなくなっています。
logging.propertiesstandalone.xml
代わりにバージョン17以降では、conf/keycloak.confやconf/quarkus.propertiesでログ出力を制御します。また、環境変数や起動コマンドのパラメーターで制御することもできます。
なお、Keycloakではリクエスト/レスポンスのヘッダーの情報や発行したSQLをログに出力することや、いくつかのJVMオプションを付加してGCログやOOME発生時のヒープダンプなどを出力することもできます。ただし、それらについてはまた別の機会にして、ここではサーバーログ、アクセスログ、監査ログについてだけ解説します。
クライアント・アダプターやLouketo ProxyなどのKeycloakと連携するアプリケーションのログについても、ここでは言及しません（ちなみにこれらはほぼ開発を停止しています）。Keycloakは、Quarkus Logging Gelf拡張の機能を活用して、Graylog、Logstash (Elastic Stack または ELK) または Fluentd (EFK) などの集中ログ管理システムにログを送信できますが、これについてもここでは詳細な解説しません。
サーバーログ
前述したとおり、バージョン17以降のKeycloakは、デフォルトでサーバーログをコンソールのみに出力します。サーバーログをファイルに出力するには、conf/quarkus.propertiesに以下のプロパティーを設定します（ただし、後述する通り、この設定方法はバージョン17のみです）。
quarkus.log.file.enable=true
他にもログローテーションの方法など様々なプロパティーがあります。例えば、以下のような設定の場合、logsディレクトリーにserver.logというファイル名のサーバーログがDEBUGレベルで出力されます。
quarkus.log.file.enable=true
quarkus.log.file.path=logs/server.log
quarkus.log.file.level=DEBUG
quarkus.log.file.rotation.rotate-on-boot=true
quarkus.log.file.rotation.max-file-size=1M
quarkus.log.file.rotation.max-backup-index=5
server.logは起動時とファイルサイズが1MBを超えた際にローテーションされ、バックアップがserver.log.1、server.log.2、・・・server.log.5と最大5ファイル出力されます。
詳細については、Quarkusの公式ガイドを参照してください。
これらのプロパティーでログに様々な制御ができるようになりますが、その後、バージョン18ではこの設定への下位互換性を捨て、それによりログローテションなどは機能しなくなりました。このクラスでKeycloakのプロパティーをQuarkusのプロパティーへマッピングしているようですが、一部のプロパティーのみを若干キー名を変えてマッピングしており、それ以外のものは定義しても機能しないようです
。quarkus.propertiesやkeycloak.confなどの設定ファイルの扱いに関しては、このページで議論されているようですが、まだ仕様レベルで混とんとしているということでしょうか。
というわけで、バージョン18以降の場合は、conf/quarkus.propertiesではなく、conf/keycloak.confに以下のようなプロパティーを設定する必要があります。
log=console,file
これにより、コンソールだけでなく、data/log/keycloak.logにサーバーログが出力されますが、出力先やファイル名を変えたい場合は、log-fileプロパティーを追加します。
log-file=logs/server.log
デフォルトのログレベルはINFOなので、トラブルシューティングなどで詳細な情報を出力したい場合は、log-levelをDEBUGなどに変更します。
log-level=DEBUG
以下のように、カテゴリー単位で出力レベルを変えることもできます。
log-level=INFO,com.arjuna:WARN,org.jboss.as.config:DEBUG
設定ファイルの他に、kc.shコマンドのパラメーターや環境変数で制御することもできます。kc.shコマンドのパラメーターの場合は、以下のようになります。
$ bin/kc.sh start-dev --log=console,file --log-file=logs/server.log --log-level=DEBUG
環境変数の場合は、以下のようになります。
$ export KC_LOG=console,file
$ export KC_LOG_FILE=logs/server.log
$ export KC_LOG_LEVEL=DEBUG
これらの3つのオプションが同時に指定された場合、優先度は、高い方から、kc.shコマンドのパラメーター、環境変数、conf/keycloak.confの順になります。3つのオプションの表記の法則性から、予想できたと思いますが、conf/keycloak.confに記述するプロパティー名（例えば、log-file）に--を付加するとkc.shコマンドのパラメーター（--log-file）になり、全て大文字にして-を_に変更してKC_を付加すると環境変数（KC_LOG_FILE）になります。
ここで紹介していないプロパティーについては、Keycloakの公式ガイドを参照してください。
アクセスログ
前述したとおり、Keycloakはデフォルトでアクセスログを出力するようになっていません。
バージョン17以降では、conf/quarkus.propertiesにquarkus.http.access-log.enabledとquarkus.http.access-log.log-to-fileのプロパティーをtrueにすることで、アクセスログが出力されるようになります。以下は単純な設定の例です。
quarkus.http.access-log.enabled=true
quarkus.http.access-log.log-to-file=true
これにより、カレントディレクトリーにquarkus.logというファイルが出力されますが、このファイル名ではアクセスログっぽくないので、例えば以下のように変更します。
quarkus.http.access-log.log-directory=logs
quarkus.http.access-log.base-file-name=access
この場合、アクセスログの出力先はlogs/で、ファイル名はaccess.logです。
なお、デフォルトではアクセスログに処理時間が出力されません。トラブルシューティングの際などに処理時間の出力が非常に重要になってきますので、これを含めるように設定を見直しておくことをお勧めします。例えば、以下のように%Dオプションを含めておくと、
quarkus.http.access-log.pattern=%h %l %u %t "%r" %s %b "%{i,Referer}" "%{i,User-Agent}" %D
以下のように、処理時間がミリ秒単位で出力されます。
127.0.0.1 - - 08/Mar/2024:13:21:03 +0900 "GET /admin/serverinfo/ HTTP/1.1" 200 196117 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/122.0.0.0 Safari/537.36" 98
ただし、処理時間を記録するためには、以下のプロパティも必要になることに注意して下さい。
quarkus.http.record-request-start-time=true
詳細については、Quarkusの公式ガイドを参照してください。
監査ログ
冒頭で述べた通り、Keycloakでは監査ログ（監査イベント）をDBに登録するのが一般的です。管理コンソールでボタンをクリックすれば監査イベント機能が有効になりますが、これについては、keycloakの公式ドキュメントの日本語訳に記載があるので、ここでは監査ログをファイルに出力する方法について説明します。
実はデフォルトの設定でも一部の監査ログがサーバーログに出力されています。よく見ると、ログイン失敗などの異常系の監査ログが以下のようにWARNレベルで出力されています。
2022-09-29 00:36:54,538 WARN [org.keycloak.events] (executor-thread-5) type=LOGIN_ERROR, realmId=6205d87f-c617-4267-9b4b-c1457461bd9e, clientId=security-admin-console, userId=d43e79f6-6ee4-4110-be96-a9fe662ce273, ipAddress=127.0.0.1, error=invalid_user_credentials, auth_method=openid-connect, auth_type=code, redirect_uri=http://localhost:8080/admin/master/console/#/realms/myrealm, code_id=69aab2f5-a541-4b69-b39f-de366ff473b6, username=admin, authSessionParentId=69aab2f5-a541-4b69-b39f-de366ff473b6, authSessionTabId=oggtstAH2iY
また、サーバーログのログレベルをDEBUGに変更すると、ログイン成功などの正常系の監査ログも出力されます。
したがって、監査ログは、デバッグレベルのサーバーログから監査に関するものだけを抽出して別のファイルに分離すれば、出力できることになります。Quarkusでは、以下のようなカテゴリー単位でのログ出力ができるので、これで出力ファイルを分けることにします。
quarkus.log.category."org.keycloak.events".level=DEBUG
quarkus.log.category."org.keycloak.events".handlers=EVENTS
quarkus.log.handler.file."EVENTS".enable=true
quarkus.log.handler.file."EVENTS".path=logs/events.log
これで監査ログのみがevents.logに出力されるようになりますが、この中には、スレッド名などの不要な情報や、カテゴリー名などの常に同一な情報も含まれます。
2022-10-03 15:23:08,238 desktop-nlupees QuarkusEntryPoint[20892] DEBUG [org.key.events] (executor-thread-3) type=LOGIN, realmId=master, clientId=security-admin-console, userId=35caae87-a7d3-4be9-b841-be5b24532cc5, ipAddress=127.0.0.1, auth_method=openid-connect, auth_type=code, response_type=code, redirect_uri=http://localhost:8080/admin/master/console/#/realms/master/clients, consent=no_consent_required, code_id=043c5714-a794-41d1-8c1c-dc6bbf92b8c0, username=admin, response_mode=fragment, authSessionParentId=043c5714-a794-41d1-8c1c-dc6bbf92b8c0, authSessionTabId=nAdHlG47LrA
2022-10-03 15:23:10,250 desktop-nlupees QuarkusEntryPoint[20892] DEBUG [org.key.events] (executor-thread-2) type=CODE_TO_TOKEN, realmId=master, clientId=security-admin-console, userId=35caae87-a7d3-4be9-b841-be5b24532cc5, ipAddress=127.0.0.1, token_id=d50aedcb-d8c0-4aee-b09d-6032e1d8f000, grant_type=authorization_code, refresh_token_type=Refresh, scope='openid email profile', refresh_token_id=ba23e818-241b-4d84-b0aa-20a41b37e3c5, code_id=043c5714-a794-41d1-8c1c-dc6bbf92b8c0, client_auth_method=client-secret
したがって、次のプロパティーで出力形式を見直した方がいいでしょう。
quarkus.log.handler.file."EVENTS".format=%d{yyyy-MM-dd HH:mm:ss,SSS} %s%e%n
これにより、不要な情報はに出力されなくなります。
2022-10-03 15:29:28,844 type=LOGIN, realmId=master, clientId=security-admin-console, userId=35caae87-a7d3-4be9-b841-be5b24532cc5, ipAddress=127.0.0.1, auth_method=openid-connect, auth_type=code, response_type=code, redirect_uri=http://localhost:8080/admin/master/console/#/realms/master/clients, consent=no_consent_required, code_id=26a516a5-3bd6-48ed-8698-2a7e01f73674, username=admin, response_mode=fragment, authSessionParentId=26a516a5-3bd6-48ed-8698-2a7e01f73674, authSessionTabId=5MImRHTDIaM
2022-10-03 15:29:31,016 type=CODE_TO_TOKEN, realmId=master, clientId=security-admin-console, userId=35caae87-a7d3-4be9-b841-be5b24532cc5, ipAddress=127.0.0.1, token_id=bb298ba3-dfff-47ef-a0c3-45fefad7dee9, grant_type=authorization_code, refresh_token_type=Refresh, scope='openid email profile', refresh_token_id=36d0b376-9c04-4f95-8fa6-50629b84c49d, code_id=26a516a5-3bd6-48ed-8698-2a7e01f73674, client_auth_method=client-secret
ただし、残念ながら監査ログはサーバーログにも引き続き出力されます。これを回避する方法は調べた限りでは無さそうでした...
最後に
ということで、この記事ではKeycloak 17以降（～19.0.2）のログ出力についてまとめました。調べてみると、イマイチなつくりになっていて、今後仕様が変わっていくのではないかと予想しています。なお、Keycloak 16以前（WildFly版）では、Keycloak稼働中にサーバーログのログレベルを変えることができましたが、17以降はできなさそうです。
少しだけ宣伝
2022年10月15日にオライリー・ジャパンから「実践 Keycloak ―OpenID Connect、OAuth 2.0を利用したモダンアプリケーションのセキュリティー保護」が出版されます。原著はWildFly版での解説でしたが、本書は新しいQuarkus版で動かせるように修正、加筆しています。また、Keycloakメンテナー乗松さんによるクライアントポリシーの解説も追加しています。執筆者と翻訳者は以下の通りです。
執筆者
- Stian Thorgersen 氏（Red Hat）：Keycloakプロジェクトを立ち上げ、現在、Keycloakのプロジェクトリーダーかつトップコントリビューター
- Pedro Igor Silva 氏（Red Hat）：Keycloakコア開発者。Keycloakへのコントリビューション4位。
レビュアー
- Hynek Mlnarik 氏（Red Hat）：Keycloakコア開発者。Keycloakへのコントリビューション5位。
- 他2名（略）
翻訳者（日本人Keycloakコントリビューター、コミット数上位4人）
- 和田 広之 氏（野村総合研究所）：IAM関連のOSSを利用したシステム構築の支援などを10年以上。NRI OpenStandiaの技術リーダー。
- 乗松 隆志 氏（日立製作所）：日本人初のKeycloakメンテナー。FAPIなどの最新仕様をKeycloakに多数コミット。
- 田畑 義之 氏（日立製作所）：Keycloakへのコントリビューション、Keycloak関連記事、講演、書籍執筆多数。
- 田村 広平：私
また、出版を祝して、Keycloakと関連プロダクトであるmidPointの勉強会（OSSセキュリティ技術の会 第11回勉強会）も開催します。興味のある方はご参加ください。