ログで解明、デバッグの謎


ログは、特に背景のコードに詳しくない場合には、長たらしくて必要な情報がわかりにくいと思うことがあるかもしれません。いっぽうで、ログはJenkins管理者であるあなたにとって最強のツールになる可能性もあります。大部分のJenkinsユーザーは、成功か失敗かで示されるプロジェクトの結果に頼っています。そういったユーザーに自助を促し、問題解決までの時間を短縮できるとしたらどうでしょうか?

ログの場所

他のJavaアプリケーションと同様に、JenkinsはアプリケーションレベルのログとJVMレベルのログを出力します。たいていのJenkins管理者は、UIのManage Jenkins > System Logで参照できるシステムログについてはおなじみでしょう。

システムログを見ると、Jenkinsに関するjava.util.loggingの出力を参照できます。CloudBees Jenkins Distributionでは、デフォルトでインストールされているSupport Core Pluginによって、${JENKINS_HOME}/logs/jenkins.log にもログが出力されており、中央ログサーバーにログメッセージを送信するのが容易です。デフォルトのログについての詳細はJenkins Wikiにあります。
また、CloudBeesの推奨ベストプラクティスに従うと、JVMアクティビティ周りで他にもログが出力されます。特に重要なのは次のファイルです。

-Xloggc:${PATH},-XX:ErrorFile=${PATH} and -XX:LogFile=${PATH}

スタックトレースの読み方

Jenkinsで問題が発生すると、次のようなスタックトレースが表示されるでしょう。
「これはいったい何なんだ?」そう言いたくなるかもしれませんね。まあ、簡単に言えば、これはJavaアプリケーションが「ちょっとここ見てくれよ、ここが問題の場所だよ」と知らせているようなものです。通常、スタックトレースが表示されるのは、コードで例外が適切に処理されていない場合です。例外は、組み込みの例外型である場合もあれば、プログラムまたはライブラリが作成したカスタム例外の場合もあります。
スタックトレースの読み方を知ることは、Jenkins管理者として工具ベルトに加えておくべき強力なツールです。なぜなら、スタックトレースには、問題が起きた場所のコード行番号などのさまざまなデータが含まれているからです。

データの収集

Jenkins管理者である私たちは、実行プロセスの前のほうで起こった他のエラーによって引き起こされたエラー表示を最終行でみることがあるため、そのエラーに囚われてしまうことがあります。ありがちな落とし穴の1つは、エラーまでの完全なスタックトレースなしで、エラーだけを見せられることです。たとえば、あるエンドユーザーがビルドが失敗したと言って、Jenkins管理者に次のようなビルドエラーを見せたとしましょう。
ERROR: Step ?Archive the artifacts? failed: no workspace for Development/My_Dev_Job #2
ERROR: Step ?Publish JUnit test result report? failed: no workspace for Development/My_Dev_Job #2
ERROR: Step ?Record JaCoCo coverage report? failed: no workspace for Development/My_Dev_Job #2
Sending e-mails to: administrator@business.com
Finished: FAILURE
さて、一見してわかるのはビルドが失敗しているということです。それからいくつかのエラーメッセージが表示されています。これを見ると、ビルドのワークスペースが利用できないようだと考えたくなります。すると、定石として次のような方向で問題を調査しようと考えるかもしれません。
  • ストレージ
  • ネットワーク
  • ホスト
  • パイプラインコード
では、私たちはどうやって問題を突き止めましょうか?まず、データを完全な形で収集します。このケースでは、Jenkins管理者である私は、エラーがDevelopment/My_Development_JobのBuild #2のものだとわかるため、コンソールログを収集して他にデータがないかどうかを確認します。
やりました!見せられたエラーに至るまでの完全なスタックトレースが見つかりました。
エラーはFATALであり、原因はリモートチャネルの接続が失われ、クローズされたことのように見えます。これらのコンソールログから、次のデータが収集できます。
  • エラーの時間
  • エラーの原因
ビルドの問題は2020-01-22 20:06:58に起こったらしいことがわかったので、Jenkinsログでこのあたりの時間に何かが起きていないかをチェックするのがよいでしょう。
Jenkinsログを見ると、案の定、以下のエントリがあります。
2020-01-22 20:06:58.217+0000[id=124635]INFO hudson.slaves.ChannelPinger$1#onDead: Ping failed. Terminating the channel JNLP4-connect connection from ip-10-10-10-101.us-west-2.compute.internal/10.10.10.101:55555.
java.util.concurrent.TimeoutException: Ping started at 1579723378215 hasn't completed by 1579723618216
at hudson.remoting.PingThread.ping(PingThread.java:134)
at hudson.remoting.PingThread.run(PingThread.java:90)
CloudBees Support Knowledge Baseを検索してみると、この記事が見つかりました。記事によると、このエラーはPing Threadによるものであり、解決方法としては、pingスレッドを無効化することが推奨されています。すべてのデータが手に入って、はじめて問題の根本原因に到達できたことに注意してください。私自身にとってもエンドユーザーにとっても、どれほどの時間の節約になったか想像がつきますか?
(この記事は、CloudBees社 Blog 「Demystifying Debugging Through Logging」2020年1月27日 Ryan Smith 投稿記事の翻訳です。)