JuliaのLogging

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

https://docs.julialang.org/en/v1/stdlib/Logging/#

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

``` julia
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
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の出力を抑制するには次のようにする。

``` julia
Logging.disable_logging(Logging.Info)
```

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

``` julia
$ 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`にタイムスタンプ情報を追加して返しているだけ。

``` julia
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`を置き換える。

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

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


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

``` julia                                            
julia> @warn [1, 2]
[ 2020-05-23T19:20:41.974 : Warning: [1, 2]                             @ Main REPL[9]:1
```
ちなみに1行に収まらなくなると、postfixは次の行に出力されるようになる。

``` julia
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の出力の挙動を見てもファイル出力に適しているとは言えない。独自にじっそうすればいいはなしではあるのだけど。