Repository: hyperledger/firefly (go)

Issue:
Structured JSON Logging
FireFly is using https://github.com/sirupsen/logrus which is great. However, when integrating with log aggregation systems which allow searching across multiple indexed fields of documents, i.e. OpenSearch, the current experience requires doing inefficient searches of message IDs, etc. within the log message itself. Instead, we can structure the logs as JSON so certain useful / often searched pieces of metadata within logs can be included as separate fields and therefore more easily searchable. Such pieces of metadata can be very high in cardinality which serves as a great compliment to our Prometheus metrics which cannot be as high in cardinality without exploding timeseries costs.

To close this issue, we should achieve two things:

1. Offer new [`log`](https://hyperledger.github.io/firefly/reference/config.html#log) options for enabling JSON logs, which just sets the logrus formatter to the `JSONFormatter` behind the scenes: https://github.com/sirupsen/logrus#environments
2. Refactor log statements throughout the code base to use `WithFields` which will help improve log clarity in the unstructured case, while simultaneously enabling searchable fields when using structured logs: https://github.com/sirupsen/logrus#fields

Pull request:
Configurable JSON Formatter and Caller Reporting for Logs
Closes #713, useful for parsing logs w/ `jq` or searching through logs using log aggregators like Filebeat + OpenSearch

Using a slightly modified config from a default `dev` stack:
```yaml
log:
  level: debug
  reportCaller: true
  json:
    enabled: true
```

and running the image locally:

```shell
make docker
docker run -v ${HOME}/.firefly/stacks/dev/init/config/:/etc/firefly -it hyperledger/firefly -f /etc/firefly/firefly_core_0.yml
```

results in:

```json
{"@timestamp":"2022-04-20T04:53:12.477Z","file":"/firefly/pkg/config/config.go:528","func":"github.com/hyperledger/firefly/pkg/config.SetupLogging","level":"debug","message":"Log level: debug","prefix":"node_0"}
{"@timestamp":"2022-04-20T04:53:12.477Z","file":"/firefly/cmd/firefly.go:105","func":"github.com/hyperledger/firefly/cmd.run","level":"info","message":"Project Firefly","prefix":"node_0"}
{"@timestamp":"2022-04-20T04:53:12.477Z","file":"/firefly/cmd/firefly.go:106","func":"github.com/hyperledger/firefly/cmd.run","level":"info","message":"© Copyright 2021 Kaleido, Inc.","prefix":"node_0"}
{"@timestamp":"2022-04-20T04:53:12.479Z","file":"/firefly/cmd/firefly.go:159","func":"github.com/hyperledger/firefly/cmd.startFirefly","level":"debug","message":"Debug HTTP endpoint listening on localhost:6060","prefix":"node_0"}

```

Patch:
diff --git a/docs/reference/config.md b/docs/reference/config.md
index ca7f4904b..f22a89f61 100644
--- a/docs/reference/config.md
+++ b/docs/reference/config.md
@@ -513,6 +513,7 @@ nav_order: 3
 |filename|Filename is the file to write logs to.  Backup log files will be retained in the same directory|`string`|`<nil>`
 |filesize|MaxSize is the maximum size the log file before it gets rotated|[`BytesSize`](https://pkg.go.dev/github.com/docker/go-units#BytesSize)|`<nil>`
 |forceColor|Force color to be enabled, even when a non-TTY output is detected|`boolean`|`<nil>`
+|includeCodeInfo|Enables the report caller for including the calling file and line number, and the calling function. If using text logs, it uses the logrus text format rather than the default prefix format.|`boolean`|`<nil>`
 |level|The log level - error, warn, info, debug, trace|`string`|`<nil>`
 |maxAge|The maximum time to retain old log files based on the timestamp encoded in their filename.|[`time.Duration`](https://pkg.go.dev/time#Duration)|`<nil>`
 |maxBackups|Maximum number of old log files to retain|`int`|`<nil>`
@@ -520,6 +521,22 @@ nav_order: 3
 |timeFormat|Custom time format for logs|[Time format](https://pkg.go.dev/time#pkg-constants) `string`|`<nil>`
 |utc|Use UTC timestamps for logs|`boolean`|`<nil>`
 
+## log.json
+
+|Key|Description|Type|Default Value|
+|---|-----------|----|-------------|
+|enabled|Enables JSON formatted logs rather than text. All log color settings are ignored when enabled.|`boolean`|`<nil>`
+
+## log.json.fields
+
+|Key|Description|Type|Default Value|
+|---|-----------|----|-------------|
+|file|configures the JSON key containing the calling file|`string`|`<nil>`
+|func|Configures the JSON key containing the calling function|`string`|`<nil>`
+|level|Configures the JSON key containing the log level|`string`|`<nil>`
+|message|Configures the JSON key containing the log message|`string`|`<nil>`
+|timestamp|Configures the JSON key containing the timestamp of the log|`string`|`<nil>`
+
 ## message.cache
 
 |Key|Description|Type|Default Value|
diff --git a/pkg/config/config.go b/pkg/config/config.go
index 87e810c8e..2aaee0e36 100644
--- a/pkg/config/config.go
+++ b/pkg/config/config.go
@@ -65,6 +65,20 @@ var (
 	LogMaxAge = ffc("log.maxAge")
 	// LogCompress sets whether to compress backups
 	LogCompress = ffc("log.compress")
+	// LogIncludeCodeInfo enables the report caller for including the calling file and line number
+	LogIncludeCodeInfo = ffc("log.includeCodeInfo")
+	// LogJSONEnabled enables JSON formatted logs rather than text
+	LogJSONEnabled = ffc("log.json.enabled")
+	// LogJSONTimestampField configures the JSON key containing the timestamp of the log
+	LogJSONTimestampField = ffc("log.json.fields.timestamp")
+	// LogJSONLevelField configures the JSON key containing the log level
+	LogJSONLevelField = ffc("log.json.fields.level")
+	// LogJSONMessageField configures the JSON key containing the log message
+	LogJSONMessageField = ffc("log.json.fields.message")
+	// LogJSONFuncField configures the JSON key containing the calling function
+	LogJSONFuncField = ffc("log.json.fields.func")
+	// LogJSONFileField configures the JSON key containing the calling file
+	LogJSONFileField = ffc("log.json.fields.file")
 )
 
 type KeySet interface {
@@ -122,6 +136,13 @@ func RootConfigReset(setServiceDefaults ...func()) {
 	viper.SetDefault(string(LogFilesize), "100m")
 	viper.SetDefault(string(LogMaxAge), "24h")
 	viper.SetDefault(string(LogMaxBackups), 2)
+	viper.SetDefault(string(LogIncludeCodeInfo), false)
+	viper.SetDefault(string(LogJSONEnabled), false)
+	viper.SetDefault(string(LogJSONTimestampField), "@timestamp")
+	viper.SetDefault(string(LogJSONLevelField), "level")
+	viper.SetDefault(string(LogJSONMessageField), "message")
+	viper.SetDefault(string(LogJSONFuncField), "func")
+	viper.SetDefault(string(LogJSONFileField), "file")
 
 	// We set the service defaults within our mutex
 	for _, fn := range setServiceDefaults {
@@ -480,10 +501,17 @@ func (c *configPrefix) Resolve(key string) string {
 // SetupLogging initializes logging
 func SetupLogging(ctx context.Context) {
 	log.SetFormatting(log.Formatting{
-		DisableColor:    GetBool(LogNoColor),
-		ForceColor:      GetBool(LogForceColor),
-		TimestampFormat: GetString(LogTimeFormat),
-		UTC:             GetBool(LogUTC),
+		DisableColor:       GetBool(LogNoColor),
+		ForceColor:         GetBool(LogForceColor),
+		TimestampFormat:    GetString(LogTimeFormat),
+		UTC:                GetBool(LogUTC),
+		IncludeCodeInfo:    GetBool(LogIncludeCodeInfo),
+		JSONEnabled:        GetBool(LogJSONEnabled),
+		JSONTimestampField: GetString(LogJSONTimestampField),
+		JSONLevelField:     GetString(LogJSONLevelField),
+		JSONMessageField:   GetString(LogJSONMessageField),
+		JSONFuncField:      GetString(LogJSONFuncField),
+		JSONFileField:      GetString(LogJSONFileField),
 	})
 	logFilename := GetString(LogFilename)
 	if logFilename != "" {
diff --git a/pkg/i18n/en_base_config_descriptions.go b/pkg/i18n/en_base_config_descriptions.go
index 444b524a8..614aa7ec6 100644
--- a/pkg/i18n/en_base_config_descriptions.go
+++ b/pkg/i18n/en_base_config_descriptions.go
@@ -29,15 +29,22 @@ var IgnoredType = "IGNORE"
 
 //revive:disable
 var (
-	ConfigLang          = FFC("config.lang", "Default language for translation (API calls may support language override using headers)", StringType)
-	ConfigLogCompress   = FFC("config.log.compress", "Determines if the rotated log files should be compressed using gzip", BooleanType)
-	ConfigLogFilename   = FFC("config.log.filename", "Filename is the file to write logs to.  Backup log files will be retained in the same directory", StringType)
-	ConfigLogFilesize   = FFC("config.log.filesize", "MaxSize is the maximum size the log file before it gets rotated", ByteSizeType)
-	ConfigLogForceColor = FFC("config.log.forceColor", "Force color to be enabled, even when a non-TTY output is detected", BooleanType)
-	ConfigLogLevel      = FFC("config.log.level", "The log level - error, warn, info, debug, trace", StringType)
-	ConfigLogMaxAge     = FFC("config.log.maxAge", "The maximum time to retain old log files based on the timestamp encoded in their filename.", TimeDurationType)
-	ConfigLogMaxBackups = FFC("config.log.maxBackups", "Maximum number of old log files to retain", IntType)
-	ConfigLogNoColor    = FFC("config.log.noColor", "Force color to be disabled, event when TTY output is detected", BooleanType)
-	ConfigLogTimeFormat = FFC("config.log.timeFormat", "Custom time format for logs", TimeFormatType)
-	ConfigLogUtc        = FFC("config.log.utc", "Use UTC timestamps for logs", BooleanType)
+	ConfigLang                  = FFC("config.lang", "Default language for translation (API calls may support language override using headers)", StringType)
+	ConfigLogCompress           = FFC("config.log.compress", "Determines if the rotated log files should be compressed using gzip", BooleanType)
+	ConfigLogFilename           = FFC("config.log.filename", "Filename is the file to write logs to.  Backup log files will be retained in the same directory", StringType)
+	ConfigLogFilesize           = FFC("config.log.filesize", "MaxSize is the maximum size the log file before it gets rotated", ByteSizeType)
+	ConfigLogForceColor         = FFC("config.log.forceColor", "Force color to be enabled, even when a non-TTY output is detected", BooleanType)
+	ConfigLogLevel              = FFC("config.log.level", "The log level - error, warn, info, debug, trace", StringType)
+	ConfigLogMaxAge             = FFC("config.log.maxAge", "The maximum time to retain old log files based on the timestamp encoded in their filename.", TimeDurationType)
+	ConfigLogMaxBackups         = FFC("config.log.maxBackups", "Maximum number of old log files to retain", IntType)
+	ConfigLogNoColor            = FFC("config.log.noColor", "Force color to be disabled, event when TTY output is detected", BooleanType)
+	ConfigLogTimeFormat         = FFC("config.log.timeFormat", "Custom time format for logs", TimeFormatType)
+	ConfigLogUtc                = FFC("config.log.utc", "Use UTC timestamps for logs", BooleanType)
+	ConfigLogIncludeCodeInfo    = FFC("config.log.includeCodeInfo", "Enables the report caller for including the calling file and line number, and the calling function. If using text logs, it uses the logrus text format rather than the default prefix format.", BooleanType)
+	ConfigLogJSONEnabled        = FFC("config.log.json.enabled", "Enables JSON formatted logs rather than text. All log color settings are ignored when enabled.", BooleanType)
+	ConfigLogJSONTimestampField = FFC("config.log.json.fields.timestamp", "Configures the JSON key containing the timestamp of the log", StringType)
+	ConfigLogJSONLevelField     = FFC("config.log.json.fields.level", "Configures the JSON key containing the log level", StringType)
+	ConfigLogJSONMessageField   = FFC("config.log.json.fields.message", "Configures the JSON key containing the log message", StringType)
+	ConfigLogJSONFuncField      = FFC("config.log.json.fields.func", "Configures the JSON key containing the calling function", StringType)
+	ConfigLogJSONFileField      = FFC("config.log.json.fields.file", "configures the JSON key containing the calling file", StringType)
 )
diff --git a/pkg/log/log.go b/pkg/log/log.go
index 3c735b3d6..9c7c7c3d4 100644
--- a/pkg/log/log.go
+++ b/pkg/log/log.go
@@ -71,10 +71,17 @@ func SetLevel(level string) {
 }
 
 type Formatting struct {
-	DisableColor    bool
-	ForceColor      bool
-	TimestampFormat string
-	UTC             bool
+	DisableColor       bool
+	ForceColor         bool
+	TimestampFormat    string
+	UTC                bool
+	IncludeCodeInfo    bool
+	JSONEnabled        bool
+	JSONTimestampField string
+	JSONLevelField     string
+	JSONMessageField   string
+	JSONFuncField      string
+	JSONFileField      string
 }
 
 type utcFormat struct {
@@ -87,16 +94,46 @@ func (utc *utcFormat) Format(e *logrus.Entry) ([]byte, error) {
 }
 
 func SetFormatting(format Formatting) {
-	var formatter logrus.Formatter = &prefixed.TextFormatter{
-		DisableColors:   format.DisableColor,
-		ForceColors:     format.ForceColor,
-		TimestampFormat: format.TimestampFormat,
-		DisableSorting:  false,
-		ForceFormatting: true,
-		FullTimestamp:   true,
+	var formatter logrus.Formatter
+
+	switch {
+	case format.JSONEnabled:
+		formatter = &logrus.JSONFormatter{
+			TimestampFormat: format.TimestampFormat,
+			FieldMap: logrus.FieldMap{
+				logrus.FieldKeyTime:  format.JSONTimestampField,
+				logrus.FieldKeyLevel: format.JSONLevelField,
+				logrus.FieldKeyMsg:   format.JSONMessageField,
+				logrus.FieldKeyFunc:  format.JSONFuncField,
+				logrus.FieldKeyFile:  format.JSONFileField,
+			},
+		}
+	case format.IncludeCodeInfo:
+		formatter = &logrus.TextFormatter{
+			DisableColors:   format.DisableColor,
+			ForceColors:     format.ForceColor,
+			TimestampFormat: format.TimestampFormat,
+			DisableSorting:  false,
+			FullTimestamp:   true,
+		}
+	default:
+		formatter = &prefixed.TextFormatter{
+			DisableColors:   format.DisableColor,
+			ForceColors:     format.ForceColor,
+			TimestampFormat: format.TimestampFormat,
+			DisableSorting:  false,
+			ForceFormatting: true,
+			FullTimestamp:   true,
+		}
+	}
+
+	if format.IncludeCodeInfo {
+		logrus.SetReportCaller(true)
 	}
+
 	if format.UTC {
 		formatter = &utcFormat{f: formatter}
 	}
+
 	logrus.SetFormatter(formatter)
 }


Test patch:
diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go
index 841f3dcf7..2bb66e3f7 100644
--- a/pkg/log/log_test.go
+++ b/pkg/log/log_test.go
@@ -66,3 +66,19 @@ func TestSetFormatting(t *testing.T) {
 	})
 	L(context.Background()).Infof("time in UTC")
 }
+
+func TestSetFormattingIncludeCodeInfo(t *testing.T) {
+	SetFormatting(Formatting{
+		IncludeCodeInfo: true,
+	})
+
+	L(context.Background()).Infof("code info included")
+}
+
+func TestSetFormattingJSONEnabled(t *testing.T) {
+	SetFormatting(Formatting{
+		JSONEnabled: true,
+	})
+
+	L(context.Background()).Infof("JSON logs")
+}