はじめに
私が最近作るアプリは、Skinny Frameworkを使用して、warに固めてTomcatで動作させてます。
Tomcat...古くから触っているからでしょうか、えも言われぬ安心感があります。
Tomcat9が出ている昨今、Tomcat8もきちんと触ってみないといかんよな、ということで遅ればせながらTomcat8で動かしてみようと思った次第です。
まずは、Tomcat8 + OpenJDK8上に固めたwarをデプロイします。うん、普通に動くじゃないか。さすがTomcat。安心感パネェ。
動作自体には問題は特に無さそうでした。そう、ログファイルを見るまでは。
「あれ、アプリのログファイルが出ていない」
logback.xmlの設定をdebug以上記録するようにした上でアクセスログをdebugレベルで書いていたのですが、指定したディレクトリにログファイル自体が存在しません。
どんなにアクセスしても一向にファイルが書き込まれることはありませんでした...。
試しにDBを止めてExceptionのログがどうなるか確認してみました。
指定したディレクトリは空のままです。
代わりに、catalina.out に書かれていました。ちがう、そこじゃない。
logback.xmlが読み込まれていない
アプリはTomcat7上では動作しており、ログも出力されています。
logback.xmlは -Dlogback.configurationFile オプションで指定する方式です。
WEB-INF/classesにもlogback.xmlがあって、どちらも読まれていないというのもおかしい。
後、違うと言えば、Skinny Frameworkのバージョンを最新(2.0.6 → 2.1.2)にしたことでしょうか。
でも、そもそもの動きを変えるとも思えないし...そういえば、slf4jのバージョンも上がってたなぁ...
組み込みJettyではlogback.xmlは読み込まれているようにも見えます。
Skinny Framework関連が悪さをしてるとも思えません。
Oracleの奴じゃないからだめなんじゃね？とか、Tomcat止めてJettyにしようかとか、設定ファイルをGroovyにしなきゃだめなんじゃね？、とかいろいろ考えられましたが、まずは心を落ち着かせて、コンソールに出力されたログを見てみることにしました。
起動時のコンソールに出ていたのは、何と...
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/usr/local/tomcat/8.0.35/webapps/ROOT/WEB-INF/lib/slf4j-simple-1.7.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/usr/local/tomcat/8.0.35/webapps/ROOT/WEB-INF/lib/logback-classic-1.1.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.SimpleLoggerFactory]
今まで気にしていませんでしたが、出てましたねー。
org.slf4j.impl.StaticLoggerBinder
が被ってるよ、というメッセージでしたが、ずっとスルーしてました。
ちなみに思い通りの振る舞いをしていた(と思っていた)、Tomcat7+OpenJDK8の環境でも出てました。
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/usr/local/tomcat/7.0.69/webapps/ROOT/WEB-INF/lib/logback-classic-1.1.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/usr/local/tomcat/7.0.69/webapps/ROOT/WEB-INF/lib/slf4j-simple-1.7.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
何かこれっぽいな、と経験年数だけは無駄に重ねてきた開発者の勘的なものが警告を鳴らしてきます。
犯人は誰だ？
ログから、
- logback-classic-1.1.7.jar
- slf4j-simple-1.7.7.jar
のjarに被ってるclassがあるよ、と読み取れたのですが、ふと疑問が浮かびます。
あれ？slf4j-simple？使ってたっけな？
Build.scalaには書いた記憶がありません。
ここから犯人探しの旅が始まります。
(孫依存jarってIntelliJ使って簡単に見つけられないもんなんですかね？今回は目で確認して回りました...)
犯人は、postgresql-9.4-1200-jdbc41、貴方だ！
なんやかんやあって、slf4j-simpleに依存していたのは、あろうことかPostgresのJDBCドライバだと突き止めました。
あー、Postgres使っちゃダメだったか...
冗談はさておき、依存関係を断ち切ります。sbt(SkinnyFrameworkのBuild.scala)では、
libraryDependencies ++= Seq(
︙
"org.postgresql" % "postgresql" % "9.4-1200-jdbc41",
︙
),
を、
libraryDependencies ++= Seq(
︙
("org.postgresql" % "postgresql" % "9.4-1200-jdbc41").exclude("org.slf4j","slf4j-simple"),
︙
),
とします。
これでTomcat8上にwarをデプロイすると...先程のメッセージは出なくなり、ログファイルが書かれるようになりました！
もう少しだけ続きます
Tomcat8ってきちんとしておかないと結構厳しいな、という印象と共に、
JDBCドライバがslf4j-simpleの依存持っちゃだめじゃないのかなーと思い、最新のJDBCドライバを見てみると...
問題のバージョン以降では依存が無くなってる、という事実に直面しました。うっ...
(スグにアプリのBuild.scalaからexcludeの記述は無くなりました)
まとめ
長々と書きましたが、要は、
Tomcat8だとslf4jの警告が出てるとlogback.xmlの設定が効きませんよー
というお話でした。
（sbtの依存関係の勉強もできて、この時間は決して無駄じゃなかったと思いたい）
一瞬でしたがScalaとTomcatって相性悪いのかな、とか、Skinny Frameworkのバージョンを上げたから？とか疑ってしまったことをお許し下さい。
間違っていたのは私です...
大丈夫、Tomcatはまだ好きです！