不具合発生時のログから注目すべき箇所を見つける方法

はじめに

オフラインで不具合解析しないといけないとき、ログは貴重な情報源になる。
ただ大規模なプロジェクトの場合、ログの量も膨大になる。
ましてや自分で作ったものでなければ、大量のログの中からどこでおかしくなったのか見つけるのは至難の業だ。
"error"とか"fatal"とかでgrepするも、正常時(?)でも大量にそのようなメッセージが出ていてションボリするのは誰しも経験することだと思う。

そこで、正常時のログと比較し、どこから挙動が変わったのかを見ることになる。
ただ往々にしてログにはタイムスタンプやランダム値など、毎回変わる情報も含まれることが多いので、意外と機械的に差分を見つけるのは難しい。

やりたいこと

下記のように、正常時のログ(ok.log)と異常時のログ(ng.log)があったとする。
異常時(ng.log)は"ACPI cmd (SET FEATURES) succeeded"が一回少ない。

ok.log

[110947.961257] ata1.00: ACPI cmd (SET FEATURES) succeeded
[110947.961259] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
[110947.961260] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out
[110947.975839] ata1.00: ACPI cmd (SET FEATURES) succeeded
[110947.975841] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
[110947.975842] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out

ng.log

[110947.961258] ata1.00: ACPI cmd (SET FEATURES) succeeded
[110947.961259] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
[110947.961262] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out
[110947.975841] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
[110947.975845] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out

この差分を見つけようと、単純にdiffをとったら、下記のように時刻がずれただけの行も差分として出力される。
そうではなく、メッセージ部だけを比較し、本質的な差分を抽出したい。

$ diff -u ok.log ng.log
--- ok.log  2019-02-14 22:45:43.580312291 +0900
+++ ng.log  2019-02-14 22:45:27.696429709 +0900
@@ -1,6 +1,5 @@
-[110947.961257] ata1.00: ACPI cmd (SET FEATURES) succeeded
+[110947.961258] ata1.00: ACPI cmd (SET FEATURES) succeeded
 [110947.961259] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
-[110947.961260] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out
-[110947.975839] ata1.00: ACPI cmd (SET FEATURES) succeeded
+[110947.961262] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out
 [110947.975841] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
-[110947.975842] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out
+[110947.975845] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out

方法1: 時間情報を消してから比較する

フォーマットが決まっていて、無視したい箇所がわかりきっているなら、予め消しておけばいい。
ググッて出てきたのは、こちらの方法ばかりだった。

$ diff -u <(sed ok.log -e 's/\[[0-9.]*\]/\[\]/g') <(sed ng.log -e 's/\[[0-9.]*\]/\[\]/g')
--- /dev/fd/63  2019-02-14 22:45:47.900280357 +0900
+++ /dev/fd/62  2019-02-14 22:45:47.900280357 +0900
@@ -1,6 +1,5 @@
 [] ata1.00: ACPI cmd (SET FEATURES) succeeded
 [] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
 [] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out
-[] ata1.00: ACPI cmd (SET FEATURES) succeeded
 [] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
 [] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out

標準コマンド(diff/sed)だけで実現できるので、簡単というのが何よりのメリット。

一方で、いくつかデメリットもある。

• 差分結果にタイムスタンプが表示されない
• 無視したい箇所が増えるたびに正規表現が複雑になる
• file名が"/dev/fd/63"とかいう謎パスになる（これは一時ファイルを作れば解決するが）

方法2: 数字[0-9]が異なっても差分と認識しないdiffコマンドを作る

ということで作ってみたのがlogdiff.
まずは実行結果から。
欲しかった結果が得られている。

$ logdiff ok.log ng.log 
--- ../tests/ok.log 2019-02-15 01:37:48 +0900
+++ ../tests/ng.log 2019-02-15 01:04:27 +0900
@@ -1,6 +1,5 @@
 [110947.961257] ata1.00: ACPI cmd (SET FEATURES) succeeded
 [110947.961259] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
 [110947.961260] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out
-[110947.975839] ata1.00: ACPI cmd (SET FEATURES) succeeded
 [110947.975841] ata1.00: ACPI cmd (SECURITY FREEZE LOCK) filtered out
 [110947.975842] ata1.00: ACPI cmd (DEVICE CONFIGURATION OVERLAY) filtered out

続いて実装について。
といってもdtl (Diff Template Library)というとても便利なライブラリがあったので、簡単に実装できた。

• C++のtemplateで実装されている
• ヘッダだけで完結しているため、導入が非常に楽
• 比較する要素の型、比較ロジックを任意のものに差し替えられる

サンプルとして含まれているunidiffをベースに、比較ロジックだけ下記のように変更した。
文字列比較時に、両者ともに数字の場合は値が異なっても一致と判定するようにしている。
結果として、timestamp等は無視される。

class DecNumberInsensitive: public dtl::Compare<std::string>
{
public:
  virtual bool impl (const std::string& lhs, const std::string& rhs) const {
    if (lhs.length() != rhs.length())
      return false;

    for (int i = 0; i < lhs.length(); i++)
      {
        if (isdigit(lhs.at(i)) && isdigit(rhs.at(i)))
          continue;
        if (lhs.at(i) != rhs.at(i))
          {
            return false;
          }
      }

    return true;
  }
};

使うかわからないが、-xオプション指定時は16進数の数値を無視するようにもしている。

  switch (comp_mode)
    {
    case MODE_DEC_INSENSITIVE:
      logdiff<DecNumberInsensitive> (path1, path2);
      break;
    case MODE_HEX_INSENSITIVE:
      logdiff<HexNumberInsensitive> (path1, path2);
      break;
    }

おわりに

comparatorを差し替えるだけでいくらでも柔軟にできるので、まだまだ拡張できそう。

それにしてもC++のテンプレートライブラリは、今回みたいにツールとしてちょっと使わせてもらう分には楽だなぁ。。。
ライブラリ側の設計・デバッグは大変なんだろうけど。。。
感謝感謝です。

参考

dtl (Diff Template Library)
diffの動作原理を知る～どのようにして差分を導き出すのか