[FAB-12942] use logfmt format for log fields

Change-Id: Ibbbf4f55bd42a0914edc4b247c391e020b3a68a4
Signed-off-by: Matthew Sykes <sykesmat@us.ibm.com>

Author: sykesm

Gopkg.lock

@@ -153,6 +153,10 @@ noverify = [
   name = "go.uber.org/zap"
   version = "1.9.0"
 
+[[constraint]]
+  branch = "master"
+  name = "github.com/sykesm/zap-logfmt"
+
 [[constraint]]
   name = "github.com/grpc-ecosystem/go-grpc-middleware"
   version = "1.0.0"

Gopkg.toml

@@ -15,10 +15,11 @@ type Encoding int8
 const (
 	CONSOLE = iota
 	JSON
+	LOGFMT
 )
 
 // EncodingSelector is used to determine whether log records are
-// encoded as JSON or in a human readable CONSOLE format.
+// encoded as JSON or in human readable CONSOLE or LOGFMT formats.
 type EncodingSelector interface {
 	Encoding() Encoding
 }

common/flogging/core.go

@@ -10,6 +10,7 @@ import (
 	"io"
 	"time"
 
+	zaplogfmt "github.com/sykesm/zap-logfmt"
 	"go.uber.org/zap/buffer"
 	"go.uber.org/zap/zapcore"
 )
@@ -29,7 +30,7 @@ type Formatter interface {
 
 func NewFormatEncoder(formatters ...Formatter) *FormatEncoder {
 	return &FormatEncoder{
-		Encoder: zapcore.NewConsoleEncoder(zapcore.EncoderConfig{
+		Encoder: zaplogfmt.NewEncoder(zapcore.EncoderConfig{
 			MessageKey:     "", // disable
 			LevelKey:       "", // disable
 			TimeKey:        "", // disable

common/flogging/fabenc/encoder.go

@@ -29,12 +29,12 @@ func TestEncodeEntry(t *testing.T) {
 		expected string
 	}{
 		{name: "empty spec and nil fields", spec: "", fields: nil, expected: "\n"},
-		{name: "empty spec with fields", spec: "", fields: []zapcore.Field{zap.String("key", "value")}, expected: `{"key": "value"}` + "\n"},
+		{name: "empty spec with fields", spec: "", fields: []zapcore.Field{zap.String("key", "value")}, expected: "key=value\n"},
 		{name: "simple spec and nil fields", spec: "simple-string", expected: "simple-string\n"},
 		{name: "simple spec and empty fields", spec: "simple-string", fields: []zapcore.Field{}, expected: "simple-string\n"},
-		{name: "simple spec with fields", spec: "simple-string", fields: []zapcore.Field{zap.String("key", "value")}, expected: `simple-string {"key": "value"}` + "\n"},
-		{name: "duration", spec: "", fields: []zapcore.Field{zap.Duration("duration", time.Second)}, expected: `{"duration": "1s"}` + "\n"},
-		{name: "time", spec: "", fields: []zapcore.Field{zap.Time("time", startTime)}, expected: fmt.Sprintf(`{"time": "%s"}`+"\n", startTime.Format("2006-01-02T15:04:05.999Z07:00"))},
+		{name: "simple spec with fields", spec: "simple-string", fields: []zapcore.Field{zap.String("key", "value")}, expected: "simple-string key=value\n"},
+		{name: "duration", spec: "", fields: []zapcore.Field{zap.Duration("duration", time.Second)}, expected: "duration=1s\n"},
+		{name: "time", spec: "", fields: []zapcore.Field{zap.Time("time", startTime)}, expected: fmt.Sprintf("time=%s\n", startTime.Format("2006-01-02T15:04:05.999Z07:00"))},
 	}
 
 	for _, tc := range tests {

common/flogging/fabenc/encoder_test.go

@@ -88,5 +88,5 @@ func TestRecordingCoreWith(t *testing.T) {
 	logger = logger.With("key", "value")
 
 	logger.Debug("message")
-	gt.Expect(recorder).To(gbytes.Say(`message {"key": "value"}`))
+	gt.Expect(recorder).To(gbytes.Say(`message key=value`))
 }

common/flogging/floggingtest/logger_test.go

@@ -64,6 +64,23 @@ func TestGlobalInitJSON(t *testing.T) {
 	assert.Regexp(t, `{"level":"debug","ts":\d+.\d+,"name":"testlogger","caller":"flogging/global_test.go:\d+","msg":"this is a message"}\s+`, buf.String())
 }
 
+func TestGlobalInitLogfmt(t *testing.T) {
+	flogging.Reset()
+	defer flogging.Reset()
+
+	buf := &bytes.Buffer{}
+	flogging.Init(flogging.Config{
+		Format:  "logfmt",
+		LogSpec: "DEBUG",
+		Writer:  buf,
+	})
+
+	logger := flogging.MustGetLogger("testlogger")
+	logger.Debug("this is a message")
+
+	assert.Regexp(t, `^ts=\d+.\d+ level=debug name=testlogger caller=flogging/global_test.go:\d+ msg="this is a message"`, buf.String())
+}
+
 func TestGlobalInitPanic(t *testing.T) {
 	flogging.Reset()
 	defer flogging.Reset()

common/flogging/global_test.go

@@ -14,6 +14,7 @@ import (
 
 	"github.com/hyperledger/fabric/common/flogging/fabenc"
 	logging "github.com/op/go-logging"
+	zaplogfmt "github.com/sykesm/zap-logfmt"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
@@ -101,9 +102,10 @@ func (s *Logging) Apply(c Config) error {
 	s.SetWriter(c.Writer)
 
 	var formatter logging.Formatter
-	if s.Encoding() == JSON {
+	switch s.Encoding() {
+	case JSON, LOGFMT:
 		formatter = SetFormat(defaultFormat)
-	} else {
+	default:
 		formatter = SetFormat(c.Format)
 	}
 
@@ -128,6 +130,11 @@ func (s *Logging) SetFormat(format string) error {
 		return nil
 	}
 
+	if format == "logfmt" {
+		s.encoding = LOGFMT
+		return nil
+	}
+
 	formatters, err := fabenc.ParseFormat(format)
 	if err != nil {
 		return err
@@ -214,6 +221,7 @@ func (s *Logging) ZapLogger(name string) *zap.Logger {
 		Encoders: map[Encoding]zapcore.Encoder{
 			JSON:    zapcore.NewJSONEncoder(s.encoderConfig),
 			CONSOLE: fabenc.NewFormatEncoder(s.multiFormatter),
+			LOGFMT:  zaplogfmt.NewEncoder(s.encoderConfig),
 		},
 		Selector: s,
 		Output:   s,

common/flogging/logging.go

@@ -33,15 +33,15 @@ func TestFabricLoggerEncoding(t *testing.T) {
 
 	buf.Reset()
 	fl.Info("string value", 0, 1.23, struct{}{})
-	assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m string value 0 1.23 {} {\"extra\": \"field\"}\n", buf.String())
+	assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m string value 0 1.23 {} extra=field\n", buf.String())
 
 	buf.Reset()
 	fl.Infof("string %s, %d, %.3f, %v", "strval", 0, 1.23, struct{}{})
-	assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m string strval, 0, 1.230, {} {\"extra\": \"field\"}\n", buf.String())
+	assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m string strval, 0, 1.230, {} extra=field\n", buf.String())
 
 	buf.Reset()
 	fl.Infow("this is a message", "int", 0, "float", 1.23, "struct", struct{}{})
-	assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m this is a message {\"extra\": \"field\", \"int\": 0, \"float\": 1.23, \"struct\": {}}\n", buf.String())
+	assert.Equal(t, "\x1b[34m[test] TestFabricLoggerEncoding -> INFO\x1b[0m this is a message extra=field int=0 float=1.23 struct={}\n", buf.String())
 }
 
 func TestFabricLogger(t *testing.T) {