From 1a6a9ae43865c888c5d4ec92a3d028cbbabc36d9 Mon Sep 17 00:00:00 2001 From: Rudolf Meijering Date: Wed, 8 Dec 2021 18:32:44 +0100 Subject: [PATCH] Surfacing deprecations with rich context from ES warning header (#120044) * First stab at surfacing deprecations from warning header * Log deprecations with error level but disable logger context by default * Don't filter out error logs from ProcRunner * Another try at not having messages ignored on CI * Log deprecation logs with warn not info * Tests * Let write() do it's writing * Commit pre-built @kbn/pm package * Second try to commit pre-built @kbn/pm package * Enable deprecation logger for jest_integration even though logs aren't interleaved * Apply suggestions from code review Co-authored-by: Luke Elmers * deprecations logger: warn for kibana and debug for users * Refactor split query and deprecation logger out of configure_client * Unit test for tooling_log_text_writer * Fix TS * Use event.meta.request.params.headers to include Client constructor headers * Fix tests * Ignore deprecation warnings not from Elasticsearch * Log on info level * Log in JSON so that entire deprecation message is on one line * commit built kbn-pm package Co-authored-by: Luke Elmers Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com> --- .../tooling_log_text_writer.test.ts.snap | 8 + .../tooling_log_text_writer.test.ts | 52 ++ .../tooling_log/tooling_log_text_writer.ts | 10 +- packages/kbn-pm/dist/index.js | 10 +- .../client/configure_client.test.ts | 411 +----------- .../elasticsearch/client/configure_client.ts | 95 +-- src/core/server/elasticsearch/client/index.ts | 3 +- .../client/log_query_and_deprecation.test.ts | 624 ++++++++++++++++++ .../client/log_query_and_deprecation.ts | 143 ++++ test/common/config.js | 4 + 10 files changed, 867 insertions(+), 493 deletions(-) create mode 100644 src/core/server/elasticsearch/client/log_query_and_deprecation.test.ts create mode 100644 src/core/server/elasticsearch/client/log_query_and_deprecation.ts diff --git a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.ts.snap b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.ts.snap index 7ff982acafbe4..5fa074d4c7739 100644 --- a/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.ts.snap +++ b/packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.ts.snap @@ -170,6 +170,14 @@ exports[`level:warning/type:warning snapshots: output 1`] = ` " `; +exports[`never ignores write messages from the kibana elasticsearch.deprecation logger context 1`] = ` +" │[elasticsearch.deprecation] + │{ foo: { bar: { '1': [Array] } }, bar: { bar: { '1': [Array] } } } + │ + │Infinity +" +`; + exports[`throws error if created with invalid level 1`] = `"Invalid log level \\"foo\\" (expected one of silent,error,warning,success,info,debug,verbose)"`; exports[`throws error if writeTo config is not defined or doesn't have a write method 1`] = `"ToolingLogTextWriter requires the \`writeTo\` option be set to a stream (like process.stdout)"`; diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.ts b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.ts index b4668f29b6e21..fbccfdcdf6ac0 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.ts +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.ts @@ -88,3 +88,55 @@ it('formats %s patterns and indents multi-line messages correctly', () => { const output = write.mock.calls.reduce((acc, chunk) => `${acc}${chunk}`, ''); expect(output).toMatchSnapshot(); }); + +it('does not write messages from sources in ignoreSources', () => { + const write = jest.fn(); + const writer = new ToolingLogTextWriter({ + ignoreSources: ['myIgnoredSource'], + level: 'debug', + writeTo: { + write, + }, + }); + + writer.write({ + source: 'myIgnoredSource', + type: 'success', + indent: 10, + args: [ + '%s\n%O\n\n%d', + 'foo bar', + { foo: { bar: { 1: [1, 2, 3] } }, bar: { bar: { 1: [1, 2, 3] } } }, + Infinity, + ], + }); + + const output = write.mock.calls.reduce((acc, chunk) => `${acc}${chunk}`, ''); + expect(output).toEqual(''); +}); + +it('never ignores write messages from the kibana elasticsearch.deprecation logger context', () => { + const write = jest.fn(); + const writer = new ToolingLogTextWriter({ + ignoreSources: ['myIgnoredSource'], + level: 'debug', + writeTo: { + write, + }, + }); + + writer.write({ + source: 'myIgnoredSource', + type: 'write', + indent: 10, + args: [ + '%s\n%O\n\n%d', + '[elasticsearch.deprecation]', + { foo: { bar: { 1: [1, 2, 3] } }, bar: { bar: { 1: [1, 2, 3] } } }, + Infinity, + ], + }); + + const output = write.mock.calls.reduce((acc, chunk) => `${acc}${chunk}`, ''); + expect(output).toMatchSnapshot(); +}); diff --git a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.ts b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.ts index 660dae3fa1f55..4fe33241cf77e 100644 --- a/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.ts +++ b/packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.ts @@ -92,7 +92,15 @@ export class ToolingLogTextWriter implements Writer { } if (this.ignoreSources && msg.source && this.ignoreSources.includes(msg.source)) { - return false; + if (msg.type === 'write') { + const txt = format(msg.args[0], ...msg.args.slice(1)); + // Ensure that Elasticsearch deprecation log messages from Kibana aren't ignored + if (!/elasticsearch\.deprecation/.test(txt)) { + return false; + } + } else { + return false; + } } const prefix = has(MSG_PREFIXES, msg.type) ? MSG_PREFIXES[msg.type] : ''; diff --git a/packages/kbn-pm/dist/index.js b/packages/kbn-pm/dist/index.js index c1d0f69e4ea07..fc92d18698132 100644 --- a/packages/kbn-pm/dist/index.js +++ b/packages/kbn-pm/dist/index.js @@ -6639,7 +6639,15 @@ class ToolingLogTextWriter { } if (this.ignoreSources && msg.source && this.ignoreSources.includes(msg.source)) { - return false; + if (msg.type === 'write') { + const txt = (0, _util.format)(msg.args[0], ...msg.args.slice(1)); // Ensure that Elasticsearch deprecation log messages from Kibana aren't ignored + + if (!/elasticsearch\.deprecation/.test(txt)) { + return false; + } + } else { + return false; + } } const prefix = has(MSG_PREFIXES, msg.type) ? MSG_PREFIXES[msg.type] : ''; diff --git a/src/core/server/elasticsearch/client/configure_client.test.ts b/src/core/server/elasticsearch/client/configure_client.test.ts index 7988e81045d17..f252993415afa 100644 --- a/src/core/server/elasticsearch/client/configure_client.test.ts +++ b/src/core/server/elasticsearch/client/configure_client.test.ts @@ -6,21 +6,16 @@ * Side Public License, v 1. */ -import { Buffer } from 'buffer'; -import { Readable } from 'stream'; - -import { errors } from '@elastic/elasticsearch'; -import type { - TransportRequestOptions, - TransportRequestParams, - DiagnosticResult, - RequestBody, -} from '@elastic/elasticsearch'; +jest.mock('./log_query_and_deprecation.ts', () => ({ + __esModule: true, + instrumentEsQueryAndDeprecationLogger: jest.fn(), +})); import { parseClientOptionsMock, ClientMock } from './configure_client.test.mocks'; import { loggingSystemMock } from '../../logging/logging_system.mock'; import type { ElasticsearchClientConfig } from './client_config'; import { configureClient } from './configure_client'; +import { instrumentEsQueryAndDeprecationLogger } from './log_query_and_deprecation'; const createFakeConfig = ( parts: Partial = {} @@ -36,40 +31,9 @@ const createFakeClient = () => { const client = new actualEs.Client({ nodes: ['http://localhost'], // Enforcing `nodes` because it's mandatory }); - jest.spyOn(client.diagnostic, 'on'); return client; }; -const createApiResponse = ({ - body, - statusCode = 200, - headers = {}, - warnings = [], - params, - requestOptions = {}, -}: { - body: T; - statusCode?: number; - headers?: Record; - warnings?: string[]; - params?: TransportRequestParams; - requestOptions?: TransportRequestOptions; -}): DiagnosticResult => { - return { - body, - statusCode, - headers, - warnings, - meta: { - body, - request: { - params: params!, - options: requestOptions, - } as any, - } as any, - }; -}; - describe('configureClient', () => { let logger: ReturnType; let config: ElasticsearchClientConfig; @@ -84,6 +48,7 @@ describe('configureClient', () => { afterEach(() => { parseClientOptionsMock.mockReset(); ClientMock.mockReset(); + jest.clearAllMocks(); }); it('calls `parseClientOptions` with the correct parameters', () => { @@ -113,366 +78,14 @@ describe('configureClient', () => { expect(client).toBe(ClientMock.mock.results[0].value); }); - it('listens to client on `response` events', () => { + it('calls instrumentEsQueryAndDeprecationLogger', () => { const client = configureClient(config, { logger, type: 'test', scoped: false }); - expect(client.diagnostic.on).toHaveBeenCalledTimes(1); - expect(client.diagnostic.on).toHaveBeenCalledWith('response', expect.any(Function)); - }); - - describe('Client logging', () => { - function createResponseWithBody(body?: RequestBody) { - return createApiResponse({ - body: {}, - statusCode: 200, - params: { - method: 'GET', - path: '/foo', - querystring: { hello: 'dolly' }, - body, - }, - }); - } - - describe('logs each query', () => { - it('creates a query logger context based on the `type` parameter', () => { - configureClient(createFakeConfig(), { logger, type: 'test123' }); - expect(logger.get).toHaveBeenCalledWith('query', 'test123'); - }); - - it('when request body is an object', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createResponseWithBody({ - seq_no_primary_term: true, - query: { - term: { user: 'kimchy' }, - }, - }); - - client.diagnostic.emit('response', null, response); - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "200 - GET /foo?hello=dolly - {\\"seq_no_primary_term\\":true,\\"query\\":{\\"term\\":{\\"user\\":\\"kimchy\\"}}}", - undefined, - ], - ] - `); - }); - - it('when request body is a string', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createResponseWithBody( - JSON.stringify({ - seq_no_primary_term: true, - query: { - term: { user: 'kimchy' }, - }, - }) - ); - - client.diagnostic.emit('response', null, response); - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "200 - GET /foo?hello=dolly - {\\"seq_no_primary_term\\":true,\\"query\\":{\\"term\\":{\\"user\\":\\"kimchy\\"}}}", - undefined, - ], - ] - `); - }); - - it('when request body is a buffer', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createResponseWithBody( - Buffer.from( - JSON.stringify({ - seq_no_primary_term: true, - query: { - term: { user: 'kimchy' }, - }, - }) - ) - ); - - client.diagnostic.emit('response', null, response); - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "200 - GET /foo?hello=dolly - [buffer]", - undefined, - ], - ] - `); - }); - - it('when request body is a readable stream', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createResponseWithBody( - Readable.from( - JSON.stringify({ - seq_no_primary_term: true, - query: { - term: { user: 'kimchy' }, - }, - }) - ) - ); - - client.diagnostic.emit('response', null, response); - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "200 - GET /foo?hello=dolly - [stream]", - undefined, - ], - ] - `); - }); - - it('when request body is not defined', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createResponseWithBody(); - - client.diagnostic.emit('response', null, response); - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "200 - GET /foo?hello=dolly", - undefined, - ], - ] - `); - }); - - it('properly encode queries', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createApiResponse({ - body: {}, - statusCode: 200, - params: { - method: 'GET', - path: '/foo', - querystring: { city: 'Münich' }, - }, - }); - - client.diagnostic.emit('response', null, response); - - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "200 - GET /foo?city=M%C3%BCnich", - undefined, - ], - ] - `); - }); - - it('logs queries even in case of errors', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createApiResponse({ - statusCode: 500, - body: { - error: { - type: 'internal server error', - }, - }, - params: { - method: 'GET', - path: '/foo', - querystring: { hello: 'dolly' }, - body: { - seq_no_primary_term: true, - query: { - term: { user: 'kimchy' }, - }, - }, - }, - }); - client.diagnostic.emit('response', new errors.ResponseError(response), response); - - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "500 - GET /foo?hello=dolly - {\\"seq_no_primary_term\\":true,\\"query\\":{\\"term\\":{\\"user\\":\\"kimchy\\"}}} [internal server error]: internal server error", - undefined, - ], - ] - `); - }); - - it('logs debug when the client emits an @elastic/elasticsearch error', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createApiResponse({ body: {} }); - client.diagnostic.emit('response', new errors.TimeoutError('message', response), response); - - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "[TimeoutError]: message", - undefined, - ], - ] - `); - }); - - it('logs debug when the client emits an ResponseError returned by elasticsearch', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - const response = createApiResponse({ - statusCode: 400, - headers: {}, - params: { - method: 'GET', - path: '/_path', - querystring: { hello: 'dolly' }, - }, - body: { - error: { - type: 'illegal_argument_exception', - reason: 'request [/_path] contains unrecognized parameter: [name]', - }, - }, - }); - client.diagnostic.emit('response', new errors.ResponseError(response), response); - - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "400 - GET /_path?hello=dolly [illegal_argument_exception]: request [/_path] contains unrecognized parameter: [name]", - undefined, - ], - ] - `); - }); - - it('logs default error info when the error response body is empty', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - let response: DiagnosticResult = createApiResponse({ - statusCode: 400, - headers: {}, - params: { - method: 'GET', - path: '/_path', - }, - body: { - error: {}, - }, - }); - client.diagnostic.emit('response', new errors.ResponseError(response), response); - - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "400 - GET /_path [undefined]: {\\"error\\":{}}", - undefined, - ], - ] - `); - - logger.debug.mockClear(); - - response = createApiResponse({ - statusCode: 400, - headers: {}, - params: { - method: 'GET', - path: '/_path', - }, - body: undefined, - }); - client.diagnostic.emit('response', new errors.ResponseError(response), response); - - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "400 - GET /_path [undefined]: Response Error", - undefined, - ], - ] - `); - }); - - it('adds meta information to logs', () => { - const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false }); - - let response = createApiResponse({ - statusCode: 400, - headers: {}, - params: { - method: 'GET', - path: '/_path', - }, - requestOptions: { - opaqueId: 'opaque-id', - }, - body: { - error: {}, - }, - }); - client.diagnostic.emit('response', null, response); - - expect(loggingSystemMock.collect(logger).debug[0][1]).toMatchInlineSnapshot(` - Object { - "http": Object { - "request": Object { - "id": "opaque-id", - }, - }, - } - `); - - logger.debug.mockClear(); - - response = createApiResponse({ - statusCode: 400, - headers: {}, - params: { - method: 'GET', - path: '/_path', - }, - requestOptions: { - opaqueId: 'opaque-id', - }, - body: {} as any, - }); - client.diagnostic.emit('response', new errors.ResponseError(response), response); - - expect(loggingSystemMock.collect(logger).debug[0][1]).toMatchInlineSnapshot(` - Object { - "http": Object { - "request": Object { - "id": "opaque-id", - }, - }, - } - `); - }); + expect(instrumentEsQueryAndDeprecationLogger).toHaveBeenCalledTimes(1); + expect(instrumentEsQueryAndDeprecationLogger).toHaveBeenCalledWith({ + logger, + client, + type: 'test', }); }); }); diff --git a/src/core/server/elasticsearch/client/configure_client.ts b/src/core/server/elasticsearch/client/configure_client.ts index fc8a06660cc5e..e48a36fa4fe58 100644 --- a/src/core/server/elasticsearch/client/configure_client.ts +++ b/src/core/server/elasticsearch/client/configure_client.ts @@ -6,21 +6,17 @@ * Side Public License, v 1. */ -import { Buffer } from 'buffer'; -import { stringify } from 'querystring'; -import { Client, errors, Transport, HttpConnection } from '@elastic/elasticsearch'; +import { Client, Transport, HttpConnection } from '@elastic/elasticsearch'; import type { KibanaClient } from '@elastic/elasticsearch/lib/api/kibana'; import type { TransportRequestParams, TransportRequestOptions, TransportResult, - DiagnosticResult, - RequestBody, } from '@elastic/elasticsearch'; import { Logger } from '../../logging'; import { parseClientOptions, ElasticsearchClientConfig } from './client_config'; -import type { ElasticsearchErrorDetails } from './types'; +import { instrumentEsQueryAndDeprecationLogger } from './log_query_and_deprecation'; const noop = () => undefined; @@ -61,91 +57,8 @@ export const configureClient = ( Transport: KibanaTransport, Connection: HttpConnection, }); - addLogging(client, logger.get('query', type)); - return client as KibanaClient; -}; - -const convertQueryString = (qs: string | Record | undefined): string => { - if (qs === undefined || typeof qs === 'string') { - return qs ?? ''; - } - return stringify(qs); -}; - -function ensureString(body: RequestBody): string { - if (typeof body === 'string') return body; - if (Buffer.isBuffer(body)) return '[buffer]'; - if ('readable' in body && body.readable && typeof body._read === 'function') return '[stream]'; - return JSON.stringify(body); -} - -/** - * Returns a debug message from an Elasticsearch error in the following format: - * [error type] error reason - */ -export function getErrorMessage(error: errors.ElasticsearchClientError): string { - if (error instanceof errors.ResponseError) { - const errorBody = error.meta.body as ElasticsearchErrorDetails; - return `[${errorBody?.error?.type}]: ${errorBody?.error?.reason ?? error.message}`; - } - return `[${error.name}]: ${error.message}`; -} + instrumentEsQueryAndDeprecationLogger({ logger, client, type }); -/** - * returns a string in format: - * - * status code - * method URL - * request body - * - * so it could be copy-pasted into the Dev console - */ -function getResponseMessage(event: DiagnosticResult): string { - const errorMeta = getRequestDebugMeta(event); - const body = errorMeta.body ? `\n${errorMeta.body}` : ''; - return `${errorMeta.statusCode}\n${errorMeta.method} ${errorMeta.url}${body}`; -} - -/** - * Returns stringified debug information from an Elasticsearch request event - * useful for logging in case of an unexpected failure. - */ -export function getRequestDebugMeta(event: DiagnosticResult): { - url: string; - body: string; - statusCode: number | null; - method: string; -} { - const params = event.meta.request.params; - // definition is wrong, `params.querystring` can be either a string or an object - const querystring = convertQueryString(params.querystring); - return { - url: `${params.path}${querystring ? `?${querystring}` : ''}`, - body: params.body ? `${ensureString(params.body)}` : '', - method: params.method, - statusCode: event.statusCode!, - }; -} - -const addLogging = (client: Client, logger: Logger) => { - client.diagnostic.on('response', (error, event) => { - if (event) { - const opaqueId = event.meta.request.options.opaqueId; - const meta = opaqueId - ? { - http: { request: { id: event.meta.request.options.opaqueId } }, - } - : undefined; // do not clutter logs if opaqueId is not present - if (error) { - if (error instanceof errors.ResponseError) { - logger.debug(`${getResponseMessage(event)} ${getErrorMessage(error)}`, meta); - } else { - logger.debug(getErrorMessage(error), meta); - } - } else { - logger.debug(getResponseMessage(event), meta); - } - } - }); + return client as KibanaClient; }; diff --git a/src/core/server/elasticsearch/client/index.ts b/src/core/server/elasticsearch/client/index.ts index 2cf5a0229a489..123c498f1ee21 100644 --- a/src/core/server/elasticsearch/client/index.ts +++ b/src/core/server/elasticsearch/client/index.ts @@ -21,5 +21,6 @@ export type { IScopedClusterClient } from './scoped_cluster_client'; export type { ElasticsearchClientConfig } from './client_config'; export { ClusterClient } from './cluster_client'; export type { IClusterClient, ICustomClusterClient } from './cluster_client'; -export { configureClient, getRequestDebugMeta, getErrorMessage } from './configure_client'; +export { configureClient } from './configure_client'; +export { getRequestDebugMeta, getErrorMessage } from './log_query_and_deprecation'; export { retryCallCluster, migrationRetryCallCluster } from './retry_call_cluster'; diff --git a/src/core/server/elasticsearch/client/log_query_and_deprecation.test.ts b/src/core/server/elasticsearch/client/log_query_and_deprecation.test.ts new file mode 100644 index 0000000000000..30d5d8b87ed1c --- /dev/null +++ b/src/core/server/elasticsearch/client/log_query_and_deprecation.test.ts @@ -0,0 +1,624 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the Elastic License + * 2.0 and the Server Side Public License, v 1; you may not use this file except + * in compliance with, at your election, the Elastic License 2.0 or the Server + * Side Public License, v 1. + */ + +import { Buffer } from 'buffer'; +import { Readable } from 'stream'; + +import { + Client, + ConnectionRequestParams, + errors, + TransportRequestOptions, + TransportRequestParams, +} from '@elastic/elasticsearch'; +import type { DiagnosticResult, RequestBody } from '@elastic/elasticsearch'; + +import { parseClientOptionsMock, ClientMock } from './configure_client.test.mocks'; +import { loggingSystemMock } from '../../logging/logging_system.mock'; +import { instrumentEsQueryAndDeprecationLogger } from './log_query_and_deprecation'; + +const createApiResponse = ({ + body, + statusCode = 200, + headers = {}, + warnings = null, + params, + requestOptions = {}, +}: { + body: T; + statusCode?: number; + headers?: Record; + warnings?: string[] | null; + params?: TransportRequestParams | ConnectionRequestParams; + requestOptions?: TransportRequestOptions; +}): DiagnosticResult => { + return { + body, + statusCode, + headers, + warnings, + meta: { + body, + request: { + params: params!, + options: requestOptions, + } as any, + } as any, + }; +}; + +const createFakeClient = () => { + const actualEs = jest.requireActual('@elastic/elasticsearch'); + const client = new actualEs.Client({ + nodes: ['http://localhost'], // Enforcing `nodes` because it's mandatory + }); + jest.spyOn(client.diagnostic, 'on'); + return client as Client; +}; + +describe('instrumentQueryAndDeprecationLogger', () => { + let logger: ReturnType; + const client = createFakeClient(); + + beforeEach(() => { + logger = loggingSystemMock.createLogger(); + parseClientOptionsMock.mockReturnValue({}); + ClientMock.mockImplementation(() => createFakeClient()); + }); + + afterEach(() => { + parseClientOptionsMock.mockReset(); + ClientMock.mockReset(); + jest.clearAllMocks(); + }); + + function createResponseWithBody(body?: RequestBody) { + return createApiResponse({ + body: {}, + statusCode: 200, + params: { + method: 'GET', + path: '/foo', + querystring: { hello: 'dolly' }, + body, + }, + }); + } + + it('creates a query logger context based on the `type` parameter', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test123' }); + expect(logger.get).toHaveBeenCalledWith('query', 'test123'); + }); + + describe('logs each query', () => { + it('when request body is an object', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createResponseWithBody({ + seq_no_primary_term: true, + query: { + term: { user: 'kimchy' }, + }, + }); + + client.diagnostic.emit('response', null, response); + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "200 + GET /foo?hello=dolly + {\\"seq_no_primary_term\\":true,\\"query\\":{\\"term\\":{\\"user\\":\\"kimchy\\"}}}", + undefined, + ], + ] + `); + }); + + it('when request body is a string', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createResponseWithBody( + JSON.stringify({ + seq_no_primary_term: true, + query: { + term: { user: 'kimchy' }, + }, + }) + ); + + client.diagnostic.emit('response', null, response); + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "200 + GET /foo?hello=dolly + {\\"seq_no_primary_term\\":true,\\"query\\":{\\"term\\":{\\"user\\":\\"kimchy\\"}}}", + undefined, + ], + ] + `); + }); + + it('when request body is a buffer', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createResponseWithBody( + Buffer.from( + JSON.stringify({ + seq_no_primary_term: true, + query: { + term: { user: 'kimchy' }, + }, + }) + ) + ); + + client.diagnostic.emit('response', null, response); + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "200 + GET /foo?hello=dolly + [buffer]", + undefined, + ], + ] + `); + }); + + it('when request body is a readable stream', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createResponseWithBody( + Readable.from( + JSON.stringify({ + seq_no_primary_term: true, + query: { + term: { user: 'kimchy' }, + }, + }) + ) + ); + + client.diagnostic.emit('response', null, response); + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "200 + GET /foo?hello=dolly + [stream]", + undefined, + ], + ] + `); + }); + + it('when request body is not defined', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createResponseWithBody(); + + client.diagnostic.emit('response', null, response); + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "200 + GET /foo?hello=dolly", + undefined, + ], + ] + `); + }); + + it('properly encode queries', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + body: {}, + statusCode: 200, + params: { + method: 'GET', + path: '/foo', + querystring: { city: 'Münich' }, + }, + }); + + client.diagnostic.emit('response', null, response); + + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "200 + GET /foo?city=M%C3%BCnich", + undefined, + ], + ] + `); + }); + + it('logs queries even in case of errors', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + statusCode: 500, + body: { + error: { + type: 'internal server error', + }, + }, + params: { + method: 'GET', + path: '/foo', + querystring: { hello: 'dolly' }, + body: { + seq_no_primary_term: true, + query: { + term: { user: 'kimchy' }, + }, + }, + }, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "500 + GET /foo?hello=dolly + {\\"seq_no_primary_term\\":true,\\"query\\":{\\"term\\":{\\"user\\":\\"kimchy\\"}}} [internal server error]: internal server error", + undefined, + ], + ] + `); + }); + + it('logs debug when the client emits an @elastic/elasticsearch error', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ body: {} }); + client.diagnostic.emit('response', new errors.TimeoutError('message', response), response); + + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "[TimeoutError]: message", + undefined, + ], + ] + `); + }); + + it('logs debug when the client emits an ResponseError returned by elasticsearch', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + statusCode: 400, + headers: {}, + params: { + method: 'GET', + path: '/_path', + querystring: { hello: 'dolly' }, + }, + body: { + error: { + type: 'illegal_argument_exception', + reason: 'request [/_path] contains unrecognized parameter: [name]', + }, + }, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "400 + GET /_path?hello=dolly [illegal_argument_exception]: request [/_path] contains unrecognized parameter: [name]", + undefined, + ], + ] + `); + }); + + it('logs default error info when the error response body is empty', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + let response: DiagnosticResult = createApiResponse({ + statusCode: 400, + headers: {}, + params: { + method: 'GET', + path: '/_path', + }, + body: { + error: {}, + }, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "400 + GET /_path [undefined]: {\\"error\\":{}}", + undefined, + ], + ] + `); + + logger.debug.mockClear(); + + response = createApiResponse({ + statusCode: 400, + headers: {}, + params: { + method: 'GET', + path: '/_path', + }, + body: undefined, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "400 + GET /_path [undefined]: Response Error", + undefined, + ], + ] + `); + }); + + it('adds meta information to logs', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + let response = createApiResponse({ + statusCode: 400, + headers: {}, + params: { + method: 'GET', + path: '/_path', + }, + requestOptions: { + opaqueId: 'opaque-id', + }, + body: { + error: {}, + }, + }); + client.diagnostic.emit('response', null, response); + + expect(loggingSystemMock.collect(logger).debug[0][1]).toMatchInlineSnapshot(` + Object { + "http": Object { + "request": Object { + "id": "opaque-id", + }, + }, + } + `); + + logger.debug.mockClear(); + + response = createApiResponse({ + statusCode: 400, + headers: {}, + params: { + method: 'GET', + path: '/_path', + }, + requestOptions: { + opaqueId: 'opaque-id', + }, + body: {} as any, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + expect(loggingSystemMock.collect(logger).debug[0][1]).toMatchInlineSnapshot(` + Object { + "http": Object { + "request": Object { + "id": "opaque-id", + }, + }, + } + `); + }); + }); + + describe('deprecation warnings from response headers', () => { + it('does not log when no deprecation warning header is returned', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + statusCode: 200, + warnings: null, + params: { + method: 'GET', + path: '/_path', + querystring: { hello: 'dolly' }, + }, + body: { + hits: [ + { + _source: 'may the source be with you', + }, + ], + }, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + // One debug log entry from 'elasticsearch.query' context + expect(loggingSystemMock.collect(logger).debug.length).toEqual(1); + expect(loggingSystemMock.collect(logger).info).toEqual([]); + }); + + it('does not log when warning header comes from a warn-agent that is not elasticsearch', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + statusCode: 200, + warnings: [ + '299 nginx/2.3.1 "GET /_path is deprecated"', + '299 nginx/2.3.1 "GET hello query param is deprecated"', + ], + params: { + method: 'GET', + path: '/_path', + querystring: { hello: 'dolly' }, + }, + body: { + hits: [ + { + _source: 'may the source be with you', + }, + ], + }, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + // One debug log entry from 'elasticsearch.query' context + expect(loggingSystemMock.collect(logger).debug.length).toEqual(1); + expect(loggingSystemMock.collect(logger).info).toEqual([]); + }); + + it('logs error when the client receives an Elasticsearch error response for a deprecated request originating from a user', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + statusCode: 400, + warnings: ['299 Elasticsearch-8.1.0 "GET /_path is deprecated"'], + params: { + method: 'GET', + path: '/_path', + querystring: { hello: 'dolly' }, + }, + body: { + error: { + type: 'illegal_argument_exception', + reason: 'request [/_path] contains unrecognized parameter: [name]', + }, + }, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + expect(loggingSystemMock.collect(logger).info).toEqual([]); + // Test debug[1] since theree is one log entry from 'elasticsearch.query' context + expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch( + 'Elasticsearch deprecation: 299 Elasticsearch-8.1.0 "GET /_path is deprecated"' + ); + expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch('Origin:user'); + expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(/Stack trace:\n.*at/); + expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch( + /Query:\n.*400\n.*GET \/_path\?hello\=dolly \[illegal_argument_exception\]: request \[\/_path\] contains unrecognized parameter: \[name\]/ + ); + }); + + it('logs warning when the client receives an Elasticsearch error response for a deprecated request originating from kibana', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + statusCode: 400, + warnings: ['299 Elasticsearch-8.1.0 "GET /_path is deprecated"'], + params: { + method: 'GET', + path: '/_path', + querystring: { hello: 'dolly' }, + // Set the request header to indicate to Elasticsearch that this is a request over which users have no control + headers: { 'x-elastic-product-origin': 'kibana' }, + }, + body: { + error: { + type: 'illegal_argument_exception', + reason: 'request [/_path] contains unrecognized parameter: [name]', + }, + }, + }); + client.diagnostic.emit('response', new errors.ResponseError(response), response); + + // One debug log entry from 'elasticsearch.query' context + expect(loggingSystemMock.collect(logger).debug.length).toEqual(1); + expect(loggingSystemMock.collect(logger).info[0][0]).toMatch( + 'Elasticsearch deprecation: 299 Elasticsearch-8.1.0 "GET /_path is deprecated"' + ); + expect(loggingSystemMock.collect(logger).info[0][0]).toMatch('Origin:kibana'); + expect(loggingSystemMock.collect(logger).info[0][0]).toMatch(/Stack trace:\n.*at/); + expect(loggingSystemMock.collect(logger).info[0][0]).toMatch( + /Query:\n.*400\n.*GET \/_path\?hello\=dolly \[illegal_argument_exception\]: request \[\/_path\] contains unrecognized parameter: \[name\]/ + ); + }); + + it('logs error when the client receives an Elasticsearch success response for a deprecated request originating from a user', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + statusCode: 200, + warnings: ['299 Elasticsearch-8.1.0 "GET /_path is deprecated"'], + params: { + method: 'GET', + path: '/_path', + querystring: { hello: 'dolly' }, + }, + body: { + hits: [ + { + _source: 'may the source be with you', + }, + ], + }, + }); + client.diagnostic.emit('response', null, response); + + expect(loggingSystemMock.collect(logger).info).toEqual([]); + // Test debug[1] since theree is one log entry from 'elasticsearch.query' context + expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch( + 'Elasticsearch deprecation: 299 Elasticsearch-8.1.0 "GET /_path is deprecated"' + ); + expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch('Origin:user'); + expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(/Stack trace:\n.*at/); + expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch( + /Query:\n.*200\n.*GET \/_path\?hello\=dolly/ + ); + }); + + it('logs warning when the client receives an Elasticsearch success response for a deprecated request originating from kibana', () => { + instrumentEsQueryAndDeprecationLogger({ logger, client, type: 'test type' }); + + const response = createApiResponse({ + statusCode: 200, + warnings: ['299 Elasticsearch-8.1.0 "GET /_path is deprecated"'], + params: { + method: 'GET', + path: '/_path', + querystring: { hello: 'dolly' }, + // Set the request header to indicate to Elasticsearch that this is a request over which users have no control + headers: { 'x-elastic-product-origin': 'kibana' }, + }, + body: { + hits: [ + { + _source: 'may the source be with you', + }, + ], + }, + }); + client.diagnostic.emit('response', null, response); + + // One debug log entry from 'elasticsearch.query' context + expect(loggingSystemMock.collect(logger).debug.length).toEqual(1); + expect(loggingSystemMock.collect(logger).info[0][0]).toMatch( + 'Elasticsearch deprecation: 299 Elasticsearch-8.1.0 "GET /_path is deprecated"' + ); + expect(loggingSystemMock.collect(logger).info[0][0]).toMatch('Origin:kibana'); + expect(loggingSystemMock.collect(logger).info[0][0]).toMatch(/Stack trace:\n.*at/); + expect(loggingSystemMock.collect(logger).info[0][0]).toMatch( + /Query:\n.*200\n.*GET \/_path\?hello\=dolly/ + ); + }); + }); +}); diff --git a/src/core/server/elasticsearch/client/log_query_and_deprecation.ts b/src/core/server/elasticsearch/client/log_query_and_deprecation.ts new file mode 100644 index 0000000000000..fc5a0fa6e1111 --- /dev/null +++ b/src/core/server/elasticsearch/client/log_query_and_deprecation.ts @@ -0,0 +1,143 @@ +/* + * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one + * or more contributor license agreements. Licensed under the Elastic License + * 2.0 and the Server Side Public License, v 1; you may not use this file except + * in compliance with, at your election, the Elastic License 2.0 or the Server + * Side Public License, v 1. + */ + +import { Buffer } from 'buffer'; +import { stringify } from 'querystring'; +import { errors, DiagnosticResult, RequestBody, Client } from '@elastic/elasticsearch'; +import type { ElasticsearchErrorDetails } from './types'; +import { Logger } from '../../logging'; + +const convertQueryString = (qs: string | Record | undefined): string => { + if (qs === undefined || typeof qs === 'string') { + return qs ?? ''; + } + return stringify(qs); +}; + +function ensureString(body: RequestBody): string { + if (typeof body === 'string') return body; + if (Buffer.isBuffer(body)) return '[buffer]'; + if ('readable' in body && body.readable && typeof body._read === 'function') return '[stream]'; + return JSON.stringify(body); +} + +/** + * Returns a debug message from an Elasticsearch error in the following format: + * [error type] error reason + */ +export function getErrorMessage(error: errors.ElasticsearchClientError): string { + if (error instanceof errors.ResponseError) { + const errorBody = error.meta.body as ElasticsearchErrorDetails; + return `[${errorBody?.error?.type}]: ${errorBody?.error?.reason ?? error.message}`; + } + return `[${error.name}]: ${error.message}`; +} + +/** + * returns a string in format: + * + * status code + * method URL + * request body + * + * so it could be copy-pasted into the Dev console + */ +function getResponseMessage(event: DiagnosticResult): string { + const errorMeta = getRequestDebugMeta(event); + const body = errorMeta.body ? `\n${errorMeta.body}` : ''; + return `${errorMeta.statusCode}\n${errorMeta.method} ${errorMeta.url}${body}`; +} + +/** + * Returns stringified debug information from an Elasticsearch request event + * useful for logging in case of an unexpected failure. + */ +export function getRequestDebugMeta(event: DiagnosticResult): { + url: string; + body: string; + statusCode: number | null; + method: string; +} { + const params = event.meta.request.params; + // definition is wrong, `params.querystring` can be either a string or an object + const querystring = convertQueryString(params.querystring); + return { + url: `${params.path}${querystring ? `?${querystring}` : ''}`, + body: params.body ? `${ensureString(params.body)}` : '', + method: params.method, + statusCode: event.statusCode!, + }; +} + +/** HTTP Warning headers have the following syntax: + * (where warn-code is a three digit number) + * This function tests if a warning comes from an Elasticsearch warn-agent + * */ +const isEsWarning = (warning: string) => /\d\d\d Elasticsearch-/.test(warning); + +export const instrumentEsQueryAndDeprecationLogger = ({ + logger, + client, + type, +}: { + logger: Logger; + client: Client; + type: string; +}) => { + const queryLogger = logger.get('query', type); + const deprecationLogger = logger.get('deprecation'); + client.diagnostic.on('response', (error, event) => { + if (event) { + const opaqueId = event.meta.request.options.opaqueId; + const meta = opaqueId + ? { + http: { request: { id: event.meta.request.options.opaqueId } }, + } + : undefined; // do not clutter logs if opaqueId is not present + let queryMsg = ''; + if (error) { + if (error instanceof errors.ResponseError) { + queryMsg = `${getResponseMessage(event)} ${getErrorMessage(error)}`; + } else { + queryMsg = getErrorMessage(error); + } + } else { + queryMsg = getResponseMessage(event); + } + + queryLogger.debug(queryMsg, meta); + + if (event.warnings && event.warnings.filter(isEsWarning).length > 0) { + // Plugins can explicitly mark requests as originating from a user by + // removing the `'x-elastic-product-origin': 'kibana'` header that's + // added by default. User requests will be shown to users in the + // upgrade assistant UI as an action item that has to be addressed + // before they upgrade. + // Kibana requests will be hidden from the upgrade assistant UI and are + // only logged to help developers maintain their plugins + const requestOrigin = + (event.meta.request.params.headers != null && + (event.meta.request.params.headers[ + 'x-elastic-product-origin' + ] as unknown as string)) === 'kibana' + ? 'kibana' + : 'user'; + + // Strip the first 5 stack trace lines as these are irrelavent to finding the call site + const stackTrace = new Error().stack?.split('\n').slice(5).join('\n'); + + const deprecationMsg = `Elasticsearch deprecation: ${event.warnings}\nOrigin:${requestOrigin}\nStack trace:\n${stackTrace}\nQuery:\n${queryMsg}`; + if (requestOrigin === 'kibana') { + deprecationLogger.info(deprecationMsg); + } else { + deprecationLogger.debug(deprecationMsg); + } + } + } + }); +}; diff --git a/test/common/config.js b/test/common/config.js index b9ab24450ac82..1a60932581847 100644 --- a/test/common/config.js +++ b/test/common/config.js @@ -56,6 +56,10 @@ export default function () { ...(!!process.env.CODE_COVERAGE ? [`--plugin-path=${path.join(__dirname, 'fixtures', 'plugins', 'coverage')}`] : []), + '--logging.appenders.deprecation.type=console', + '--logging.appenders.deprecation.layout.type=json', + '--logging.loggers[0].name=elasticsearch.deprecation', + '--logging.loggers[0].appenders[0]=deprecation', ], }, services,