LoginSignup
11
8

More than 1 year has passed since last update.

@kikuyuta(豊 菊池)inkochi.ex

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

Last updated at Posted at 2019-01-01

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

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

デバッグ出力は IO.puts や IO.inspect で出してましたが、公式マニュアル Elixir 1.7.4 Logger によると 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 で検索してみると 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 がよく使われてるようなので、安直にこれを使ってみることにしました。

まず 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

MacOS ではレベルによってログが出ない

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

上で、デバッグメッセージをあえて warn レベルで出力したのはこのためです。以前の記事で 階段の上でも下でも電灯を点けたり消したりする でも「電灯の点灯/消灯に関するメッセージ」ごときを 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 下のファイルを触れないように元に戻す（忘れがち）

参考文献

11
8
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
11
8