mtail 勘所

最近は[github で binary が配布されている](https://github.com/google/mtail/releases)ので、デプロイは簡単になった。Ansible では[uri moudle](https://docs.ansible.com/ansible/latest/modules/uri_module.html)で `/usr/local/bin` にでも放り込んで、[file module](https://docs.ansible.com/ansible/latest/modules/file_module.html)で実行ビットを立てると簡単。Ansible galaxy にも[登録した](https://galaxy.ansible.com/hkwi/mtail) ので、さくっと入れたい場合はこちらを。

- `mtail` では、まず `syslog` 出力を処理することを中心に考えるとよい。
- ファイル出力が既にある場合は、それを使う。
- `mtail` は syslog や file 出力がよくメンテされている様子（[例](https://github.com/google/mtail/blob/master/docs/Deploying.md)）。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](https://github.com/google/mtail/issues/107), [Ref](https://github.com/google/mtail/issues/151))
- `-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 を[設定できる](https://github.com/google/mtail/blob/master/docs/Deploying.md#setting-a-default-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 も使えるように[書かれている](https://github.com/google/mtail/issues/58)。しかし mtail 内部の fsnotify 自体は named pipe には[反応しないことになっている](https://github.com/fsnotify/fsnotify/pull/98)し、mtail で独自にケアが入っているようにも見えない。

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

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

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