enhance(logging): add flag to allow logging in ecs format, map custom…

… fields to ecs fields (#971)

cmd/vela-server/main.go

@@ -48,6 +48,12 @@ func main() {
 			Usage:   "set log level - options: (trace|debug|info|warn|error|fatal|panic)",
 			Value:   "info",
 		},
+		&cli.StringFlag{
+			EnvVars: []string{"VELA_LOG_FORMATTER", "LOG_FORMATTER"},
+			Name:    "log-formatter",
+			Usage:   "set log formatter - options: (json|ecs)",
+			Value:   "json",
+		},
 		&cli.StringFlag{
 			EnvVars: []string{"VELA_ADDR", "VELA_HOST"},
 			Name:    "server-addr",
@@ -247,9 +253,6 @@ func main() {
 	// Add Source Flags
 	app.Flags = append(app.Flags, scm.Flags...)
 
-	// set logrus to log in JSON format
-	logrus.SetFormatter(&logrus.JSONFormatter{})
-
 	if err = app.Run(os.Args); err != nil {
 		logrus.Fatal(err)
 	}

cmd/vela-server/server.go

@@ -26,6 +26,18 @@ import (
 )
 
 func server(c *cli.Context) error {
+	// set log formatter
+	switch c.String("log-formatter") {
+	case "json":
+		// set logrus to log in JSON format
+		logrus.SetFormatter(&logrus.JSONFormatter{})
+	case "ecs":
+		// set logrus to log in Elasticsearch Common Schema (ecs) format
+		logrus.SetFormatter(&middleware.ECSFormatter{
+			DataKey: "labels.vela",
+		})
+	}
+
 	// validate all input
 	err := validate(c)
 	if err != nil {

router/middleware/logger.go

@@ -20,6 +20,20 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
+// This file, in part, reproduces portions of
+// https://github.com/elastic/ecs-logging-go-logrus/blob/v1.0.0/formatter.go
+// to handle our custom fields in Format().
+
+// ECSFormatter holds ECS parameter information for logging.
+type ECSFormatter struct {
+	// DataKey allows users to put all the log entry parameters into a
+	// nested dictionary at a given key.
+	//
+	// DataKey is ignored for well-defined fields, such as "error",
+	// which will instead be stored under the appropriate ECS fields.
+	DataKey string
+}
+
 // Logger returns a gin.HandlerFunc (middleware) that logs requests using logrus.
 //
 // Requests with errors are logged using logrus.Error().
@@ -98,7 +112,7 @@ func Logger(logger *logrus.Logger, timeFormat string) gin.HandlerFunc {
 				// Append error field if this is an erroneous request.
 				entry.Error(c.Errors.String())
 			} else {
-				entry.Info()
+				entry.Infof("%v %v %v %s %s", fields["status"], fields["latency"], fields["ip"], fields["method"], fields["path"])
 			}
 		}
 	}
@@ -114,3 +128,60 @@ func sanitize(body interface{}) interface{} {
 
 	return body
 }
+
+// Format formats logrus.Entry as ECS-compliant JSON,
+// mapping our custom fields to ECS fields.
+func (f *ECSFormatter) Format(e *logrus.Entry) ([]byte, error) {
+	datahint := len(e.Data)
+	if f.DataKey != "" {
+		datahint = 2
+	}
+	data := make(logrus.Fields, datahint)
+	if len(e.Data) > 0 {
+		extraData := data
+		if f.DataKey != "" {
+			extraData = make(logrus.Fields, len(e.Data))
+		}
+		for k, v := range e.Data {
+			switch k {
+			case "ip":
+				data["client.ip"] = v
+			case "latency":
+				data["event.duration"] = v
+			case "method":
+				data["http.request.method"] = v
+			case "path":
+				data["url.path"] = v
+			case "status":
+				data["http.response.status_code"] = v
+			case "user-agent":
+				data["user_agent.name"] = v
+			case "version":
+				data["user_agent.version"] = v
+			default:
+				extraData[k] = v
+			}
+		}
+		if f.DataKey != "" && len(extraData) > 0 {
+			data[f.DataKey] = extraData
+		}
+	}
+
+	// ecsVersion holds the version of ECS with which the formatter is compatible.
+	data["ecs.version"] = "1.6.0"
+	ecopy := *e
+	ecopy.Data = data
+	e = &ecopy
+
+	ecsFieldMap := logrus.FieldMap{
+		logrus.FieldKeyTime:  "@timestamp",
+		logrus.FieldKeyMsg:   "message",
+		logrus.FieldKeyLevel: "log.level",
+	}
+
+	jf := logrus.JSONFormatter{
+		TimestampFormat: "2006-01-02T15:04:05.000Z0700",
+		FieldMap:        ecsFieldMap,
+	}
+	return jf.Format(e)
+}

router/middleware/logger_test.go

@@ -67,7 +67,6 @@ func TestMiddleware_Logger(t *testing.T) {
 
 	payload, _ := json.Marshal(`{"foo": "bar"}`)
 	wantLevel := logrus.InfoLevel
-	wantMessage := ""
 
 	logger, hook := test.NewNullLogger()
 	defer hook.Reset()
@@ -106,8 +105,16 @@ func TestMiddleware_Logger(t *testing.T) {
 		t.Errorf("Logger Level is %v, want %v", gotLevel, wantLevel)
 	}
 
-	if !reflect.DeepEqual(gotMessage, wantMessage) {
-		t.Errorf("Logger Message is %v, want %v", gotMessage, wantMessage)
+	if gotMessage == "" {
+		t.Errorf("Logger Message is %v, want non-empty string", gotMessage)
+	}
+
+	if strings.Contains(gotMessage, "GET") {
+		t.Errorf("Logger Message is %v, want message to contain GET", gotMessage)
+	}
+
+	if !strings.Contains(gotMessage, "POST") {
+		t.Errorf("Logger Message is %v, message shouldn't contain POST", gotMessage)
 	}
 }
 
@@ -217,3 +224,54 @@ func TestMiddleware_Logger_Sanitize(t *testing.T) {
 		}
 	}
 }
+
+func TestMiddleware_Format(t *testing.T) {
+
+	wantLabels := "labels.vela"
+
+	// setup data, fields, and logger
+	formatter := &ECSFormatter{
+		DataKey: wantLabels,
+	}
+
+	fields := logrus.Fields{
+		"ip":         "123.4.5.6",
+		"method":     http.MethodGet,
+		"path":       "/foobar",
+		"latency":    0,
+		"status":     http.StatusOK,
+		"user-agent": "foobar",
+		"version":    "v1.0.0",
+		"org":        "foo",
+	}
+
+	logger := logrus.NewEntry(logrus.StandardLogger())
+	entry := logger.WithFields(fields)
+
+	got, err := formatter.Format(entry)
+
+	fmt.Println("got:", string(got))
+	// run test
+	gotLabels := string(formatter.DataKey)
+
+	if err != nil {
+		t.Errorf("Format returned err: %v", err)
+	}
+
+	if got == nil {
+		t.Errorf("Format returned nothing, want a log")
+	}
+
+	if !reflect.DeepEqual(gotLabels, wantLabels) {
+		t.Errorf("Logger returned %v, want %v", gotLabels, wantLabels)
+	}
+
+	if !strings.Contains(string(got), "GET") {
+		t.Errorf("Format returned %v, want to contain GET", string(got))
+	}
+
+	if !strings.Contains(string(got), "/foobar") {
+		t.Errorf("Format returned %v, want to contain GET", string(got))
+	}
+
+}