Keycloakが出力するログについて

<!--　　　![Keycloak.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/9d68a697-c897-2f47-f641-7cdefad886a4.png) -->
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/1f3b8d8b-3d15-ef87-ce54-0d1b06650c33.png)

この記事では、Keycloakが出力するログについて説明します。実はログの設定について、Keycloakの公式ドキュメントにはほとんど記載がありません...ということでこの記事を書きました。

なお、このドキュメントを書く際に使用したバージョンはKeycloak 6.0.1ですが、他のバージョンでもおそらく同様だと思います。

# はじめに

Webアプリケーションが出力するログには、一般的に以下があります。

 - デバッグログ
 - アクセスログ
 - 監査ログ

Keycloakでは、通常、デバッグログ（※）とアクセスログをファイルに出力し、監査ログ（監査イベント）をDBに登録します。

<table><td>※：Keycloakでは「サーバーログ」という呼び方をしているので、以降は「サーバーログ」と表記します。</td></table>

さらに、Keycloakではリクエスト/レスポンスのヘッダーの情報や発行したSQLをログに出力することや、いくつかのJVMオプションを付加してGCログやOOME発生時のヒープダンプなどを出力することもできますが、それらについてはまた別の機会にして、ここではサーバーログ、アクセスログ、監査ログについてだけ解説します。なお、クライアント・アダプターやGatekeeperなどのKeycloakと連携するアプリケーションのログについても、ここでは言及しません。

# サーバーログ

スタンドアローン・モード（※）のKeycloakは、デフォルトでサーバーログをファイル（`standalone/log/server.log`）とコンソール（標準出力）に出力します。この動作を制御する設定ファイルは次の2つです。

 - `logging.properties`
 - `standalone.xml`

いずれのファイルも`standalone/configuration/`にあります。Keycloak起動直後（数秒間）のログレベルは前者によって決まり、WildFlyの`logging`サブシステムが起動すると後者に切り替わります。トラブルシューティングのためログレベルを変更する場合は、後者のみを変更すれば十分です。ただし、起動直後に出力されるログは前者の設定に依存していることは覚えておいた方がいいです。後述しますが、前者の扱いには少し注意が必要です。

<table><td>※：Keycloakには単独で起動するスタンドアローン・モードの他にクラスター構成で起動するスタンドアローン・クラスター・モードやドメイン・モードなどがあり、モードにより設定ファイルのファイル名が異なります。スタンドアローン・モードの設定ファイルは<code>standalone.xml</code>です。詳細については、<a href="https://keycloak-documentation.openstandia.jp/master/ja_JP/server_installation/index.html#_operating-mode">ガイド</a>を参照してください。</td></table>

## `logging`サブシステム起動後のログの設定（`standalone.xml`）

前述したとおり、`standalone.xml`が実質的なKeycloakのログ出力を制御する設定ファイルになります。バージョン6.0.1における`standalone.xml`の定義（ロギング定義のみの抜粋）は、以下のようになっています。

```xml
<subsystem xmlns="urn:jboss:domain:logging:5.0">
    <console-handler name="CONSOLE">
        <level name="INFO"/>
        <formatter>
            <named-formatter name="COLOR-PATTERN"/>
        </formatter>
    </console-handler>
    <periodic-rotating-file-handler name="FILE" autoflush="true">
        <formatter>
            <named-formatter name="PATTERN"/>
        </formatter>
        <file relative-to="jboss.server.log.dir" path="server.log"/>
        <suffix value=".yyyy-MM-dd"/>
        <append value="true"/>
    </periodic-rotating-file-handler>
    <logger category="com.arjuna">
        <level name="WARN"/>
    </logger>
    <logger category="org.jboss.as.config">
        <level name="DEBUG"/>
    </logger>
    <logger category="sun.rmi">
        <level name="WARN"/>
    </logger>
    <root-logger>
        <level name="INFO"/>
        <handlers>
            <handler name="CONSOLE"/>
            <handler name="FILE"/>
        </handlers>
    </root-logger>
    <formatter name="PATTERN">
        <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
    </formatter>
    <formatter name="COLOR-PATTERN">
        <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
    </formatter>
</subsystem>
```

この定義を見ると、コンソールに出力する`console-handler`と、ファイルに出力し定期的にローテーションする`periodic-rotating-file-handler`があるのが分かります。デフォルトの設定の`periodic-rotating-file-handler`は、`server.log.2019-06-04`というような名前で日時でログファイルをローテーションします。

トラブルシューティングのために出力されるログの量を多くしたい場合は、`root-logger`のログレベルを`INFO`から`DEBUG`に変更すればいいです。

```xml
    <root-logger>
        <!-- <level name="INFO"/> -->
        <level name="DEBUG"/>
```

この場合は、コンソールのログ出力量は増えずに、ファイルのログ出力量が増えます。`console-handler`には明示的に`<level name="INFO"/>`が指定されているため、`root-logger`のログレベルの変更が適用されないからです（※）。

<table><td>※：デフォルトでは、<code>root-logger</code>にも<code>console-handler</code>にも同じログレベル（<code>&lt;level name="INFO"/&gt;</code>）が指定されています。もし、両者のログレベルが異なる場合（例えば、<code>root-logger</code>が<code>DEBUG</code>で<code>console-handler</code>が<code>INFO</code>の場合）、どちらのログレベルが有効になるでしょうか？答えは、ログレベルが高い方（ログの出力量が少ない方）になります。つまり、<code>INFO</code>が採用されます。<code>root-logger</code>が<code>INFO</code>で<code>console-handler</code>が<code>DEBUG</code>の場合でも<code>INFO</code>が採用されます。</td></table>

`DEBUG`レベルのログの出力量はかなり多いです。トラブルシューティングの大きな助けになるとはいえ、本番環境では常時`DEBUG`にしない方がいいかもしれません。

## Keycloak起動直後のログの設定（`logging.properties`）

WildFlyの`logging`サブシステムが起動するまでのログの設定は`logging.properties`に依存します。バージョン6.0.1の`logging.properties`の定義は、以下のようになっています。

```properties
loggers=sun.rmi,io.jaegertracing.Configuration,org.jboss.as.config,com.arjuna

logger.level=INFO
logger.handlers=FILE,CONSOLE

logger.sun.rmi.level=WARN
logger.sun.rmi.useParentHandlers=true

logger.io.jaegertracing.Configuration.level=WARN
logger.io.jaegertracing.Configuration.useParentHandlers=true

logger.org.jboss.as.config.level=DEBUG
logger.org.jboss.as.config.useParentHandlers=true

logger.com.arjuna.level=WARN
logger.com.arjuna.useParentHandlers=true

handler.CONSOLE=org.jboss.logmanager.handlers.ConsoleHandler
handler.CONSOLE.level=INFO
handler.CONSOLE.formatter=COLOR-PATTERN
handler.CONSOLE.properties=autoFlush,target,enabled
handler.CONSOLE.autoFlush=true
handler.CONSOLE.target=SYSTEM_OUT
handler.CONSOLE.enabled=true

handler.FILE=org.jboss.logmanager.handlers.PeriodicRotatingFileHandler
handler.FILE.level=ALL
handler.FILE.formatter=PATTERN
handler.FILE.properties=append,autoFlush,enabled,suffix,fileName
handler.FILE.constructorProperties=fileName,append
handler.FILE.append=true
handler.FILE.autoFlush=true
handler.FILE.enabled=true
handler.FILE.suffix=.yyyy-MM-dd
handler.FILE.fileName=/opt/keycloak-6.0.1/standalone/log/server.log

formatter.PATTERN=org.jboss.logmanager.formatters.PatternFormatter
formatter.PATTERN.properties=pattern
formatter.PATTERN.pattern=%d{yyyy-MM-dd HH\:mm\:ss,SSS} %-5p [%c] (%t) %s%e%n

formatter.COLOR-PATTERN=org.jboss.logmanager.formatters.PatternFormatter
formatter.COLOR-PATTERN.properties=pattern
formatter.COLOR-PATTERN.pattern=%K{level}%d{HH\:mm\:ss,SSS} %-5p [%c] (%t) %s%e%n
```

起動直後のトラブルシューティングのために出力されるログの量を多くしたい場合は、`logger.level`を`INFO`から`DEBUG`などに変更すればいいです。この場合、コンソールのログ出力量は増えずに、ファイルのログ出力量が増えます。

```properties
# logger.level=INFO
logger.level=DEBUG
```

`logging.properties`の定義も、`logger.level`と`handler.CONSOLE.level`の値を異なる値にすることができます。例えば、`logger.level=INFO`と`handler.CONSOLE.level=DEBUG`の2つの定義があるような場合です。この場合、コンソールに出力されるログのレベルは`INFO`になります。`standalone.xml`と同様に、2つの定義がある場合は、ログレベルが高い方が採用されます。

### `logging.properties`に関する注意事項

`logging.properties`の扱いには少し注意が必要です。`logging.properties`の先頭（以下）に書いてあるように、このファイルはKeycloakの起動中に`standalone.xml`のロギング定義に合わせて上書きされます。

```
# Note this file has been generated and will be overwritten if a
# logging subsystem has been defined in the XML configuration.
```

したがって、`logging.properties`の定義を修正しなくても、`standalone.xml`のロギング定義が変更されていれば、それに合わせて自動的に上書きされてしまいます。ただし、`standalone.xml`のロギング定義を変更した直後の1回目のKeycloakの起動では、最初に古い`logging.properties`の定義が読み取られます。ログレベルを変えていたとしても、その数秒だけはログレベルが変わりません。その後、`logging`サブシステムが起動して、`standalone.xml`に合わせて`logging.properties`が上書きされると、それ以降は変更したログレベルが適用されることになります。

![flow.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/43869/92c7bcdc-c1ec-44aa-0d37-3ffcbe001b22.png)

ちなみに、`logging.properties`は、存在しなくても（削除してしまっても）、Keycloakを起動すれば`standalone.xml`のロギング定義をもとに自動的に生成されます。

# アクセスログ

Keycloakはデフォルトでアクセスログを出力するようになっていません。

スタンドアローン・モードの場合、`standalone.xml`に`<access-log>`の設定を追加することで、アクセスログが出力されるようになります。以下は最も単純な設定の例です。

```xml
<subsystem xmlns="urn:jboss:domain:undertow:4.0">
    <buffer-cache name="default"/>
    <server name="default-server">
        ...
        <host name="default-host" alias="localhost">
            <location name="/" handler="welcome-content"/>
            <!-- 以下の1行を追加 -->
            <access-log worker="default" directory="${jboss.server.log.dir}" prefix="access." suffix="log"/>
            <http-invoker security-realm="ApplicationRealm"/>
            <filter-ref name="proxy-peer"/>
        </host>
    </server>
```

この場合、アクセスログの出力先は`standalone/log/`で、ファイル名は`access.log`です。

# 監査ログ

冒頭で述べた通り、Keycloakでは監査ログ（監査イベント）をDBに登録するのが一般的です。管理コンソールでボタンをクリックすれば監査イベント機能が有効になりますが、これについては、[ドキュメント](https://keycloak-documentation.openstandia.jp/master/ja_JP/server_admin/index.html#%E7%9B%A3%E6%9F%BB%E3%81%A8%E3%82%A4%E3%83%99%E3%83%B3%E3%83%88)に記載があるので、ここでは監査ログをファイルに出力する方法について説明します。

と言っても、実はデフォルトの設定でも一部の監査ログがサーバーログに出力されています。よく見ると、ログイン失敗などの異常系のログが以下のように出力されています。

```
20:04:48,625 WARN  [org.keycloak.events] (default task-11) type=LOGIN_ERROR, realmId=master, clientId=security-admin-console, userId=null, ipAddress=192.178.185.216, error=user_not_found, auth_method=openid-connect, auth_type=code, redirect_uri=http://openstack02.example.co.jp:8080/auth/admin/master/console/#/realms/master, code_id=4944825c-e383-43a8-a513-3555a359febc, username=ichiro
```

サーバーログのエラーレベルがデフォルトの`INFO`の場合、エラーレベルを`DEBUG`に変更するか、以下のように`jboss-cli.sh`で監査ログの正常系のログレベル（`success-level`）を`info`に設定すると（デフォルトは`debug`）、正常系の監査ログもサーバーログに出力されます。ちなみに異常系のエラーレベル（`error-level`）はデフォルトで`warn`です。

```
$ cd $KEYCLOAK_HOME
$ bin/jboss-cli.sh
[disconnected /] connect
[standalone@localhost:9990 /] /subsystem=keycloak-server/spi=eventsListener:add(default-provider=jboss-logging)
[standalone@localhost:9990 /] /subsystem=keycloak-server/spi=eventsListener/provider=jboss-logging:add(enabled=true)
[standalone@localhost:9990 /] /subsystem=keycloak-server/spi=eventsListener/provider=jboss-logging:write-attribute(name=properties.success-level,value=info)
[standalone@localhost:9990 /] :reload
```

また、次のような定義を`standalone.xml`（スタンドアローン・モードの場合）に追加すれば、監査ログをサーバーログと分離して、JSON形式でファイルに出力することもできます。

```xml
<size-rotating-file-handler name="EVENTLOG" autoflush="true">
   <formatter>
      <named-formatter name="json-formatter" />
   </formatter>
   <file relative-to="jboss.server.log.dir" path="events.log" />
   <rotate-size value="10M" />
   <max-backup-index value="5" />
   <append value="true" />
</size-rotating-file-handler>
<logger category="org.keycloak.events">
   <level name="DEBUG" />
   <handlers>
      <handler name="EVENTLOG" />
   </handlers>
</logger>
<formatter name="json-formatter">
   <json-formatter />
</formatter>
```

このとき、次のような行を含むファイル（`events.log`）が`standalone/log/`に出力されます。

```
{"timestamp":"2019-07-30T20:37:42.937+09:00","sequence":100,"loggerClassName":"org.jboss.logging.Logger","loggerName":"org.keycloak.events","level":"WARN","message":"type=LOGIN_ERROR, realmId=master, clientId=security-admin-console, userId=null, ipAddress=192.178.185.216, error=user_not_found, auth_method=openid-connect, auth_type=code, redirect_uri=http://openstack02.example.co.jp:8080/auth/admin/master/console/#/realms/master, code_id=9ca6f9f4-978e-4591-9f83-b12961846638, username=test","threadName":"default task-7","threadId":125,"mdc":{},"ndc":"","hostName":"openstack02.example.co.jp","processName":"jboss-modules.jar","processId":13711}
```

# ログに関するQ&A

- Q1. 稼働中にサーバーログのログレベルを変えることはできますか？
  - A1. はい。`jboss-cli.sh`を使用すると、変更ができます。以下の例では、`root-logger`のログレベルを`DEBUG`に、`console-handler`のログレベルを`ALL`に変更しています。
  
    ```
    $ cd $KEYCLOAK_HOME
    $ bin/jboss-cli.sh
    [disconnected /] connect
    [standalone@localhost:9990 /] /subsystem=logging/console-handler=CONSOLE:change-log-level(level=ALL)
    [standalone@localhost:9990 /] /subsystem=logging/root-logger=ROOT/:write-attribute(name=level,value=DEBUG)
    ```

- Q2. モジュールを限定してサーバーログのログレベルを変えることはできますか？
  - A2. できます。`standalone.xml`を見ると分かりますが、`category`属性にパッケージ名を指定した定義があります。例えば、デフォルトの設定には次のような定義がありますが、

    ```xml
    <logger category="org.jboss.as.config">
        <level name="DEBUG"/>
    </logger>
    ```
    `root-logger`が`INFO`に設定されているにも関わらず、`org.jboss.as.config`パッケージのクラスのロガーは`DEBUG`レベルの情報を出力します（正確にはファイルに出力し、コンソールには出力しません）。この設定も`jboss-cli.sh`で変更ができます。例えば、以下のコマンドにより、`org.jboss.as.config`のログレベルを`WARN`に変えることができます。

    ```
    $ cd $KEYCLOAK_HOME
    $ bin/jboss-cli.sh
    [disconnected /] connect
    [standalone@localhost:9990 /] /subsystem=logging/logger=org.jboss.as.config:write-attribute(name="level", value="WARN") 
    ```

- Q3. `audit.log`というログファイルが出力されていますが、これはKeycloakの監査ログではないのですか？
  - A3. 違います。スタンドアローン・モードのKeycloakは、デフォルトで`standalone/log/`に`audit.log`を出力しますが、Keycloakの監査ログではなく、WildFlyに含まれるElytronというフレームワークの監査ログです。おそらく、通常のKeycloakの利用範囲では、空のまま何も書き込まれることは無いと思います。


- Q4. `standalone.xml`に`<audit-log>`のセクションがありますが、これはKeycloakの監査ログの設定ではないのですか？
  - A4. 違います。確かに以下のような設定がありますが、これはWildFlyの管理インターフェイス（URL：[http://127.0.0.1:9990/](http://127.0.0.1:9990/)）の監査ログです。

    ```xml
    <audit-log>
        <formatters>
            <json-formatter name="json-formatter"/>
        </formatters>
        <handlers>
            <file-handler name="file" formatter="json-formatter" path="audit-log.log" relative-to="jboss.server.data.dir"/>
        </handlers>
        <logger log-boot="true" log-read-only="false" enabled="false">
            <handlers>
                <handler name="file"/>
            </handlers>
        </logger>
    </audit-log>
    ```

    `logger`要素の`enabled`属性を`"true"`に変更してみると、

    ```xml
    <!-- <logger log-boot="true" log-read-only="false" enabled="false"> -->
    <logger log-boot="true" log-read-only="false" enabled="true">
    ```

    次のような行を含む`audit-log.log`という名前のファイルが`standalon/data`ディレクトリーに出力されます。

    ```json
    2019-07-31 17:13:34 - {
        "type" : "core",
        "r/o" : false,
        "booting" : true,
        "version" : "4.8.3.Final",
        "user" : "anonymous",
        "domainUUID" : null,
        "access" : null,
        "remote-address" : null,
        "success" : true,
        "ops" : [
            {
                "operation" : "parallel-extension-add",
                "address" : []
            },
    ```

    WildFlyの管理インターフェイスにアクセスし、設定を変更したりすると、JSON形式のデータが追加されます。ちなみに、1回の監査ログで数千行も出力されることがあります...

- Q5. アクセスログはローテーションできますか？
  - A5. 前述の定義で自動的に日時ローテーションされます。この定義の場合、バックアップされるファイル名は`access.2019-07-26.log`のようになります（サーバーログのバックアップのファイル名は`server.log.2019-07-26`なので、統一感がありませんが...)

<!--
- Q6. ローテーションしたログのファイル名の形式を統一したいのですが、できますか？（`access.2019-07-26.log`と`server.log.2019-07-26`のようにならないように）
  - A6. はい。`suffix`などの日付部分の解析は`java.text.SimpleDateFormat`が適用されるので、「'」(シングルクォーテーション)で「log」などの文字列を囲むと、`server.log.2019-07-26`が`server.2019-07-26.log`のようになります。
 
    ```xml
    <file relative-to="jboss.server.log.dir" path="server"/>
    <suffix value=".yyyyMMdd.'log'"/>
    ```
-->

- Q6. アクセスログの出力形式やローテーションの仕方を変更できますか？
  - A6. はい。アクセスログも他のログと同様に以下のようなことができます。
      - ファイル名や出力先を変更する
      - ログの出力形式を変更する
      - ローテーションしないようにする
      - ファイルサイズでローテーションする
      - 指定したファイル数を超えないように、バックアップファイルを削除する

# 最後に

他にもログに関するいろいろな設定があります。以下の参考資料に載せたWildFlyの公式ドキュメントなどが参考になると思います。

# 参考資料

 - [JBoss EAP を用いたロギング](https://access.redhat.com/documentation/ja-jp/red_hat_jboss_enterprise_application_platform/7.0/html/configuration_guide/logging_with_jboss_eap)
 - [WildFly 10 Documentation - Logging Configuration](https://docs.jboss.org/author/display/WFLY10/Logging+Configuration)
 - [Keycloak 日本語ドキュメント by OpenStandia](https://keycloak-documentation.openstandia.jp/)
 - [SlideShare - Single Sign On with Keycloak by 
Julien Pivottoさん](https://www.slideshare.net/roidelapluie/single-sign-on-with-keycloak)

<!--
https://lists.jboss.org/pipermail/keycloak-user/2017-February/009498.html

https://lists.jboss.org/pipermail/keycloak-dev/2017-March/009080.html
-->