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

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

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

はじめに

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

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

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

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

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

サーバーログ

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

• logging.properties
• standalone.xml

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

※：Keycloakには単独で起動するスタンドアローン・モードの他にクラスター構成で起動するスタンドアローン・クラスター・モードやドメイン・モードなどがあり、モードにより設定ファイルのファイル名が異なります。スタンドアローン・モードの設定ファイルはstandalone.xmlです。詳細については、ガイドを参照してください。

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

前述したとおり、standalone.xmlが実質的なKeycloakのログ出力を制御する設定ファイルになります。バージョン6.0.1におけるstandalone.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に変更すればいいです。

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

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

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

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

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

WildFlyのloggingサブシステムが起動するまでのログの設定はlogging.propertiesに依存します。バージョン6.0.1のlogging.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などに変更すればいいです。この場合、コンソールのログ出力量は増えずに、ファイルのログ出力量が増えます。

# 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が上書きされると、それ以降は変更したログレベルが適用されることになります。

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

アクセスログ

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

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

<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に登録するのが一般的です。管理コンソールでボタンをクリックすれば監査イベント機能が有効になりますが、これについては、ドキュメントに記載があるので、ここでは監査ログをファイルに出力する方法について説明します。

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

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形式でファイルに出力することもできます。

<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属性にパッケージ名を指定した定義があります。例えば、デフォルトの設定には次のような定義がありますが、

    <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/）の監査ログです。

    <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"に変更してみると、

    <!-- <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ディレクトリーに出力されます。

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

最後に

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

参考資料

• JBoss EAP を用いたロギング
• WildFly 10 Documentation - Logging Configuration
• Keycloak 日本語ドキュメント by OpenStandia
• SlideShare - Single Sign On with Keycloak by
  Julien Pivottoさん