[7.x] Ensure ECS compliant logging when enabled. (#3829) (#4536)

If `logging.ecs` is set log data in ECS compliant way.

closes #3796

_meta/beat.yml

@@ -1058,13 +1058,10 @@ output.elasticsearch:
  # Unix epoch. Defaults to disabled.
  #interval: 0
 
-# Set to true to log messages in json format.
-#logging.json: false
-
-# Set to true to log with minimal Elastic Common Schema (ECS) fields set.
-# It is recommended to set `logging.json=true` when enabling ECS logging.
-# Defaults to false.
-#logging.ecs: false
+# Set to true, to log messages with minimal required Elastic Common Schema (ECS)
+# information. Recommended to use in combination with `logging.json=true`
+# Defaults to true.
+#logging.ecs: true
 
 
 #=============================== HTTP Endpoint ===============================

apm-server.docker.yml

@@ -1058,13 +1058,10 @@ output.elasticsearch:
  # Unix epoch. Defaults to disabled.
  #interval: 0
 
-# Set to true to log messages in json format.
-#logging.json: false
-
-# Set to true to log with minimal Elastic Common Schema (ECS) fields set.
-# It is recommended to set `logging.json=true` when enabling ECS logging.
-# Defaults to false.
-#logging.ecs: false
+# Set to true, to log messages with minimal required Elastic Common Schema (ECS)
+# information. Recommended to use in combination with `logging.json=true`
+# Defaults to true.
+#logging.ecs: true
 
 
 #=============================== HTTP Endpoint ===============================

apm-server.yml

@@ -1058,13 +1058,10 @@ output.elasticsearch:
  # Unix epoch. Defaults to disabled.
  #interval: 0
 
-# Set to true to log messages in json format.
-#logging.json: false
-
-# Set to true to log with minimal Elastic Common Schema (ECS) fields set.
-# It is recommended to set `logging.json=true` when enabling ECS logging.
-# Defaults to false.
-#logging.ecs: false
+# Set to true, to log messages with minimal required Elastic Common Schema (ECS)
+# information. Recommended to use in combination with `logging.json=true`
+# Defaults to true.
+#logging.ecs: true
 
 
 #=============================== HTTP Endpoint ===============================

beater/middleware/log_middleware.go

@@ -34,73 +34,76 @@ import (
 
 // LogMiddleware returns a middleware taking care of logging processing a request in the middleware and the request handler
 func LogMiddleware() Middleware {
- logger := logp.NewLogger(logs.Request)
  return func(h request.Handler) (request.Handler, error) {
-
  return func(c *request.Context) {
- var reqID, transactionID, traceID string
  start := time.Now()
- tx := apm.TransactionFromContext(c.Request.Context())
- if tx != nil {
- // This request is being traced, grab its IDs to add to logs.
- traceContext := tx.TraceContext()
- transactionID = traceContext.Span.String()
- traceID = traceContext.Trace.String()
- reqID = transactionID
- } else {
- uuid, err := uuid.NewV4()
- if err != nil {
- id := request.IDResponseErrorsInternal
- logger.Errorw(request.MapResultIDToStatus[id].Keyword, "error", err)
- c.Result.SetWithError(id, err)
- c.Write()
- return
- }
- reqID = uuid.String()
- }
-
- reqLogger := logger.With(
- "request_id", reqID,
- "method", c.Request.Method,
- "URL", c.Request.URL,
- "content_length", c.Request.ContentLength,
- "remote_address", utility.RemoteAddr(c.Request),
- "user-agent", c.Request.Header.Get(headers.UserAgent))
-
- if traceID != "" {
- reqLogger = reqLogger.With(
- "trace.id", traceID,
- "transaction.id", transactionID,
- )
+ c.Logger = loggerWithRequestContext(c)
+ var err error
+ if c.Logger, err = loggerWithTraceContext(c); err != nil {
+ id := request.IDResponseErrorsInternal
+ c.Logger.Error(request.MapResultIDToStatus[id].Keyword, logp.Error(err))
+ c.Result.SetWithError(id, err)
+ c.Write()
+ return
  }
-
- c.Logger = reqLogger
  h(c)
- reqLogger = reqLogger.With("event.duration", time.Since(start))
-
+ c.Logger = c.Logger.With("event.duration", time.Since(start))
  if c.MultipleWriteAttempts() {
- reqLogger.Warn("multiple write attempts")
+ c.Logger.Warn("multiple write attempts")
  }
-
  keyword := c.Result.Keyword
  if keyword == "" {
  keyword = "handled request"
  }
-
- keysAndValues := []interface{}{"response_code", c.Result.StatusCode}
- if c.Result.Err != nil {
- keysAndValues = append(keysAndValues, "error", c.Result.Err.Error())
- }
- if c.Result.Stacktrace != "" {
- keysAndValues = append(keysAndValues, "stacktrace", c.Result.Stacktrace)
- }
-
+ c.Logger = loggerWithResult(c)
  if c.Result.Failure() {
- reqLogger.Errorw(keyword, keysAndValues...)
- } else {
- reqLogger.Infow(keyword, keysAndValues...)
+ c.Logger.Error(keyword)
+ return
  }
-
+ c.Logger.Info(keyword)
  }, nil
  }
 }
+
+func loggerWithRequestContext(c *request.Context) *logp.Logger {
+ logger := logp.NewLogger(logs.Request).With(
+ "url.original", c.Request.URL.String(),
+ "http.request.method", c.Request.Method,
+ "user_agent.original", c.Request.Header.Get(headers.UserAgent),
+ "source.address", utility.RemoteAddr(c.Request))
+ if c.Request.ContentLength != -1 {
+ logger = logger.With("http.request.body.bytes", c.Request.ContentLength)
+ }
+ return logger
+}
+
+func loggerWithTraceContext(c *request.Context) (*logp.Logger, error) {
+ tx := apm.TransactionFromContext(c.Request.Context())
+ if tx == nil {
+ uuid, err := uuid.NewV4()
+ if err != nil {
+ return c.Logger, err
+ }
+ return c.Logger.With("http.request.id", uuid.String()), nil
+ }
+ // This request is being traced, grab its IDs to add to logs.
+ traceContext := tx.TraceContext()
+ transactionID := traceContext.Span.String()
+ return c.Logger.With(
+ "trace.id", traceContext.Trace.String(),
+ "transaction.id", transactionID,
+ "http.request.id", transactionID,
+ ), nil
+}
+
+func loggerWithResult(c *request.Context) *logp.Logger {
+ logger := c.Logger.With(
+ "http.response.status_code", c.Result.StatusCode)
+ if c.Result.Err != nil {
+ logger = logger.With("error.message", c.Result.Err.Error())
+ }
+ if c.Result.Stacktrace != "" {
+ logger = logger.With("error.stack_trace", c.Result.Stacktrace)
+ }
+ return logger
+}

beater/middleware/log_middleware_test.go

@@ -21,15 +21,16 @@ import (
  "net/http"
  "testing"
 
- "github.com/pkg/errors"
  "github.com/stretchr/testify/assert"
  "github.com/stretchr/testify/require"
  "go.uber.org/zap/zapcore"
 
  "go.elastic.co/apm"
  "go.elastic.co/apm/apmtest"
 
+ "github.com/elastic/beats/v7/libbeat/common"
  "github.com/elastic/beats/v7/libbeat/logp"
+ "github.com/elastic/beats/v7/libbeat/logp/configure"
 
  "github.com/elastic/apm-server/beater/beatertest"
  "github.com/elastic/apm-server/beater/headers"
@@ -38,31 +39,30 @@ import (
 )
 
 func TestLogMiddleware(t *testing.T) {
- err := logp.DevelopmentSetup(logp.ToObserverOutput())
- require.NoError(t, err)
 
  testCases := []struct {
  name, message string
  level zapcore.Level
  handler request.Handler
  code int
- error error
- stacktrace bool
  traced bool
+ ecsKeys []string
  }{
  {
  name: "Accepted",
  message: "request accepted",
  level: zapcore.InfoLevel,
  handler: beatertest.Handler202,
  code: http.StatusAccepted,
+ ecsKeys: []string{"url.original"},
  },
  {
  name: "Traced",
  message: "request accepted",
  level: zapcore.InfoLevel,
  handler: beatertest.Handler202,
  code: http.StatusAccepted,
+ ecsKeys: []string{"url.original", "trace.id", "transaction.id"},
  traced: true,
  },
  {
@@ -71,16 +71,15 @@ func TestLogMiddleware(t *testing.T) {
  level: zapcore.ErrorLevel,
  handler: beatertest.Handler403,
  code: http.StatusForbidden,
- error: errors.New("forbidden request"),
+ ecsKeys: []string{"url.original", "error.message"},
  },
  {
- name: "Panic",
- message: "internal error",
- level: zapcore.ErrorLevel,
- handler: Apply(RecoverPanicMiddleware(), beatertest.HandlerPanic),
- code: http.StatusInternalServerError,
- error: errors.New("panic on Handle"),
- stacktrace: true,
+ name: "Panic",
+ message: "internal error",
+ level: zapcore.ErrorLevel,
+ handler: Apply(RecoverPanicMiddleware(), beatertest.HandlerPanic),
+ code: http.StatusInternalServerError,
+ ecsKeys: []string{"url.original", "error.message", "error.stack_trace"},
  },
  {
  name: "Error without keyword",
@@ -90,12 +89,19 @@ func TestLogMiddleware(t *testing.T) {
  c.Result.StatusCode = http.StatusForbidden
  c.Write()
  },
- code: http.StatusForbidden,
+ code: http.StatusForbidden,
+ ecsKeys: []string{"url.original"},
  },
  }
 
  for _, tc := range testCases {
  t.Run(tc.name, func(t *testing.T) {
+ // log setup
+ configure.Logging("APM Server test",
+ common.MustNewConfigFrom(`{"ecs":true}`))
+ require.NoError(t, logp.DevelopmentSetup(logp.ToObserverOutput()))
+
+ // prepare and record request
  c, rec := beatertest.DefaultContextWithResponseRecorder()
  c.Request.Header.Set(headers.UserAgent, tc.name)
  if tc.traced {
@@ -105,39 +111,27 @@ func TestLogMiddleware(t *testing.T) {
  }
  Apply(LogMiddleware(), tc.handler)(c)
 
+ // check log lines
  assert.Equal(t, tc.code, rec.Code)
- for i, entry := range logp.ObserverLogs().TakeAll() {
-  // expect only one log entry per request
-  assert.Equal(t, i, 0)
-  assert.Equal(t, logs.Request, entry.LoggerName)
-  assert.Equal(t, tc.level, entry.Level)
-  assert.Equal(t, tc.message, entry.Message)
+ entries := logp.ObserverLogs().TakeAll()
+ require.Equal(t, 1, len(entries))
+ entry := entries[0]
+ assert.Equal(t, logs.Request, entry.LoggerName)
+ assert.Equal(t, tc.level, entry.Level)
+ assert.Equal(t, tc.message, entry.Message)
 
- ec := entry.ContextMap()
- t.Logf("context map: %v", ec)
-
- assert.NotEmpty(t, ec["request_id"])
- assert.NotEmpty(t, ec["method"])
- assert.Equal(t, c.Request.URL.String(), ec["URL"])
- assert.NotEmpty(t, ec["remote_address"])
- assert.Contains(t, ec, "event.duration")
- assert.Equal(t, c.Request.Header.Get(headers.UserAgent), ec["user-agent"])
- // zap encoded type
- assert.Equal(t, tc.code, int(ec["response_code"].(int64)))
- if tc.error != nil {
- assert.Equal(t, tc.error.Error(), ec["error"])
- }
- if tc.stacktrace {
- assert.NotZero(t, ec["stacktrace"])
- }
- if tc.traced {
- assert.NotEmpty(t, ec, "trace.id")
- assert.NotEmpty(t, ec, "transaction.id")
- assert.Equal(t, ec["request_id"], ec["transaction.id"])
- } else {
- assert.NotContains(t, ec, "trace.id")
- assert.NotContains(t, ec, "transaction.id")
- }
+ encoder := zapcore.NewMapObjectEncoder()
+ ec := common.MapStr{}
+ for _, f := range entry.Context {
+ f.AddTo(encoder)
+ ec.DeepUpdate(encoder.Fields)
+ }
+ keys := []string{"http.request.id", "http.request.method", "http.request.body.bytes",
+ "source.address", "user_agent.original", "http.response.status_code", "event.duration"}
+ keys = append(keys, tc.ecsKeys...)
+ for _, key := range keys {
+ ok, _ := ec.HasKey(key)
+ assert.True(t, ok, key)
  }
  })
  }

cmd/root.go

@@ -48,6 +48,7 @@ var libbeatConfigOverrides = []cfgfile.ConditionalOverride{{
  "metrics": map[string]interface{}{
  "enabled": false,
  },
+ "ecs": true,
  },
  }),
 }}

docs/copied-from-beats/docs/loggingconfig.asciidoc

@@ -249,8 +249,7 @@ When true, logs messages in JSON format. The default is false.
 [float]
 ==== `logging.ecs`
 
-When true, logs messages with minimal required Elastic Common Schema (ECS)
-information.
+When true, logs messages in Elastic Common Schema (ECS) compliant format.
 
 ifndef::serverless[]
 [float]

systemtest/export_test.go

@@ -49,6 +49,7 @@ func TestExportConfigDefaults(t *testing.T) {
 
  expectedConfig := strings.ReplaceAll(`
 logging:
+ ecs: true
  metrics:
  enabled: false
 path:
@@ -69,6 +70,7 @@ func TestExportConfigOverrideDefaults(t *testing.T) {
 
  expectedConfig := strings.ReplaceAll(`
 logging:
+ ecs: true
  metrics:
  enabled: true
 path:

systemtest/logging_test.go

@@ -69,8 +69,8 @@ func TestAPMServerRequestLoggingValid(t *testing.T) {
 
  srv.Close()
  for _, entry := range srv.Logs.All() {
- if entry.Logger == "request" && entry.Fields["URL"] == "/intake/v2/events" {
- statusCode, _ := entry.Fields["response_code"].(float64)
+ if entry.Logger == "request" && entry.Fields["url.original"] == "/intake/v2/events" {
+ statusCode, _ := entry.Fields["http.response.status_code"].(float64)
  logEntries = append(logEntries, entry)
  requestEntries = append(requestEntries, requestEntry{
  level: entry.Level,
@@ -95,8 +95,8 @@ func TestAPMServerRequestLoggingValid(t *testing.T) {
  }}, requestEntries)
 
  assert.NotContains(t, logEntries[0].Fields, "error")
- assert.Regexp(t, "validation error: 'transaction' required", logEntries[1].Fields["error"])
- assert.Equal(t, "event exceeded the permitted size.", logEntries[2].Fields["error"])
+ assert.Regexp(t, "validation error: 'transaction' required", logEntries[1].Fields["error.message"])
+ assert.Equal(t, "event exceeded the permitted size.", logEntries[2].Fields["error.message"])
 }
 
 // validMetadataJSON returns valid JSON-encoded metadata,