Logging

Logging モジュールは計算の履歴や進捗をイベントのログとして記録する方法を提供します。イベントはソースコードにログを表す文を挿入することで作成されます:

@warn "Abandon printf debugging, all ye who enter here!"
┌ Warning: Abandon printf debugging, all ye who enter here!
└ @ Main REPL[1]:1

Logging モジュールのシステムは println() をソースコード中にまき散らすよりもいくつかの点で優れています。第一に、Logging を使うとメッセージの可視性や表示方法をソースコードを改変せずに変更できます。例えば上の例で使った @warn ではなく @debug を使って

@debug "The sum of some values $(sum(rand(100)))"

とすると、デフォルトでは何も出力されなくなります。さらにシステムは無視されるメッセージを評価しないので、ソースコードにこういったデバッグ文を残しておいても実行速度への影響はごくわずかです。この例で言えば、sum(rand(100)) の評価とその後の文字列処理はデバッグログが有効になっていない限り実行されません。

第二に、ログツールを使うと各イベントに任意のデータをキーバリューペアとして関連付けられるようになります。この機能を使うとローカル変数などのプログラムの状態をキャプチャして後で解析するといったことが可能です。例えばローカル変数の配列 A とベクトル v の和をログに関連付けるには次のようにします。ここで v の和には s という名前が付きます:

A = ones(Int, 4, 4)
v = ones(100)
@info "Some variables"  A  s=sum(v)

# 出力
┌ Info: Some variables
│   A =
│    4×4 Array{Int64,2}:
│     1  1  1  1
│     1  1  1  1
│     1  1  1  1
│     1  1  1  1
└   s = 100.0

マクロ @debug, @info, @warn, @error は共通の機能を持ちます。この機能は一般的なマクロ @logmsg のドキュメントで説明されています。

ログイベントの構造

各イベントはいくらかのデータを生成します。イベントのデータにはユーザーによって提供されるものもあれば、自動的に取得されるものもあります。次に示すのはユーザーが定義するデータです:

• ログレベルはメッセージの大まかなカテゴリであり、早い段階のフィルタリングで使われます。LogLevel 型で表される標準のログレベルがいくつかありますが、ユーザー定義のログレベルも利用できます。標準のログレベルはそれぞれ異なる用途を持ちます:

  • Debug はプログラムの開発者に向けられた情報です。このイベントはデフォルトで無効化されます。
  • Info はユーザーに向けられた一般的な情報です。これは println を直接使う代わりと考えてください。
  • Warn はプログラムが正しく動作しておらず、おそらく何らかの対処が必要になることを意味します。ただし Warn が出てもプログラムの動作を続けることはできます。
  • Error はプログラムが正しく動作しておらず、(少なくとも現在のコードからは) おそらく回復できないことを意味します。例外を出せば必要なデータは全て伝達できるので、このログレベルが必要にならない場合もよくあります。

• メッセージはイベントを説明するオブジェクトです。慣習として、メッセージとして渡される AbstractString は Markdown フォーマットとみなされます。他の型のメッセージは、テキストベースの出力では print(io, obj) または string(obj) を使って文字列に変換されます。インストールされたロガーで使われる他のマルチメディア表示がある場合は show(io,mime,obj) が使われることもあります。

• 省略可能なキーバリューペアはイベントに任意のデータを関連付けます。いくつかのキーは慣習として特別な意味を持ち、イベントの解釈方法が変わります。詳しくは @logmsg を参照してください。

ログシステムは各イベントに対して標準的な情報も生成します:

• module: ログマクロが展開されたモジュールです。
• file, line: ログマクロが展開された場所を表すファイル名と行番号です。
• id: ログマクロが書かれたソースコードにおける文を表す固定されたユニークなメッセージ識別子です。この識別子はファイルのソースコードが変更されても (ログ文が同じなら) それなりに安定するように設計されています。
• group: デフォルトでは現在実行中のファイル名の拡張子を除いたベースネームに設定されます。これはログレベルよりも細かいカテゴリ (例えば非推奨の警告を示すグループ :depwarn など) でメッセージをまとめるとき、あるいはモジュール単位で (またはモジュールをまたいで) メッセージを論理的にまとめるときに利用できます。

発生時刻などの使われてもおかしくない情報がデフォルトではイベントデータに含まれていないことに注意してください。そういった情報は取得コストが大きく、現在のロガーからは動的にしか利用できないためです。イベントデータに時刻・バックトレース・グローバル変数の値やその他の情報を必要に応じて追加する独自のロガーは簡単に定義できます。

ログイベントの処理

これまでの例からも分かるように、ログ文にはログイベントの行き先や処理方法の指定がありません。これはログシステムを合成可能にして並行処理でも自然に利用できるようにするために鍵となる特徴です。ログシステムがこの方法を採用したのは、二つの異なる関心を分離するためです:

• ログイベントの作成は、イベントの発生場所や含めるべきデータを決める必要のあるモジュールの著者の関心です。
• 表示・フィルタリング・収集・記録といったログイベントの処理は、複数のモジュールを組み合わせて協調動作させるアプリケーションの著者の関心です。

ロガー

イベントの処理は logger によって行われます。logger はイベントを表示させるために調整できる最初のコードです。全てのロガーは AbstractLogger の部分型となります。

イベントが起動すると適切なロガーが検索されます。タスクにローカルなロガーがまず検索され、見つからなければグローバルなロガーがフォールバックとなります。アプリケーションコードはイベントの処理方法を知っているはずであり、コールスタックのどこかにロガーが存在するはずだ、というのがここでのアイデアです。つまりコールスタックを上に向かいながらロガーが検索するということです ──言い換えれば、ロガーは動的スコープです (これはロガーが静的スコープのログフレームワークと対称的です。静的スコープのシステムでは複数のモジュールの機能を合成する状況でログの制御が不格好になります)。

グローバルのロガーは global_logger で設定でき、タスクローカルのロガーは with_logger で設定できます。新しく起動されるタスクは親タスクのロガーを継承します。

Julia のログライブラリは三つのロガーを提供します。ConsoleLogger は REPL を開始したときのデフォルトのロガーであり、イベントを人間が読めるテキストフォーマットで表示し、フォーマットとフィルタリングに関して簡単かつユーザーフレンドリーな制御を提供します。NullLogger はメッセージを捨てるためのロガーであり、ストリームの devnull に似たものです。SimpleLogger はテキストフォーマットに対応した非常に単純なロガーであり、主にログシステムをデバッグするのに使われます。

独自のロガーがオーバーロードすべき関数はリファレンスで説明されます。

早期フィルタリングとメッセージ処理

イベントが発生すると、出力されないメッセージの生成を避けるための早期フィルタリングが行われます:

1. メッセージのログレベルとグローバルの最小ログレベル (disable_logging で設定される値) が比較されます。これは単純で非常にコストの小さいグローバルな設定です。
2. ロガーの現在状態が確認され、ロガーがキャッシュした最小ログレベル (min_enabled_level が返す値) とメッセージレベルが比較されます。この振る舞いは環境変数で上書きできます (後述)。
3. 現在のロガーと静的に計算できる最小限の情報 (レベル・モジュール・グループ・ID) を引数として shouldlog 関数が呼び出されます。shouldlog の引数で特に便利なのが id で、この値があると別の場所にキャッシュされた真偽値を使って通常よりも早くイベントを破棄できます。

以上のチェックを全て通過するとメッセージとキーバリューペアは完全に評価され、handle_message を通して現在のロガーに渡されます。handle_message は必要ならさらにフィルタリングを行ってから、イベントをスクリーンに表示したりファイルへ保存したりといった処理を行います。

ログイベントの生成中に発生した例外はデフォルトで捕捉されて記録されます。こうなっているのは、プロダクションシステムで稀にしか使われないデバッグイベントを有効化したときに壊れたイベントがアプリケーションをクラッシュさせるのを防ぐためです。この振る舞いは catch_exceptions を拡張することでロガー型ごとにカスタマイズできます。

ログイベントのテスト

ログイベントは通常のコード実行に付随する副次的な処理ですが、特定の情報を持ったメッセージや警告をテストしたい場合もあるでしょう。ログイベントストリームに対してパターンマッチを行う @test_logs マクロが Test モジュールによって提供されます。

環境変数

メッセージのフィルタリングは環境変数 JULIA_DEBUG で設定でき、この機能を使えばファイルまたはモジュール単位でデバッグログを簡単に有効化できます。例えば JULIA_DEBUG=loading として julia を起動すると、loading.jl に含まれる @debug からのログメッセージが有効になります:

$ JULIA_DEBUG=loading julia -e 'using OhMyREPL'
┌ Debug: Rejecting cache file /home/user/.julia/compiled/v0.7/OhMyREPL.ji due to it containing an invalid cache header
└ @ Base loading.jl:1328
[ Info: Recompiling stale cache file /home/user/.julia/compiled/v0.7/OhMyREPL.ji for module OhMyREPL
┌ Debug: Rejecting cache file /home/user/.julia/compiled/v0.7/Tokenize.ji due to it containing an invalid cache header
└ @ Base loading.jl:1328
...

同様の方法で、モジュール (例: Pkg) やモジュールルート (参照: Base.moduleroot) 単位のデバッグログを環境変数から有効にできます。特別な値 all に設定すると全てのデバッグログを有効にできます。

REPL からデバッグログを有効にするには、ENV["JULIA_DEBUG"] を対象のモジュールの名前に設定します。REPL で定義される関数はモジュール Main に属するので、次のようにすれば REPL で定義される関数に含まれる @debug を確認できます:

julia> foo() = @debug "foo"
foo (generic function with 1 method)

julia> foo()

julia> ENV["JULIA_DEBUG"] = Main
Main

julia> foo()
┌ Debug: foo
└ @ Main REPL[1]:1

ログイベントの保存

ログイベントをファイルに書き込めると便利な場合もあります。タスクローカルなロガーおよびローカルなロガーを使ってログの情報をテキストファイルに書き込む例を示します:

# logging モジュールを読み込む。
julia> using Logging

# テキストファイルを書き込み用に開く。
julia> io = open("log.txt", "w+")
IOStream(<file log.txt>)

# SimpleLogger を作成する。
julia> logger = SimpleLogger(io)
SimpleLogger(IOStream(<file log.txt>), Info, Dict{Any,Int64}())

# タスクローカルなメッセージをログとして出力する。
julia> with_logger(logger) do
           @info("a context specific log message")
       end

# バッファされたメッセージをファイルに書き込む。
julia> flush(io)

# グローバルなロガーを logger に設定する。
julia> global_logger(logger)
SimpleLogger(IOStream(<file log.txt>), Info, Dict{Any,Int64}())

# このメッセージはファイルに書き込まれる。
julia> @info("a global log message")

# ファイルを閉じる。
julia> close(io)

リファレンス

モジュールの読み込み

イベントの作成

@debug message  [key=value | value ...]
@info  message  [key=value | value ...]
@warn  message  [key=value | value ...]
@error message  [key=value | value ...]

@logmsg level message [key=value | value ...]

@debug "冗長なデバッグ情報/デフォルトでは非表示"
@info  "ユーザーに情報を伝えるメッセージ"
@warn  "何かがおかしい/注意が必要"
@error "致命的でないエラーの発生"

x = 10
@info "メッセージに変数の値を付ける" x a=42.0

@debug begin
    sA = sum(A)
    "sum(A) = $sA はコストの大きい演算であり、shouldlog が true を返したときにだけ評価される"
end

for i=1:10000
    @info "デフォルトのバックエンドでは (i = $i) が十回だけ表示される" maxlog=10
    @debug "Algorithm1" i progress=i/10000
end

LogLevel(level)

AbstractLogger を使ったイベントの処理

イベントの処理は抽象型 AbstractLogger に関連付いた関数をオーバーライドすることで制御されます:

handle_message(logger, level, message, _module,
               group, id, file, line; key1=val1, ...)

shouldlog(logger, level, _module, group, id)

min_enabled_level(logger)

catch_exceptions(logger)

disable_logging(level)

ロガーの利用

global_logger()

global_logger(logger)

with_logger(function, logger)

function test(x)
    @info "x = $x"
end

with_logger(logger) do
    test(1)
    test([1,2])
end

current_logger()

Julia のログシステムに付属するロガー

NullLogger()

ConsoleLogger(stream=stderr, min_level=Info; meta_formatter=default_metafmt,
              show_limited=true, right_justify=0)

SimpleLogger(stream=stderr, min_level=Info)