More than 5 years have passed since last update.

オープンソースまるごと by NRI OpenStandiaAdvent Calendar 2018

@tamura__246(Kohei Tamura)in

株式会社野村総合研究所

ログレベルが突然変わる謎の事象を追う～あるOSSサポートエンジニアの1日

Last updated at 2019-03-31Posted at 2018-12-02

はじめに

次のJavaのコードには問題があります。何が問題か分かりますか？

    Logger.getLogger("test").setLevel(Level.OFF);

これは、testという名前のロガーのログ出力を抑止することを目的としたコードです。

ここで使っているLoggerはJava標準のjava.util.logging.Loggerで、getLogger()は引数で与えられた名前のロガーインスタンスが既に生成されていればそれを返し、無ければ新たに生成するメソッドです。setLevel()は、そのロガーのログレベルを設定します。引数はLevel.OFFなので、ログ出力を無効にします。

この記事は、上記コードが引き起こした問題についての実話です。

このコードが起こした問題

ある日、私のもとに至急の調査依頼が来ました。その内容は、「Tomcatの再起動をきっかけに、Webアプリケーションがボディの無い正常応答を返すようになった」というものでした。

その後の再起動で事象は再現しなくなったものの、今後に備えて原因を調査をして欲しいとのこと。

調べる

ということで、さっそく調査開始。もし、報告された事象が事実であるならば、Tomcatのアクセスログに次のような行が出力されているはずです。

192.169.1.8 ･･･(略)･･･ HTTP/1.1" 200 - 379 PostmanRuntime/7.1.3

「次のような行」というのは、HTTPのバージョン(この例では「HTTP/1.1」）の後に、正常応答のステータスコードを示す「200」と、レスポンスボディのサイズが0であることを示す「-」が続く行のことです¹。

この条件で、アクセスログをgrepしてみると、確かに該当する行が多数ありました。どれも事象の発生が確認されたTomcatの再起動後から次の再起動までの間の、特定のURLへのアクセスログだけです。

さらに調べてみると、事象発生と同時刻にNullPointerExceptionも発生していることが分かりました。NullPointerExceptionの発生箇所は、Webアプリケーションが内部で使用しているRestlet²のクラスLogFilterの次のメソッドでした。見ての通り、INFOレベルのログを出力するだけのメソッドです。

org.restlet.engine.log.LogFilter

protected void afterHandle(Request request, Response response) {

	if ((request.isLoggable()) && (this.logLogger.isLoggable(Level.INFO))) {
		// ★★ 次の行でNPEが発生していた ★★
		long startTime = ((Long)request.getAttributes().get("org.restlet.startTime")).longValue();
		int duration = (int)(System.currentTimeMillis() - startTime);
		this.logLogger.log(Level.INFO, this.logService.getResponseLogMessage(response, duration));
	}
}

調査を進めた結果、NullPointerExceptionが発生することと、それに起因してボディの無い正常応答が返ってしまうことは、Restletのバグ³が原因であることが判明しました。また、事象が発生したURLにアクセスすると、必ず上記メソッドが呼び出されることも分かりました。

しかし、一つ分からないことが残りました。

残された謎

それは、上記if文内のコードがWebアプリケーションでは実質的にはデッドコードだということです。つまり、この分岐条件の中には入るはずがないのです。

というのも、条件式のthis.logLogger.isLoggable(Level.INFO))が必ずfalseになるような対策がWebアプリケーションのソースコードに実施されていたからです。Webアプリケーションでは、Restletのログがcatalina.out（Tomcatのログ）に大量に出力されることが以前から問題視されており、出力を無効にする対策がされていました。

対策は、次のようなものでした。

ServiceEndpointApplication（WebアプリケーションのRestlet呼び出しの起点になっているクラス）

     final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";

     static {
         Logger logger = Logger.getLogger(RESTLET_LOGGER_NAME);
         logger.setLevel(Level.OFF);
     }

冒頭で書いたものと同様のログ出力無効化処理が、WebアプリケーションのServiceEndpointApplicationというクラスのstaticイニシャライザーに実装されています。

RestletのLogFilterがRestlet用のロガーインスタンスをフィールドに保持しているので、このクラスが呼び出される直前に必ず呼び出されるServiceEndpointApplicationで、ログレベルをOFFにしてログ出力を抑止してしまおう、というのがこの対策の意図です。

Webアプリケーションでは、Restletの限定的な使い方しかしていなかったので、「Restletのログを出力しなくても問題は無い」という判断だったのではないかと思います。

この対策があれば、ログレベルはOFFなので、先ほどのif文の分岐には入らないはずですが、実際には分岐に入りNullPointerExceptionが発生していました。さらに不思議なことに、Tomcatの再起動は過去に何度も行っていたにもかかわらず、この事象が発生したことはありませんでした。そして、事象発生後のTomcatの再起動により、一切事象は再現しなくなりました。

なぜログレベルが変わったのか

最初に疑うのは、再起動の際にログレベルを変える何らかのファイルが混入したということでしょう。例えば、古いバージョンのWebアプリケーションのwarファイルがデプロイされたとか、ログレベルを変更するためのプロパティファイルが追加されたということが考えられます。

しかし、担当者に確認すると、再起動のプロセスは自動化されており、その可能性は極めて低いという回答でした。確かに、事象発生後の再起動で事象が再現しなくなったことを考えると、何らかのファイルが混入した可能性は低いように思えます（そのファイルを元に戻さなければ、その後も事象が発生し続けるので）。

いずれにしても、事象を再現できないと調査は難しいので、ローカル環境で再現するか確認することにしてみました。事象が発生するリクエスト（URL）は特定できていたので、それをWebアプリケーションに送信して、再現できないか確認してみましたが、全く再現しません。事象が発生した環境でも、ある日の再起動後しか発生しなかった程度の発生率なので、簡単には再現しないはずで、何らかの条件があると考えられます。

そして、試行錯誤の末、ついに事象を再現することができました。再起動直後にJMeterを使ってマルチスレッドで大量のリクエストを送信した場合に、5回に1度程度の確率で再現したのです。つまり、前述のWebアプリケーションの対策には何らかの問題があるということです。

マルチスレッドでの誤動作？

マルチスレッドでの誤動作が疑われますが、それ以前にログが出力されない理由を知る必要があります。ここで真っ先に考えられる理由は、次の2つでしょう。

このstaticイニシャライザーの後にどこかで、setLevel()が呼び出されている
そもそも、setLevel()が呼び出されていない

まず、1つ目の理由が正しいかを検証するためにWebアプリケーションとRestletのソースコードを「setLevel」、のキーワードでgrepしてみました。しかし、原因となりそうなコードは見つけれられませんでした。WebアプリケーションとRestlet以外のソースコードでsetLevel()を呼び出している可能性は考えにくいので、これが理由では無さそうです。

次に、2つ目の理由が正しいかを検証するために、このstaticイニシャライザーにSystem.out.println()文を追加して、動作確認してみることにしました。

つまり、こういうことです。

ServiceEndpointApplication（WebアプリケーションのRestlet呼び出しの起点になっているクラス）

     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");
     }

これにより、マルチスレッドの場合に、このクラスがロードされなかったり、staticイニシャライザーで例外（エラー）が発生していないかが分かります。

しかし、事象が再現したときの出力の結果は、次のようになっていました。

ServiceEndpointApplication#clinit start
ServiceEndpointApplication#clinit end

つまり、Level.OFFにしているのは確かだと言うことです。1つ目の理由も2つ目の理由も正しくなさそうです。

異なるクラスローダーでの実行？

そうであれば、異なるクラスローダーによって初期化されたなどの理由で、Webアプリケーションが予め生成したロガーインスタンス（ログレベルが無効な）を、Restletが使用していないのかもしれません。

ということで、次のような修正を加えて、再度再現確認をしてみました。ロガーインスタンスを最初に生成する箇所と取得してログ出力する箇所に、ロガーインスタンスの名前とIDとロードしたクラスローダーの情報を出力させています。

ServiceEndpointApplication（WebアプリケーションのRestlet呼び出しの起点になっているクラス）

     final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";

     static {
        Logger logger = Logger.getLogger(RESTLET_LOGGER_NAME);
        logger.setLevel(Level.OFF);
		System.out.println("ServiceEndpointApplication#clinit");
		System.out.println("-------------------------------------");
		System.out.println("Logger Name: " + logger.getName());
		System.out.println("Logger Instance ID: " + logger);
		System.out.println("Class Loader: " + Thread.currentThread().getContextClassLoader());
     }

org.restlet.engine.log.LogFilter

protected void afterHandle(Request request, Response response) {

	System.out.println("LogFilter#afterHandle");
	System.out.println("-------------------------------------");
	System.out.println("Logger Name: " + logger.getName());
	System.out.println("Logger Instance ID: " + logger);
	System.out.println("Class Loader: " + Thread.currentThread().getContextClassLoader());
	if ((request.isLoggable()) && (this.logLogger.isLoggable(Level.INFO))) {
		long startTime = ((Long)request.getAttributes().get("org.restlet.startTime")).longValue();
		int duration = (int)(System.currentTimeMillis() - startTime);
		this.logLogger.log(Level.INFO, this.logService.getResponseLogMessage(response, duration));
	}
}

出力は以下のようになりました。

ServiceEndpointApplication#clinit
-------------------------------------
Logger Name: org.restlet.Component.LogService
Logger Instance ID: java.util.logging.Logger@1051f7a6
Class Loader: WebappClassLoader
  context: /Webapp1
  delegate: false
  repositories:
    /WEB-INF/classes/
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@2d3b52e

LogFilter#afterHandle: 
-------------------------------------
Logger Name: org.restlet.Component.LogService
Logger Instance ID: java.util.logging.Logger@b5270f5
Class Loader: WebappClassLoader
  context: /Webapp1
  delegate: false
  repositories:
    /WEB-INF/classes/
----------> Parent Classloader:
org.apache.catalina.loader.StandardClassLoader@2d3b52e

この結果から分かるのは、ロガークラスは同じクラスローダーからロードされているものの、異なるインスタンスであるということです。ということは、一度生成されたロガーインスタンスが破棄され、新たに生成されたということかもしれません。

他の可能性？

そこで、初心にかえってjava.util.logging.Logger.getLogger()のJavadocを確認してみることにしました。そして、次の記述があるのを見つけました。

注: LogManagerは新しく作成されたロガーへの弱参照しか保持できません。指定した名前で以前に作成されたロガーは、ロガーへの強い参照がない場合に、いつでもガベージ・コレクトされる可能性があることを理解することが重要です。特に、このことは、getLogger("MyLogger").log(...)などの2つの連続した呼出しで、プログラムのどこにも「MyLogger」という名前のロガーへの強い参照がない場合、「MyLogger」という名前の別のロガー・オブジェクトが使われる可能性があることを意味します。

つまり、ServiceEndpointApplicationのstaicイニシャライザーが呼び出されてから、LogFilter#afterHandle()が呼び出されるまでのわずかな時間（1ミリ秒であっても）にGCが発生すれば、Logger.getLogger()は別のインスタンスとなる可能性があり、セットしたはずのログレベルはデフォルトになるというわけです。

このわずかな時間内にGCが発生しなければ、その後Restletのクラスでロガーインスタンスが保持される（＝強参照される）ため、永久（再起動しなければ）にGCの対象にはならなくなります。何度も行っていた再起動で１回しか事象が発生しなかった理由は、そこにありました。

動作確認する

この動作を簡単なプログラムで再現してみると、以下のようになります。

	public static void main(String[] args) {
		Logger.getLogger("test").setLevel(Level.OFF);
		// もしここでGCが発生したら、
		System.gc();
		// 以降、getLevel()はnullを返します。
		System.out.println(Logger.getLogger("test").getLevel());
	}

結果はnullになります。System.gc();をコメントアウトして、その間にGCが発生しなければ、OFFと出力されます。

以下のようなロガーをフィールド変数にセットするコードをよく見かけますが、それには理由があったわけです（GCにより、インスタンスに設定した属性が失われることを防ぐ）。

    public static Logger logger = Logger.getLogger("xxx.xxx");

ということで、ソースコードを修正してみましょう。最低限の修正に留めるなら以下のようになるでしょうか。

ServiceEndpointApplication（WebアプリケーションのRestlet呼び出しの起点になっているクラス）

     final static String RESTLET_LOGGER_NAME = "org.restlet.Component.LogService";

     static Logger;
     static {
         logger = Logger.getLogger(RESTLET_LOGGER_NAME);
         logger.setLevel(Level.OFF);
     }

実際に、この修正を適用してから、見つけた再現手順で20回動作確認してみましたが、今回の事象は発生しませんでした。5回に１回程度の再現率だったので、20回やっても再現しなければ問題は無いと言っていいでしょう（ $\scriptsize{ (1 - 0.8^{20}) * 100 ≒ 99% }$ 確かなので）。

最後に

あらためて最初の質問の回答をします。

    Logger.getLogger("test").setLevel(Level.OFF);

このコードはtestという名前のロガーのログ出力を抑止する保証がありません。少し言い換えると、次のinfo()メソッドがtest!と出力する可能性はゼロではないということです。

    Logger.getLogger("test").setLevel(Level.OFF);
    // ここでGCが発生すれば、Logger.getLogger()は別インスタンスを返す
    Logger.getLogger("test").info("test!");

正確にはTomcatのアクセスログの出力形式に依存します。この環境では、デフォルトの出力形式でした。 ↩
RestletはRESTfullなWebアプリケーションを構築するためのOSSのフレームワークです。 ↩
このコミットで対策されています。修正の仕方がイマイチですが... ↩

189

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up

ログレベルが突然変わる謎の事象を追う ～ あるOSSサポートエンジニアの1日

はじめに

このコードが起こした問題

調べる

残された謎

なぜログレベルが変わったのか

マルチスレッドでの誤動作？

異なるクラスローダーでの実行？

他の可能性？

動作確認する

最後に

ログレベルが突然変わる謎の事象を追う～あるOSSサポートエンジニアの1日