kagamihogeの日記

kagamihogeの日記です。

WildFly 10でLogback使おうとして挫折した話

Java WildFly

まとめ

WildFly 10でLogback使うやり方がわからなかったのと、ログの要件がそんなにきつくなかったのでPer-deployment Loggingを使うことにした。

やったこと

pom.xmlにLogbackの依存性を追加する。

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.3</version>
</dependency>

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.25</version>
</dependency>

main/resources/logback.xmlを適当に作成する。

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>logback - %d{HH:mm:ss.SSS} %-5level %logger{10} %msg%n</pattern>
    </encoder>
  </appender>

  <root level="TRACE">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

適当なテスト用のcontrollerをspring-mvcで作っておく。

@RestController
public class HogeController {
    private Logger logger = LoggerFactory.getLogger(HogeController.class);
    
    @RequestMapping("/i")
    public String index() {
        logger.debug("debug");
        logger.info("info");
        logger.error("error");
        
        return "hoge";
    }
}

この段階ではまだlogbackでのログ出力はできない。

jboss - Override logging in WildFly - Stack Overflow や logging - WIldfly 10 + logback - Stack Overflow にあるように、WebContent/META-INF/jboss-deployment-structure.xml を作成する。wildfly側のloggingのsubsytemをdisableにする必要がある、とのこと。

<jboss-deployment-structure>
  <deployment>
     <!-- exclude-subsystem prevents a subsystems deployment unit processors running on a deployment -->
     <!-- which gives basically the same effect as removing the subsystem, but it only affects single deployment -->
     <exclude-subsystems>
        <subsystem name="logging" />
    </exclude-subsystems>
  </deployment>
</jboss-deployment-structure>

しかしEclipse上のコンソールログがちょっとおかしい。

22:27:27,264 INFO  [stdout] (default task-2) logback - 22:27:27.262 DEBUG k.w.c.HogeController debug

22:27:27,265 INFO  [stdout] (default task-2) logback - 22:27:27.265 INFO  k.w.c.HogeController info

22:27:27,265 INFO  [stdout] (default task-2) logback - 22:27:27.265 ERROR k.w.c.HogeController error

こんな感じに余計な改行が一つ入ってしまっている。

java - Wildfly and logback with blank lines - Stack Overflow と、これを読む限り、wildflyがSystem.outをラップするために改行がいっこ余計に入る、ということらしい。

じゃあってんで、logback.xmlから改行を取り除くとフラッシュが起きなくなるからかログが出なくなる。<immediateFlush>false</immediateFlush>も意味なし（デフォルトtrueだし）

というわけでstandalone.xmlのフォーマットから改行を取り除いてみる。

            <formatter name="COLOR-PATTERN">
                <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e"/>
            </formatter>

これでログに余計な改行が無くなるが、今度はwildflyのログの一部（COLOR-PATTERNを使うものと思うが）が改行されなくなる。

logbackが出力するコンソールやファイルへのログは正常に出るんでこれで妥協できなくもないが…

そこでちょっと待てよとlogback.xmlのpatternの末尾を%nではなく\nに変えてみる。

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>logback - %d{HH:mm:ss.SSS} %-5level %logger{10} %msg\n</pattern>
    </encoder>
  </appender>

22:51:45,733 INFO  [stdout] (default task-2) logback - 22:51:45.730 DEBUG k.w.c.HogeController debug
22:51:45,734 INFO  [stdout] (default task-2) logback - 22:51:45.733 INFO  k.w.c.HogeController info
22:51:45,734 INFO  [stdout] (default task-2) logback - 22:51:45.734 ERROR k.w.c.HogeController error

余計な改行が無くなった。ただしwindowsでしか動かしてないので、プラットフォームや環境が変わると動くかどうかはわからない。つまり場当たり的対処でしかない……

そういうわけで。WildFlyのPer-deployment Logging使っておけば良いのでは？　という結論になった。この機能はlog4j.xmlとか特定の名前のログ設定ファイルをwarなどに含めておくと、その設定ファイルを使用してwildflyがログ出力してくれるもの。ロギングのライブラリの依存性をwarに含める必要が無く、基本的にはslf4j-apiをprovidedで入れるだけ。

ログの要件的にはこれで十分だったんで、まぁいっかとこれで妥協することにした。

WildFly 10のドキュメントのLogging Configurationを読んだ

WildFly Java テキトー翻訳

https://docs.jboss.org/author/display/WFLY10/Logging+Configuration を読んだ。

WildFly 10が持ってるログのとこ良く分からんなーという感じだったので読んだ。

Logging Configuration

Overview

全体的なサーバのログ設定はlogging subsytemで指定します。logging subsytemは4つの構成要素があり、handler, logger, root logger（ログカテゴリ）, profileがあります。loggerはhandler（もしくはその組み合わせ）を参照します。hadlerはログフォーマットと出力を宣言します。

<subsystem xmlns="urn:jboss:domain:logging:3.0">
   <console-handler name="CONSOLE" autoflush="true">
       <level name="DEBUG"/>
       <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"/>
   </periodic-rotating-file-handler>
   <logger category="com.arjuna">
       <level name="WARN"/>
   </logger>
   [...]
   <root-logger>
       <level name="DEBUG"/>
       <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>

Attributes

ルート要素には二つの属性add-logging-api-dependenciesとuse-deployment-logging-configがあります。

add-logging-api-dependencies

add-logging-api-dependenciesはデプロイ対象物に暗黙的なロギングAPIの依存性をコンテナが追加するかどうかを制御します。デフォルトのtrueの場合はすべての暗黙的なロギングAPIの依存性が追加されます。falseの場合は追加されません。

use-deployment-logging-config

use-deployment-logging-configはデプロイ対象物がper-deployment loggingのスキャン対象にするかどうかを制御します。デフォルトのtrueの場合はper-deployment loggingは有効化されます。falseの場合は無効化されます。

Per-deployment Logging

Per-deployment loggingを使うと、デプロイ対象物にログ設定ファイルを追加するとその設定ファイルに従ったロギングが行われます。EARでは設定ファイルはMETA-INFディレクトリに配置します。WARやJARではMETA-INFかWEB-INF/classesに置きます。

以下の設定ファイルが使用可能です。

なおuse-deployment-logging-config属性をfalseに変更することでこの機能を無効化できます。

Logging Profiles

Logging profilesはlogging subsystemsを追加する感じのものです。個々のLogging profilesは上述の四要素のうちhandler, logger, root loggerの三つで構成されます。

デプロイ対象物にはmanifest経由でlogging profileを割り当てられます。MANIFEST.MFファイルにLogging-Profileエントリを追加してその値にlogging profileのidを指定します。/subsystem=logging/logging-profile=ejbsで定義したlogging profileはMANIFEST.MFで以下のように指定します。

Manifest-Version: 1.0
Logging-Profile: ejbs

logging profileは複数のデプロイ対象物で指定可能です。また、logging profileを使うことで実行時に設定を変更可能になります。これはper-deployment loggingにはない利点で、ログ設定の変更を反映するのに再デプロイが不要です。

Default Log File Locations

Managed Domain

managed domainでは二種類のログファイルが存在し、Controllerとserver logsがあります。controllerコンポーネントは全体的なドメインを管理します。このコンポーネントはサーバインスタンスのstart/stopとドメイン全体のマネージド操作実行を担当します。Server logsには特定のサーバインスタンスのログ情報が含まれます。これらのログは稼働中のサーバとホストに配置されます。

説明を簡単にするためマネージドドメインのデフォルトのセットアップを見ます。この場合ドメインコントローラーコンポーネントとサーバは両方とも同一ホスト上に存在します。

Process Log File
Host Controller ./domain/log/host-controller.log
Process Controller ./domain/log/process-controller.log
“Server One” ./domain/servers/server-one/log/server.log
“Server Two” ./domain/servers/server-two/log/server.log
“Server Three” ./domain/servers/server-three/log/server.log

Standalone Server

standaloneサーバのデフォルトのログファイルはディストリビューションのlogディレクトリにあります。

Process Log File
Server ./standalone/log/server.log

Filter Expressions

Filter Type Expression Description Parameter(s) Examples
accept accept すべてのログメッセージを許容 なし accept
deny deny すべてのログメッセージを拒否 なし deny
not not(filterExpression) 引数としてフィルタを取りその戻り値を反転 引数に一つのフィルタを取る not(match(“JBAS”))
all all(filterExpressions) チェーンの複数フィルタから成るフィルタ。あるフィルタがunloggableなログメッセージを検出する場合、そのメッセージはログ出力されず、それ以降のフィルタはチェックされません。 引数にフィルタリストのカンマ区切りを取る all(match(“JBAS”), match(“WELD”))
any any(filterExpressions) チェーンの複数フィルタから成るフィルタ。あるフィルタがログ出力可能なメッセージを検出する場合、そのメッセージはログ出力され、それ以降のフィルタはチェックされません。 引数にフィルタリストのカンマ区切りを取る any(match(“JBAS”), match(“WELD”))
levelChange levelChange(level) ログレコードを別のレベルに変更するフィルタ 引数にレベルの文字列を一つ取る levelChange(WARN)
levels levels(levels) リストで示すレベルのログメッセージを含むフィルタ。 引数にレベルのカンマ区切りのリストを取る levels(DEBUG, INFO, WARN, ERROR)
levelRange levelRange([minLevel,maxLevel]) あるレベル範囲内のログを出力するフィルタ 最小レベルを"[“、最大レベルを”]“で示すフィルター式です。反対に”(“と”)“はそのレベルを含みません。式の最初の引数が最小レベルで、二つ目が最大レベルです。 最小レベルはERROR未満で最大レベルはDEBUGより大きい。

levelRange(ERROR, DEBUG)

最小レベルはERROR以下で最大レベルはDEBUGより大きい。

levelRange[ERROR, DEBUG)

最小レベルはERROR以下で最大レベルはINFO以上。

levelRange[ERROR, INFO]
match match(“pattern”) 正規表現ベースのフィルタ。パターンマッチには未フォーマットの生メッセージが使われます。 この式は引数に正規表現を取る。 match(“JBAS\d+”)
substitute substitute(“pattern”, “replacement value”) パターンに最初にマッチする箇所をreplacementの値で置換するフィルタ。 最初の引数がパターンで次が置換するテキスト substitute(“JBAS”, “EAP”)
substituteAll substituteAll(“pattern”, “replacement value”) パターンにマッチするすべての箇所をreplacementの値で置換するフィルタ。 最初の引数がパターンで次が置換するテキスト substituteAll(“JBAS”, “EAP”)

List Log Files and Reading Log Files

ログファイルは管理操作で参照や一覧表示ができます。参照可能なログファイルは意図的に制限されており、jboss.server.log.dirに存在するファイルで既知のファイルハンドラを関連付けているファイルに限られます。既知のファイルハンドラの種類はfile-handler, periodic-rotating-file-handle, size-rotating-file-handlerです。管理操作はstandaloneとdomainモードの両方で有効です。

List Log Files

logging subsystemにはログファイルを一覧表示するlog-fileがあります。これにはsubsystem rootのリソースとlogging-profileのリソースは含みません。*1

CLI command and output

[standalone@localhost:9990 /] /subsystem=logging:read-children-names(child-type=log-file)
{
    "outcome" => "success",
    "result" => [
        "server.log",
        "server.log.2014-02-12",
        "server.log.2014-02-13"
    ]
}

Read Log File

read-log-fileオペレーションはlog-fileリソースに対して使用可能です。このオペレーションには4つのオプションパラメータがあります。

Name Description
encoding 読み込むファイルのエンコーディング
lines ファイルの行数。-1はすべて読み込む
skip 読み込む前にスキップする行数
tail trueでファイルの終端から、falseで開始から読み込む

CLI command and output

[standalone@localhost:9990 /] /subsystem=logging/log-file=server.log:read-log-file
{
    "outcome" => "success",
    "result" => [
        "2014-02-14 14:16:48,781 INFO  [org.jboss.as.server.deployment.scanner] (MSC service thread 1-11) JBAS015012: Started FileSystemDeploymentService for directory /home/jperkins/servers/wildfly-8.0.0.Final/standalone/deployments",
        "2014-02-14 14:16:48,782 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-8) JBAS010400: Bound data source [java:jboss/myDs]",
        "2014-02-14 14:16:48,782 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-15) JBAS010400: Bound data source [java:jboss/datasources/ExampleDS]",
        "2014-02-14 14:16:48,786 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-9) JBAS015876: Starting deployment of \"simple-servlet.war\" (runtime-name: \"simple-servlet.war\")",
        "2014-02-14 14:16:48,978 INFO  [org.jboss.ws.common.management] (MSC service thread 1-10) JBWS022052: Starting JBoss Web Services - Stack CXF Server 4.2.3.Final",
        "2014-02-14 14:16:49,160 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-16) JBAS017534: Registered web context: /simple-servlet",
        "2014-02-14 14:16:49,189 INFO  [org.jboss.as.server] (Controller Boot Thread) JBAS018559: Deployed \"simple-servlet.war\" (runtime-name : \"simple-servlet.war\")",
        "2014-02-14 14:16:49,224 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015961: Http management interface listening on http://127.0.0.1:9990/management",
        "2014-02-14 14:16:49,224 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015951: Admin console listening on http://127.0.0.1:9990",
        "2014-02-14 14:16:49,225 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015874: WildFly 8.0.0.Final \"WildFly\" started in 1906ms - Started 258 of 312 services (90 services are lazy, passive or on-demand)"
    ]
}

FAQ

Why is there a logging.properties file?

configurationディレクトリのlogging.propertiesの存在をご存知かもしれません。サーバ起動時にlogging subsystemが開始するまではこれがロギングの設定になります。もしlogging subsystemを設定で含めない場合、このファイルがサーバ全体のロギング設定として振る舞います。

logging.propertiesファイルはブート時に上書きされ、変更箇所はlogging subsystemに反映されます。ファイルに加えられた変更は永続化されません。XML configurationもしくは管理操作で加えられた変更はlogging.propertiesに永続化されて次回のブート時に使用されます。

*1:The logging subsystem has a log-file resource off the subsystem root resource and off each logging-profile resource to list each log file. が原文。二回出てくるoffのあたりがちょっと訳に自信が無い。

WildFlyでSpringのJTA設定

Java Oracle Spring PostgreSQL WildFly

JTAの実体はWildFlyを使用してSpringの設定を行う。

環境

事前準備

WildFlyにOracleとPostgreSQLのXAデータソースを作成しておく。

pg_hba.confにmax_prepared_transactionsのコメントアウトを外してとりあえず20にしておく。

max_prepared_transactions = 20

これを設定しておかないと以下のようなエラーになる。

Caused by: org.postgresql.util.PSQLException: ERROR: prepared transactions are disabled
  ヒント: Set max_prepared_transactions to a nonzero value.

コード

動作確認用のspring-mvcとspring-jdbcをpom.xmlに入れる。

<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-webmvc</artifactId>
    <version>4.3.8.RELEASE</version>
</dependency>
<dependency>
    <groupId>javax.servlet</groupId>
    <artifactId>javax.servlet-api</artifactId>
    <version>3.1.0</version>
</dependency>
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-jdbc</artifactId>
    <version>4.3.8.RELEASE</version>
</dependency>

configurationを作る。特にこれといって何の変哲もなく、JTA固有の設定項目としてはtransactionManagerにJtaTransactionManagerを使用している程度。

@Configuration
@EnableTransactionManagement
@ComponentScan(basePackages={"kagamihoge.springjtasample"})
public class SpringJtaConfig {
    
    @Bean
    public DataSource postgresqlDataSource() {
        JndiDataSourceLookup l = new JndiDataSourceLookup();
        return l.getDataSource("java:/PostgresXADS");
    }
    
    @Bean
    public DataSource oracleDataSource() {
        JndiDataSourceLookup l = new JndiDataSourceLookup();
        return l.getDataSource("java:/XAOracleDS");
    }
    
    @Bean
    public PlatformTransactionManager transactionManager() {
        return new JtaTransactionManager();
    }
    
    @Bean
    public JdbcTemplate postgresqlJdbcTemplate() {
        return new JdbcTemplate(postgresqlDataSource());
    }
    
    @Bean
    public JdbcTemplate oracleJdbcTemplate() {
        return new JdbcTemplate(oracleDataSource());
    }
}

configuration以降はほとんど今まで通りのコードとやることは変わらない。

JdbcTemplateで適当な更新SQLを二つのRDBMSに対して実行してみる。

@Component
public class SampleComponent {
    
    @Autowired
    private JdbcTemplate postgresqlJdbcTemplate;
    
    @Autowired
    private JdbcTemplate oracleJdbcTemplate;
    
    @Transactional
    public void execute() {
        int i1 = oracleJdbcTemplate.queryForObject("select 1 from dual", Integer.class);
        int i2 = postgresqlJdbcTemplate.queryForObject("select 1", Integer.class);
        System.out.println(i1 + " " + i2);
        
        int j1 = oracleJdbcTemplate.update("insert into t1(c1) values (1)");
        int j2 = postgresqlJdbcTemplate.update("insert into t1(c1) values (1)");
        System.out.println(j1 + " " + j2);
    }
    
    @Transactional
    public void executeAndRollback() {
        int j1 = oracleJdbcTemplate.update("insert into t1(c1) values (1)");
        int j2 = postgresqlJdbcTemplate.update("insert into t1(c1) values (1)");
        
        throw new RuntimeException();
    }
}

これまで通り、@Transactionalアノテーションをつけておけばメソッド実行後にコミットされる。適当な例外をスローすればロールバックが行われる。

メモ

JdbcTemplateは特に何もしなくても動作するが、ORマッパーのライブラリによってはデータソースをTransactionAwareDataSourceProxyでラップする必要がある。