LoginSignup
2
2

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 5 years have passed since last update.

@neriudon

ログが出力されたかをDBを介してプログラムで確認する

Posted at

開発環境

  • Java 1.8.0
  • Spring Boot 2.0.1.RELEASE
  • Spring Framework 5.0.5.RELEASE
  • Logback 1.2.3
  • SLF4J 2.10.0
  • Apache Commons DBCP 2.2.0
  • H2 1.4.197

はじめに

エラーの原因を突き止めたり、性能が出ているかを確認するために有用なログですが、

  • 特定の条件下で出力されるか。
  • ログのフォーマットが正しいか。

をどのように確認していますか？
もちろん目視で確認できなくはないですが、プログラムでログを出力している以上、プログラムでログの検証もしたいですよね。
この記事では以下のアプローチでログの検証をおこないます。

  1. SLF4Jを介してLogbackでデータベースにログ出力
  2. JDBCTemplateでログをデータベースから取得
  3. アサーション！

※ログ出力にフォーカスを当てているので、それ以外の実装は適当です。

サンプルアプリ

このサンプルで想定するログ

InterceptorやAOPを活用してRest APIの応答時間・業務処理時間を計測した性能ログを出力し、出力されたログのフォーマットが正しいことを検証します。ログは以下の要件を満たします。

  • ログレベルはTRACEとします。
  • 応答・処理時間の単位はマイクロ秒とします。
  • Rest APIの応答時間と業務処理時間を見分けられるようにします。

ログの設定

クラスパス上にlogback-test.xmlを作成しログ出力方法やフォーマットの設定をします。
LogbackのDBAppenderを使うことで、データベースにログ出力することができます。
このサンプルではH2を使うので、<dataSource>タグ内でH2用の設定をしています。
※コンソール出力のAppenderは割愛します。

logback-test.xml
  <appender name="PERFORMANCE_LOG_FILE"
    class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${app.log.dir:-log}/gw-lib_performance.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${app.log.dir:-log}/performance-%d{yyyyMMdd}.log
      </fileNamePattern>
      <maxHistory>7</maxHistory>
    </rollingPolicy>
    <encoder>
      <charset>UTF-8</charset>
      <pattern><![CDATA[%d{yyyy-MM-dd HH:mm:ss.SSS}\t%msg%n]]></pattern>
    </encoder>
  </appender>

  <appender name="DB" class="ch.qos.logback.classic.db.DBAppender">
    <connectionSource class="ch.qos.logback.core.db.DataSourceConnectionSource">
      <dataSource class="org.apache.commons.dbcp2.BasicDataSource">
        <driverClassName>org.h2.Driver</driverClassName>
        <url>jdbc:h2:mem:testdb</url>
        <username>sa</username>
        <password></password>
      </dataSource>
    </connectionSource>
  </appender> 

  <logger name="PerformanceLog" additivity="false">
    <level value="trace" />
    <appender-ref ref="STDOUT" />
    <appender-ref ref="PERFORMANCE_LOG_FILE" />
    <appender-ref ref="DB" />
  </logger>

性能ログクラスの作成

SLF4JのLoggerを直接使用してもいいのですが、個人的に引数のバリエーションが多すぎて混乱するのと、ログレベルをTRACEに限定しているので、SLF4JのLoggerをラップした性能ログクラスを作成します。

PerformanceLogger.java
public class PerformanceLogger {

  private static final PerformanceLogger instance = new PerformanceLogger();
  private static final Logger logger = LoggerFactory.getLogger("PerformanceLog");
  private static final String TOTAL_PROCESSING_TIME = "TOTAL";
  private static final String METHOD_PROCESSING_TIME = "METHOD";
  private final int nanosToMicros = 1000;

  private PerformanceLogger() {}

  public static PerformanceLogger getLog() {
    return instance;
  }

  private void trace(String format, Object... args) {
    logger.trace(format, args);
  }
  // 応答時間のログには"TOTAL"という文字列と応答時間を出力
  public void trace(long startNanoTime, long endNanoTime) {
    trace("{}\t{}", TOTAL_PROCESSING_TIME, (endNanoTime - startNanoTime) / nanosToMicros);
  }

  // 業務処理時間のログには"METHOD"という文字列と処理時間とメソッドの詳細を出力
  public void trace(long startNanoTime, long endNanoTime, MethodSignature signature) {
    trace("{}\t{}\t{} {}.{}{}", METHOD_PROCESSING_TIME,
        (endNanoTime - startNanoTime) / nanosToMicros, signature.getReturnType().getSimpleName(),
        signature.getMethod().getDeclaringClass().getName(), signature.getMethod().getName(),
        Arrays.stream(signature.getParameterTypes()).map(c -> c.getSimpleName())
            .collect(Collectors.joining(",", "(", ")")));
  }
}

Handlerメソッドの呼び出し前後に応答時間計測処理を入れる

HandlerInterceptorAdapterを継承したクラスを作成し処理開始時間の取得とログ出力を追加するだけです。

PerformanceLogInterceptor.java
public class PerformanceLogInterceptor extends HandlerInterceptorAdapter {

  private static final PerformanceLogger logger = PerformanceLogger.getLog();

  private long startNanoTime;

  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
      throws Exception {
    // 処理開始時間を取得
    startNanoTime = System.nanoTime();
    return super.preHandle(request, response, handler);
  }

  @Override
  public void afterCompletion(HttpServletRequest request, HttpServletResponse response,
      Object handler, Exception ex) throws Exception {
    // ログ出力
    logger.trace(startNanoTime, System.nanoTime());
  }
}

業務処理の前後に処理時間計測処理を入れる

（特に書くことは）ないです。

ArroundMethodLoggingAspect.java
public class ArroundMethodLoggingAspect {

  private static final PerformanceLogger logger = PerformanceLogger.getLog();

  public Object log(ProceedingJoinPoint joinPoint) throws Throwable {
    // 処理開始時間取得
    long startTime = System.nanoTime();
    try {
      // 業務処理
      return joinPoint.proceed();
    } finally {
      // ログ出力
      logger.trace(startTime, System.nanoTime(), (MethodSignature) joinPoint.getSignature());
    }
  }
}

ビーン定義（ログ出力）

↑で作成したクラスを適用します。
以下の設定例では、インターセプタは/sampleというパスにリクエストが来た場合に、AOPはXXXServiceImplというクラスのメソッドが呼ばれた場合に有効になります。

xontext.xml
  <!-- Interceptor -->
  <mvc:interceptors>
    <mvc:interceptor>
      <mvc:mapping path="/sample" />
      <bean class="com.neriudon.example.app.interceptor.PerformanceLogInterceptor" />
    </mvc:interceptor>
  </mvc:interceptors>

  <!-- AOP -->
  <aop:aspectj-autoproxy />

  <aop:config>
    <aop:aspect ref="arroundMethodLoggingAspect">
      <aop:around pointcut="execution(* *..*ServiceImpl.*(..))" method="log" />
    </aop:aspect>
  </aop:config>

  <bean id="arroundMethodLoggingAspect"
    class="com.neriudon.example.utils.log.ArroundMethodLoggingAspect" />

データベースの準備

嬉しいことに、LogbackがH2にログ出力する際のテーブル定義は公開されているので、これを使います。

h2.sql

ビーン定義（データベース）

<jdbc:embedded-database>タグのtypeにH2を指定し、データベース名と読み込むSQLファイルを設定します。
ついでにテストで使うJdbcTemplateもビーン定義しておきます。

context.xml
  <!-- DB -->
  <jdbc:embedded-database id="dataSource" type="H2" database-name="testdb">
    <jdbc:script location="classpath:/database/h2.sql" />
  </jdbc:embedded-database>

  <bean class="org.springframework.jdbc.core.JdbcTemplate">
    <constructor-arg ref="dataSource" />
  </bean>

※ControllerとServiceは適当に作ってください:smile:。

サンプルの実行例

実行すると↓のようなログが出力されます。
サンプルの実装ではリクエスト受信→業務処理→レスポンス返却の順で処理されるので、業務処理時間→応答時間の順に出力されます。

log.txt
2018-04-10 22:42:20.371	METHOD	8223	String com.neriudon.example.domain.service.SampleServiceImpl.echo(String)
2018-04-10 22:42:20.419	TOTAL	124786

ログの検証

この記事で一番重要なところだと思うのですが、MockMVCでリクエストを送り処理が終わった後に、JdbcTemplateでログを取得すれば、後は自由に検証できます:wink:。
以下はログ出力された回数とログの種類（応答時間か業務処理か）を検証する例です。

ogAssertionSampleApplicationTests.java
@RunWith(SpringRunner.class)
@SpringBootTest
@WebAppConfiguration
public class LogAssertionSampleApplicationTests {

  private static final String BODY = "test";
  private static final String PATH_WITH_INTERCEPTOR = "/sample";
  private static final String LOG_KIND_REQUEST_AND_RESPONSE = "TOTAL";
  private static final String LOG_KIND_METHOD = "METHOD";

  @Autowired
  WebApplicationContext webApplicationContext;

  @Autowired
  JdbcTemplate jdbcTemplate;

  MockMvc mockMvc;

  @Before
  public void setup() {
    mockMvc = MockMvcBuilders.webAppContextSetup(webApplicationContext).alwaysDo(log())
        .addDispatcherServletCustomizer(customizer -> {
          customizer.setThrowExceptionIfNoHandlerFound(true);
        }).build();
  }

  @Test
  public void outputPerformanceLogTest() throws Exception {
    mockMvc.perform(post(PATH_WITH_INTERCEPTOR).content(BODY)).andExpect(status().isOk())
        .andExpect(content().string(BODY));

    List<String> loggingEvents = jdbcTemplate.queryForList(
        "SELECT formatted_message FROM logging_event ORDER BY timestmp", String.class);

    if (loggingEvents.size() != 2) {
      fail();
    }
    assertThat(String.valueOf(logginEvents.get(0)), containsString(LOG_KIND_METHOD));
    assertThat(String.valueOf(logginEvents.get(1)), containsString(LOG_KIND_REQUEST_AND_RESPONSE));
  }
}

サンプルアプリ

簡素ではありますが、この記事向けに作成したサンプルをGitHub上に公開しています。
log_assertion_sample

投稿に至った経緯

ログ出力機能を実装しているときに、出力されたことを確認するにはどうしたらいいんだろう:thinking:と思い、試行錯誤した結果をまとめました。
他に良い方法があればぜひ教えてください:yum:。

2
2
2

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
2
2

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?