store traceId manually during hapi lifecycle

Author: restrry

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,7 @@ export class HttpServer {
         ...(request.app ?? {}),
         requestId,
         requestUuid: uuid.v4(),
+        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

@@ -332,13 +332,13 @@ test('format() meta can not override tracing properties', () => {
         context: 'bar',
         pid: 3,
         meta: {
-          span: 'span_override',
-          trace: 'trace_override',
-          transaction: 'transaction_override',
+          span: { id: 'span_override' },
+          trace: { id: 'trace_override' },
+          transaction: { id: 'transaction_override' },
         },
-        spanId: 'spanId-1',
-        traceId: 'traceId-1',
-        transactionId: 'transactionId-1',
+        spanId: 'spanId',
+        traceId: 'traceId',
+        transactionId: 'transactionId',
       })
     )
   ).toStrictEqual({
@@ -352,8 +352,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;