ライブラリ調査で問題に遭遇したときに考えること

開発を行っていると必ず利用するライブラリを選定したり、検証したりする機会があると思います。

このような作業を行っていると、動かない、謎のエラーが出るという問題に直面することもあります。何度か経験していると勘でなんとなくわかってきますが、初心に返って私が考えていることを少し書いてみたいと思います。

説明するためにSpring Bootを使ったJavaプロジェクトでログの設定をしていたところ、突然起動しなくなった事例を取り上げます。

事象

Spring Boot + logback にてlogbackにJaninoEventEvaluatorを設定した場合に、./gradlew bootRun を実行するとスタックトレースも無く finished with non-zero exit value 1 と表示され、Spring Bootが起動しない。

環境

事象が発生した環境は次の構成です。

• macOS: Catalina verion 10.15.4
• AdoptOpenJDK: 1.8.0_252
• Spring Boot: 2.1.15.BUILD-SNAPSHOT

• build.gradle

  バージョンや利用ライブラリの部分のみ抜粋しました。

  plugins {
      id 'org.springframework.boot' version '2.1.15.BUILD-SNAPSHOT'
      id 'io.spring.dependency-management' version '1.0.9.RELEASE'
      id 'java'
  }
  dependencies {
      implementation "org.springframework.boot:spring-boot-starter-web"
      implementation "com.google.guava:guava:26.0-android"
  
      // logger
      implementation "org.slf4j:slf4j-api"
      implementation "org.slf4j:jul-to-slf4j"
      implementation "ch.qos.logback:logback-classic"
      implementation "ch.qos.logback.contrib:logback-json-classic:0.1.5"
      implementation "ch.qos.logback.contrib:logback-jackson:0.1.5"
      implementation "org.codehaus.janino:janino:3.1.2" // for log evaluator
  
      annotationProcessor 'org.projectlombok:lombok'
      testImplementation 'org.springframework.boot:spring-boot-starter-test'
  
  }

• logback-spring.xml

  logback公式の設定を元に作成しました。

  <?xml version="1.0"?>
  <configuration scan="true" scanPeriod="30 seconds">
  <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
      <resetJUL>true</resetJUL>
  </contextListener>
  
  <springProfile name="local">
      <property name="ApplicationName" value="metropolis-manta-environment"/>
  
      <!-- ======== Appenders ======== -->
      <appender name="GENERAL" class="ch.qos.logback.core.ConsoleAppender">
      <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
      <evaluator> <!-- defaults to type ch.qos.logback.classic.boolex.JaninoEventEvaluator -->
          <expression>return message.contains("billing");</expression>
      </evaluator>
      <OnMismatch>NEUTRAL</OnMismatch>
      <OnMatch>DENY</OnMatch>
      </filter>
      <encoder>
      <pattern>
          %-4relative [%thread] %-5level %logger - %msg%n
      </pattern>
      </encoder>
      </appender>
  
      <appender name="ASYNC_GENERAL" class="ch.qos.logback.classic.AsyncAppender">
      <appender-ref ref="GENERAL"/>
      </appender>
      <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
      <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
  </springProfile>
  
  <!-- ======== Loggers ======== -->
  <!-- Root Logger -->
  <springProfile name="local">
      <root level="INFO">
      <appender-ref ref="ASYNC_GENERAL"/>
      </root>
  </springProfile>
  </configuration>

調査

私はスタックトレースのような原因を特定する情報がまったく得られないような場合は、以下のような段階で原因解決できないか探ります。

1. 自分の作成したプログラムや設定でエラー発生箇所を特定し、記述誤りなどがないか確認する
2. 1. で解決しない場合は、実行環境(OSやJavaバージョンなど)に依存してエラーが発生していないか確認する
3. 2. で解決しない場合は、ライブラリの特定のバージョンでエラーが発生していないか確認する
4. 3. で解決しない場合は、実行環境やライブラリでIssueなどが報告されていないか確認する

最後まで確認しても解決できないときが稀にありますが、そういうときは諦めます。おそらく相性がとても悪いのでしょう。。。。

一段目

この段階では自分が原因である可能性を疑っているため、自分の作成したプログラムや設定ファイルをチェックします。そのときは次のような手順で確認していきます。問題は複数の要因で発生していることも多いため、1つの項目だけ変更して調査します。

1. エラーメッセージやスタックトレースがコンソールやログファイルに出力されていないか
2. ログレベルをDEBUGにして解決の糸口が出力されないか
3. 正常動作する時点まで、プログラムや設定の切り戻し(コメントアウトすることが多い)をおこない正常時の動作を確認する
4. 修正したプログラムや設定を1つずつ有効にする
5. エラーが再現するプログラムや設定の修正項目を特定する
6. 修正に誤りがないか確認し修正する

ここまでの手順で原因となる箇所が特定でき、構文誤りなどのミスであれば解決できます。

調査した結果

そこで地道にコメントアウトとアンコメントを繰り返して　logback-spring.xml の設定を検証したところ、 filter の evaluator を有効にすると起動しないことが判明しました。しかしこの設定は公式サイトからの転記のため間違っていない可能性が高いです。

そこで次の調査に進みます。

二段目

先の調査で、構文誤りなどの自分の記述誤りである可能性が低くなったため、実行環境要因を疑っていきます。

実行環境要因を調べる際は、変更が容易な部分から変更して調査しますが、手順は簡単です。ここでも問題は複数の要因で発生していることも多いため、実行環境の要因を1つずつ変更して調査します

1. 正常に動作するプログラムや動作が実行環境を変えて、正常となるか
2. エラーが発生するプログラムや動作が実行環境を変えて、正常となるか
3. 実行環境の要因を変えて、 1. から再度おこなう

ここまでの手順で正常とエラー発生が変化すれば実行環境の問題とわかるため、正常に動作するよう環境を整えれば解決できます。

調査した結果

今回は、 macOS と Java を実行環境として捉えます。

Javaの用にJVMなどの仕組みによりOSに依存しない(しにくい)場合は、OSを対象外とします。ただしJavaはリフレクションなどの低レイヤーを利用している場合、リリースベンダー(オラクル、AdoptOpenJDK、Amazon Correttoなど)のカスタマイズの影響を受ける可能性があります。

• AdoptOpenJDK 1.8.0 -> 起動しません

• AdoptOpenJDK 11.0.7 -> 起動しません

しかしJavaのバージョンを変えても変化しなかったため、次の調査に進みます。

三段目

ライブラリのバージョンを調査する際に利用しているライブラリをすべて調べるのは大変なため、次の手順で調査します。基本的にはエラー発生箇所に依存性・関連性が強いライブラリから弱いライブラリの順で、バージョンを変えながら試します。

1. エラーが発生している箇所で利用しているライブラリ
   1. マイナーバージョンを変えて、正常となるか
   2. メジャーバージョンを変えて、正常となるか
2. エラーが発生している箇所で利用しているライブラリと依存性・関連性が強いライブラリ
   1. マイナーバージョンを変えて、正常となるか
   2. メジャーバージョンを変えて、正常となるか

調査した結果

今回の場合は以下が関係性の強いライブラリTOP3です。

1. janino: 3.1.2
2. logback-classic: 1.2.3
3. Spring Boot: 2.1.15.BUILD-SNAPSHOT

はじめにjaninoのバージョンを変えて検証したところ、マイナーバージョンの変更で動作が変わりました。

• janino 3.1.2 -> 起動しません

• janino 3.0.16 -> 起動します！

これで無事に原因と対処方法が見つかりました。

まとめ

今回は三段目まで調査したところで原因がわかりました。古めのSpring Bootと最新のjaninoの組み合わせでは、filter の evaluator で異常が発生している可能性の高いことが判明しました。もし今回の事象が最新のSpring Bootで発生する場合であれば、原因のコミットを見つけるといった詳細な調査をおこないPull Requestを送るなどが有益ですが、今回は古めのバージョンのためココまでの調査とします。

原因がわかれば単純なことですが、今回のようにログにスタックトレースなどもなく手がかりが exit code のみと言うときは、問題解決に思わぬ時間をとられたりします。

そのためライブラリの組み合わせとバージョン選択にはいつも頭を悩まされます。

余談

• 公式サイトから転記であっても使用しているバージョン違いなどで動作しないことがあるので、注意して確認します。
• 人間が作ったものなので公式サイトでも誤記で動作しないこともあります。IssueやPull Requestを送りましょう。
• Spring Boot 2.2.4.RELEASE では janino 3.1.2 が動作しました。