github-mirrors/kibana
1
0
Fork 0
mirror of https://github.com/elastic/kibana.git synced 2025-04-23 17:28:26 -04:00
Code Issues Projects Releases Packages Wiki Activity

Surfacing deprecations with rich context from ES warning header (#120044) (#120800)

Browse source 
* 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 <lukeelmers@gmail.com>

* 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 <lukeelmers@gmail.com>
Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>

Co-authored-by: Rudolf Meijering <rudolf.meijering@elastic.co>
Co-authored-by: Luke Elmers <lukeelmers@gmail.com>
This commit is contained in:
Kibana Machine 2021-12-08 13:53:17 -05:00 • committed by GitHub
parent 24b86085f8
commit 5b04d2b064
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
10 changed files with 867 additions and 493 deletions
Download patch file Download diff file Expand all files Collapse all files

8
packages/kbn-dev-utils/src/tooling_log/__snapshots__/tooling_log_text_writer.test.ts.snap generated
View file

@ -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)"`;

52
packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.test.ts
View file

@ -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();
});

10
packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.ts
View file

@ -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] : '';

10
packages/kbn-pm/dist/index.js vendored
View file

@ -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] : '';

411
src/core/server/elasticsearch/client/configure_client.test.ts
View file

@ -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<ElasticsearchClientConfig> = {}
@ -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 = <T>({
body,
statusCode = 200,
headers = {},
warnings = [],
params,
requestOptions = {},
}: {
body: T;
statusCode?: number;
headers?: Record<string, string>;
warnings?: string[];
params?: TransportRequestParams;
requestOptions?: TransportRequestOptions;
}): DiagnosticResult<T> => {
return {
body,
statusCode,
headers,
warnings,
meta: {
body,
request: {
params: params!,
options: requestOptions,
} as any,
} as any,
};
};
describe('configureClient', () => {
let logger: ReturnType<typeof loggingSystemMock.createLogger>;
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<any, any> = 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',
});
});
});

95
src/core/server/elasticsearch/client/configure_client.ts
View file

@ -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));
instrumentEsQueryAndDeprecationLogger({ logger, client, type });
return client as KibanaClient;
};
const convertQueryString = (qs: string | Record<string, any> | 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!,
};
}
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);
}
}
});
};

3
src/core/server/elasticsearch/client/index.ts
View file

@ -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';

624
src/core/server/elasticsearch/client/log_query_and_deprecation.test.ts Normal file
View file

@ -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 = <T>({
body,
statusCode = 200,
headers = {},
warnings = null,
params,
requestOptions = {},
}: {
body: T;
statusCode?: number;
headers?: Record<string, string>;
warnings?: string[] | null;
params?: TransportRequestParams | ConnectionRequestParams;
requestOptions?: TransportRequestOptions;
}): DiagnosticResult<T> => {
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<typeof loggingSystemMock.createLogger>;
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<any, any> = 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/
);
});
});
});

143
src/core/server/elasticsearch/client/log_query_and_deprecation.ts Normal file
View file

@ -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<string, any> | 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:
* <warn-code> <warn-agent> <warn-text> (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);
}
}
}
});
};

4
test/common/config.js
View file

@ -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,