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 のドキュメントで説明されています。

ログイベントの構造

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

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

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

ログイベントの処理

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

ロガー

イベントの処理は 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)

リファレンス

モジュールの読み込み

Logging.Logging ── モジュール

ログイベントのストリームのキャプチャ・フィルタリング・表示を行うユーティリティが含まれます。@info などの標準のログマクロはデフォルトで利用可能なので、ログイベントを作成するだけなら Logging のインポートは必要ありません。

イベントの作成

[email protected] ── マクロ
@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 ...]

ログレコードを作成します。message はログを表すメッセージです。利便性のため、標準の深刻度 Debug, Info, Warn, Error を使うログマクロ @debug, @info, @warn, @error が定義されます。@logmsg を使うと level をプログラムから設定でき、任意の LogLevel あるいは独自のログレベル型を利用できます。

message はログイベントを人間が読める形で説明する文字列に評価される式であるべきです。慣習として、この文字列は表示されるとき Markdown として整形されます。

省略可能な key=value 組のリストはユーザーが自由に定義できるメタデータであり、ログレコードの一部としてログバックエンドに渡されます。バリューだけを表す value という式だけが与えられると、キーを表す式は Symbol を使って生成されます。例えば xx=x となり、foo(10)Symbol("foo(10)")=foo(10) となります。キーバリューペアを “開く” には、標準の splat 構文を使って @info "blah" kws... としてください。

自動的に生成されるログデータを上書きするための特別なキーが存在します:

  • _module=mod: ログが属するモジュールをメッセージの位置と異なるモジュールに設定します。
  • _group=symbol: メッセージグループを上書きします (通常メッセージグループはソースファイルの名前から生成されます)。
  • _id=symbol: 自動的に生成されるメッセージの識別子を上書きします。これはソースファイルの異なる行で生成される複数のメッセージを非常に強く関連付ける必要があるときに有用です。
  • _file=string, _line=integer: ログメッセージの (見た目の) 生成位置を上書きします。

慣習として特別な意味を持つキーも存在します:

  • maxlog=integer: この警告は最大でも maxlog 回しか表示してはいけないことをバックエンドに伝えるヒントです。
  • exception=ex: ログメッセージで例外を転送するときに使われます。exception=(ex,bt) とすればバックトレース bt を付けることもできます。

@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
Logging.LogLevel ──
LogLevel(level)

ログレコードの深刻度/冗長度です。

ログレベルはログレコードをフィルタリングするための判断材料を提供します。この型の値を使えばログレコードのデータ構造を構築する処理を始める前に最低限のフィルタリングが行えます。

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

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

実装すべきメソッド 簡単な説明
handle_message ログイベントの処理
shouldlog イベントの早期フィルタリング
min_enabled_level 受理するイベントの最低ログレベル
省略可能なメソッド デフォルトの定義 簡単な説明
catch_exceptions true イベント評価中に発生する例外を捕捉するかどうか

ロガーを表す抽象型です。ロガーはログレコードのフィルタリングとディスパッチを制御します。生成されたログレコードを検査して何をすべきかを判断するときにユーザーから制御できる最初のコードがロガーのコードです。

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

レベル level のメッセージを logger に記録します。メッセージの (論理的な) 発生場所はモジュール _module, グループ group, ソースファイル名 file, ソースの行番号 line で与えられます。id は形式の指定されないユニークな値 (典型的には Symbol) であり、フィルタリングでログ文を特定するときのキーとして利用できます。

Logging.shouldlog ── 関数
shouldlog(logger, level, _module, group, id)

レベル level, モジュール _module, グループ group, 一意ログ識別子 id を持つメッセージを logger が受理するなら true を返します。

min_enabled_level(logger)

logger の早期フィルタリングで使われる最小有効化レベルを返します。つまり、このレベル以下のメッセージは全てフィルタリングで取り除かれます。

Logging.catch_exceptions ── 関数
catch_exceptions(logger)

ログレコードの構築中に発生した例外を logger が捕捉するなら true を返します。デフォルトでは捕捉されます。

デフォルトでは全ての例外が捕捉され、ログレコードの構築がプログラムをクラッシュさせないようになっています。このため、ユーザーはめったに使われない機能 ──例えばデバッグログ── をプロダクションシステムで臆することなく利用できます。

ログを監査証跡 (audit trail) として使う場合には、独自のロガー型に対して例外の捕捉を無効化するべきです。

Logging.disable_logging ── 関数
disable_logging(level)

レベル level 以下のログメッセージを無効化します。これはグローバルな設定であり、デバッグログを非常に小さなコストで無効化するためにあります。

ロガーの利用

Logging.global_logger ── 関数
global_logger()

グローバルなロガーを返します。現在のタスクに対するロガーが用意されていないときはこのロガーがメッセージを受け取ります。

global_logger(logger)

グローバルなロガーを logger に設定し、以前のグローバルなロガーを返します。

Logging.with_logger ── 関数
with_logger(function, logger)

ログメッセージを logger にリダイレクトしながら function を実行します。

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

with_logger(logger) do
    test(1)
    test([1,2])
end
Logging.current_logger ── 関数
current_logger()

現在のタスクに対するロガーを返します。現在のタスクにロガーが設定されていなければグローバルなロガーを返します。

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

Logging.NullLogger ──
NullLogger()

全てのメッセージを無視して何も出力しないロガーです。ロガーにおける /dev/null です。

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

テキストコンソールにおける可読性を最適化するフォーマットを持ったロガーです。例えば Julia REPL で対話的な処理を行うときの利用が想定されています。

min_level より小さいログレベルはフィルタリングによって取り除かれます。

キーワード引数を渡すとメッセージのフォーマットを変更できます:

  • meta_formatter: ログイベントのメタデータ (level, _module, group, id, file, line) を受け取ってログメッセージの色・先頭に付ける文字列・末尾に付ける文字列を返す関数です (色は printstyled で使われます)。デフォルトでは先頭にログレベルが付き、末尾にモジュール・ファイル・行番号が付きます。
  • show_limited: 大きなデータ構造を出力するときにスクリーンに収まるよう幅に制限を加えます。フォーマットで使われる IOContext:limit が設定されます。
  • right_justify: ログメタデータを右揃えするときの列数を表す整数です。デフォルトはゼロ (揃えない) です。
SimpleLogger(stream=stderr, min_level=Info)

min_level 以上のメッセージを全てログとして出力する単純なロガーです。