О логировании и ротации логов в Haskell при помощи пакета fast-logger, а также о механизме middleware в Scotty

21 июля 2014

Если hslogger — это такая навороченная штуковина с уровнями логирования, какими-то деревьями, форматерами, хендлерами и syslog’ом, то пакет fast-logger предназначен для очень простого, но эффективного логирования в файлики. Эффективного, потому что fast-logger скейлится на многоядерных системах за счет создания отдельных буферов на каждое ядро процессора. Лог-записи попадают в различные буферы в зависимости от id нитки, делающей запись. При заполнении буфер сбрасывается на диск. Принцип такой же, как при шардинге — данные разделяются, нитки меньше мешают друг другу.

Еще одна причина, по которой fast-logger заслуживает внимания, заключается в том, что он по умолчанию используется в WAI. Если вы используете Scotty или Yesod, то автоматически тащите в качестве зависимости fast-logger. А раз в вашем приложении уже есть какой-то логер, почему бы не воспользоваться им, вместо того, чтобы тащить еще один логер и как-то конвертировать типы fast-logger’а в типы, с которыми работает этот другой логер?

В первом приближении fast-logger предельно прост в использовании:

ghci> :m + System.Log.FastLogger
ghci> loggerSet <- newFileLoggerSet defaultBufSize "./temp/info.log"
ghci> pushLogStr loggerSet "log entry 1\n"
ghci> pushLogStr loggerSet "log entry 2\n"
ghci> flushLogStr loggerSet

Но тут есть несколько проблем. Во-первых, в отличие от hslogger, fast-logger не предлагает из коробки какого-то глобального логера или монады, в которую он был бы обернут. Во-вторых, в fast-logger нет ни уровней (debug, info, warning, error), ни форматеров. То есть, если вы хотите писать в лог таймстампы, придется все закодить самому. С одной стороны, это все очень плохо, потому что нужно думать и что-то делать. Но с другой стороны, fast-logger предоставляет программисту больше гибкости. Можно заточить его под наши конкретные нужды.

На практике все не так плохо, как кажется. Реализация глобального логера с таймстампами занимает 15 строк кода:

{-# NOINLINE globalLogger #-}
globalLogger :: LoggerSet
globalLogger =
  unsafePerformIO $ do
    conf      <- loadConfig
    logFile   <- lookupDefault "./info.log" conf "logging.file"
    buffSize  <- lookupDefault defaultBufSize conf "logging.buff_size"
    newFileLoggerSet buffSize logFile

writeLog :: BS.ByteString -> IO ()
writeLog str = do
  utcTime <- getCurrentTime
  let timestampStr = formatISO8601Millis utcTime
      timestamp    = BS.pack timestampStr
      logEntry     = timestamp <> " " <> str <> "\n"
  pushLogStr globalLogger $ toLogStr logEntry

Для чтения конфига здесь используется пакет configurator, а для форматирования времени в ISO 8601 — пакет iso8601-time. Объяснение приема с глобальными переменными в Haskell через unsafePerformIO можно найти здесь (пункт 3). Это стандартный и безопасный прием в мире Haskell. В пакете hslogger делается точно так же.

Еще из коробки fast-logger не делает ротацию логов. Однако она также легко прикручивается:

ghci> let logspec = FileLogSpec { log_file = "./temp/info.log", log_file_size = 10000000, log_backup_number = 4 }
ghci> rotate logspec >> renewLoggerSet loggerSet

Перед вызовом renewLoggerSet обязательно следует произвести ротацию, иначе будет брошено исключение:

ghci> renewLoggerSet loggerSet
*** Exception: openFile: resource busy (file is locked)

Помимо функции rotate есть еще функция check, которая не производит ротацию, а только проверяет, что ее можно выполнить — хватает прав и так далее.

Как часто нужно делать ротацию, опять же, решать вам. В следующем примере ротация выполняется один раз в сутки:

forkLogRotator :: Config -> IO ()
forkLogRotator conf = do
  _ <- forkIO $ do
    writeLog "Log rotator started"
    -- читаем из конфига logFile, fileSize, backupNumber, flushInt
    -- ...
    let logSpec  = FileLogSpec
                   { log_file = logFile
                   , log_file_size = fileSize
                   , log_backup_number = backupNumber
                   }
    forever $
      catchAny (getCurrentTime >>= logRotatorPayload flushInt logSpec)
               (\e -> void (writeLog $ "LogRot: " <> BS.pack (show e)))
  return ()

logRotatorPayload :: Int -> FileLogSpec -> UTCTime -> IO ()
logRotatorPayload flushInterval logSpec oldTime = do
  newTime <- getCurrentTime
  let [newYMD@(_,_,_), oldYMD] = map DT.toGregorian' [newTime, oldTime]
  flushLogStr globalLogger
  when (newYMD /= oldYMD) $ do
    writeLog "Rotating logs..."
    rotate logSpec
    renewLoggerSet globalLogger
  sleepSeconds flushInterval
  logRotatorPayload flushInterval logSpec newTime

Создается отдельная нитка, которая просыпается один раз во flushInterval секунд. Каждый раз, просыпаясь, нитка делает flush логов на диск. Кроме того, если выясняется, что с момента последнего пробуждения изменилась текущая дата, нитка выполняет ротацию логов. В случае возникновения любого исключения нитка записывает информацию об исключении в лог и продолжает свою работу. Для поимки всех исключений используется функция catchAny из замечательного пакета enclosed-exceptions. Кстати, к вопросу о том, «как же в Haskell делаются долгоживущие процессы».

Напоследок посмотрим, как при помощи fast-logger можно прикрутить к Scotty логирование всех запросов. Для решения подобного рода задач предназначены так называемые middleware. Это очень мощных механизм. С помощью middleware можно произвольным образом обрабатывать и менять как запросы пользователя, так ответы сервера. В том числе middleware позволяют прикручивать сжатие при помощи gzip, реализовывать какую-то хитрую авторизацию и так далее. Для прикручивания нового middleware в Scotty есть одноименная функция:

middleware :: Middleware -> ScottyM ()

… где определение типа Middleware следующее:

type Middleware  =  Application -> Application
type Application =  Request
                 -> (Response -> IO ResponseReceived)
                 -> IO ResponseReceived

На первый взгляд все это может показаться несколько запутанным, но в действительности тут нет ничего кроме обыкновенных функций высших порядков. Приложение (Application) — это функция, которая принимает запрос (Request), функцию отправки ответа (Response) и, видимо, обязательно должна вызывать эту функцию, чтобы вернуть ожидаемый тип (IO ResponseReceived). А Middleware представляет собой функцию, которая принимает Application и возвращает Application. Которые в свою очередь, напоминаю, являются просто функциями.

Проще всего понять, как работаю middleware, посмотрев на пример простейшего middleware, который ничего не делает:

dummyMiddleware :: Application -> Application
dummyMiddleware app req sendResp =
  app req (\resp -> do
            let resp' = id resp -- не преобразуем
            sendResp resp'
          )

Если все еще непонятно, просто помедитируйте над этим примером подольше, тут правда нет ничего сложного.

Так вот, а теперь вернемся к логированию запросов. Есть такой пакет wai-extra, предоставляющий дюжину готовых middleware, в том числе RequestLogger, предназначенный для логирования запросов. Создание нового RequestLogger’а происходит при помощи функции mkRequestLogger:

mkRequestLogger :: RequestLoggerSettings -> IO Middleware

В действии это выглядит следующим образом:

  -- ...
  let logConf = def
                { destination = Callback (writeLog . fromLogStr)
                , outputFormat = CustomOutputFormat requestLoggingFmt
                }
  logger <- mkRequestLogger logConf
  scotty port $ do
    middleware logger
    get  "/api/v1.0/server_info" getServerInfo

… где функция requestLoggingFmt определена как-то так:

requestLoggingFmt :: ZonedDate
                  -> Request
                  -> Status
                  -> Maybe Integer
                  -> LogStr
requestLoggingFmt _ req _ _ =
  let logMethod      = requestMethod req
      logPathInfo    = rawPathInfo req
      logQueryString = rawQueryString req
      logClientAddr  = remoteHost req
      logHeaders     = requestHeaders req
      logBodyLenAdt  = requestBodyLength req
      logBodyLenStr  = case logBodyLenAdt of
                         ChunkedBody -> "(chunked)"
                         KnownLength len -> show len
  in toLogStr $ "Request from "   <> BS.pack (show logClientAddr) <>
                " " <> logMethod  <> " " <> logPathInfo           <>
                                            logQueryString        <>
                ", headers: "     <> BS.pack (show logHeaders)    <>
                ", body length: " <> BS.pack logBodyLenStr

Если вас пугают непонятные стрелочки <>, ознакомьтесь с моей заметкой про моноиды.

Итак, подводя итог. Из коробки пакет fast-logger не дает всего и сразу, но только потому что он не знает, чем вы решили читать конфиги, предпочитаете ли вы монады или глобальные переменные, в каком формате вы хотите логировать время, как часто следует выполнять ротацию логов и так далее. На Hackage можно найти несколько попыток сделать как бы более удобную обертку над fast-logger, но все они, похоже, в итоге оказываются заточенными под нужды конкретных авторов. Помимо hslogger и fast-logger из интересных пакетов для логирования можно посоветовать rotating-log. Он совмещает в себе простоту fast-logger и способность самостоятельно выполнять ротацию логов. Впрочем, в отличие от fast-logger, он не оптимизирован под работу на многоядерных машинах.

Я подозреваю, что большая часть читателей отвалилась на моменте, где я начал рассказывать о middleware, так что, кто дочитал заметку до конца, тот молодец. Как всегда, буду рад вашим вопросам и дополнениям.

Метки: , .


Вы можете прислать свой комментарий мне на почту, или воспользоваться комментариями в Telegram-группе.