LibertyによるWebサービスアプリ開発メモ: (4)ロギング

はじめに

Webサービス(REST)アプリを開発してLiberty上で動かすまでの流れについて、試したことを備忘録として記載していきます。
今回はロギングについて。

ログの仕組みは色々変遷があるようですが、トレンドとしてはSLF4J + Logbackが優勢のようなので、そいつを使ってみます。とりあえず一通り動かすところまで。

関連記事

LibertyによるWebサービスアプリ開発メモ: (1)環境構築
LibertyによるWebサービスアプリ開発メモ: (2)MavenプロジェクトによるJAX-RSアプリ開発
LibertyによるWebサービスアプリ開発メモ: (3)JPA経由でのDBアクセス
LibertyによるWebサービスアプリ開発メモ: (4)ロギング
LibertyによるWebサービスアプリ開発メモ: (5)JUnitによる単体テスト
LibertyによるWebサービスアプリ開発メモ: (6)Eclipse-GitHub連携

設定

以前の記事「LibertyによるWebサービスアプリ開発メモ: (2)MavenプロジェクトによるJAX-RSアプリ開発」で作成したMavenプロジェクトをベースにカスタマイズしてみます。
まずは当該プロジェクトのpom.xmlにて、SLF4J, Logback関連の依存関係を追加します。
以下の3つをセットで追加します。

pom.xml

...
		<!-- https://mvnrepository.com/artifact/org.slf4j/slf4j-api -->
		<dependency>
		    <groupId>org.slf4j</groupId>
		    <artifactId>slf4j-api</artifactId>
		    <version>1.7.25</version>
		</dependency>
		
		<!-- https://mvnrepository.com/artifact/ch.qos.logback/logback-classic -->
		<dependency>
		    <groupId>ch.qos.logback</groupId>
		    <artifactId>logback-classic</artifactId>
		    <version>1.2.3</version>
		</dependency>
		
		
		<!-- https://mvnrepository.com/artifact/ch.qos.logback/logback-core -->
		<dependency>
		    <groupId>ch.qos.logback</groupId>
		    <artifactId>logback-core</artifactId>
		    <version>1.2.3</version>
		</dependency>
...

pom.xmlを変更したら、プロジェクトを右クリック - [Maven] - [Update Project]を選択し、project configurationのアップデートを行っておきましょう。

基本形

ログのレベルや出力先の設定などはXMLファイルで制御することができますが、設定ファイル無しでもデフォルト構成でログ出力は行えるので、まずは一旦このままアプリから使ってみます。

アプリケーションからの利用

JAX-RS経由で呼び出されるクラス部分にロガーによる出力を行うコードを仕込んで見ます。
LoggerFactory.getLogger()でLoggerオブジェクトを取得して、Loggerのinfo()やdebug()などレベルごとのメソッドで出力させたい内容を指定します。

HelloWorldResource01.java

package com.ibm.jaxrs.sample;

import javax.ws.rs.DefaultValue;
import javax.ws.rs.GET;
import javax.ws.rs.Path;
import javax.ws.rs.Produces;
import javax.ws.rs.QueryParam;
import javax.ws.rs.core.Response;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.ibm.json.java.JSONObject;


@Path("/helloworld")
public class HelloWorldResource01 {

  Logger logger = LoggerFactory.getLogger(HelloWorldResource01.class);

  ...

  @GET
  @Path("/getQueryParam")
  @Produces("application/json")
  public Response getQueryParam(@DefaultValue("XXX") @QueryParam("name1") final String name1,
      @DefaultValue("YYY") @QueryParam("name2") final String name2) {

    logger.info("***getQueryParm***");
    logger.debug("LogTest: name1={}, name2={}", name1, name2);

    Response response = null;

    // String strData = "Hello " + name1 + " " + name2;
    // System.out.println(strData);

    response = Response.status(Response.Status.OK).entity(new JSONObject()).build();

    return response;
  }
}

上のdebug()メソッドの例で示しているように、プレースホルダ("{}"で示されている部分)が使用できます。後続の引数で与えた値がプレースホルダの位置に表示されることになります。
※ちなみに、logger.debug("LogTest: name1=" + name1 + ", name2=" + name2);というような書き方は避けるべきです。ロギングのレベルをdebugより低くしてログ出力を抑止したとしても、文字列連結の処理は動いてしまうので無駄なオーバーヘッドになってしまうからです。

稼働確認

このアプリをLibertyにデプロイして動かしてみましょう。
ロギングを実装したメソッドを呼び出すために以下のサービスを呼び出すと...
「http://localhost:9080/MavenLibertyTest01/rest/helloworld/getQueryParam」

Libertyのコンソールに以下のようなメッセージが出力されました！

xxx\usr\servers\server1\logs\messages.log

11:38:07.810 [LargeThreadPool-thread-31] INFO com.ibm.jaxrs.sample.HelloWorldResource01 - ***getQueryParm***
11:38:07.810 [LargeThreadPool-thread-31] DEBUG com.ibm.jaxrs.sample.HelloWorldResource01 - LogTest: name1=XXX, name2=YYY

応用編

スタックトレース

出力用メソッドの引数に例外オブジェクトを渡すとスタックトレースを出力できます。

 public Response getQueryParam(@DefaultValue("XXX") @QueryParam("name1") final String name1,
      @DefaultValue("YYY") @QueryParam("name2") final String name2) {

    logger.info("***getQueryParm***");
    logger.debug("LogTest: name1={}, name2={}", name1, name2);

    try {
      String aaa = null;
      aaa.length();
    } catch (Exception e) {
      logger.error("StackTraceTest: name1={}, name2={} / ", name1, name2, e);
    }

    Response response = null;

    response = Response.status(Response.Status.OK).entity(new JSONObject()).build();

    return response;
  }

xxx\usr\servers\server1\logs\messages.log

14:50:09.755 [Default Executor-thread-4] INFO com.ibm.jaxrs.sample.HelloWorldResource01 - ***getQueryParm***
14:50:09.755 [Default Executor-thread-4] DEBUG com.ibm.jaxrs.sample.HelloWorldResource01 - LogTest: name1=XXX, name2=YYY
14:50:09.755 [Default Executor-thread-4] ERROR com.ibm.jaxrs.sample.HelloWorldResource01 - StackTraceTest: name1=XXX, name2=YYY / 
java.lang.NullPointerException: null
	at com.ibm.jaxrs.sample.HelloWorldResource01.getQueryParam(HelloWorldResource01.java:38)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:632)
	at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.performInvocation(LibertyJaxRsInvoker.java:118)
	at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96)
	at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:252)
	at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:189)
	at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:423)
	at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:99)
	at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:61)
	at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:99)
	at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
	at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:124)
	at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:274)
	at com.ibm.ws.jaxrs20.endpoint.AbstractJaxRsWebEndpoint.invoke(AbstractJaxRsWebEndpoint.java:134)
	at com.ibm.websphere.jaxrs.server.IBMRestServlet.handleRequest(IBMRestServlet.java:149)
	at com.ibm.websphere.jaxrs.server.IBMRestServlet.doGet(IBMRestServlet.java:115)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
	at com.ibm.websphere.jaxrs.server.IBMRestServlet.service(IBMRestServlet.java:99)
	at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1290)
	at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:778)
	at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:475)
	at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:148)
	at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:94)
	at com.ibm.ws.security.jaspi.JaspiServletFilter.doFilter(JaspiServletFilter.java:57)
	at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:207)
	at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:91)
	at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:1021)
	at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1143)
	at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:82)
	at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:956)
	at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.run(DynamicVirtualHost.java:280)
	at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:967)
	at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:359)
	at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:318)
	at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:471)
	at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:405)
	at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:285)
	at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:256)
	at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:174)
	at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:83)
	at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:504)
	at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:574)
	at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:929)
	at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1018)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

設定ファイルのカスタマイズ

logback.xmlファイルをクラスパス配下に配置します。ここでは、src/main/resourcesフォルダを作って配置します。
ファイルの中身は、Logback - 第3章 logbackの設定 のsample0.xml

logback.xml

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <!-- encoders are assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>
  
  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

上のリンクの記述によると、上の設定内容は、設定ファイル無しのデフォルト構成と同じ動作になるとのことだが、ちょっと結果が違ってました。

xxx\usr\servers\server1\logs\messages.log

15:13:57.355 [Default Executor-thread-176] INFO  c.i.j.sample.HelloWorldResource01 - ***getQueryParm***
15:13:57.355 [Default Executor-thread-176] DEBUG c.i.j.sample.HelloWorldResource01 - LogTest: name1=XXX, name2=YYY
15:13:57.355 [Default Executor-thread-176] ERROR c.i.j.sample.HelloWorldResource01 - StackTraceTest: name1=XXX, name2=YYY / 
java.lang.NullPointerException: null
	at com.ibm.jaxrs.sample.HelloWorldResource01.getQueryParam(HelloWorldResource01.java:38)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...

で出力ログのフォーマットを指定していますが、今回使用しているロガーの名前が、%loggerの所で指定している桁数(36)を超えているのでクラス名のパッケージ部分が省略されて出力されているようです。以下のようにlogback.xmlので桁数指定の部分を削除してみると...

logback.xml

  ...
  <pattern>%d{HH:mm:ss.SSS} [%thread] %level %logger - %msg%n</pattern>
  ...

最初と同じように出力されました。

xxx\usr\servers\server1\logs\messages.log

15:29:38.130 [Default Executor-thread-343] INFO com.ibm.jaxrs.sample.HelloWorldResource01 - ***getQueryParm***
15:29:38.130 [Default Executor-thread-343] DEBUG com.ibm.jaxrs.sample.HelloWorldResource01 - LogTest: name1=XXX, name2=YYY
15:29:38.130 [Default Executor-thread-343] ERROR com.ibm.jaxrs.sample.HelloWorldResource01 - StackTraceTest: name1=XXX, name2=YYY / 
java.lang.NullPointerException: null
	at com.ibm.jaxrs.sample.HelloWorldResource01.getQueryParam(HelloWorldResource01.java:38)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

参考: Logback - 第6章 レイアウト

出力レベル変更

出力のレベルは TRACE < DEBUG < INFO < WARN < ERRORとなっているので、rootのlevelをINFOに変更してみると...

logback.xml

  ...
    <root level="INFO">
      <appender-ref ref="STDOUT" />
    </root>
  ...

INFO以下のレベルのDEBUGのメッセージは出力が抑止されます。

xxx\usr\servers\server1\logs\messages.log

15:35:59.603 [Default Executor-thread-451] INFO com.ibm.jaxrs.sample.HelloWorldResource01 - ***getQueryParm***
15:35:59.603 [Default Executor-thread-451] ERROR com.ibm.jaxrs.sample.HelloWorldResource01 - StackTraceTest: name1=XXX, name2=YYY / 
java.lang.NullPointerException: null
	at com.ibm.jaxrs.sample.HelloWorldResource01.getQueryParam(HelloWorldResource01.java:38)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

ロガーを指定して、ロガー毎にレベルの調整も可能です。
rootのレベルをDEBUGにして、特定のロガーを指定してそのロガーのレベルをERRORにしてみると、当該ロガーについてはINFO, DEBUGの出力が抑止されます。

logback.xml

  ...
  <logger name="com.ibm.jaxrs.sample.HelloWorldResource01" level="ERROR"/>
  
  <root level="DEBUG">
    <appender-ref ref="STDOUT" />
  </root
  ...

xxx\usr\servers\server1\logs\messages.log

15:46:16.691 [Default Executor-thread-523] ERROR com.ibm.jaxrs.sample.HelloWorldResource01 - StackTraceTest: name1=XXX, name2=YYY / 
java.lang.NullPointerException: null
	at com.ibm.jaxrs.sample.HelloWorldResource01.getQueryParam(HelloWorldResource01.java:38)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

あとは出力先やらフォーマットやらはこれをベースに適宜変更していく感じで。