はじめてな Elixir(24) ログを出力しない

今回はログの出力を抑制する方法を見てみます。ログの出し方は前回の投稿 [はじめてな Elixir(23) ログを出力する](https://qiita.com/kikuyuta/items/b4d6a4e0ea591281f920) を御覧ください。

デバッグ中にはログをジャンジャン出したいところです。しかし、ログ出力がアプリケーションの動作に悪影響を与えたりすることもあるでしょう。ログ出力が不要になったときに、もう一切ログの影響を受けたくないけど、でもまたデバッグのときには以前と同じ様にログを出したい… なんてこともあるでしょう。Elixir の `Logger` はこの辺は良く出来てる感じです。

# ログ出力を制御する
Elixir でログの出力を制御するには
- `Logger` の関数を用いる
- アプリケーションを開始する前にパラメータを設定しておく
- アプリケーションの動作中にパラメータを設定する
という3つのパターンがあり、それぞれ設定できる内容に違いがあります。

## ログ機能を on/off する
一番シンプルな方法で単純にログ機能を止めたり再開したりします。

```
iex(1)> require Logger              # Logger モジュールを呼ぶ
Logger
iex(2)> Logger.info("hello world!") # info レベルで出力する

19:19:16.597 [info]  hello world!   # ログが出力される
:ok
iex(3)> Logger.disable(self())      # ログ機能を無効にする
:ok
iex(4)> Logger.info("hello world!") # 今度はログが…
:ok                                 # …出力されない
iex(5)> Logger.enable(self())       # ログ機能を有効にする
:ok
iex(6)> Logger.info("hello world!") # やってみると…

19:19:38.455 [info]  hello world!   # …ログが出力される
:ok
```

これは自分だけでなく他のプロセスのログ機能も（プロセス番号が分かっているなら）on/off できます。

## アプリケーションの動作中に設定できる制御
公式マニュアルでは Runtime Configuration というのに分類しています。設定できるパラメータが6種類ほどあります。ここではそのいくつかを試します。

なお、プログラム中でも設定の変更ができますし、`config/config.exs` に設定を書いておいて起動時に有効にすることもできます。

### ログレベルを変える
`Logger` ではログレベルの概念があり、緊急性の高い方から `:error`, `:warn`, `:info`, `:debug` の4種類があります（なぜ syslog に完全に合わせないんだ！ 不満）。緊急性の高い方を表示して、そうでないのを表示しないためには `:level` を設定します。

```temp4.ex
defmodule Temp4 do
  require Logger

  def log() do
    Logger.error("Error: hello")
    Logger.warn("Warn: hello")
    Logger.info("Info: hello")
    Logger.debug("Debug: hello")
  end
end
```
とかやって実行してみましょう。

```
iex(1)> c "temp4.ex"
[Temp4]
iex(2)> Temp4.log # 4種類のレベルのログを表示させる

18:21:51.313 [error] Error: hello
 
18:21:51.316 [warn]  Warn: hello

18:21:51.316 [info]  Info: hello

18:21:51.316 [debug] Debug: hello
:ok
                                       # 4つのログが全部表示される

iex(3)> Logger.configure(level: :info) # info に制限
:ok:

iex(4)> Temp4.log                      # 4種類のレベルのログを表示させる

18:22:25.330 [error] Error: hello
:ok

18:22:25.330 [warn]  Warn: hello

18:22:25.330 [info]  Info: hello
                                       # debug レベルは表示されない

iex(5)> Logger.configure(level: :warn) # warn レベルに制限
:ok
iex(6)> Temp4.log                     

18:22:37.156 [error] Error: hello
:ok

18:22:37.156 [warn]  Warn: hello
                                        # debug, info レベルは表示されない

iex(7)> Logger.configure(level: :error) # error レベルに制限
:ok
iex(8)> Temp4.log                      

18:22:42.398 [error] Error: hello
:ok
                                        # debug, info, warn レベルは表示されない

iex(9)> Logger.configure(level: :debug) # debug レベルに戻す
:ok
iex(10)> Temp4.log                      

18:22:48.795 [error] Error: hello
:ok

18:22:48.795 [warn]  Warn: hello

18:22:48.795 [info]  Info: hello

18:22:48.795 [debug] Debug: hello
                                        # 再び全てのログが表示される

iex(11)> 
```

UNIX syslog の動作と似てますからわかりやすいですね、ね！

### タイムゾーンを変える
これは表示の制約じゃないですが、まあ、簡単にできるのでやってみましょう。

```
iex(12)> require Logger
Logger
iex(13)> Logger.info("good evening world") # ログ表示をすると

18:29:25.236 [info]  good evening world # 地元時刻(JST)表示になる
:ok
iex(14)> Logger.configure(utc_log: :true) # という設定を入れると
:ok
iex(15)> Logger.info("good evening world")

09:29:40.946 [info]  good evening world # 協定世界時(UTC)表示になる
:ok
iex(16)> Logger.configure(utc_log: :false) # という設定を入れると
:ok
iex(17)> Logger.info("good evening world")

18:29:46.122 [info]  good evening world # 地元時刻(JST)表示にもどる
:ok
```
タイムゾーンが明示されないのがアレですな。表示フォーマットをいじれるのでハックすればできるようになるでしょう。

### ログ表示の文字数を制限する
文字数の制限は `:truncate` に設定します。デフォは 8192 です。先程のモジュールに以下を追加します。

```temp4.ex
  def log_long(n) do
    Stream.repeatedly(fn -> "z" end)
    |> Enum.take(n) |> Enum.join |> Logger.info()
  end
```
同じ文字を沢山出すってこんな関数で良いんですかね。パッとこれしか思いつかなかった。


```
iex(1)> c "temp4.ex"
[Temp4]
iex(2)> Temp4.log_long(10)    #10文字出力する

18:35:55.925 [info]  zzzzzzzzzz
:ok
iex(3)> Temp4.log_long(10000) #10000文字出力する

18:35:59.823 [info]  zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz
                              # 途中は省略します…
zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz (truncated) #長すぎて後ろは切られた
:ok
iex(4)> Logger.configure(truncate: 20) # ログ長を20文字に制限
:ok
iex(5)> Temp4.log_long(10000) # 10000文字出力しようとしても

18:38:07.643 [info]  zzzzzzzzzzzzzzzzzzzz (truncated) # 20文字で切られる
:ok
```
`:truncate` の値は表示する全体の文字ではなく、引数に渡す文字列に対して利いてます。

### ログ表示が追いつかないとき
ログの表示が多いとか、アプリケーションの動作が速いとかで、動作に対してログ表示が追いつかない場合にはアプリケーション側の動作を抑制することができます。`sync_threshold` に値を入れておくとログのキューがそれを越えたときに同期モードになってアプリ側の動作を止めてログ出力を優先します。ログが出力されてキューが短く（設定値の3/4に）なると非同期モードになり、アプリを止めてたのが解除されます。設定値を `0` にすると常に同期モードになります。

```
iex(6)> Temp4.log # 4種類のログをいっぺんに表示させる…
:ok               # …とアプリ側が先に終了して、その後にログが追いかけてくる

18:49:33.493 [error] Error: hello
 
18:49:33.493 [warn]  Warn: hello

18:49:33.493 [info]  Info: hello

18:49:33.494 [debug] Debug: hello
iex(7)> Logger.configure(sync_threshold: 0) # ログのキューに溜まったらアプリを抑制する
:ok
iex(8)> Temp4.log                           # もう一度、ログをいっぺんに表示させる

18:50:25.851 [error] Error: hello
 
18:50:25.851 [warn]  Warn: hello

18:50:25.851 [info]  Info: hello
 
18:50:25.851 [debug] Debug: hello
:ok                                   # ログ出力が終わるのをアプリが待つようになった
iex(9)> 
```

## アプリケーションを開始する前に設定しておく制御内容
ここに示す内容は `Logger` アプリが立ち上がるより前に設定されてる必要があります。例えば [はじめてな Elixir(23) ログを出力する](https://qiita.com/kikuyuta/items/b4d6a4e0ea591281f920) に出てきた `:backends` の設定もこれに相当します。これらの設定は `config/config.exs` に書いておきましょう。

### コンパイル時にログレベルでの出力抑制を決定する
ログレベルに応じて出力するかどうかは `Logger.configure/1` を用いることで実行時にも制御ができました。これはログ出力をする度に毎度チェックすることになります。ここの方法はそうではなくて、コンパイル時にどのレベルまでをログ出力するかを決めてしまいます。これの利点はログ出力しないレベルについては実行時間に全く影響を与えないというところです。

例えば、ソフトウェアの開発時点では `error` `warn` `info` `debug` を使ってて、リリース時以降は `error` と `warn` だけ出力するとしましょう。この場合に `Logger.configure` で制御すると `Logger.info/2` や `Logger.debug/2` を呼んでるところでも「ログを表示しない判断」の処理が行われて計算資源を使います。以下の方法を使うと計算資源を使わないように「あたかもその行がなかったかのごとく」コンパイルしてくれます。

以下のプログラムで試してみます。`mix new temp` してから各ファイルを加筆修正しています。まず、起動するアプリケーションを `mix.exs` に記述します。

```mix.exs
  def application do
    [
      extra_applications: [:logger], # これのあることの確認、そしてカンマ
      mod: {Temp.Application, []}    # これを追加
    ]
  end
```

アプリケーションは一定時間ごとにログを出力します。

```lib/temp/application.ex
defmodule Temp.Application do
  use Application
  require Logger
  @behaviour GenServer

  @pname :afo
  @impl Application
  def start(_type, _args) do
    Logger.info("server started named #{@pname}")
    Logger.debug("There is no supervisor")
    GenServer.start_link(__MODULE__, nil, name: @pname)
  end

  @impl GenServer
  def init(_void) do
    set_interval()
    {:ok, 0}
  end

  @interval 2000
  defp set_interval() do
    Logger.debug(fn -> "interval timer set for #{@interval} milli seconds" end)
    Process.send_after(self(), :wakeup, @interval)
  end

  @impl GenServer
  def handle_info(:wakeup, num) do
    Logger.info("done #{num}th cycle")
    set_interval()
    {:noreply, num + 1}
  end
end
```

さてこれを素のままで実行してみましょう。（iex のプロンプトが出てきますが、見にくくなるので編集でカットしてます）

```
$ iex -S mix
Erlang/OTP 21 [erts-10.2.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe] [dtrace]

Compiling 3 files (.ex)
Generated temp5 app

21:27:35.750 [info]  server started named afo # info レベルのログが出てます
 
21:27:35.750 [debug] There is no supervisor   # debug レベルのログも出てます

21:27:35.750 [debug] interval timer set for 2000 milli seconds

21:27:37.751 [info]  done 0th cycle
 
21:27:37.751 [debug] interval timer set for 2000 milli seconds
 
21:27:39.752 [info]  done 1th cycle
 
21:27:39.752 [debug] interval timer set for 2000 milli seconds
 
21:27:41.753 [info]  done 2th cycle
 
21:27:41.753 [debug] interval timer set for 2000 milli seconds
```
という `:info` レベルと `:debug` レベルのログが2秒ごとに繰り返されて出続けます。

つぎに `config/config.exs` に以下の設定を入れてみます。

```config/config.exs
config :logger,
  compile_time_purge_matching: [
    [level_lower_than: :info]
  ]
```

これで実行するとこうなります。

```
$ iex -S mix
Erlang/OTP 21 [erts-10.2.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe] [dtrace]

Compiling 3 files (.ex)
Generated temp5 app

21:30:04.184 [info]  server started named afo

21:30:06.184 [info]  done 0th cycle
 
21:30:08.185 [info]  done 1th cycle
 
21:30:10.186 [info]  done 2th cycle
 
21:30:12.187 [info]  done 3th cycle
```

と `:info` より優先度の低いログ（この場合は `:debug` レベルのログ）は出なくなります。これは `Logger.configure/1` で抑制しても見た目は同じですが、実行のオーバヘッドが減っています。

この制御はモジュール・関数ごとに設定できます。例えば、起動時のみ `:debug` レベルのログも出したくて、本体実行中には `:info` 以上のログしか出したくないような場合は以下のように記述します。

```config/config.exs
config :logger,
  compile_time_purge_matching: [
    [module: Temp.Application, function: "start/2", level_lower_than: :debug],
    [module: Temp.Application, function: "set_interval/0", level_lower_than: :info]
  ]
```

これを実行すると想定どおりに起動時だけ `:debug` レベルのログが出ました。

```
$ iex -S mix
Erlang/OTP 21 [erts-10.2.1] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:1] [hipe] [dtrace]

Compiling 3 files (.ex)
Generated temp5 app

21:38:05.100 [info]  server started named afo
 
21:38:05.100 [debug] There is no supervisor

21:38:07.102 [info]  done 0th cycle
 
21:38:09.103 [info]  done 1th cycle
 
21:38:11.104 [info]  done 2th cycle
```

これ `config/config.exs` の記述だけでできますので、製品版を出荷するときに `Logger.disable` や `Logger.configure/1` でログを抑制している場合は `:compile_time_purge_matching` で抑制すると良いでしょう。

# 参考文献
[Elixir v1.8.1 Logger](https://hexdocs.pm/logger/Logger.html)
[はじめてな Elixir(23) ログを出力する](https://qiita.com/kikuyuta/items/b4d6a4e0ea591281f920)