Pony 試乗記(3) ログ記録

# はじめに

[素数列生成](https://qiita.com/tadashi9e/items/c0b697d9b6bf79248c1e)プログラムが本当に非同期で動作しているのか確かめたいと思いました。
そのために、各所にログを入れて動かしてみます。

# ロガー

Pony の標準ライブラリにロガーがあるのでそれを使います。

https://stdlib.ponylang.io/logger--index/

ログレベルとして、Fine/Info/Warn/Error が用意されており、単純に Info レベルのログを出すだけなら

~~~pony
  let logger = StringLogger(Info, env.out)
  logger.log("some message")
~~~

という感じで出せそうです。

ドキュメントによると、log メソッド引数文字列の構築コストを抑えるために当該ログレベルが出力対象かチェックしてから log メソッドを呼び出すことが推奨されています:

~~~pony
  let logger = StringLogger(Info, env.out)  // Info レベル以上が出力対象
  logger(Info) and logger.log("Info レベルのメッセージなのでなので出力される")
  logger(Fine) and logger.log("Fine レベルのメッセージなので出力されない")
~~~

## 時刻を付与したログ出力

[デフォルトのログ出力フォーマット](https://stdlib.ponylang.io/logger-DefaultLogFormatter/) では、

- ソースファイルパス名
- 行番号
- 行のなかの位置

を付けてログ出力してくれます。さらにタイムスタンプも付けたいと思います。

そこで、タイムスタンプ付き LogFormatter を作成してみます。

### 現在時刻文字列の生成

時刻を yyyy-mm-dd hh:<span>mm</span>:ss.fffffffff 形式の文字列で取得する標準ライブラリがないかと見回してみたのですが、見つかりませんでした。探し方が悪いのか、将来追加されるかもしれません。
仕方がないので、まずは hh:<span>mm</span>:ss.fffffffff 形式で時刻を表す文字列を取得するクラスを作成します。

~~~pony
use "format"
use "time"

class DateTimeFormatter
  fun hms(t: (I64, I64) = Time.now()): String =>
    """
    「hh:mm:ss.fffffffff」形式で時刻を返す。
    引数に時刻（を表すタプル）が与えられなければ、現在時刻を表す文字列を返す。
    """
    let h_str: String = _h(t)
    let m_str: String = _m(t)
    let s_str: String = _s(t)
    let f_str: String = _f(t)
    (recover String(h_str.size() + m_str.size() + s_str.size()
    + f_str.size() + 3) end)
    .> append(h_str)
    .> append(":")
    .> append(m_str)
    .> append(":")
    .> append(s_str)
    .> append(".")
    .> append(f_str)
  fun _h(now: (I64,I64) = Time.now()): String =>
    """
    「時」部分を 0 埋めされた 2 桁の文字列として返す
    """
    let hour = (9 + (now._1  / (60 * 60))) % 24
    Format.int[I64](hour where width = 2, fill='0')
  fun _m(now: (I64,I64) = Time.now()): String =>
    """
    「分」部分を 0 埋めされた 2 桁の文字列として返す
    """
    let min = (now._1  / 60) % 60
    Format.int[I64](min where width = 2, fill='0')
  fun _s(now: (I64,I64) = Time.now()): String =>
    """
    「秒」の整数部分を 0 埋めされた 2 桁の文字列として返す
    """
    let sec = now._1 % 60
    Format.int[I64](sec where width = 2, fill='0')
  fun _f(now: (I64,I64) = Time.now()): String =>
    """
    「秒」の小数点以下の部分を 0 埋めされた 2 桁の文字列として返す
    """
    let sec = now._1 % 60
    Format.int[I64](now._2 where width = 9, fill='0')
~~~

[DefaultLogFormatter](https://stdlib.ponylang.io/src/logger/logger/#L160) のソースを見ると、予め文字数をカウントして必要になる文字列領域を確保しておきそこに append で文字列を構築する、という小技が使われていたのでそれを真似しました。

### 時刻付きログフォーマッタの作成

上で作った DateTimeFormatter を用いるログフォーマッタ DateTimeLogFormatter を、インターフェース LogFormatter の実装として作成します。

- 時刻
- ソースファイル名
- 行番号

をメッセージ行頭に付与します。

ソースファイル名部分は DefaultLogFormatter だとフルパス名ですが出力行が長いのでファイル名に変更しました。

~~~pony
use "logger"

class DateTimeLogFormatter is LogFormatter
  fun box apply(msg: String, loc: SourceLoc): String =>
    let hms: String = DateTimeFormatter.hms()
    let file_name: String = _basename(loc)
    let linenum: String = loc.line().string()
    (recover String(hms.size() + file_name.size() + linenum.size()
      + msg.size() + 5)
    end)
    .> append(hms)
    .> append(": ")
    .> append(file_name)
    .> append(":")
    .> append(linenum)
    .> append(": ")
    .> append(msg)
  fun _basename(loc: SourceLoc): String =>
    let s = loc.file()
    try
      let i = s.rfind("/")?
      s.substring(i + 1)
    else
      s
    end
~~~

### 時刻付きロガー作成（失敗）

作成した DateTimeLogFormatter をそのまま StringLogger に引数として与えれば、とりあえず「時刻付きでログを出したい」という希望は叶えられますが、さらにログレベルも付けられるようにしたいと思いました。

独自のロガークラス MyLogger を作って、その log メソッド引数に渡されたログレベルを元に "[Fine]"/"[Info]"/"[Warn]"/"[Error]" をログメッセージに追加してみます。

~~~pony
class MyLogger
  let logger: Logger[String]
  new create(level: LogLevel, env: Env) =>
    logger = StringLogger(level, env.out, DateTimeLogFormatter)
  fun apply(level: LogLevel): Bool =>
    logger(level)
  fun log(level: LogLevel, msg: String): Bool =>
    logger.log(
      (match level
        | Fine => "[Fine]"
        | Info => "[Info]"
        | Warn => "[Warn]"
        | Error => "[Error]"
        end) + msg)
~~~

これを使って

~~~pony
let logger = MyLogger(Fine, env)
logger.log(Fine, "テスト")
~~~

のようにしてみると、一見うまく動作しているように見えますがよくよく見ると記録される行番号が MyLogger で StringLogger の log を呼び出している部分になっています。これでは行番号を出す意味がありません。

仕方がないので一旦ログレベルの付与は諦めることにしました。

~~~pony
let logger: Logger[String] = StringLogger(Fine, env.out, DateTimeLogFormatter)
logger(Fine) and logger.log(Fine, "[Fine] これは Fine レベルのメッセージです")
~~~
のように呼び出し側で付与することでとりあえずは凌げます。

# 使ってみる

上記で作った 素数列生成プログラムにログを仕込んで再度動かしてみました。非同期で動作する様子を確認することができました。

~~~
$ ./primes_logger 10
11:46:54.007034849: primes.pony:99: [Fine] TwoAndOddsStream: 2
11:46:54.007038636: primes.pony:108: [Fine] TwoAndOddsStream: 3
11:46:54.007040830: primes.pony:108: [Fine] TwoAndOddsStream: 5
11:46:54.007042383: primes.pony:108: [Fine] TwoAndOddsStream: 7
11:46:54.007041702: primes.pony:136: [Fine] PrimeStream[2]: is prime
2
11:46:54.007045629: primes.pony:108: [Fine] TwoAndOddsStream: 9
11:46:54.007074123: primes.pony:126: [Fine] PrimeStream[3]: checking (2)
11:46:54.007077269: primes.pony:136: [Fine] PrimeStream[3]: is prime
3
11:46:54.007079813: primes.pony:126: [Fine] PrimeStream[5]: checking (2)
11:46:54.007083029: primes.pony:126: [Fine] PrimeStream[5]: checking (3)
11:46:54.007084512: primes.pony:136: [Fine] PrimeStream[5]: is prime
5
11:46:54.007087438: primes.pony:126: [Fine] PrimeStream[7]: checking (2)
11:46:54.007089061: primes.pony:126: [Fine] PrimeStream[7]: checking (3)
11:46:54.007090413: primes.pony:126: [Fine] PrimeStream[7]: checking (5)
11:46:54.007092527: primes.pony:136: [Fine] PrimeStream[7]: is prime
7
11:46:54.007095773: primes.pony:126: [Fine] PrimeStream[9]: checking (2)
11:46:54.007112635: primes.pony:126: [Fine] PrimeStream[9]: checking (3)
11:46:54.007114649: primes.pony:130: [Fine] PrimeStream[9]: not prime (3)
~~~