mtail 勘所

最近はgithub で binary が配布されているので、デプロイは簡単になった。Ansible ではuri moudleで /usr/local/bin にでも放り込んで、file moduleで実行ビットを立てると簡単。Ansible galaxy にも登録した ので、さくっと入れたい場合はこちらを。

• mtail では、まず syslog 出力を処理することを中心に考えるとよい。
• ファイル出力が既にある場合は、それを使う。
• mtail は syslog や file 出力がよくメンテされている様子（例）。named pipe なども対応している風な記述も見かけるけれど、うまく動いたり動かなかったり。
• mtail では、プログラムファイル（*.mtail）とログファイルの位置を指定する。そして mtail は起動引数でしかオプションは指定できない。つまり基本的に systemd unit ファイルとの食い合わせは悪いので、思い切って syslog に振り切って、unit ファイルでは、それのみを使うことにするのも手。
• systemd unit の ExecStart で変数展開してもいい。
• journald をメインに使っていても syslog に接続するのは比較的簡単。

mtail.service

[Unit]
Description = mtail

[Service]
ExecStart=/usr/local/bin/mtail -logtostderr -progs /usr/local/etc/mtail -logs /var/log/syslog
Restart = always
OOMScoreAdjust=1000
Nice=19

[Install]
WantedBy = multi-user.target

Testing

-one_shot オプション付きでテストすると効率が良い。稼働させる場合は -one_shot を外す。

mtail -progs /path/to/rule/dir -logs /path/to/logfile -logtostderr -one_shot

• なぜか -one_shot の場合は log の path が相対パスでも動作するが、-one_shot 無しの場合は絶対パスでないと動作しなかった時があった。(Ref, Ref)
• -one_shot の場合は strptime のパースに失敗した場合してもメトリクスが出力されるが、-one_shot 無しの場合は記録自体が行われない。strptime の失敗は -logtostderr にしておかないと、なかなか気づけない（デフォルトでは /tmp にログファイルとして出力されている）。テストでは -logtostderr は常に付けておこう。

mtail strptime

strptime builtin function で timestamp レジスタがセットできる。ログが都合よく timezone aware であれば、次のようにパースできたりするだろう。golang の time で使われるフォーマッタと同じ。

/(?P<date>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(Z|[\+\-]\d{2}:?\d{2}))/ {
  strptime($date, "2006-01-02T15:04:05Z07:00")
}

timezone unaware な感じでログされていて、ログの timezone が明らかな場合は、次のように文字列連結してパースすればよさそうだ。「文字列連結」は実は + でできる。

/(?P<date>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2})/ {
  strptime($date + "Z", "2006-01-02T15:04:05Z07:00")
}

すごくわかりにくいのだけれど、mtail の起動オプション -override_timezone でtimezone unaware な時刻に対してデフォルトの timezone を設定できる。--help によると、デフォルトでは local timezone が反映されるような書きぶりをされているけど、設定しないと UTC になっているはず。

1 秒未満の取り扱い

mtail での秒未満の取り扱いは要注意。たいてい少数は左に 0 パディングした整数で文字列として書かれていると思うけれども、mtail はマッチした文字列が整数であれば自動的に整数の型に変換する。つまり文字列での左の0パディングがなくなる。例を示す。

秒未満の数値を、カンマ区切りで書かれた場合。典型的には python logging.Formatter.default_msec_format が該当する。Workaround は次のようになる。

def gettme {
	/(?P<tm>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}),(?P<ms>\d{3})/ {
		# $tm will be converted to integer automatically.
		# $tm would not converted to integer automatically.
		$ms < 10 {
			strptime($tm+".00"+$ms, "2006-01-02 15:04:05.000")
		}
		10 <= $ms && $ms < 100 {
			strptime($tm+".0"+$ms, "2006-01-02 15:04:05.000")
		}
		100 <= $ms {
			strptime($tm+"."+$ms, "2006-01-02 15:04:05.000")
		}
	}
}

これで metrics の timestamp が nano sec の整数値で milli sec の粒度で記録される。

timestamp()

mtail プログラム中で使える builtin 関数 timestamp() は「整数のエポック秒」が返される。一秒未満は削られる。アプリケーションでdurationを計測しておらず、ログから再構成するときは次のようにする。

gauge session_ms_sum
counter session_ms_count
hidden gauge session_start_ms by session

@gettime {
	/start session=(?P<session>\w+)/ {
		session_start_ms[$session] = timestamp() * 1000 + $ms
	}
	/end session=(?P<session>\w+)/ {
		session_ms_sum += (timestamp() * 1000 + $ms - session_start_ms[$session])
		session_ms_count ++
		del session_start_ms[$session]
	}
}

整数で取り扱うほうが安全なケース。

text 型

実はtext型がある（ドキュメントには見つけられなかった）。上の変化形で次のように使える。

gauge session_ms_sum by name
counter session_ms_count by name
hidden gauge session_start_ms by session
hidden text session_name by session

@gettime {
	/start session=(?P<session>\w+) name=(?P<name>\w+)/ {
		session_start_ms[$session] = timestamp() * 1000 + $ms
		session_name[$session] = $name
	}
	/end session=(?P<session>\w+)/ {
		session_ms_sum[session_name[$session]] += (timestamp() * 1000 + $ms - session_start_ms[$session])
		session_ms_count[session_name[$session]] ++
		del session_start_ms[$session]
		del session_name[$session]
	}
}

named pipe

-logs の対象として、named pipe も使えるように書かれている。しかし mtail 内部の fsnotify 自体は named pipe には反応しないことになっているし、mtail で独自にケアが入っているようにも見えない。

実際に試してみても現時点での挙動としては、初期化時の最初の読み込みで block されて、Port 3903 Listen が開始されない。書き込み側の終了などで EOF が発生した場合に読み直しが起こり、ようやく Listen 開始されるといった具合。

要するに壊れていて mtail を修正すべきだけれども、一時的に修正しても安定してメンテナンスされる機能にはならない予感がする。

抜本的に修正されるまで、named pipe は使わないのが吉。