Include tracing information in the Kibana logs (#112973) (#118604)

* change APM nodejs agent default

By default APM agent instruments the code to be a base for log correlation. But it doesn't send transactions to the APM server.

* emit trace IDs into the logs

* use ELASTIC_APM_DISABLE_SEND to keep APM agent active but disable send when necessary

* send data whenver active is set to "true"

* update tests

* keep APM agent active. control disableSend instead

* update snapshot tests

* add debug logging

* REMOVE me. log path to the agent

* init APM agent explicitly in test plugin. it uses another package instance

* REMOVE me. create transaction explicitly

* increase timeout setting for the test

* refactor tests

* remove debug logs

* remove explicit transaction creation

* Revert "remove explicit transaction creation"

This reverts commit cdf2d30.

* point to apm nodejs agent commit temporary until a new version is released

* migrate from disableSend to contextPropagationOnly

* TO DISCUSS. what if we enforce contextPropagationOnly to be configured when active is defined

* Revert "TO DISCUSS. what if we enforce contextPropagationOnly to be configured when active is defined"

This reverts commit 62dda4f.

* bump to version with fix

* commit using @elastic.co

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>

.buildkite/scripts/common/env.sh

@@ -38,8 +38,10 @@ export ELASTIC_APM_TRANSACTION_SAMPLE_RATE=0.1
 if is_pr; then
   if [[ "${GITHUB_PR_LABELS:-}" == *"ci:collect-apm"* ]]; then
     export ELASTIC_APM_ACTIVE=true
+    export ELASTIC_APM_CONTEXT_PROPAGATION_ONLY=false
   else
-    export ELASTIC_APM_ACTIVE=false
+    export ELASTIC_APM_ACTIVE=true
+    export ELASTIC_APM_CONTEXT_PROPAGATION_ONLY=true
   fi
 
   if [[ "${GITHUB_STEP_COMMIT_STATUS_ENABLED:-}" != "true" ]]; then
@@ -61,6 +63,7 @@ if is_pr; then
   export PR_TARGET_BRANCH="$GITHUB_PR_TARGET_BRANCH"
 else
   export ELASTIC_APM_ACTIVE=true
+  export ELASTIC_APM_CONTEXT_PROPAGATION_ONLY=false
   export CHECKS_REPORTER_ACTIVE=false
 fi
 

package.json

@@ -217,7 +217,7 @@
     "deep-freeze-strict": "^1.1.1",
     "deepmerge": "^4.2.2",
     "del": "^5.1.0",
-    "elastic-apm-node": "^3.23.0",
+    "elastic-apm-node": "3.24.0",
     "execa": "^4.0.2",
     "exit-hook": "^2.2.0",
     "expiry-js": "0.1.7",

packages/kbn-apm-config-loader/src/config.test.ts

@@ -21,7 +21,7 @@ describe('ApmConfiguration', () => {
   beforeEach(() => {
     // start with an empty env to avoid CI from spoiling snapshots, env is unique for each jest file
     process.env = {};
-
+    devConfigMock.raw = {};
     packageMock.raw = {
       version: '8.0.0',
       build: {
@@ -86,10 +86,11 @@ describe('ApmConfiguration', () => {
     let config = new ApmConfiguration(mockedRootDir, {}, false);
     expect(config.getConfig('serviceName')).toMatchInlineSnapshot(`
       Object {
-        "active": false,
+        "active": true,
         "breakdownMetrics": true,
         "captureSpanStackTraces": false,
         "centralConfig": false,
+        "contextPropagationOnly": true,
         "environment": "development",
         "globalLabels": Object {},
         "logUncaughtExceptions": true,
@@ -105,12 +106,13 @@ describe('ApmConfiguration', () => {
     config = new ApmConfiguration(mockedRootDir, {}, true);
     expect(config.getConfig('serviceName')).toMatchInlineSnapshot(`
       Object {
-        "active": false,
+        "active": true,
         "breakdownMetrics": false,
         "captureBody": "off",
         "captureHeaders": false,
         "captureSpanStackTraces": false,
         "centralConfig": false,
+        "contextPropagationOnly": true,
         "environment": "development",
         "globalLabels": Object {
           "git_rev": "sha",
@@ -162,13 +164,12 @@ describe('ApmConfiguration', () => {
 
   it('does not load the configuration from the dev config in distributable', () => {
     devConfigMock.raw = {
-      active: true,
-      serverUrl: 'https://dev-url.co',
+      active: false,
     };
     const config = new ApmConfiguration(mockedRootDir, {}, true);
     expect(config.getConfig('serviceName')).toEqual(
       expect.objectContaining({
-        active: false,
+        active: true,
       })
     );
   });
@@ -224,4 +225,130 @@ describe('ApmConfiguration', () => {
       })
     );
   });
+
+  describe('contextPropagationOnly', () => {
+    it('sets "active: true" and "contextPropagationOnly: true" by default', () => {
+      expect(new ApmConfiguration(mockedRootDir, {}, false).getConfig('serviceName')).toEqual(
+        expect.objectContaining({
+          active: true,
+          contextPropagationOnly: true,
+        })
+      );
+
+      expect(new ApmConfiguration(mockedRootDir, {}, true).getConfig('serviceName')).toEqual(
+        expect.objectContaining({
+          active: true,
+          contextPropagationOnly: true,
+        })
+      );
+    });
+
+    it('value from config overrides the default', () => {
+      const kibanaConfig = {
+        elastic: {
+          apm: {
+            active: false,
+            contextPropagationOnly: false,
+          },
+        },
+      };
+
+      expect(
+        new ApmConfiguration(mockedRootDir, kibanaConfig, false).getConfig('serviceName')
+      ).toEqual(
+        expect.objectContaining({
+          active: false,
+          contextPropagationOnly: false,
+        })
+      );
+
+      expect(
+        new ApmConfiguration(mockedRootDir, kibanaConfig, true).getConfig('serviceName')
+      ).toEqual(
+        expect.objectContaining({
+          active: false,
+          contextPropagationOnly: false,
+        })
+      );
+    });
+
+    it('is "false" if "active: true" configured and "contextPropagationOnly" is not specified', () => {
+      const kibanaConfig = {
+        elastic: {
+          apm: {
+            active: true,
+          },
+        },
+      };
+
+      expect(
+        new ApmConfiguration(mockedRootDir, kibanaConfig, false).getConfig('serviceName')
+      ).toEqual(
+        expect.objectContaining({
+          active: true,
+          contextPropagationOnly: false,
+        })
+      );
+
+      expect(
+        new ApmConfiguration(mockedRootDir, kibanaConfig, true).getConfig('serviceName')
+      ).toEqual(
+        expect.objectContaining({
+          active: true,
+          contextPropagationOnly: false,
+        })
+      );
+    });
+
+    it('throws if "active: false" set without configuring "contextPropagationOnly: false"', () => {
+      const kibanaConfig = {
+        elastic: {
+          apm: {
+            active: false,
+          },
+        },
+      };
+
+      expect(() =>
+        new ApmConfiguration(mockedRootDir, kibanaConfig, false).getConfig('serviceName')
+      ).toThrowErrorMatchingInlineSnapshot(
+        `"APM is disabled, but context propagation is enabled. Please disable context propagation with contextPropagationOnly:false"`
+      );
+
+      expect(() =>
+        new ApmConfiguration(mockedRootDir, kibanaConfig, true).getConfig('serviceName')
+      ).toThrowErrorMatchingInlineSnapshot(
+        `"APM is disabled, but context propagation is enabled. Please disable context propagation with contextPropagationOnly:false"`
+      );
+    });
+
+    it('does not throw if "active: false" and "contextPropagationOnly: false" configured', () => {
+      const kibanaConfig = {
+        elastic: {
+          apm: {
+            active: false,
+            contextPropagationOnly: false,
+          },
+        },
+      };
+
+      expect(
+        new ApmConfiguration(mockedRootDir, kibanaConfig, false).getConfig('serviceName')
+      ).toEqual(
+        expect.objectContaining({
+          active: false,
+          contextPropagationOnly: false,
+        })
+      );
+
+      expect(
+        new ApmConfiguration(mockedRootDir, kibanaConfig, true).getConfig('serviceName')
+      ).toEqual(
+        expect.objectContaining({
+          active: false,
+          contextPropagationOnly: false,
+        })
+      );
+    });
+  });
 });

packages/kbn-apm-config-loader/src/config.ts

@@ -16,7 +16,8 @@ import type { AgentConfigOptions } from 'elastic-apm-node';
 
 // https://www.elastic.co/guide/en/apm/agent/nodejs/current/configuration.html
 const DEFAULT_CONFIG: AgentConfigOptions = {
-  active: false,
+  active: true,
+  contextPropagationOnly: true,
   environment: 'development',
   logUncaughtExceptions: true,
   globalLabels: {},
@@ -71,6 +72,8 @@ export class ApmConfiguration {
 
   private getBaseConfig() {
     if (!this.baseConfig) {
+      const configFromSources = this.getConfigFromAllSources();
+
       this.baseConfig = merge(
         {
           serviceVersion: this.kibanaVersion,
@@ -79,9 +82,7 @@ export class ApmConfiguration {
         this.getUuidConfig(),
         this.getGitConfig(),
         this.getCiConfig(),
-        this.getConfigFromKibanaConfig(),
-        this.getDevConfig(),
-        this.getConfigFromEnv()
+        configFromSources
       );
 
       /**
@@ -114,6 +115,12 @@ export class ApmConfiguration {
       config.active = true;
     }
 
+    if (process.env.ELASTIC_APM_CONTEXT_PROPAGATION_ONLY === 'true') {
+      config.contextPropagationOnly = true;
+    } else if (process.env.ELASTIC_APM_CONTEXT_PROPAGATION_ONLY === 'false') {
+      config.contextPropagationOnly = false;
+    }
+
     if (process.env.ELASTIC_APM_ENVIRONMENT || process.env.NODE_ENV) {
       config.environment = process.env.ELASTIC_APM_ENVIRONMENT || process.env.NODE_ENV;
     }
@@ -249,4 +256,28 @@ export class ApmConfiguration {
       return {};
     }
   }
+
+  /**
+   * Reads APM configuration from different sources and merges them together.
+   */
+  private getConfigFromAllSources(): AgentConfigOptions {
+    const config = merge(
+      {},
+      this.getConfigFromKibanaConfig(),
+      this.getDevConfig(),
+      this.getConfigFromEnv()
+    );
+
+    if (config.active === false && config.contextPropagationOnly !== false) {
+      throw new Error(
+        'APM is disabled, but context propagation is enabled. Please disable context propagation with contextPropagationOnly:false'
+      );
+    }
+
+    if (config.active === true) {
+      config.contextPropagationOnly = config.contextPropagationOnly ?? false;
+    }
+
+    return config;
+  }
 }

packages/kbn-logging/src/log_record.ts

@@ -20,4 +20,7 @@ export interface LogRecord {
   error?: Error;
   meta?: { [name: string]: any };
   pid: number;
+  spanId?: string;
+  traceId?: string;
+  transactionId?: string;
 }

src/core/server/logging/layouts/json_layout.test.ts

@@ -58,6 +58,16 @@ const records: LogRecord[] = [
     timestamp,
     pid: 5355,
   },
+  {
+    context: 'context-7',
+    level: LogLevel.Trace,
+    message: 'message-6',
+    timestamp,
+    pid: 5355,
+    spanId: 'spanId-1',
+    traceId: 'traceId-1',
+    transactionId: 'transactionId-1',
+  },
 ];
 
 test('`createConfigSchema()` creates correct schema.', () => {
@@ -310,3 +320,40 @@ test('format() meta can not override timestamp', () => {
     },
   });
 });
+
+test('format() meta can not override tracing properties', () => {
+  const layout = new JsonLayout();
+  expect(
+    JSON.parse(
+      layout.format({
+        message: 'foo',
+        timestamp,
+        level: LogLevel.Debug,
+        context: 'bar',
+        pid: 3,
+        meta: {
+          span: 'span_override',
+          trace: 'trace_override',
+          transaction: 'transaction_override',
+        },
+        spanId: 'spanId-1',
+        traceId: 'traceId-1',
+        transactionId: 'transactionId-1',
+      })
+    )
+  ).toStrictEqual({
+    ecs: { version: expect.any(String) },
+    '@timestamp': '2012-02-01T09:30:22.011-05:00',
+    message: 'foo',
+    log: {
+      level: 'DEBUG',
+      logger: 'bar',
+    },
+    process: {
+      pid: 3,
+    },
+    span: { id: 'spanId-1' },
+    trace: { id: 'traceId-1' },
+    transaction: { id: 'transactionId-1' },
+  });
+});