From 5ba8b8200ad770780d408e3a080f1e0d91b6a480 Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Wed, 24 Nov 2021 09:59:53 +0100 Subject: [PATCH] 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 | 4 ++ .../http/logging/get_response_log.test.ts | 15 ++++++++ .../server/http/logging/get_response_log.ts | 4 ++ src/core/server/http/router/request.ts | 1 + .../logging/layouts/json_layout.test.ts | 12 +++--- .../server/logging/layouts/json_layout.ts | 10 +++-- .../functional_execution_context/config.ts | 4 ++ .../fixtures/plugins/alerts/server/plugin.ts | 10 +++-- .../tests/log_correlation.ts | 37 +++++++++++++++---- 9 files changed, 78 insertions(+), 19 deletions(-) diff --git a/src/core/server/http/http_server.ts b/src/core/server/http/http_server.ts index 26725aff71b6c4..348b5c4af3e58c 100644 --- a/src/core/server/http/http_server.ts +++ b/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; }); diff --git a/src/core/server/http/logging/get_response_log.test.ts b/src/core/server/http/logging/get_response_log.test.ts index df91ae9c1a98b8..4e749e9b6c8e0c 100644 --- a/src/core/server/http/logging/get_response_log.test.ts +++ b/src/core/server/http/logging/get_response_log.test.ts @@ -27,6 +27,7 @@ interface RequestFixtureOptions { path?: string; query?: Record; response?: Record | Boom.Boom; + app?: Record; } 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": "", diff --git a/src/core/server/http/logging/get_response_log.ts b/src/core/server/http/logging/get_response_log.ts index 37ee618e43395d..e65871c1b1f11c 100644 --- a/src/core/server/http/logging/get_response_log.ts +++ b/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 { diff --git a/src/core/server/http/router/request.ts b/src/core/server/http/router/request.ts index 89511c00a8f326..94d353e1335b31 100644 --- a/src/core/server/http/router/request.ts +++ b/src/core/server/http/router/request.ts @@ -35,6 +35,7 @@ export interface KibanaRequestState extends RequestApplicationState { requestId: string; requestUuid: string; rewrittenUrl?: URL; + traceId?: string; } /** diff --git a/src/core/server/logging/layouts/json_layout.test.ts b/src/core/server/logging/layouts/json_layout.test.ts index d3bf2eab473a4d..259900fd5d3fb8 100644 --- a/src/core/server/logging/layouts/json_layout.test.ts +++ b/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' }, }); }); diff --git a/src/core/server/logging/layouts/json_layout.ts b/src/core/server/logging/layouts/json_layout.ts index 5c23e7ac1a9111..84ceb0a30e9bb0 100644 --- a/src/core/server/logging/layouts/json_layout.ts +++ b/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; diff --git a/x-pack/test/functional_execution_context/config.ts b/x-pack/test/functional_execution_context/config.ts index 456d31b586ad08..6c7935593a18d8 100644 --- a/x-pack/test/functional_execution_context/config.ts +++ b/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'])}`, ], }, }; diff --git a/x-pack/test/functional_execution_context/fixtures/plugins/alerts/server/plugin.ts b/x-pack/test/functional_execution_context/fixtures/plugins/alerts/server/plugin.ts index ec4e3ef99c6df3..20e0adbf5dacd8 100644 --- a/x-pack/test/functional_execution_context/fixtures/plugins/alerts/server/plugin.ts +++ b/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 { + // 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(); diff --git a/x-pack/test/functional_execution_context/tests/log_correlation.ts b/x-pack/test/functional_execution_context/tests/log_correlation.ts index 80bb2285a665e8..fddaf282b7a7ff 100644 --- a/x-pack/test/functional_execution_context/tests/log_correlation.ts +++ b/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, }); });