From a2813c8cff2d78917676770cf750ce062bfccc1e Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Thu, 10 Dec 2020 23:38:38 +0300 Subject: [PATCH] [KP] log details of the failed elasticsearch client requests when logQueries:true (#73672) * log request details in case of errors * update test * log errors in the new client only when logQueries: true * add comment about log format --- .../client/configure_client.test.ts | 379 ++++++++++-------- .../elasticsearch/client/configure_client.ts | 70 ++-- 2 files changed, 258 insertions(+), 191 deletions(-) diff --git a/src/core/server/elasticsearch/client/configure_client.test.ts b/src/core/server/elasticsearch/client/configure_client.test.ts index 22cb7275b6a23..27f3ab30ac8f3 100644 --- a/src/core/server/elasticsearch/client/configure_client.test.ts +++ b/src/core/server/elasticsearch/client/configure_client.test.ts @@ -120,97 +120,43 @@ describe('configureClient', () => { }); describe('Client logging', () => { - it('logs error when the client emits an @elastic/elasticsearch error', () => { - const client = configureClient(config, { logger, scoped: false }); - - const response = createApiResponse({ body: {} }); - client.emit('response', new errors.TimeoutError('message', response), response); - - expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` - Array [ - Array [ - "[TimeoutError]: message", - ], - ] - `); - }); - - it('logs error when the client emits an ResponseError returned by elasticsearch', () => { - const client = configureClient(config, { logger, scoped: false }); - - const response = createApiResponse({ - statusCode: 400, - headers: {}, - body: { - error: { - type: 'illegal_argument_exception', - reason: 'request [/_path] contains unrecognized parameter: [name]', - }, + function createResponseWithBody(body?: RequestBody) { + return createApiResponse({ + body: {}, + statusCode: 200, + params: { + method: 'GET', + path: '/foo', + querystring: { hello: 'dolly' }, + body, }, }); - client.emit('response', new errors.ResponseError(response), response); - - expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` - Array [ - Array [ - "[illegal_argument_exception]: request [/_path] contains unrecognized parameter: [name]", - ], - ] - `); - }); - - it('logs default error info when the error response body is empty', () => { - const client = configureClient(config, { logger, scoped: false }); + } + describe('does not log whrn "logQueries: false"', () => { + it('response', () => { + const client = configureClient(config, { logger, scoped: false }); + const response = createResponseWithBody({ + seq_no_primary_term: true, + query: { + term: { user: 'kimchy' }, + }, + }); - let response = createApiResponse({ - statusCode: 400, - headers: {}, - body: { - error: {}, - }, + client.emit('response', null, response); + expect(loggingSystemMock.collect(logger).debug).toHaveLength(0); }); - client.emit('response', new errors.ResponseError(response), response); - expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` - Array [ - Array [ - "[ResponseError]: Response Error", - ], - ] - `); + it('error', () => { + const client = configureClient(config, { logger, scoped: false }); - logger.error.mockClear(); + const response = createApiResponse({ body: {} }); + client.emit('response', new errors.TimeoutError('message', response), response); - response = createApiResponse({ - statusCode: 400, - headers: {}, - body: {} as any, + expect(loggingSystemMock.collect(logger).error).toHaveLength(0); }); - client.emit('response', new errors.ResponseError(response), response); - - expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` - Array [ - Array [ - "[ResponseError]: Response Error", - ], - ] - `); }); describe('logs each queries if `logQueries` is true', () => { - function createResponseWithBody(body?: RequestBody) { - return createApiResponse({ - body: {}, - statusCode: 200, - params: { - method: 'GET', - path: '/foo', - querystring: { hello: 'dolly' }, - body, - }, - }); - } - it('when request body is an object', () => { const client = configureClient( createFakeConfig({ @@ -374,108 +320,211 @@ describe('configureClient', () => { ] `); }); - }); - it('properly encode queries', () => { - const client = configureClient( - createFakeConfig({ - logQueries: true, - }), - { logger, scoped: false } - ); + it('properly encode queries', () => { + const client = configureClient( + createFakeConfig({ + logQueries: true, + }), + { logger, scoped: false } + ); - const response = createApiResponse({ - body: {}, - statusCode: 200, - params: { - method: 'GET', - path: '/foo', - querystring: { city: 'Münich' }, - }, + const response = createApiResponse({ + body: {}, + statusCode: 200, + params: { + method: 'GET', + path: '/foo', + querystring: { city: 'Münich' }, + }, + }); + + client.emit('response', null, response); + + expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` + Array [ + Array [ + "200 + GET /foo?city=M%C3%BCnich", + Object { + "tags": Array [ + "query", + ], + }, + ], + ] + `); }); - client.emit('response', null, response); + it('logs queries even in case of errors if `logQueries` is true', () => { + const client = configureClient( + createFakeConfig({ + logQueries: true, + }), + { logger, scoped: false } + ); - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ - Array [ - "200 - GET /foo?city=M%C3%BCnich", - Object { - "tags": Array [ - "query", - ], + 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.emit('response', new errors.ResponseError(response), response); + + expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` + Array [ + Array [ + "500 + GET /foo?hello=dolly + {\\"seq_no_primary_term\\":true,\\"query\\":{\\"term\\":{\\"user\\":\\"kimchy\\"}}} [internal server error]: internal server error", + ], + ] + `); + }); - it('logs queries even in case of errors if `logQueries` is true', () => { - const client = configureClient( - createFakeConfig({ - logQueries: true, - }), - { logger, scoped: false } - ); - - const response = createApiResponse({ - statusCode: 500, - body: { - error: { - type: 'internal server error', + it('does not log queries if `logQueries` is false', () => { + const client = configureClient( + createFakeConfig({ + logQueries: false, + }), + { logger, scoped: false } + ); + + const response = createApiResponse({ + body: {}, + statusCode: 200, + params: { + method: 'GET', + path: '/foo', + }, + }); + + client.emit('response', null, response); + + expect(logger.debug).not.toHaveBeenCalled(); + }); + + it('logs error when the client emits an @elastic/elasticsearch error', () => { + const client = configureClient( + createFakeConfig({ + logQueries: true, + }), + { logger, scoped: false } + ); + + const response = createApiResponse({ body: {} }); + client.emit('response', new errors.TimeoutError('message', response), response); + + expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` + Array [ + Array [ + "[TimeoutError]: message", + ], + ] + `); + }); + + it('logs error when the client emits an ResponseError returned by elasticsearch', () => { + const client = configureClient( + createFakeConfig({ + logQueries: true, + }), + { logger, scoped: false } + ); + + const response = createApiResponse({ + statusCode: 400, + headers: {}, + params: { + method: 'GET', + path: '/_path', + querystring: { hello: 'dolly' }, }, - }, - params: { - method: 'GET', - path: '/foo', - querystring: { hello: 'dolly' }, body: { - seq_no_primary_term: true, - query: { - term: { user: 'kimchy' }, + error: { + type: 'illegal_argument_exception', + reason: 'request [/_path] contains unrecognized parameter: [name]', }, }, - }, - }); - client.emit('response', new errors.ResponseError(response), response); + }); + client.emit('response', new errors.ResponseError(response), response); - expect(loggingSystemMock.collect(logger).debug).toMatchInlineSnapshot(` - Array [ + expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` Array [ - "500 - GET /foo?hello=dolly - {\\"seq_no_primary_term\\":true,\\"query\\":{\\"term\\":{\\"user\\":\\"kimchy\\"}}}", - Object { - "tags": Array [ - "query", - ], - }, - ], - ] - `); - }); + Array [ + "400 + GET /_path?hello=dolly [illegal_argument_exception]: request [/_path] contains unrecognized parameter: [name]", + ], + ] + `); + }); - it('does not log queries if `logQueries` is false', () => { - const client = configureClient( - createFakeConfig({ - logQueries: false, - }), - { logger, scoped: false } - ); + it('logs default error info when the error response body is empty', () => { + const client = configureClient( + createFakeConfig({ + logQueries: true, + }), + { logger, scoped: false } + ); - const response = createApiResponse({ - body: {}, - statusCode: 200, - params: { - method: 'GET', - path: '/foo', - }, - }); + let response = createApiResponse({ + statusCode: 400, + headers: {}, + params: { + method: 'GET', + path: '/_path', + }, + body: { + error: {}, + }, + }); + client.emit('response', new errors.ResponseError(response), response); + + expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` + Array [ + Array [ + "400 + GET /_path [undefined]: Response Error", + ], + ] + `); + + logger.error.mockClear(); - client.emit('response', null, response); + response = createApiResponse({ + statusCode: 400, + headers: {}, + params: { + method: 'GET', + path: '/_path', + }, + body: {} as any, + }); + client.emit('response', new errors.ResponseError(response), response); - expect(logger.debug).not.toHaveBeenCalled(); + expect(loggingSystemMock.collect(logger).error).toMatchInlineSnapshot(` + Array [ + Array [ + "400 + GET /_path [undefined]: Response Error", + ], + ] + `); + }); }); }); }); diff --git a/src/core/server/elasticsearch/client/configure_client.ts b/src/core/server/elasticsearch/client/configure_client.ts index bf07ea604d228..920a713a60332 100644 --- a/src/core/server/elasticsearch/client/configure_client.ts +++ b/src/core/server/elasticsearch/client/configure_client.ts @@ -18,9 +18,8 @@ */ import { Buffer } from 'buffer'; import { stringify } from 'querystring'; -import { Client } from '@elastic/elasticsearch'; -import { RequestBody } from '@elastic/elasticsearch/lib/Transport'; - +import { ApiError, Client, RequestEvent, errors } from '@elastic/elasticsearch'; +import type { RequestBody } from '@elastic/elasticsearch/lib/Transport'; import { Logger } from '../../logging'; import { parseClientOptions, ElasticsearchClientConfig } from './client_config'; @@ -36,29 +35,6 @@ export const configureClient = ( return client; }; -const addLogging = (client: Client, logger: Logger, logQueries: boolean) => { - client.on('response', (error, event) => { - if (error) { - const errorMessage = - // error details for response errors provided by elasticsearch, defaults to error name/message - `[${event.body?.error?.type ?? error.name}]: ${event.body?.error?.reason ?? error.message}`; - - logger.error(errorMessage); - } - if (event && logQueries) { - const params = event.meta.request.params; - - // definition is wrong, `params.querystring` can be either a string or an object - const querystring = convertQueryString(params.querystring); - const url = `${params.path}${querystring ? `?${querystring}` : ''}`; - const body = params.body ? `\n${ensureString(params.body)}` : ''; - logger.debug(`${event.statusCode}\n${params.method} ${url}${body}`, { - tags: ['query'], - }); - } - }); -}; - const convertQueryString = (qs: string | Record | undefined): string => { if (qs === undefined || typeof qs === 'string') { return qs ?? ''; @@ -72,3 +48,45 @@ function ensureString(body: RequestBody): string { if ('readable' in body && body.readable && typeof body._read === 'function') return '[stream]'; return JSON.stringify(body); } + +function getErrorMessage(error: ApiError, event: RequestEvent): string { + if (error instanceof errors.ResponseError) { + return `${getResponseMessage(event)} [${event.body?.error?.type}]: ${ + event.body?.error?.reason ?? error.message + }`; + } + return `[${error.name}]: ${error.message}`; +} + +/** + * returns a string in format: + * + * status code + * URL + * request body + * + * so it could be copy-pasted into the Dev console + */ +function getResponseMessage(event: RequestEvent): 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); + const url = `${params.path}${querystring ? `?${querystring}` : ''}`; + const body = params.body ? `\n${ensureString(params.body)}` : ''; + return `${event.statusCode}\n${params.method} ${url}${body}`; +} + +const addLogging = (client: Client, logger: Logger, logQueries: boolean) => { + client.on('response', (error, event) => { + if (event && logQueries) { + if (error) { + logger.error(getErrorMessage(error, event)); + } else { + logger.debug(getResponseMessage(event), { + tags: ['query'], + }); + } + } + }); +};