commercialhaskell / rio

A standard library for Haskell
Other
836 stars 54 forks source link

Add generic logging #203

Closed chrisdone closed 4 years ago

chrisdone commented 4 years ago

This PR adds generic logging to RIO such that you can log any data type rather than just Utf8Builder, and you don't have to decide what log level or format your logs are going to be until later. This is not intended as a replacement for RIO's existing logger, but rather allows different backends to be used, including the "classic" logger.

Many apps I write might want to log in different ways with non trivial filtering of the logs, with sublogging, and I don't necessarily know right away what levels my logs should be at the call site (it might depend on context). Going through a data type isn't necessarily as fast as going straight to Utf8Builder, but that's a conscious trade-off. Idiom is an example of such an app that is using this.

(Aside: This PR isn't meant to address various perf. improvement techniques, but if you are really suffering from log speeds and still want to use a generic data type, you have the option to use a newtype wrapper around Utf8Builder, and PatternSynonyms which immediately render to the Utf8Builder. This would be an advanced case. Alternatively, you could experiment with INLINE with the intention of having the compiler bypass allocation of the constructor altogether.)

Example:

{-# LANGUAGE StandaloneDeriving #-}
{-# LANGUAGE DeriveGeneric #-}
{-# LANGUAGE OverloadedStrings #-}

import           Data.Aeson
import qualified Data.ByteString.Lazy.Char8 as L8
import           GHC.Stack
import           RIO

data Msg
  = DoThis
  | DidThat Double

-- Only needed for JSON logger

  deriving (Generic)
instance ToJSON Msg

-- Only needed to use RIO's classic logger

instance Display Msg where
  display DoThis = "Do this!"
  display (DidThat i) = " ... did that: " <> display i

instance HasLogLevel Msg where
  getLogLevel DoThis = LevelDebug
  getLogLevel DidThat {} = LevelInfo

instance HasLogSource Msg where
  getLogSource _ = "Msg"

main :: IO ()
main = do
  -- Terminal logging:
  logOptions <- logOptionsHandle stderr True
  withLogFunc
    logOptions
    (\logFunc ->
       runRIO
         (gLogFuncClassic logFunc)
         app)
  -- JSON logging:
  runRIO gLogFuncJSON app

-- App that doesn't care how its messages are logged.
app :: RIO (GLogFunc Msg) ()
app = do
  glog DoThis
  glog (DidThat 123.23)

-- Example JSON logger thrown together for this demo (imagine a service receiving this on a socket)

gLogFuncJSON :: ToJSON msg => GLogFunc msg
gLogFuncJSON =
  mkGLogFunc
    (\stack msg ->
       L8.putStrLn
         (encode (object ["origin" .= stackToJSON stack, "msg" .= toJSON msg])))

stackToJSON :: CallStack -> Value
stackToJSON cs =
  case reverse $ getCallStack cs of
    [] -> Null
    (_desc, loc):_ ->
      let file = srcLocFile loc
       in object
            [ "file" .= file
            , "line" .= srcLocStartLine loc
            , "column" .= srcLocStartCol loc
            ]

Example output:

> main
2019-12-04 11:36:36.398755: [debug] Do this!
@(/home/chris/Work/fpco/idiom/src/ddemo.hs:42:3)
2019-12-04 11:36:36.398903: [info]  ... did that: 123.23
@(/home/chris/Work/fpco/idiom/src/ddemo.hs:43:3)
{"origin":{"line":42,"column":3,"file":"/home/chris/Work/fpco/idiom/src/ddemo.hs"},"msg":{"tag":"DoThis"}}
{"origin":{"line":43,"column":3,"file":"/home/chris/Work/fpco/idiom/src/ddemo.hs"},"msg":{"tag":"DidThat","contents":123.23}}
snoyberg commented 4 years ago

Some high level thoughts:

chrisdone commented 4 years ago

Disadvantage: it throws an obstacle in the face of new users about which logging system to use (docs may help there)

I can definitely push a commit to address this more explicitly in docs.

chrisdone commented 4 years ago

I've updated the commentary, but I haven't experimented with an associated type instead of the fundep yet.

chrisdone commented 4 years ago

Hurrah, passing tests. Merging! :tada: