[CBR-345] cleanup and documentation

lib/src/Pos/Diffusion/Full/Block.hs

@@ -495,7 +495,7 @@ announceBlockHeader logTrace logic protocolConstants recoveryHeadersMessage enqu
         when (AttackNoBlocks `elem` spAttackTypes sparams) (throwOnIgnored nodeId)
         traceWith logTrace (Debug,
             sformat
-                ("Announcing block"%shortHashF%" to "%build)
+                ("Announcing block "%shortHashF%" to "%build)
                 (headerHash header)
                 nodeId)
         send cA $ MsgHeaders (one (BlockHeaderMain header))

log-configs/cluster.yaml

@@ -1,6 +1,18 @@
 # This config is used by cluster nodes (core, relay, explorer)
 
+rotation:
+    logLimit: 16777216
+    keepFiles: 20
+
 loggerTree:
   severity: Debug+
   files:
     - node.log
+
+  handlers:
+    - { name: "JSON"
+      , filepath: "node.json"
+      , logsafety: SecretLogLevel
+      , severity: Info
+      , backend: FileJsonBE }
+

util/README.md

@@ -17,3 +17,156 @@ A library of utility data types are functions for Cardano SL, including:
 * A collection of QuickCheck helpers and Arbitrary instances.
 * A `Some` data type that allows a constraint to turned into an existential type.
 * A restart-able, STM-based timer.
+
+## Logging
+
+### Context naming
+
+In all logging modes, it is handy to name the context in which logging happens.
+This named context is added to the log message. The root is always named 'cardano-sl'.
+The context naming is similar to a stack: entering a new named context 
+corresponds to pushing the name onto the naming stack. On leaving the context,
+the named context is reset to the previous version, thus dropping the last name.
+
+in compatibility mode (Pos.Util.Wlog):
+```
+import Pos.Util.Wlog (WithLogger, logInfo, addLoggerName)
+
+interestingContext :: WithLogger m => m ()
+interestingContext = do
+    addLoggerName "interestingContext" $ do
+        logInfo "we now are in a new context"
+        evalOtherContext 42
+```
+its output will look like this:
+```
+[cardano-sl.interestingContext:Info:ThreadId 123] [2018-10-04 06:30:23.01 UTC] we now are in a new context
+```
+
+to produce the same output in 'Trace' logging (Pos.Util.Trace.Named):
+```
+import Pos.Util.Trace.Named (TraceNamed, appendName, logInfo)
+
+interestingContext :: (MonadIO m) => TraceNamed m -> m ()
+interestingContext logTrace0 = do
+    let logTrace = appendName "interestingContext" logTrace0
+    logInfo logTrace "we now are in a new context"
+    evalOtherContext logTrace 42
+```
+
+### Structured logging
+
+Structured logging enables us to record JSON objects and directly work on them (e.g. using 'jq' queries).
+
+In this example we output the time from one slot to the next in the field "data":
+```
+{"at":"2018-10-03T12:37:57.001766381Z","env":"bench:1.3.0","ns":["cardano-sl","node","slotting"],"data":{"TimeDiff":"19998265"},
+"app":["cardano-sl"],"msg":"","pid":"13560","loc":null,"host":"hostname","sev":"Info","thread":"ThreadId 7532"}
+```
+or nicely formatted with jq:
+```
+{
+  "at": "2018-10-03T12:37:57.001766381Z",
+  "env": "bench:1.3.0",
+  "ns": [
+    "cardano-sl",
+    "node",
+    "slotting"
+  ],
+  "data": {
+    "TimeDiff": "19998265"
+  },
+  "app": [
+    "cardano-sl"
+  ],
+  "msg": "",
+  "pid": "13560",
+  "sev": "Info",
+  "thread": "ThreadId 7532"
+}
+```
+
+Only JSON `Object`s (key->value maps) can be logged through the structured logging functions
+`logDebugX` through `logWarningX`. Other variants of JSON values will silently be ignored.
+
+For the above structured output of a `TimeDiff`, the following instance was implemented:
+(in `core/src/Pos/Core/Slotting/TimeDiff.hs`)
+```
+instance ToObject TimeDiff where
+    toObject (TimeDiff usec) = singleton "TimeDiff" $ String $ show $ toMicroseconds usec
+```
+
+Another way of outputting structures as `Object` is via `ToJSON`. The class `ToObject` (in `Pos.Util.Log`)
+has a default implementation of `toObject` which accepts `ToJSON` values:
+```
+import Pos.Util.Log (ToObject (..))
+import Pos.Util.Log.Structured (logInfoX)
+import Pos.Util.Wlog (WithLogger, logInfo, addLoggerName)
+
+-- | a loggable data structure with JSON representation
+data Loggable = Loggable {
+                  _fieldN :: Int
+                , _fieldS :: String
+                }
+                deriving (Show, Generic)
+instance ToJSON Loggable
+instance ToObject Loggable
+
+
+evalOtherContext n = do
+    logInfoX (Loggable n "msg")
+
+interestingContext :: WithLogger m => m ()
+interestingContext = do
+    addLoggerName (<> "interestingContext") $ do
+        logInfo "we now are in a new context"
+        evalOtherContext 42
+```
+
+
+### Output selection
+
+Logging is setup via a `LoggerConfig` and includes:
+* log rotation parameters
+* compatiblity to old format with shortcuts like 'files:' etc.
+* handlers are instances of output backends
+  * FileTextBE - textual output to files
+  * FileJsonBE - outputs JSON representation to files
+  * StdoutBE, StderrBE - output to `/dev/stdout` or `/dev/stderr`
+  * DevNullBE - no output at all
+
+As an example, this is the configuration for `Daedalus`:
+```
+# This config is used by Daedalus (in production).
+
+rotation:
+    logLimit: 5242880 # 5MB
+    keepFiles: 10
+
+loggerTree:
+  severity: Info+
+  cardano-sl.syncWalletWorker: Error+
+  files:
+    - node
+
+  handlers:
+    - { name: "JSON"
+      , filepath: "pub/node.json"
+      , logsafety: PublicLogLevel
+      , severity: Info
+      , backend: FileJsonBE }
+
+```
+
+- it sets up log rotation to keep the ten most recent files, where each
+has size of at most five megabytes.
+- under "loggerTree", the compatiblity to the old format, it defines
+global severity filter to be at least 'Info', and for the named context 
+"cardano-sl.syncWalletWorker" only errors are output. The keyword 'files:' 
+lists the output files which are created.
+- under 'handlers:' a list of outputs can be defined. Here we open a JSON 
+backend to a file and only output messages with severity at least 'Info' and 
+marked "public" (`LogSecurityLevel` is one of: `SecretLogLevel`, `PublicLogLevel`;
+log files marked "secret" contain all messages, whereas "public" log files 
+contain masked log messages where identifying information is hidden)
+

util/src/Pos/Util/Trace/Named.hs

@@ -145,15 +145,15 @@ namedTrace lh = Trace $ Op $ \namedLogitem ->
 
 {- testing:
 
-logTrace' <- setupLogging "test" (Pos.Util.LoggerConfig.defaultInteractiveConfiguration Log.Debug) "named"
+logTrace' <- setupLogging "test" (Pos.Util.Log.LoggerConfig.defaultInteractiveConfiguration Log.Debug) "named"
 let li = publicLogItem (Log.Debug, "testing")
     ni = namedItem "Tests" li
 
 traceWith logTrace' ni
 traceWith (named $ appendName "more" logTrace') li
 
 
-logTrace' <- setupLogging "test" (Pos.Util.LoggerConfig.jsonInteractiveConfiguration Log.Debug) "named"
+logTrace' <- setupLogging "test" (Pos.Util.Log.LoggerConfig.jsonInteractiveConfiguration Log.Debug) "named"
 logDebug logTrace' "hello"
 logDebug (appendName "blabla" logTrace') "hello"
 -}

util/src/Pos/Util/Wlog.hs

@@ -28,6 +28,8 @@ module Pos.Util.Wlog
         , LoggerNameBox (..)
         , HasLoggerName (..)
         , usingLoggerName
+        , addLoggerName
+        , setLoggerName
           -- * LoggerConfig
         , LoggerConfig (..)
         , lcTree
@@ -52,8 +54,10 @@ import           Pos.Util.Log.LoggerConfig (LoggerConfig (..), lcTree,
                      parseLoggerConfig, setLogPrefix)
 import           Pos.Util.Wlog.Compatibility (CanLog (..), HasLoggerName (..),
                      LogEvent (..), LoggerNameBox (..), NamedPureLogger (..),
-                     WithLogger, centiUtcTimeF, dispatchEvents, getLinesLogged,
-                     launchNamedPureLog, logDebug, logError, logInfo, logMCond,
-                     logMessage, logNotice, logWarning, productionB,
-                     removeAllHandlers, retrieveLogContent, runNamedPureLog,
-                     setupLogging, setupTestLogging, usingLoggerName)
+                     WithLogger, addLoggerName, centiUtcTimeF, dispatchEvents,
+                     getLinesLogged, launchNamedPureLog, logDebug, logError,
+                     logInfo, logMCond, logMessage, logNotice, logWarning,
+                     productionB, removeAllHandlers, retrieveLogContent,
+                     runNamedPureLog, setLoggerName, setupLogging,
+                     setupTestLogging, usingLoggerName)
+

util/src/Pos/Util/Wlog/Compatibility.hs

@@ -22,6 +22,8 @@ module Pos.Util.Wlog.Compatibility
          , LoggerNameBox (..)
          , HasLoggerName (..)
          , usingLoggerName
+         , addLoggerName
+         , setLoggerName
          , Severity (..)
            -- * LoggerConfig
          , productionB
@@ -171,6 +173,12 @@ instance Monad m => HasLoggerName (LoggerNameBox m) where
   askLoggerName = LoggerNameBox ask
   modifyLoggerName how = LoggerNameBox . local how . loggerNameBoxEntry
 
+addLoggerName :: HasLoggerName m => LoggerName -> m a -> m a
+addLoggerName m = modifyLoggerName (<> ("." `T.append` m))
+
+setLoggerName :: HasLoggerName m => LoggerName -> m a -> m a
+setLoggerName m = modifyLoggerName (const m)
+
 launchNamedPureLog
     :: (WithLogger n, Monad m)
     => (forall f. Functor f => m (f a) -> n (f b))
@@ -310,7 +318,7 @@ filterWithSafety condition = filter (\lh -> case _lhSecurityLevel lh of
 --   Also, ToJSON a => KC.LogItem (see Pos.Util.Log).
 logMX :: (MonadIO m, Log.ToObject a) => LoggerName -> Severity -> a -> m ()
 logMX name severity a = do
-    let ns = K.Namespace [name]
+    let ns = K.Namespace (T.split (=='.') name)
     lh <- liftIO $ readMVar loggingHandler
     logItemCond lh
                 a
@@ -327,7 +335,7 @@ filterJsonScribes = filter (\lh -> _lhBackend lh == FileJsonBE)
 -- | Logs an item only into JSON 'Scribes' which match the 'SelectionMode'.
 logXCond :: (MonadIO m, Log.ToObject a) => LoggerName -> Severity -> a -> SelectionMode -> m ()
 logXCond name severity a cond = do
-    let ns = K.Namespace [name]
+    let ns = K.Namespace (T.split (=='.') name)
     lh <- liftIO $ readMVar loggingHandler
     logItemCond lh
                 a

util/test/Test/Pos/Util/LogStructuredSpec.hs

@@ -72,8 +72,9 @@ testLog = do
     logInfo "info"
     logInfoX item
 
-    logNotice "notice"
-    logNoticeX item
+    addLoggerName "note" $ do
+        logNotice "notice"
+        logNoticeX item
 
     logWarning "warning"
     logWarningX item
@@ -98,4 +99,5 @@ spec = describe "Strucutured logging" $ do
                     contents <- readFile logFile
                     putStrLn contents
                     liftIO $ removeFile logFile
+                    liftIO $ removeFile "node.json"
                 Nothing -> putStrLn ("JSON file NOT found:" :: Text)

util/test/Test/Pos/Util/WlogSpec.hs

@@ -17,9 +17,9 @@ import           Test.QuickCheck.Monadic (assert, monadicIO, run)
 
 import           Pos.Util.Log.LoggerConfig (defaultTestConfiguration,
                      lcLoggerTree, ltNamedSeverity)
-import           Pos.Util.Wlog (Severity (..), WithLogger, getLinesLogged,
-                     logDebug, logError, logInfo, logNotice, logWarning,
-                     modifyLoggerName, setupLogging, usingLoggerName)
+import           Pos.Util.Wlog (Severity (..), WithLogger, addLoggerName,
+                     getLinesLogged, logDebug, logError, logInfo, logNotice,
+                     logWarning, setLoggerName, setupLogging, usingLoggerName)
 
 {-# ANN module ("HLint: ignore Reduce duplication" :: String) #-}
 
@@ -78,10 +78,10 @@ someLogging = do
     usingLoggerName "testing" $ do
         testLog
         -- context: cardano-sl.testing.more
-        modifyLoggerName (<> ".more") $ do
+        addLoggerName "more" $ do
             testLog
             -- context: cardano-sl.final
-            modifyLoggerName (const "final") $ do
+            setLoggerName "final" $ do
                 testLog
 
 testLog :: (MonadIO m, WithLogger m) => m ()