Tomcatのcatalina.outが「java.util.zip.ZipException: error in opening zip file」で溢れかえった原因はAppleDouble

1 事象
2 原因
3 対処
4 まとめ

事象

ある日、共有development環境として使っているCentOSのディスク使用率がどんどん増えていってることに気づきました。

増加原因になっていたTomcat8.5.32のログファイルcatalina.outを見ると、warファイルをデプロイする度に「ZIPファイルが開けない」旨の例外が発生しています。

08-Aug-2019 14:41:43.557 情報 [localhost-startStop-8] org.apache.catalina.startup.HostConfig.deployWAR Webアプリケーショ
ンアーカイブ [/usr/local/apache-tomcat-8.5.32/webapps/xxxxxx.war] を配備します
08-Aug-2019 14:41:44.710 警告 [localhost-startStop-8] org.apache.tomcat.util.scan.StandardJarScanner.processURLs Failed
to scan [file:/usr/local/apache-tomcat-8.5.32/lib/._el-api.jar] from classloader hierarchy
 java.util.zip.ZipException: error in opening zip file
        at java.util.zip.ZipFile.open(Native Method)
        at java.util.zip.ZipFile.<init>(ZipFile.java:219)
        at java.util.zip.ZipFile.<init>(ZipFile.java:149)
        at java.util.jar.JarFile.<init>(JarFile.java:166)
        at java.util.jar.JarFile.<init>(JarFile.java:130)
        at org.apache.tomcat.util.compat.JreCompat.jarFileNewInstance(JreCompat.java:188)
        at org.apache.tomcat.util.scan.JarFileUrlJar.<init>(JarFileUrlJar.java:65)
        at org.apache.tomcat.util.scan.JarFactory.newInstance(JarFactory.java:49)
        at org.apache.tomcat.util.scan.StandardJarScanner.process(StandardJarScanner.java:374)
        at org.apache.tomcat.util.scan.StandardJarScanner.processURLs(StandardJarScanner.java:309)
        at org.apache.tomcat.util.scan.StandardJarScanner.doScanClassPath(StandardJarScanner.java:266)
        at org.apache.tomcat.util.scan.StandardJarScanner.scan(StandardJarScanner.java:229)
        at org.apache.catalina.startup.ContextConfig.processJarsForWebFragments(ContextConfig.java:1888)
        at org.apache.catalina.startup.ContextConfig.webConfig(ContextConfig.java:1116)
        at org.apache.catalina.startup.ContextConfig.configureStart(ContextConfig.java:765)
        at org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java:299)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:94)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5154)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:754)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:730)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:985)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1857)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

この例外はtomcat/lib配下のjarファイル25個に対して出ており、上記のログが一度に連続して25回出ています。

GitLabへpush
Jenkinsがビルド
このTomcatへデプロイ

のフローを自動化している為、誰かがgit pushする度にどんどんファイルサイズが増加していました。

原因

例外対象のjarファイルをよく見ると先頭に「._」が付いています。
tomcat/libをls -aしてみると、通常のjarの他「._」が付いた隠しファイルが実際に居ました。

# ls -la
合計 7828
drwxr-xr-x 2 tomcat tomcat    4096  7月 25  2018 .
drwxr-xr-x 9 tomcat tomcat     336  6月 20  2018 ..
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._annotations-api.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._catalina-ant.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._catalina-ha.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._catalina-storeconfig.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._catalina-tribes.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._catalina.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._ecj-4.6.3.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._el-api.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._jasper-el.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._jasper.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._jaspic-api.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._jsp-api.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._servlet-api.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-api.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-coyote.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-dbcp.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-i18n-es.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-i18n-fr.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-i18n-ja.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-jdbc.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-jni.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-util-scan.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-util.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._tomcat-websocket.jar
-rw-r--r-- 1 tomcat tomcat     212  6月 20  2018 ._websocket-api.jar
-rw-r--r-- 1 tomcat tomcat   12371  6月 20  2018 annotations-api.jar
-rw-r--r-- 1 tomcat tomcat   54183  6月 20  2018 catalina-ant.jar
-rw-r--r-- 1 tomcat tomcat  118606  6月 20  2018 catalina-ha.jar
-rw-r--r-- 1 tomcat tomcat   75852  6月 20  2018 catalina-storeconfig.jar
-rw-r--r-- 1 tomcat tomcat  283697  6月 20  2018 catalina-tribes.jar
-rw-r--r-- 1 tomcat tomcat 1641155  6月 20  2018 catalina.jar
-rw-r--r-- 1 tomcat tomcat 2450404  6月 20  2018 ecj-4.6.3.jar
-rw-r--r-- 1 tomcat tomcat   82382  6月 20  2018 el-api.jar
-rw-r--r-- 1 tomcat tomcat  164666  6月 20  2018 jasper-el.jar
-rw-r--r-- 1 tomcat tomcat  591616  6月 20  2018 jasper.jar
-rw-r--r-- 1 tomcat tomcat   26912  6月 20  2018 jaspic-api.jar
-rw-r--r-- 1 tomcat tomcat   61652  6月 20  2018 jsp-api.jar
-rw-r--r-- 1 tomcat tomcat  244064  6月 20  2018 servlet-api.jar
-rw-r--r-- 1 tomcat tomcat   10664  6月 20  2018 tomcat-api.jar
-rw-r--r-- 1 tomcat tomcat  810072  6月 20  2018 tomcat-coyote.jar
-rw-r--r-- 1 tomcat tomcat  278730  6月 20  2018 tomcat-dbcp.jar
-rw-r--r-- 1 tomcat tomcat   66897  6月 20  2018 tomcat-i18n-es.jar
-rw-r--r-- 1 tomcat tomcat   40792  6月 20  2018 tomcat-i18n-fr.jar
-rw-r--r-- 1 tomcat tomcat   42087  6月 20  2018 tomcat-i18n-ja.jar
-rw-r--r-- 1 tomcat tomcat  148296  6月 20  2018 tomcat-jdbc.jar
-rw-r--r-- 1 tomcat tomcat   34562  6月 20  2018 tomcat-jni.jar
-rw-r--r-- 1 tomcat tomcat  208448  6月 20  2018 tomcat-util-scan.jar
-rw-r--r-- 1 tomcat tomcat  143092  6月 20  2018 tomcat-util.jar
-rw-r--r-- 1 tomcat tomcat  224850  6月 20  2018 tomcat-websocket.jar
-rw-r--r-- 1 tomcat tomcat   36905  6月 20  2018 websocket-api.jar

これらの正体は「AppleDouble」というファイルです。

# file ./._annotations-api.jar
./._annotations-api.jar: AppleDouble encoded Macintosh file

# cat ._annotations-api.jar
Mac OS X                2｢ﾔATTRﾔ<<com.apple.quarantineq/0083;5b5674fe;Safari;6DFD0406-1C16-4C92-A6EB-F563DC5411CC

Macのファイルシステム管理を補佐する為の情報が入っていて、HFS+ではOS内部でこの情報を持つ為、Macを使っている分にはFinderではお目に掛からないファイルです。

Mac（HFS+）からWindows（FAT32）やLinux（ext4）へファイル共有した時にこれらの情報が抜け落ちないようにわざわざファイルを作ってくれるんですね。Macユーザ以外に嫌われがちな「.DS_store」と同じ目的です。

拡張子はjarですが、中身はjarではないので、Tomcatがこれらのファイルにzipを期待してアクセスする度「zipじゃない」と警告をログに残します。

これらのファイルがインストールに使ったと思われるapache-tomcat-8.5.32.zipに混入したのが原因でした。

対処

暫定対処としてtomcat/libから._ファイルを削除。
取りあえず例外は出なくなります。

# cd ${TOMCAT_HOME}/lib
# rm ./._*

こちらの場合、ミドルはansibleでインストールしていてチーム内リポジトリからインストール資源を持ってくるので、社内リポジトリのapache-tomcat-8.5.32.zipをまともなものに置換しました。

まとめ

寧ろどうやってzipの中にAppleDoubleファイルを入れたのか、の疑問が残りました。

このTomcatのアップデート作業を行ったのは2か月前に退社した人で連絡も取れず真相は迷宮入りです。

落としてきたtomcatのzipをリポジトリディレクトリに放り込んで、ansible playbookのyamlをちょちょいとコピーするだけだったんですが・・・。

Macでapache-tomcat-8.5.32.zipをダウンロード、解凍
Windowsにディレクトリを転送して再zip

とかしたんでしょうかね・・・謎は深まるばかりです。