Qiitaにこんな記事を書いたのですが、実はこのとき調査を混乱させるもう一つの謎の事象がありました。
Qiita – ログレベルが突然変わる謎の事象を追う ～ あるOSSサポートエンジニアの1日
記事が少し長くなることと話の軸がぶれることを考慮して、その事象についてばっさりカットしたのですが、今後同じような問題に遭遇する人がいるかもしれないので、私のブログで紹介します。
記事の簡単なおさらい
Qiitaの記事の問題となったのは以下のコードでした。
final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";
static {
Logger logger = Logger.getLogger(RESTLET_LOGGER_NAME);
logger.setLevel(Level.OFF);
}
このコードはロガーのログ出力を抑止する意図でWebアプリケーションに追加されたコードで、そのWebアプリケーションでは必ず実行されるはずなんですが、それにもかかわらず、ロガーがログを出力したという問題です。
原因は、弱参照しかないロガー（ログレベル=OFF）をGCが回収して、新たにロガーが生成されたことでした。
で、この調査の際に、原因を探るために、以下のような修正を行って動作検証をしました。
final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";
static {
System.out.println("ServiceEndpointApplication#clinit start");
Logger logger = Logger.getLogger(RESTLET_LOGGER_NAME);
logger.setLevel(Level.OFF);
System.out.println("ServiceEndpointApplication#clinit end");
}
そして、tail -fコマンドでTomcatのログ（catalina.out）を監視しながら、JMeterで大量のリクエストを送信したわけです。
もう一つの謎
実はそのとき、tail -fコマンドの結果に以下のような出力があったのです（Qiitaの記事には書きませんでしたが）。
ServiceEndpointApplication#clinit start
ServiceEndpointApplication#clinit end
ServiceEndpointApplication#clinit end
endが2回出力されています。もちろん、System.out.println("ServiceEndpointApplication#clinit end");が他のソースコードにもあったということではありません。staticイニシャライザーにSystem.out.println();を追加した後でこの奇妙な出力が得られました。もし、次のようにstartが2回出力されたのであれば、そこまで驚きはしませんでした。
ServiceEndpointApplication#clinit start
ServiceEndpointApplication#clinit start
ServiceEndpointApplication#clinit end
startが2回出力されたのであれば、異なるクラスローダーがこのクラスをロードして、一方でエラー（ExceptionInInitializerError）が発生し、それをcatchして無視した可能性も考えられます（まあ、それも考えにくいですが…）。しかし、endが2回出力されたのであれば、そういうレベルの問題ではありません。
このとき、みなさんはどういった可能性を疑いますか？
私がそのとき考えたのはJVMのバグでした。それしか無いように思えました。
あっけなく分かった原因
その後、JVMのバグを探してみたり、同件の事例が無いかググってみましたが、それらしいものは見つからず。ふと、catalina.outをviで見たときに気がつきました。実は、ServiceEndpointApplication#clinit endは1回しか出力されていないということに。つまり、JMeterで瞬間的に大量のリクエストを送信した結果、tail -fコマンドが1回余計にServiceEndpointApplication#clinit endを出力したということのようでした。
では、なぜtail -fコマンドが1回余計に出力したのかというと…
実はそれは分かっていません（今回はそれ以上原因追求する必要はなかったので…すいません）。このあたりに詳しい方はぜひ教えて下さい。
追記
シェルの達人さとうさんから以下のようなコメントをいただきました。ありがとうございました～
出力先の端末の問題の可能性? tail は無実じゃないかなぁ。
— ふみやす＠シェルまおう(自称でない) .JSON (@satoh_fumiyasu) 2018年12月21日
tail(1) はファイルを最後まで read(2) し続け、最後まで行ったら新たなデータが来るまで待って (inotify かな? または stat(2) でポーリング? どっちでもこの問題に関係ないかと)、データが来たらまた read(2) するだけ、でしょうから、バグる余地がないと思うので。
— ふみやす＠シェルまおう(自称でない) .JSON (@satoh_fumiyasu) 2018年12月21日
OSS ∞ Lab 