Improve logging and logging options in Fluffy (#1548)

* Improve logging and logging options in Fluffy

- Allow selection of log format, including:
  - JSON
  - automatic selection based on tty
- Allow log levels per topic configured on cli

fluffy/conf.nim

@@ -14,6 +14,7 @@ import
   json_rpc/rpcproxy,
   nimcrypto/hash,
   stew/byteutils,
+  ./logging,
   ./network/wire/portal_protocol_config
 
 proc defaultDataDir*(): string =
@@ -56,10 +57,16 @@ type
 
   PortalConf* = object
     logLevel* {.
-      defaultValue: LogLevel.INFO
-      defaultValueDesc: $LogLevel.INFO
-      desc: "Sets the log level"
-      name: "log-level" .}: LogLevel
+      desc: "Sets the log level for process and topics (e.g. \"DEBUG; TRACE:discv5,portal_wire; REQUIRED:none; DISABLED:none\")"
+      defaultValue: "INFO"
+      name: "log-level" .}: string
+
+    logStdout* {.
+      hidden
+      desc: "Specifies what kind of logs should be written to stdout (auto, colors, nocolors, json)"
+      defaultValueDesc: "auto"
+      defaultValue: StdoutLogKind.Auto
+      name: "log-format" .}: StdoutLogKind
 
     udpPort* {.
       defaultValue: 9009
@@ -281,3 +288,7 @@ proc parseCmdArg*(T: type ClientConfig, p: string): T
 
 proc completeCmdArg*(T: type ClientConfig, val: string): seq[string] =
   return @[]
+
+chronicles.formatIt(InputDir): $it
+chronicles.formatIt(OutDir): $it
+chronicles.formatIt(InputFile): $it

fluffy/fluffy.cfg

@@ -0,0 +1,7 @@
+-d:"chronicles_sinks=textlines[dynamic],json[dynamic]"
+-d:"chronicles_runtime_filtering=on"
+-d:"chronicles_disable_thread_id"
+
+@if release:
+  -d:"chronicles_line_numbers:0"
+@end

fluffy/fluffy.nim

@@ -29,7 +29,10 @@ import
   ],
   ./network/wire/[portal_stream, portal_protocol_config],
   ./eth_data/history_data_ssz_e2s,
-  ./content_db
+  ./content_db,
+  ./version, ./logging
+
+chronicles.formatIt(IoErrorCode): $it
 
 proc initBeaconLightClient(
       network: LightClientNetwork, networkData: NetworkInitData,
@@ -96,6 +99,11 @@ proc initBeaconLightClient(
   lc
 
 proc run(config: PortalConf) {.raises: [CatchableError].} =
+  setupLogging(config.logLevel, config.logStdout)
+
+  notice "Launching Fluffy",
+    version = fullVersionStr, cmdParams = commandLineParams()
+
   # Make sure dataDir exists
   let pathExists = createPath(config.dataDir.string)
   if pathExists.isErr():
@@ -270,8 +278,6 @@ when isMainModule:
   let config = PortalConf.load()
   {.push raises: [].}
 
-  setLogLevel(config.logLevel)
-
   case config.cmd
   of PortalCmd.noCommand:
     run(config)

fluffy/logging.nim

@@ -0,0 +1,146 @@
+# Nimbus Fluffy
+# Copyright (c) 2023 Status Research & Development GmbH
+# Licensed and distributed under either of
+#   * MIT license (license terms in the root directory or at https://opensource.org/licenses/MIT).
+#   * Apache v2 license (license terms in the root directory or at https://www.apache.org/licenses/LICENSE-2.0).
+# at your option. This file may not be copied, modified, or distributed except according to those terms.
+
+# Note:
+# Code taken from nimbus-eth2/beacon_chain/nimbus_binary_common with minor
+# adjustments. The write to file logic is removed as it never was an option
+# in Fluffy.
+
+{.push raises: [].}
+
+import
+  std/[strutils, tables, terminal, typetraits],
+  pkg/chronicles, pkg/chronicles/helpers, chronicles/topics_registry,
+  pkg/stew/results
+
+export results
+
+type
+  StdoutLogKind* {.pure.} = enum
+    Auto = "auto"
+    Colors = "colors"
+    NoColors = "nocolors"
+    Json = "json"
+    None = "none"
+
+# silly chronicles, colors is a compile-time property
+proc stripAnsi(v: string): string =
+  var
+    res = newStringOfCap(v.len)
+    i: int
+
+  while i < v.len:
+    let c = v[i]
+    if c == '\x1b':
+      var
+        x = i + 1
+        found = false
+
+      while x < v.len: # look for [..m
+        let c2 = v[x]
+        if x == i + 1:
+          if c2 != '[':
+            break
+        else:
+          if c2 in {'0'..'9'} + {';'}:
+            discard # keep looking
+          elif c2 == 'm':
+            i = x + 1
+            found = true
+            break
+          else:
+            break
+        inc x
+
+      if found: # skip adding c
+        continue
+    res.add c
+    inc i
+
+  res
+
+proc updateLogLevel(logLevel: string) {.raises: [ValueError].} =
+  # Updates log levels (without clearing old ones)
+  let directives = logLevel.split(";")
+  try:
+    setLogLevel(parseEnum[LogLevel](directives[0].capitalizeAscii()))
+  except ValueError:
+    raise (ref ValueError)(msg: "Please specify one of TRACE, DEBUG, INFO, NOTICE, WARN, ERROR or FATAL")
+
+  if directives.len > 1:
+    for topicName, settings in parseTopicDirectives(directives[1..^1]):
+      if not setTopicState(topicName, settings.state, settings.logLevel):
+        warn "Unrecognized logging topic", topic = topicName
+
+proc detectTTY(stdoutKind: StdoutLogKind): StdoutLogKind =
+  if stdoutKind == StdoutLogKind.Auto:
+    if isatty(stdout):
+      # On a TTY, let's be fancy
+      StdoutLogKind.Colors
+    else:
+      # When there's no TTY, we output no colors because this matches what
+      # released binaries were doing before auto-detection was around and
+      # looks decent in systemd-captured journals.
+      StdoutLogKind.NoColors
+  else:
+    stdoutKind
+
+proc setupLogging*(
+    logLevel: string, stdoutKind: StdoutLogKind) =
+  # In the cfg file for fluffy, we create two formats: textlines and json.
+  # Here, we either write those logs to an output, or not, depending on the
+  # given configuration.
+  # Arguably, if we don't use a format, chronicles should not create it.
+
+  when defaultChroniclesStream.outputs.type.arity != 2:
+    warn "Logging configuration options not enabled in the current build"
+  else:
+    # Naive approach where chronicles will form a string and we will discard
+    # it, even if it could have skipped the formatting phase
+    proc noOutput(logLevel: LogLevel, msg: LogOutputStr) = discard
+    proc writeAndFlush(f: File, msg: LogOutputStr) =
+      try:
+        f.write(msg)
+        f.flushFile()
+      except IOError as err:
+        logLoggingFailure(cstring(msg), err)
+
+    proc stdoutFlush(logLevel: LogLevel, msg: LogOutputStr) =
+      writeAndFlush(stdout, msg)
+
+    proc noColorsFlush(logLevel: LogLevel, msg: LogOutputStr) =
+      writeAndFlush(stdout, stripAnsi(msg))
+
+    defaultChroniclesStream.outputs[1].writer = noOutput
+
+    let tmp = detectTTY(stdoutKind)
+
+    case tmp
+    of StdoutLogKind.Auto: raiseAssert "checked in detectTTY"
+    of StdoutLogKind.Colors:
+      defaultChroniclesStream.outputs[0].writer = stdoutFlush
+    of StdoutLogKind.NoColors:
+      defaultChroniclesStream.outputs[0].writer = noColorsFlush
+    of StdoutLogKind.Json:
+      defaultChroniclesStream.outputs[0].writer = noOutput
+
+      let prevWriter = defaultChroniclesStream.outputs[1].writer
+      defaultChroniclesStream.outputs[1].writer =
+        proc(logLevel: LogLevel, msg: LogOutputStr) =
+          stdoutFlush(logLevel, msg)
+          prevWriter(logLevel, msg)
+    of StdoutLogKind.None:
+     defaultChroniclesStream.outputs[0].writer = noOutput
+
+  try:
+    updateLogLevel(logLevel)
+  except ValueError as err:
+    try:
+      stderr.write "Invalid value for --log-level. " & err.msg
+    except IOError:
+      echo "Invalid value for --log-level. " & err.msg
+    quit 1

fluffy/nim.cfg

@@ -1,6 +1,10 @@
 -d:"chronicles_runtime_filtering=on"
 -d:"chronicles_disable_thread_id"
 
+@if release:
+  -d:"chronicles_line_numbers:0"
+@end
+
 -d:chronosStrictException
 --styleCheck:usages
 --styleCheck:hint

fluffy/tools/eth_data_exporter.nim

@@ -54,6 +54,8 @@ import
 # Need to be selective due to the `Block` type conflict from downloader
 from ../network/history/history_network import encode
 
+chronicles.formatIt(IoErrorCode): $it
+
 proc defaultDataDir*(): string =
   let dataDir = when defined(windows):
     "AppData" / "Roaming" / "EthData"

nimbus/config.nim

@@ -658,7 +658,7 @@ proc getProtocolFlags*(conf: NimbusConf): set[ProtocolFlag] =
       error "Unknown protocol", name=item
       quit QuitFailure
   if noneOk and 0 < result.len:
-    error "Setting none contradicts wire protocols", names=result
+    error "Setting none contradicts wire protocols", names = $result
     quit QuitFailure
 
 proc getRpcFlags(api: openArray[string]): set[RpcFlag] =

vendor/nim-eth

@@ -1 +1 @@
-Subproject commit ea3c164a0018bd62232f27d1554a91e9bdb93840
+Subproject commit 25b0da02801a216fe7fc8cba5aaf0d5c0138e267