propagate trace.id to http response log manually (#118466)

* store traceId manually during hapi lifecycle

* update functional test

* REMOVE ME

* REMOVE ME

* REMOVE ME

* arghhh

* REMOVE ME

* REMOVE ME

* ARGH

* cleanup

* cleanup 2

* fix test

* add ping check

src/core/server/http/http_server.ts

@@ -16,6 +16,7 @@ import {
   getServerOptions,
   getRequestId,
 } from '@kbn/server-http-tools';
+import agent from 'elastic-apm-node';
 
 import type { Duration } from 'moment';
 import { Observable } from 'rxjs';
@@ -345,6 +346,9 @@ export class HttpServer {
         ...(request.app ?? {}),
         requestId,
         requestUuid: uuid.v4(),
+        // Kibana stores trace.id until https://github.com/elastic/apm-agent-nodejs/issues/2353 is resolved
+        // The current implementation of the APM agent ends a request transaction before "response" log is emitted.
+        traceId: agent.currentTraceIds['trace.id'],
       } as KibanaRequestState;
       return responseToolkit.continue;
     });

src/core/server/http/logging/get_response_log.test.ts

@@ -27,6 +27,7 @@ interface RequestFixtureOptions {
   path?: string;
   query?: Record<string, any>;
   response?: Record<string, any> | Boom.Boom;
+  app?: Record<string, any>;
 }
 
 function createMockHapiRequest({
@@ -39,6 +40,7 @@ function createMockHapiRequest({
   path = '/path',
   query = {},
   response = { headers: {}, statusCode: 200 },
+  app = {},
 }: RequestFixtureOptions = {}): Request {
   return {
     auth,
@@ -50,6 +52,7 @@ function createMockHapiRequest({
     path,
     query,
     response,
+    app,
   } as unknown as Request;
 }
 
@@ -143,6 +146,17 @@ describe('getEcsResponseLog', () => {
     expect(result.message).toMatchInlineSnapshot(`"GET /path 200"`);
   });
 
+  test('set traceId stored in the request app storage', () => {
+    const req = createMockHapiRequest({
+      app: {
+        foo: 'bar',
+        traceId: 'trace_id',
+      },
+    });
+    const result = getEcsResponseLog(req, logger);
+    expect(result.meta?.trace?.id).toBe('trace_id');
+  });
+
   test('handles Boom errors in the response', () => {
     const req = createMockHapiRequest({
       response: Boom.badRequest(),
@@ -280,6 +294,7 @@ describe('getEcsResponseLog', () => {
                 "status_code": 200,
               },
             },
+            "trace": undefined,
             "url": Object {
               "path": "/path",
               "query": "",

src/core/server/http/logging/get_response_log.ts

@@ -13,6 +13,7 @@ import numeral from '@elastic/numeral';
 import { LogMeta } from '@kbn/logging';
 import { Logger } from '../../logging';
 import { getResponsePayloadBytes } from './get_payload_size';
+import type { KibanaRequestState } from '../router';
 
 const FORBIDDEN_HEADERS = ['authorization', 'cookie', 'set-cookie'];
 const REDACTED_HEADER_TEXT = '[REDACTED]';
@@ -65,6 +66,8 @@ export function getEcsResponseLog(request: Request, log: Logger) {
   const bytes = getResponsePayloadBytes(response, log);
   const bytesMsg = bytes ? ` - ${numeral(bytes).format('0.0b')}` : '';
 
+  const traceId = (request.app as KibanaRequestState).traceId;
+
   const meta: LogMeta = {
     client: {
       ip: request.info.remoteAddress,
@@ -95,6 +98,7 @@ export function getEcsResponseLog(request: Request, log: Logger) {
     user_agent: {
       original: request.headers['user-agent'],
     },
+    trace: traceId ? { id: traceId } : undefined,
   };
 
   return {

src/core/server/http/router/request.ts

@@ -35,6 +35,7 @@ export interface KibanaRequestState extends RequestApplicationState {
   requestId: string;
   requestUuid: string;
   rewrittenUrl?: URL;
+  traceId?: string;
 }
 
 /**

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

@@ -343,9 +343,9 @@ test('format() meta can not override tracing properties', () => {
           trace: { id: 'trace_override' },
           transaction: { id: 'transaction_override' },
         },
-        spanId: 'spanId-1',
-        traceId: 'traceId-1',
-        transactionId: 'transactionId-1',
+        spanId: 'spanId',
+        traceId: 'traceId',
+        transactionId: 'transactionId',
       })
     )
   ).toStrictEqual({
@@ -359,8 +359,8 @@ test('format() meta can not override tracing properties', () => {
     process: {
       pid: 3,
     },
-    span: { id: 'spanId-1' },
-    trace: { id: 'traceId-1' },
-    transaction: { id: 'transactionId-1' },
+    span: { id: 'span_override' },
+    trace: { id: 'trace_override' },
+    transaction: { id: 'transaction_override' },
   });
 });

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

@@ -42,6 +42,10 @@ export class JsonLayout implements Layout {
   }
 
   public format(record: LogRecord): string {
+    const spanId = record.meta?.span?.id ?? record.spanId;
+    const traceId = record.meta?.trace?.id ?? record.traceId;
+    const transactionId = record.meta?.transaction?.id ?? record.transactionId;
+
     const log: Ecs = {
       ecs: { version: '8.0.0' },
       '@timestamp': moment(record.timestamp).format('YYYY-MM-DDTHH:mm:ss.SSSZ'),
@@ -54,9 +58,9 @@ export class JsonLayout implements Layout {
       process: {
         pid: record.pid,
       },
-      span: record.spanId ? { id: record.spanId } : undefined,
-      trace: record.traceId ? { id: record.traceId } : undefined,
-      transaction: record.transactionId ? { id: record.transactionId } : undefined,
+      span: spanId ? { id: spanId } : undefined,
+      trace: traceId ? { id: traceId } : undefined,
+      transaction: transactionId ? { id: transactionId } : undefined,
     };
     const output = record.meta ? merge({ ...record.meta }, log) : log;
 

x-pack/test/functional_execution_context/config.ts

@@ -55,6 +55,10 @@ export default async function ({ readConfigFile }: FtrConfigProviderContext) {
         '--logging.loggers[1].name=execution_context',
         '--logging.loggers[1].level=debug',
         `--logging.loggers[1].appenders=${JSON.stringify(['file'])}`,
+
+        '--logging.loggers[2].name=http.server.response',
+        '--logging.loggers[2].level=all',
+        `--logging.loggers[2].appenders=${JSON.stringify(['file'])}`,
       ],
     },
   };

x-pack/test/functional_execution_context/fixtures/plugins/alerts/server/plugin.ts

@@ -6,7 +6,7 @@
  */
 import apmAgent from 'elastic-apm-node';
 
-import { Plugin, CoreSetup } from 'kibana/server';
+import type { Plugin, CoreSetup } from 'kibana/server';
 import { PluginSetupContract as AlertingPluginSetup } from '../../../../../../plugins/alerting/server/plugin';
 import { EncryptedSavedObjectsPluginStart } from '../../../../../../plugins/encrypted_saved_objects/server';
 import { PluginSetupContract as FeaturesPluginSetup } from '../../../../../../plugins/features/server';
@@ -93,10 +93,14 @@ export class FixturePlugin implements Plugin<void, void, FixtureSetupDeps, Fixtu
         },
       },
       async (ctx, req, res) => {
+        // Kibana might set transactiopnSampleRate < 1.0 on CI, so we need to
+        // enforce transaction creation to prevent the test from failing.
         const transaction = apmAgent.startTransaction();
         const subscription = req.events.completed$.subscribe(() => {
-          transaction?.end();
-          subscription.unsubscribe();
+          setTimeout(() => {
+            transaction?.end();
+            subscription.unsubscribe();
+          }, 1_000);
         });
 
         await ctx.core.elasticsearch.client.asInternalUser.ping();

x-pack/test/functional_execution_context/tests/log_correlation.ts

@@ -14,23 +14,46 @@ export default function ({ getService }: FtrProviderContext) {
 
   describe('Log Correlation', () => {
     it('Emits "trace.id" into the logs', async () => {
-      const response1 = await supertest
-        .get('/emit_log_with_trace_id')
-        .set('x-opaque-id', 'myheader1');
-
+      const response1 = await supertest.get('/emit_log_with_trace_id');
+      expect(response1.status).to.be(200);
       expect(response1.body.traceId).to.be.a('string');
 
       const response2 = await supertest.get('/emit_log_with_trace_id');
+      expect(response2.status).to.be(200);
       expect(response1.body.traceId).to.be.a('string');
 
       expect(response2.body.traceId).not.to.be(response1.body.traceId);
 
+      let responseTraceId: string | undefined;
       await assertLogContains({
-        description: 'traceId included in the Kibana logs',
-        predicate: (record) =>
+        description: 'traceId included in the http logs',
+        predicate: (record) => {
           // we don't check trace.id value since trace.id in the test plugin and Kibana are different on CI.
           // because different 'elastic-apm-node' instaces are imported
-          Boolean(record.http?.request?.id?.includes('myheader1') && record.trace?.id),
+          if (
+            record.log?.logger === 'http.server.response' &&
+            record.url?.path === '/emit_log_with_trace_id'
+          ) {
+            responseTraceId = record.trace?.id;
+            return true;
+          }
+          return false;
+        },
+        retry,
+      });
+
+      expect(responseTraceId).to.be.a('string');
+
+      await assertLogContains({
+        description: 'elasticsearch logs have the same traceId',
+        predicate: (record) =>
+          Boolean(
+            record.log?.logger === 'elasticsearch.query.data' &&
+              record.trace?.id === responseTraceId &&
+              // esClient.ping() request
+              record.message?.includes('HEAD /')
+          ),
+
         retry,
       });
     });