HaskellのロガーKatipを試す

モチベ

Haskell の実行時ログ出力を行うライブラリは monad-logger が一番有名っぽい。 これは Yesod 陣営が開発しているから安心感があるし、バックエンドが fast-logger なので速度も信頼できる。 ただ (自分の調べ方が悪いのかもしれないが) ちょっと自分の用途には機能が足りなかった。 具体的には以下の機能:

  • ログにタイムスタンプを付記したい。
  • ロガーに名前をつけたい。
  • ファイルサイズか日付でログローテーションしたい。

Katip という別のロガーライブラリは機能が豊富のようなので今回はそれを試してみる。

(この記事のHaskell環境: lts-6.23)

Katipのおそらく最小の構成

とりあえず動かしてみる。

{-# LANGUAGE OverloadedStrings #-}
{-# LANGUAGE TemplateHaskell #-}

module Main where

import System.IO (stdout)
import Control.Monad.Trans (lift)

import Katip

main :: IO ()
main = do
  le <- initLogEnv "MyApp" "prod"                      -- (1)
  hs <- mkHandleScribe ColorIfTerminal stdout InfoS V0 -- (2)
  let le' = registerScribe "stdout scribe" hs le       -- (3)
  runKatipContextT le' () "main" $ do                  -- (4)
    $logTM InfoS "ログ出力"                            -- (5)
    $logTM DebugS "これは出力されない"                 -- (6)
    lift $ putStrLn "ふつうの出力"
    return ()
  return ()
  
-- > [2016-10-30 08:00:31][MyApp.main][Info][kaz-mba-lb8o][23644][ThreadId 7][main:Main app/Main.hs:17:5] ログ出力
-- > ふつうの出力
  1. 新しい LogEnv を作る。ルートロガー名と実行環境名を指定している。
  2. 新しい Scribe を作る。 Scribe というのはログの出力先とログレベルなどの設定を組にしたもの。Katip はログレベルとして severity level (InfoとかErrorとか) だけでなくverbosity level (V0とかV1とか) も指定できる。
  3. LogEnvScribe を登録する。
  4. 作成した LogEnv でロガーのモナドを走らせる。
  5. Info レベルでログを出力する。 $ がついているのは TemplateHaskell でソースファイルの行番号などをログに出力するため。
  6. Debug レベルでログを出力する。しかし LogEnv が Info レベルの Scribe しか持っていないので出力されない。

ロガーのモナドの下でログ出力を行うという点以外はかなり普通のロガーという感じだ。 ファイルに出力したいときは stdout の代わりにファイルハンドルを渡せばいいし、 出力先を増やしたいときは Scribe を追加すればいい。

ログローテーション

Katip は組込みのログローテーションの仕組みは持っていないようだが、 Katip の開発元の Soostone 社は Katip と別に rotating-log というライブラリを公開している。 rotating-log の説明文によると、どうやらファイルサイズベースのローテーションを提供しているらしい。

それならログローテーションはこれでやればいいのかな……と思いきや、

This is so that it can be used to log non-textual streams such as binary serialized or compressed content.

とのことなのでテキストログのローテーションで使うものではないらしい。

一応 rotating-log を Scribe にしてテキストログのローテーションを試してみたが (以下のコード) 参考にしない方がいいかもしれない。

{-# LANGUAGE OverloadedStrings #-}
{-# LANGUAGE TemplateHaskell #-}

module Main where

import System.IO ( hSetBuffering, hIsTerminalDevice, stdout
                 , BufferMode(..)
                 , Handle
                 )
import Control.Monad (when)
import Control.Monad.Trans (lift)
import Data.Monoid ((<>))
import qualified Data.Text.Encoding as T
import qualified Data.Text.Lazy as LT
import qualified Data.Text.Lazy.IO as LT
import qualified Data.Text.Lazy.Builder as LT
import qualified Data.Text.Lazy.Encoding as LT

import Katip
import Katip.Scribes.Handle (formatItem)
import System.RotatingLog ( RotatingLog
                          , mkRotatingLog, archiveFile
                          , rotatedWrite, rotatedClose
                          )

mkRotatingLogScribe :: RotatingLog -> Severity -> Verbosity -> IO Scribe
mkRotatingLogScribe rl sev verb =
  return $ Scribe $ \i -> do
    when (permitItem sev i) $
      rotatedWrite rl $ T.encodeUtf8 $ LT.toStrict $ LT.toLazyText $ (formatItem False verb i <> "\n")

main :: IO ()
main = do
  le <- initLogEnv "MyApp" "prod"
  rl <- mkRotatingLog "log/myapp" 256 LineBuffering (archiveFile "log/archive/")
  s <- mkRotatingLogScribe rl InfoS V0
  let le' = registerScribe "rotating log scribe" s le
  runKatipContextT le' () "main" $ do
    sequence_ $ replicate 10 $ $logTM InfoS "ログ出力"

-- > $ tree log
-- > log
-- > ├── archive
-- > │   ├── myapp_2016_10_30_17_07_51.852205.log
-- > │   ├── myapp_2016_10_30_17_07_51.852508.log
-- > │   ├── myapp_2016_10_30_17_07_51.85274.log
-- > │   └── myapp_2016_10_30_17_07_51.852956.log
-- > └── myapp.log

ちなみに fast-logger はサイズベースのローテーションの仕組みを持っている。 その一方で monad-logger は fast-logger を使って実装されているにも関わらずローテーションのインターフェースを持っていない。 推測だが、monad-logger を開発している Yesod 陣営が Keter を使っているためではないかと思う。 Keter についてはよく分かっていないのだが、Web アプリケーションのデプロイをサポートするものとのことで、 Yesod アプリのデプロイなどに使われているらしい。 ドキュメントによると Keter はログローテーションのAPIを持っているので、 Yesod 陣営にとっては monad-logger にローテーションを実装する必要性がないのではないだろうか。

まとめ

Katip はタイムスタンプや名前空間など、一般的なロガーライブラリが持っているような機能は十分備えている。 ログローテーションの仕組みはないが、これは logrotate コマンドなどを使えばなんとかなるので大きい問題ではないと思う。

なお Katip はこの記事で紹介した以外にも次のような機能がある。

続・Haskellの最近の例外ハンドリング

前回 の記事ではHaskellの例外ハンドリングには exceptions パッケージを使えばいいのではないかと書いた。

ところが今年の6月に safe-exceptions という exceptions を拡張したようなパッケージがさる FPComplete から 発表 された。

そこでこの記事では safe-exceptions について調べてみる。 おそらくほぼ FPComplete の発表の受け売りになってしまうので英語を読める人は原文を読む方がいいかもしれない。

さすが FPComplete だけあってこれは既に LTS Haskell に入っている。 この記事では lts-6.14 を用いる。

Haskellの例外のつらいところ

自分が認識している範囲ではHaskellの例外まわりは以下のところがつらい。

  1. 標準の例外系の関数が IO に特化されていて取り回しが悪い
  2. いかにも純粋そうな関数が例外を出したりスレッドセーフでなかったりする
  3. 例外型は何でも非同期例外として投げることができるし、キャッチ部で非同期例外かそうでないかの区別をつけられない

1.については前回の記事で紹介した exceptions パッケージによってかなり改善される。

2.は内部的にFFIでC関数を呼ぶライブラリを使うとたまにある。 まあ例外出すかやスレッドセーフかどうかはHaddockに大体書いてあるし、気になるのは好みの問題かもしれない。

3.が結構な問題である。 非同期例外というのは別のスレッドから来る例外で、 コード上ではtry節の外で発生する。 以下の someFunccatch はもちろん InternalException をキャッチするために書かれている。 しかし実際は ExternalException をキャッチしてしまうのである!

{-# LANGUAGE ScopedTypeVariables, DeriveDataTypeable #-}

module Main where

import Data.Typeable (Typeable)
import Control.Concurrent (forkIO, threadDelay)
import Control.Exception

data InternalException = InternalException String
                       deriving (Show, Typeable)
instance Exception InternalException

data ExternalException = ExternalException String
                       deriving (Show, Typeable)
instance Exception ExternalException

someFunc :: IO ()
someFunc = do
    (
        do
            threadDelay $ 1000 * 1000
            throw $ InternalException "error form inside!"
        ) `catch` (\(e::SomeException) -> do
            print e
        )
        
main :: IO ()
main = do
    threadId <- forkIO someFunc
    threadDelay $ 500 * 1000
    throwTo threadId $ ExternalException "error from outside!"
    threadDelay $ 100 * 1000
    return ()

-- > ExternalException "error from outside!"

この例では InternalExceptionExternalException で同期例外と非同期例外を型で区別できそうにも見える。 しかし throwTo はどんな例外でも投げることができるので InternalException も投げる可能性を排除できない。

すべての catch は非同期例外を受け取りうるし、キャッチした例外が同期か非同期か区別できないということを 念頭に置いて書かなければならない。 これは非常につらい。

safe-exceptions以前の対処

enclosed-exceptions パッケージというものがある。 enclosedの名前のとおり、try部の中の例外だけをキャッチする関数を提供する。

その仕組みは FPCompleteの記事 に書かれているが、 非同期処理をもって非同期例外を倒すという感じで面白い。

safe-exceptions

enclosed-exceptions は内部的に非同期処理を用いて非同期例外をうまく扱う。 しかし非同期処理を使うことのオーバーヘッドが生まれてしまった。

safe-exceptions は別のアプローチを用いる。 このライブラリは throwthrowTo をラップして同名で再エクスポートする。 これらは実際に例外を投げる「前」に例外を SyncExceptionWrapper もしくは AsyncExceptionWrapper で包んで投げる。 catch は同期例外と非同期例外を型で区別できないので、投げるときに区別できるようにしてしまうわけだ。 非同期処理を使っていないので非同期処理によるオーバーヘッドもない。

このライブラリは throwthrowTo のほかにも、 throwIOcatchcatchIO などの おなじみの関数を再実装しているので新たに使いかたを学ぶ必要はほとんどない。 しかも exceptions と同様にモナド変換子に対応している。

もし危険性を理解して非同期例外もキャッチしたいときには catchDeep が使える。

まとめ

safe-exceptions を使おう。

Haskellの最近の例外ハンドリング

どうもHaskellには標準のControl.Exceptionモジュールだけでなくmtlexceptionsexceptionalといった例外を扱うためのパッケージがあるらしいのだが、そのあたりのパッケージの選び方や使い方についてまとまった情報を見つけられなかった。 HaskellWiki例外のページも少々古いようで、deprecatedなものや統合される前のパッケージを書いていたりする。

調べた限り、mtlexceptionsが今の主流っぽい。 その2つの使い方をまとめる。

なおバージョンはlts-6.1を基準としている。

mtl

mtlパッケージのControl.Monad.ExceptモジュールはMonadErrorというモナドExceptTというモナド変換子を提供する。 以下のように使う。

import Control.Monad.Trans(lift)
import Control.Monad.Except(runExceptT, throwError, catchError)

main :: IO ()
main = do
    runExceptT $ do
        (do
                lift $ print "start"
                throwError "exception!"
                lift $ print "finish"
            ) `catchError` (\e -> do
                lift $ print "caught"
                lift $ print e
            )
    return ()

-- > "start"
-- > "caught"
-- > "exception!"

throwErrorcatchErrorMonadErrorのプリミティブで、 runExceptTExceptTをはがす役である。

catchErrorでキャッチしない場合はEitherとして取り出せる。

main = do
    ret <- runExceptT $ do
        lift $ print "start"
        throwError "exception!"
        return "ret value"
    print ret

-- > "start"
-- > Left "exception!"

あくまでthrowErrorをキャッチするものだということに注意:

main = do
    ret <- runExceptT $ do
        lift $ print "start"
        file <- lift $ readFile "nothing.txt"
        throwError "exception!"
        lift $ print file
        return "ret value"
    print ret

-- > "start"
-- > except-test-exe: nothing.txt: openFile: does not exist (No such file or directory)

実はIOMonadErrorインスタンスなので、IO中のIOExceptionをキャッチしたい場合はrunExceptTなしで] 以下のように書ける。

main = do
    (do
            print "start"
            file <- readFile "nothing.txt"
            print file
        ) `catchError` (\e -> do
            print "caught"
            print e
        )

-- > "start"
-- > "caught"
-- > nothing.txt: openFile: does not exist (No such file or directory)

ただし、IOMonadErrorとして使う場合はthrowErrorできるのはIOExceptionだけである。 以下のようなものはコンパイルエラーになってしまう。

main = do
    (do
            print "start"
            file <- readFile "nothing.txt"
            throwError "my error"          -- > Couldn't match type ‘GHC.IO.Exception.IOException’ with ‘[Char]’
            print file
        ) `catchError` (\e -> do
            print "caught"
            print e
        )

自作の別の例外を投げたいときはやはりrunExceptTを使う必要がある。

exceptions

exceptionsパッケージのControl.Monad.Catchモジュールは標準のControl.Exceptionに対してよりフレンドリーである。 Control.Exceptionの大部分をラップあるいは再エクスポートしており、Control.Exceptionをインポートしなくても Control.Exceptionと同じ名前の関数が同じように使える。

{-# LANGUAGE DeriveDataTypeable #-}
{-# LANGUAGE ScopedTypeVariables #-}

import Data.Typeable
import Control.Monad.Catch

data MyException = MyException String
                 deriving(Show, Typeable)
instance Exception MyException

data MyAnotherException = MyAnotherException String
                  deriving(Show, Typeable)
instance Exception MyAnotherException

main = do
    (do
            print "start"
            throwM $ MyException "exception!"
            throwM $ MyAnotherException "another exception!"
            print "finish"
        ) `catch` (\(e::SomeException) -> do
            print "caught"
            print e
        )
-- > "start"
-- > "caught"
-- > MyException "exception!"

Control.Exceptionとの違いはthrowthrowMに変わるくらいである。 Control.ExceptionthrowモナドIOに限定されてしまうが、exceptionsthrowMではMonadThrowを実装しているモナドであればよい。 MonadThrowの実装が提供されているのはIOのほかにはmtlパッケージの各モナド(WriterTなど)がある。

まとめ

例外のためにモナドスタックを一段増やすのは例外の意義から言ってもやりすぎのような気がする。 IOがすでに失敗しうるという意味を含んでいるし。

個人的には実用上はexceptionsを使えばよいと思う。