はじめてな Elixir(23) ログを出力する

錬金術師のみなさま、新年あけましておめでとうございます。元日の今日は Logger モジュールを使って、コンソール、ファイル、syslog にログを出力してみます。

追記：関連する以下の記事も見て下さい。(2021.06.14)
- [Elixir 1.11 でついに新しくなった Logger](https://qiita.com/kikuyuta/items/aa6a073a81f002ebbcc5): この記事のときから Logger が大きく変わってます。
- [はじめてな Elixir(24) ログを出力しない](https://qiita.com/kikuyuta/items/9f15e92046845dcba4b0): ログ出力の制御についての記事です。

デバッグ出力は IO.puts や IO.inspect で出してましたが、公式マニュアル [Elixir 1.7.4 Logger](https://hexdocs.pm/logger/Logger.html) によると Logger 使うと良いことがいくつもあって、アプリケーションから恒常的にログを出力するようなら Logger に慣れるのが良さそうです。

- ログレベルによる出力する/しないの制御
  - syslog のログレベルに類似してます。ただし4段階しかない（不満たらたら）
- 負荷やパフォーマンスに対する対応
  - コンパイル時に完全に取り除くとかもできる
- 出力先（バックエンド）のカスタマイズ

なかなか機能満載な感じです。今回は UNIX の syslog にログを出すことを目標にしました。まずはテキスト「プログラミング Elixir」の 13.12 節 タスク：ロギングの追加」を見てください。なお、以下は OTP で遊んでる最中にログにチャレンジしたのでスーパバイザとか使ってますが、Logger を使うのに必須ではないです。

# コンソールにログを出力する
Elixir の Logger にはバックエンドという概念があって、そこに後付で出力先を変えるようにすることができます。Logger はデフォルトではコンソール、つまり今ユーザが入出力してる画面にログを出力します。

ロガーはアプリケーションとして動くので mix.exs に宣言しておいて、起動してもらうようにお願いします。mix new するときにデフォールトでここまで書いてあります。

```mix.exs
  def application do
    [
      extra_applications: [:logger], # この行があることを確認する
      mod: {Temp.Application, []}    # ここに起動するアプリケーションを記述
    ]
  end
```

あとはプログラムにロギングの行を突っ込めば出来上がり。

* `Logger.info("server started")` と文字列をダイレクトにかけるほか
* `Logger.debug(fn -> "interval timer set" end)` という風に関数を呼んでその結果の表示もできます。

上を動作させたプログラム一式を載せておきます。モジュール名は Temp という名前でやってます。これはアプリケーションの立ち上がりで1回ログにメッセージを出した後、2000ms ごとにメッセージを出すようにしてます。

```lib/temp/application.ex
defmodule Temp.Application do
  use Application

  def start(_type, _args) do
    {:ok, _pid} = Temp.Supervisor.start_link(:afo)
  end
end
```
これはスーパバイザ使ってる例で、最初にスーパバイザを起動して、スーパバイザが Server モジュールを起動して監視するようになってます。

```lib/temp/supervisor.ex
defmodule Temp.Supervisor do
  use Supervisor

  def start_link(pname) do
    {:ok, _sup} = Supervisor.start_link(__MODULE__, pname)
  end

  def init(pname) do
    child_processes = [worker(Temp.Server, [pname])]
    supervise(child_processes, strategy: :one_for_one)
  end
end
```
以下はスタート時に info レベルで起動されたことをログ出力して、その後は 2000ms ごとに debug レベルでログを出力します。num に debug ログを出力した回数が記録されてます。起動時のログ出力は文字列を指定しています。2000ms ごとの出力は無理やり無名関数を使ってみてます。

```lib/temp/server.ex
defmodule Temp.Server do
  @behaviour GenServer
  require Logger

  def start_link(pname) do
    Logger.info("server started named #{pname}")
    GenServer.start_link(__MODULE__, nil, name: pname)
  end

  def last(pname) do
    GenServer.call(pname, :last)
  end

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

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

  @impl GenServer
  def handle_info(:wakeup, num) do
    set_interval()
    {:noreply, num + 1}
  end

  @impl GenServer
  def handle_call(:last, _from, num) do
    {:reply, {:ok, num}, num}
  end
end
```
実行するとこんな感じになります。

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


18:13:19.524 [info]  server started named afo
 
rgb(255,0,0) 18:13:19.524 [debug] interval timer set
Interactive Elixir (1.7.4) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> Temp.Server.last(:afo)
{:ok, 0}
iex(2)> 
18:13:21.526 [debug] interval timer set
 
18:13:23.527 [debug] interval timer set
 
18:13:25.528 [debug] interval timer set
iex(2)> Temp.Server.last(:afo)
{:ok, 3}
iex(3)> 
18:13:27.529 [debug] interval timer set
 
18:13:29.530 [debug] interval timer set
```

info はデフォルトで `rgb(0,0,0)` で、debug は `rgb(0,255,255)` でコンソールに出力されてます。あと、warn が `rgb(255,255,0)` で、error が `rgb(255,0,0)` で表示されます。


# ログの出力先をファイルにする

コンソールじゃなくてファイルに出力したい場合はひとひねりが必要です。Elixir のライブラリにある Logger モジュール自体はファイルへの入出力やネットワークとのやりとりの機構をもちません。バックエンドと言われる拡張機能を別途入れる必要があります。

どんな拡張が良いのかなと [hex を logger で検索してみる](https://hex.pm/packages?search=logger&sort=recent_downloads)と [logger_file_backend](https://hex.pm/packages/logger_file_backend) がダントツでダウンロードされてます。web を見てもこれを使ってる例ばかりなので、安直ですがこれを入れてみます。

先程の mix.exs にさらに以下を追加します。使ってる Elixir の version が現在最新の 1.7.4 なので、バックエンドも最新が良いかと 0.0.10 以上を指定してます。（これ、動かす環境によっては新しすぎる可能性もあるかと思いますので適宜調整してください）

```mix.exs
  defp deps do
    [
      {:logger_file_backend, "~> 0.0.10"} # logger のバックエンドを入れる
    ]
  end
```

これを変えたら `mix deps.get` します。

つぎに logger の backend として LoggerFileBackend を使うことを宣言します。これは config.exs に記述します。

```config/config.exs
use Mix.Config

config :logger,
  backends: [{LoggerFileBackend, :error_log}]

config :logger, :error_log,
  path: "elixir.log"
```

これで望むファイルにログが出力されます。

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

Interactive Elixir (1.7.4) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)>  Temp.Server.last :afo
{:ok, 0}
iex(2)>  Temp.Server.last :afo
{:ok, 1}
iex(3)> 
```

```elixir.log
20:15:51.465 [info] server started named afo
20:15:51.465 [debug] interval timer set
20:15:53.465 [debug] interval timer set
20:15:55.467 [debug] interval timer set
```

# Syslog を使う
UNIX でいろいろ動かすなら syslog にまとめてログを突っ込んで、ログの流れの整理は syslog.conf でやりたいところです。これも検索すると [ex_syslogger](https://github.com/slashmili/ex_syslogger) がよく使われてるようなので、安直にこれを使ってみることにしました。

まず mix.exs を編集して mix deps.get します。

```mix.exs
  def application do
    [
      extra_applications: [:logger],
      included_applications: [:ex_syslogger],
      mod: {Temp.Application, []}
    ]
  end

  # Run "mix help deps" to learn about dependencies.
  defp deps do
    [
      {:ex_syslogger, "~> 1.4"},
    ]
  end
```

以下、アプリケーションとスーパバイザのプログラムを一通り載せておきます。が、コンソール出力のものと同じです。バックエンドを変えることで出力先が変わるだけです。

```application.ex
defmodule Temp.Application do
  use Application

  def start(_type, _args) do
    {:ok, _pid} = Temp.Supervisor.start_link(:afo)
  end
end
```

```supervisor.ex
defmodule Temp.Supervisor do
  use Supervisor

  def start_link(pname) do
    {:ok, _sup} = Supervisor.start_link(__MODULE__, pname)
  end

  def init(pname) do
    child_processes = [worker(Temp.Server, [pname])]
    supervise(child_processes, strategy: :one_for_one)
  end
end
```
サーバはちょっと変えてあります。起動時に error, warn , info, debug の4レベルで出力してみてます。さらに 2000ms ごとの "debug" と出てくるメッセージをなぜか warn レベルで出力してます。これ、あとで MacOS の話に絡みます。

```server.ex
defmodule Temp.Server do
  @behaviour GenServer
  require Logger

  def start_link(pname) do
    Logger.error("E: server started named #{pname}")
    Logger.warn("W: server started named #{pname}")
    Logger.info("I: server started named #{pname}")
    Logger.debug("D: server started named #{pname}")

    GenServer.start_link(__MODULE__, nil, name: pname)
  end

  def last(pname) do
    GenServer.call(pname, :last)
  end

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

  @interval 2000
  defp set_interval() do
    Logger.warn(fn -> "debug: interval timer set" end)
    Process.send_after(self(), :wakeup, @interval)
  end

  @impl GenServer
  def handle_info(:wakeup, num) do
    set_interval()
    {:noreply, num + 1}
  end

  @impl GenServer
  def handle_call(:last, _from, num) do
    {:reply, {:ok, num}, num}
  end
end
```

これを実行するとコンソールには何も出てきませんが、動かしてるマシンで syslogd が動いていて syslog.conf で記録が残るようにしておけば、その設定に従ってログが記録されます。

MacOS では syslog が動いていますので、Mac のコンソールアプリケーションで見ることができます。出てくるのはこれのログだけではないので大量のログが見えて大変見にくいです。*beam* とかでフィルタしてやると見やすいです。
![syslog.jpeg](https://qiita-image-store.s3.amazonaws.com/0/260320/20e2462e-ef0a-5e49-e109-afad20aad237.jpeg)

## MacOS ではレベルによってログが出ない
上をよく見ると、error レベルと warn レベルしか記録されてません。MacOS はデフォルトでは info レベル以下のログを出力しないようになってるようです。info レベル以下というと info レベルと debug レベルが該当しますので、なんと Elixir（や erlang）に4つあるログレベルのうち2つが出力されないということになります。

上で、デバッグメッセージをあえて warn レベルで出力したのはこのためです。以前の記事で [階段の上でも下でも電灯を点けたり消したりする](https://qiita.com/kikuyuta/items/632496c527fcd7c158d5) でも「電灯の点灯/消灯に関するメッセージ」ごときを warn レベルでロギングしているのはこのためです。

なお、Linux 環境の方は難しくなく syslog でログ出力できると思います。私は手元にさっと環境が用意できなかったので試してません。そもそもでいうと、erlang の syslog モジュールが4レベルとかせこいことを言わずに全部のレベルをサポートしてくれてればよかったんですが、どうも中途半端です。

### MacOS で syslog を制御する
今どきの MacOS は syslog に手が加えられていて ASL (Apple System Logger) というメカニズムに拡張されています。/etc/syslog.conf を見ると先頭に `# Note that flat file logs are now configured in /etc/asl.conf` とか書いてあって /etc/asl.conf というファイルで管理しているのがわかります。このあたりをハックするとすべてのレベルのログが出力できるのかもしれません。が、残念ながら結構時間かけてみたんですが私の力量では未だできず… です。

以下で可能と思うので、我こそはと思う方はチャレンジして、できたら私に教えてくださいませ。チャレンジの内容は参考文献等を見てください。MacOS でなにかするなら /etc/asl.conf （ひょっとすると /etc/syslog.conf も）触らないとなりません。sudo して特権ユーザになってもこのファイルシステムを変更できないので、なかなか面倒です。

- /etc 下のファイルを触れるように変更する
- syslog をしばく
 - syslog に関する設定ファイルを変更する /etc/asl.conf /etc/syslog.conf
 - syslogd に HUP シグナルを送る
- /etc 下のファイルを触れないように元に戻す（忘れがち）


# 参考文献

- 既出記事
 - [階段の上でも下でも電灯を点けたり消したりする](https://qiita.com/kikuyuta/items/632496c527fcd7c158d5)
 - [はじめてな Elixir(0)](https://qiita.com/kikuyuta/items/3c1798d15508040ccaaf)
 - [はじめてな Elixir(21) OTPのスーパバイザを使ってみる](https://qiita.com/kikuyuta/items/27f3198b3adacb4306aa)
 - [はじめてな Elixir(22) 自作のプロセスをスーパバイザの監視下におく](https://qiita.com/kikuyuta/items/04888d107edd9591aa1d)
 - [はじめてな Elixir(24) ログを出力しない](https://qiita.com/kikuyuta/items/9f15e92046845dcba4b0)
 - [Elixir 1.11 でついに新しくなった Logger](https://qiita.com/kikuyuta/items/aa6a073a81f002ebbcc5)
- Elixir の Logger 関係
 - [Elixir v1.7 Logger](https://hexdocs.pm/logger/Logger.html)
 - [Elixir v1.3 Logger 和訳](http://ns.maqcsa.org/elixir/docs/v1.3.0-dev/logger/Logger.html)
 - [logger_file_backend](https://hex.pm/packages/logger_file_backend)
 - [ex_syslogger](https://github.com/slashmili/ex_syslogger)
- Mac OS での log 関係
 - [Apple の Logging 記事](https://developer.apple.com/documentation/os/logging)
 - [外部マシンのsyslogをMacで確認する](https://qiita.com/gm_kou/items/ee2ac91177468cd8e646)
 - [【RTX810】OSX10.10 YosemiteでSyslogを外部から取得する【ヤマハ】](http://www.kyoji-kuzunoha.com/2014/12/yosemite-syslog.html)
 - [Mac OS Xでsyslogにデバッグログを出力する。](https://gist.github.com/poohtaro/5612430)
 - [macOS Sierra時代のsyslogとの付き合いかた](http://sugamasao.hatenablog.com/entry/2017/04/06/231713)
 - [外部マシンのsyslogをMacで確認する](https://qiita.com/gm_kou/items/ee2ac91177468cd8e646)
- Mac OS での特権の解除に関する記事（みだりにやらないこと）
 - [ターミナルでコマンド実行時に「Operation not permitted」と表示される場合の対処法](https://gori.me/mac/mac-tips/112082)
 - [EI Capitanでsudo付けているOperation not permittedが出た時の対処法](http://berukann.hatenablog.jp/entry/2015/12/30/123020)
[OS X 10.11 El Capitanのシステム保護機能「Rootless」を無効にするcsrutilコマンドの使い方。](https://applech2.com/archives/46435268.html)
- 昨年の大晦日に Elixir Logger の記事が出てましたよ。syslog 通さずにいろんなファイルにログを出力したい方はこちらも御覧ください
 - [[Elixir]Loggerで便利にログ出力](https://www.rikitechblog.com/elixir/logger-file-output-daily/)