JuliaのLogging

近代的な言語にはデフォルトでログライブラリが用意されているものだが、Juliaにもある。Loggingがそれ。

概要

グローバルにLoggerが一つ定義されており、後述のマクロを使うとこのLoggerを用いて出力が行われる。デフォルトでは、ConsoleLoggerが設定されている。これはログをstderrに書き出す。

julia> import Logging

julia> Logging.current_logger()
ConsoleLogger(Base.TTY(RawFD(0x00000010) open, 0 bytes waiting), Info, Logging.default_metafmt, true, 0, Dict{Any,Int64}())

Log レベル

デフォルトでは、下記4つのログレベルが用意されている。

• Debug
• Info
• Warn
• Error

上から下に向かってシビアさが上がっていく。XXX以上にシビアなログだけを出力する、というような形でログ出力を制御する。デフォルトではInfo以上しか出力されないので、Debugレベルのログは出力されない。

この分類はだいたい標準的。ちなみに、Log4j だとこれに加えてもっと細かいtraceと致命的なエラーを表すfatalがある。ソースを見てみると、これらのレベルにはそれぞれ、-1000, 0, 1000, 2000の間の値が割り当てられているので、この上も下も間も勝手に作ることができるようだ。

使い方

マクロ@debug, @info, @warn, @errorを使う。

julia> @debug [1, 2]

julia> @info [1, 2]
[ Info: [1, 2]

julia> @warn [1, 2]
┌ Warning: [1, 2]
└ @ Main REPL[3]:1

julia> @error [1, 2]
┌ Error: [1, 2]
└ @ Main REPL[4]:1

デフォルトでは、@debugだとログレベルが低すぎるため何も出力されない。また、@infoでは行番号やモジュール名などの情報が出力されないが、@warnや@errorでは出力される。このあたりの挙動はConsoleLoggerのmeta_formatterで変更する事ができる。

出力レベルの変更

デフォルトではレベル0以上、つまりInfo以上のシビアさのものが出力される。Infoの出力を抑制するには次のようにする。

Logging.disable_logging(Logging.Info)

一方Debugを出力するには、環境変数JULIA_DEBUGに対象となるモジュール名を指定するのがお作法のようだ。

$ JULIA_DEBUG=Main julia 
略
julia> @debug "test"
┌ Debug: test
└ @ Main REPL[1]:1

ソースを読むとJULIA_DEBUG=A,Bのように列挙したり、JULIA_DEBUG=!Cみたいに「C以外」のような指定ができるようなのだが、この辺も全くドキュメントに書かれてないんだよなあ。。

disable_loggingで十分小さい値を指定してやればDebugが出力されるようになりそうなものだが、試してみるとできない。どうも環境変数を設定しないと絶対出ないようだ。なんか不思議な設計だなあ。。

出力をカスタマイズ

普通ログには時刻を表示するものだろう、ということでConsoleLoggerのmeta_formatterをカスタマイズして時刻が表示されるようにしてみる。ついでに、ファイル名や行数が必ず別の行に表示されるという挙動もいやなので、これも変更する。

まず、時刻付きのフォーマット関数を定義する。デフォルトのdefault_metafmtを呼び出して、その出力のprefixにタイムスタンプ情報を追加して返しているだけ。

import Logging
import Dates

function timed_metafmt(level, _module, group, id, file, line)
  color, prefix, suffix = 
    Logging.default_metafmt(level, _module, group, id, file, line)
  timestamp = Dates.now()
  prefix2 = "$timestamp : $prefix"
  return color, prefix2, suffix
end

これを使って、global_loggerを置き換える。

Logging.global_logger(Logging.ConsoleLogger(meta_formatter=timed_metafmt,
                                            right_justify=100))

ConsoleLoggerは、prefix, message, postfix を出力するのだが、prefixとmessageは左揃えで出力し、postfix
(モジュール名、ファイル名、行番号)は右揃えで出力する。right_justify というのはこのとき右揃えに揃える。

こうすると、こんな感じに出力される。

julia> @warn [1, 2]
[ 2020-05-23T19:20:41.974 : Warning: [1, 2]                             @ Main REPL[9]:1

ちなみに1行に収まらなくなると、postfixは次の行に出力されるようになる。

julia> @warn collect(1:40)
┌ 2020-05-23T19:35:02.957 : Warning: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40]
└                                                                       @ Main REPL[13]:1

所感

そういう言語じゃないので当たり前なのだろうけど、JavaなどのLoggingライブラリと比べるといろいろ貧弱。JavaなどのLogライブラリだと外部ファイルでLoggingの挙動を制御できるのが普通だが、そういう事ができるようにはなっていない。ファイルに書き出すLoggerも用意されていない。もちろんローテーションなんてしてくれない。また、Loggerがデフォルトでグローバルというのも便利といえば便利だが、あんまり関心しないというか。。ログのレベル設定もグローバルにしかできない。

時刻を記録する方法がデフォルトで存在しないのも理解に苦しむ。時刻を入れるようにすると遅くなるから、というようなことがドキュメントに書いてあるけど、デフォルトで有効にするかどうかはともかく、普通用意はするだろ、と。

ConsoleLoggerの出力をファイルに出すこともできるが、postfixの出力の挙動を見てもファイル出力に適しているとは言えない。独自にじっそうすればいいはなしではあるのだけど。