From f9b2ad129123b568d26292921c80c62cd49a2487 Mon Sep 17 00:00:00 2001 From: Luke Elmers Date: Thu, 4 Feb 2021 09:19:31 -0700 Subject: [PATCH] [7.x] [core.logging] Add response logs to the KP logging system. (#87939) (#90280) --- .../src/get_logging_config.ts | 13 +- packages/kbn-legacy-logging/src/log_events.ts | 4 +- packages/kbn-legacy-logging/src/log_format.ts | 33 +- .../src/log_format_json.test.ts | 63 ++-- .../src/utils/get_payload_size.test.ts | 101 ++++++ .../src/utils/get_payload_size.ts | 64 ++++ .../kbn-legacy-logging/src/utils/index.ts | 1 + .../deprecation/core_deprecations.test.ts | 44 ++- .../config/deprecation/core_deprecations.ts | 16 +- src/core/server/http/http_server.ts | 26 +- .../http/integration_tests/logging.test.ts | 338 ++++++++++++++++++ .../http/logging/get_payload_size.test.ts | 204 +++++++++++ .../server/http/logging/get_payload_size.ts | 73 ++++ .../http/logging/get_response_log.test.ts | 247 +++++++++++++ .../server/http/logging/get_response_log.ts | 92 +++++ src/core/server/http/logging/index.ts | 9 + src/core/server/logging/README.md | 44 +++ src/core/server/logging/ecs.ts | 65 +++- src/core/server/logging/index.ts | 8 +- .../metrics/logging/get_ops_metrics_log.ts | 4 +- 20 files changed, 1383 insertions(+), 66 deletions(-) create mode 100644 packages/kbn-legacy-logging/src/utils/get_payload_size.test.ts create mode 100644 packages/kbn-legacy-logging/src/utils/get_payload_size.ts create mode 100644 src/core/server/http/integration_tests/logging.test.ts create mode 100644 src/core/server/http/logging/get_payload_size.test.ts create mode 100644 src/core/server/http/logging/get_payload_size.ts create mode 100644 src/core/server/http/logging/get_response_log.test.ts create mode 100644 src/core/server/http/logging/get_response_log.ts create mode 100644 src/core/server/http/logging/index.ts diff --git a/packages/kbn-legacy-logging/src/get_logging_config.ts b/packages/kbn-legacy-logging/src/get_logging_config.ts index 713f3b79e4e0e7..bde02bd9006573 100644 --- a/packages/kbn-legacy-logging/src/get_logging_config.ts +++ b/packages/kbn-legacy-logging/src/get_logging_config.ts @@ -27,14 +27,14 @@ export function getLoggingConfiguration(config: LegacyLoggingConfig, opsInterval }); } else if (config.verbose) { _.defaults(events, { + error: '*', log: '*', - // To avoid duplicate logs, we explicitly disable this in verbose - // mode as it is already provided by the new logging config under - // the `metrics.ops` context. + // To avoid duplicate logs, we explicitly disable these in verbose + // mode as they are already provided by the new logging config under + // the `http.server.response` and `metrics.ops` contexts. ops: '!', - request: '*', - response: '*', - error: '*', + request: '!', + response: '!', }); } else { _.defaults(events, { @@ -76,6 +76,7 @@ export function getLoggingConfiguration(config: LegacyLoggingConfig, opsInterval }, includes: { request: ['headers', 'payload'], + response: ['headers', 'payload'], }, reporters: { logReporter: [loggerStream], diff --git a/packages/kbn-legacy-logging/src/log_events.ts b/packages/kbn-legacy-logging/src/log_events.ts index bb5bc245d14fb6..193bfbea42ace6 100644 --- a/packages/kbn-legacy-logging/src/log_events.ts +++ b/packages/kbn-legacy-logging/src/log_events.ts @@ -6,6 +6,7 @@ * Side Public License, v 1. */ +import type { ResponseObject } from '@hapi/hapi'; import { EventData, isEventData } from './metadata'; export interface BaseEvent { @@ -21,7 +22,8 @@ export interface ResponseEvent extends BaseEvent { statusCode: number; path: string; headers: Record; - responsePayload: string; + responseHeaders: Record; + responsePayload: ResponseObject['source']; responseTime: string; query: Record; } diff --git a/packages/kbn-legacy-logging/src/log_format.ts b/packages/kbn-legacy-logging/src/log_format.ts index ec2628a4389a33..a0eaf023dff19b 100644 --- a/packages/kbn-legacy-logging/src/log_format.ts +++ b/packages/kbn-legacy-logging/src/log_format.ts @@ -12,15 +12,14 @@ import _ from 'lodash'; import queryString from 'query-string'; import numeral from '@elastic/numeral'; import chalk from 'chalk'; -// @ts-expect-error missing type def -import stringify from 'json-stringify-safe'; import { inspect } from 'util'; -import { applyFiltersToKeys } from './utils'; +import { applyFiltersToKeys, getResponsePayloadBytes } from './utils'; import { getLogEventData } from './metadata'; import { LegacyLoggingConfig } from './schema'; import { AnyEvent, + ResponseEvent, isResponseEvent, isOpsEvent, isErrorEvent, @@ -70,6 +69,23 @@ export abstract class BaseLogFormat extends Stream.Transform { next(); } + getContentLength({ responsePayload, responseHeaders }: ResponseEvent): number | undefined { + try { + return getResponsePayloadBytes(responsePayload, responseHeaders); + } catch (e) { + // We intentionally swallow any errors as this information is + // only a nicety for logging purposes, and should not cause the + // server to crash if it cannot be determined. + this.push( + this.format({ + type: 'log', + tags: ['warning', 'logging'], + message: `Failed to calculate response payload bytes. [${e}]`, + }) + '\n' + ); + } + } + extractAndFormatTimestamp(data: Record, format?: string) { const { timezone } = this.config; const date = moment(data['@timestamp']); @@ -100,15 +116,10 @@ export abstract class BaseLogFormat extends Stream.Transform { referer: source.referer, }; - const contentLength = - event.responsePayload === 'object' - ? stringify(event.responsePayload).length - : String(event.responsePayload).length; - data.res = { statusCode: event.statusCode, responseTime: event.responseTime, - contentLength, + contentLength: this.getContentLength(event), }; const query = queryString.stringify(event.query, { sort: false }); @@ -122,7 +133,9 @@ export abstract class BaseLogFormat extends Stream.Transform { data.message += levelColor(data.res.statusCode); data.message += ' '; data.message += chalk.gray(data.res.responseTime + 'ms'); - data.message += chalk.gray(' - ' + numeral(contentLength).format('0.0b')); + if (data.res.contentLength) { + data.message += chalk.gray(' - ' + numeral(data.res.contentLength).format('0.0b')); + } } else if (isOpsEvent(event)) { _.defaults(data, _.pick(event, ['pid', 'os', 'proc', 'load'])); data.message = chalk.gray('memory: '); diff --git a/packages/kbn-legacy-logging/src/log_format_json.test.ts b/packages/kbn-legacy-logging/src/log_format_json.test.ts index edeb8187d7ac1a..3255c5d17bb307 100644 --- a/packages/kbn-legacy-logging/src/log_format_json.test.ts +++ b/packages/kbn-legacy-logging/src/log_format_json.test.ts @@ -39,30 +39,45 @@ describe('KbnLoggerJsonFormat', () => { expect(message).toBe('undefined'); }); - it('response', async () => { - const event = { - ...makeEvent('response'), - statusCode: 200, - contentLength: 800, - responseTime: 12000, - method: 'GET', - path: '/path/to/resource', - responsePayload: '1234567879890', - source: { - remoteAddress: '127.0.0.1', - userAgent: 'Test Thing', - referer: 'elastic.co', - }, - }; - const result = await createPromiseFromStreams([createListStream([event]), format]); - const { type, method, statusCode, message, req } = JSON.parse(result); - - expect(type).toBe('response'); - expect(method).toBe('GET'); - expect(statusCode).toBe(200); - expect(message).toBe('GET /path/to/resource 200 12000ms - 13.0B'); - expect(req.remoteAddress).toBe('127.0.0.1'); - expect(req.userAgent).toBe('Test Thing'); + describe('response', () => { + it('handles a response object', async () => { + const event = { + ...makeEvent('response'), + statusCode: 200, + contentLength: 800, + responseTime: 12000, + method: 'GET', + path: '/path/to/resource', + responsePayload: '1234567879890', + source: { + remoteAddress: '127.0.0.1', + userAgent: 'Test Thing', + referer: 'elastic.co', + }, + }; + const result = await createPromiseFromStreams([createListStream([event]), format]); + const { type, method, statusCode, message, req } = JSON.parse(result); + + expect(type).toBe('response'); + expect(method).toBe('GET'); + expect(statusCode).toBe(200); + expect(message).toBe('GET /path/to/resource 200 12000ms - 13.0B'); + expect(req.remoteAddress).toBe('127.0.0.1'); + expect(req.userAgent).toBe('Test Thing'); + }); + + it('leaves payload size empty if not available', async () => { + const event = { + ...makeEvent('response'), + statusCode: 200, + responseTime: 12000, + method: 'GET', + path: '/path/to/resource', + responsePayload: null, + }; + const result = await createPromiseFromStreams([createListStream([event]), format]); + expect(JSON.parse(result).message).toBe('GET /path/to/resource 200 12000ms'); + }); }); it('ops', async () => { diff --git a/packages/kbn-legacy-logging/src/utils/get_payload_size.test.ts b/packages/kbn-legacy-logging/src/utils/get_payload_size.test.ts new file mode 100644 index 00000000000000..c70f95b9ddc110 --- /dev/null +++ b/packages/kbn-legacy-logging/src/utils/get_payload_size.test.ts @@ -0,0 +1,101 @@ +/* + * 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 mockFs from 'mock-fs'; +import { createReadStream } from 'fs'; + +import { getResponsePayloadBytes } from './get_payload_size'; + +describe('getPayloadSize', () => { + describe('handles Buffers', () => { + test('with ascii characters', () => { + const payload = 'heya'; + const result = getResponsePayloadBytes(Buffer.from(payload)); + expect(result).toBe(4); + }); + + test('with special characters', () => { + const payload = '¡hola!'; + const result = getResponsePayloadBytes(Buffer.from(payload)); + expect(result).toBe(7); + }); + }); + + describe('handles fs streams', () => { + afterEach(() => mockFs.restore()); + + test('with ascii characters', async () => { + mockFs({ 'test.txt': 'heya' }); + const readStream = createReadStream('test.txt'); + + let data = ''; + for await (const chunk of readStream) { + data += chunk; + } + + const result = getResponsePayloadBytes(readStream); + expect(result).toBe(Buffer.byteLength(data)); + }); + + test('with special characters', async () => { + mockFs({ 'test.txt': '¡hola!' }); + const readStream = createReadStream('test.txt'); + + let data = ''; + for await (const chunk of readStream) { + data += chunk; + } + + const result = getResponsePayloadBytes(readStream); + expect(result).toBe(Buffer.byteLength(data)); + }); + }); + + describe('handles plain responses', () => { + test('when source is text', () => { + const result = getResponsePayloadBytes('heya'); + expect(result).toBe(4); + }); + + test('when source contains special characters', () => { + const result = getResponsePayloadBytes('¡hola!'); + expect(result).toBe(7); + }); + + test('when source is object', () => { + const payload = { message: 'heya' }; + const result = getResponsePayloadBytes(payload); + expect(result).toBe(JSON.stringify(payload).length); + }); + }); + + describe('handles content-length header', () => { + test('always provides content-length header if available', () => { + const headers = { 'content-length': '123' }; + const result = getResponsePayloadBytes('heya', headers); + expect(result).toBe(123); + }); + + test('uses first value when hapi header is an array', () => { + const headers = { 'content-length': ['123', '456'] }; + const result = getResponsePayloadBytes(null, headers); + expect(result).toBe(123); + }); + + test('returns undefined if length is NaN', () => { + const headers = { 'content-length': 'oops' }; + const result = getResponsePayloadBytes(null, headers); + expect(result).toBeUndefined(); + }); + }); + + test('defaults to undefined', () => { + const result = getResponsePayloadBytes(null); + expect(result).toBeUndefined(); + }); +}); diff --git a/packages/kbn-legacy-logging/src/utils/get_payload_size.ts b/packages/kbn-legacy-logging/src/utils/get_payload_size.ts new file mode 100644 index 00000000000000..de96ad70027315 --- /dev/null +++ b/packages/kbn-legacy-logging/src/utils/get_payload_size.ts @@ -0,0 +1,64 @@ +/* + * 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 type { ReadStream } from 'fs'; +import type { ResponseObject } from '@hapi/hapi'; + +const isBuffer = (obj: unknown): obj is Buffer => Buffer.isBuffer(obj); +const isObject = (obj: unknown): obj is Record => + typeof obj === 'object' && obj !== null; +const isFsReadStream = (obj: unknown): obj is ReadStream => + typeof obj === 'object' && obj !== null && 'bytesRead' in obj; +const isString = (obj: unknown): obj is string => typeof obj === 'string'; + +/** + * Attempts to determine the size (in bytes) of a hapi/good + * responsePayload based on the payload type. Falls back to + * `undefined` if the size cannot be determined. + * + * This is similar to the implementation in `core/server/http/logging`, + * however it uses more duck typing as we do not have access to the + * entire hapi request object like we do in the HttpServer. + * + * @param headers responseHeaders from hapi/good event + * @param payload responsePayload from hapi/good event + * + * @internal + */ +export function getResponsePayloadBytes( + payload: ResponseObject['source'], + headers: Record = {} +): number | undefined { + const contentLength = headers['content-length']; + if (contentLength) { + const val = parseInt( + // hapi response headers can be `string | string[]`, so we need to handle both cases + Array.isArray(contentLength) ? String(contentLength) : contentLength, + 10 + ); + return !isNaN(val) ? val : undefined; + } + + if (isBuffer(payload)) { + return payload.byteLength; + } + + if (isFsReadStream(payload)) { + return payload.bytesRead; + } + + if (isString(payload)) { + return Buffer.byteLength(payload); + } + + if (isObject(payload)) { + return Buffer.byteLength(JSON.stringify(payload)); + } + + return undefined; +} diff --git a/packages/kbn-legacy-logging/src/utils/index.ts b/packages/kbn-legacy-logging/src/utils/index.ts index 166fac130f7716..3036671121fe0b 100644 --- a/packages/kbn-legacy-logging/src/utils/index.ts +++ b/packages/kbn-legacy-logging/src/utils/index.ts @@ -7,3 +7,4 @@ */ export { applyFiltersToKeys } from './apply_filters_to_keys'; +export { getResponsePayloadBytes } from './get_payload_size'; diff --git a/src/core/server/config/deprecation/core_deprecations.test.ts b/src/core/server/config/deprecation/core_deprecations.test.ts index c0988c0164928f..a64d4d562e082a 100644 --- a/src/core/server/config/deprecation/core_deprecations.test.ts +++ b/src/core/server/config/deprecation/core_deprecations.test.ts @@ -264,7 +264,49 @@ describe('core deprecations', () => { }); expect(messages).toMatchInlineSnapshot(` Array [ - "\\"logging.events.ops\\" has been deprecated and will be removed in 8.0. To access ops data moving forward, please enable debug logs for the \\"metrics.ops\\" context in your logging configuration.", + "\\"logging.events.ops\\" has been deprecated and will be removed in 8.0. To access ops data moving forward, please enable debug logs for the \\"metrics.ops\\" context in your logging configuration. For more details, see https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md", + ] + `); + }); + + it('does not warn when other events are configured', () => { + const { messages } = applyCoreDeprecations({ + logging: { events: { log: '*' } }, + }); + expect(messages).toEqual([]); + }); + }); + + describe('logging.events.request and logging.events.response', () => { + it('warns when request and response events are used', () => { + const { messages } = applyCoreDeprecations({ + logging: { events: { request: '*', response: '*' } }, + }); + expect(messages).toMatchInlineSnapshot(` + Array [ + "\\"logging.events.request\\" and \\"logging.events.response\\" have been deprecated and will be removed in 8.0. To access request and/or response data moving forward, please enable debug logs for the \\"http.server.response\\" context in your logging configuration. For more details, see https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md", + ] + `); + }); + + it('warns when only request event is used', () => { + const { messages } = applyCoreDeprecations({ + logging: { events: { request: '*' } }, + }); + expect(messages).toMatchInlineSnapshot(` + Array [ + "\\"logging.events.request\\" and \\"logging.events.response\\" have been deprecated and will be removed in 8.0. To access request and/or response data moving forward, please enable debug logs for the \\"http.server.response\\" context in your logging configuration. For more details, see https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md", + ] + `); + }); + + it('warns when only response event is used', () => { + const { messages } = applyCoreDeprecations({ + logging: { events: { response: '*' } }, + }); + expect(messages).toMatchInlineSnapshot(` + Array [ + "\\"logging.events.request\\" and \\"logging.events.response\\" have been deprecated and will be removed in 8.0. To access request and/or response data moving forward, please enable debug logs for the \\"http.server.response\\" context in your logging configuration. For more details, see https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md", ] `); }); diff --git a/src/core/server/config/deprecation/core_deprecations.ts b/src/core/server/config/deprecation/core_deprecations.ts index 72f09a4b7e7814..cd8c3183100f97 100644 --- a/src/core/server/config/deprecation/core_deprecations.ts +++ b/src/core/server/config/deprecation/core_deprecations.ts @@ -118,7 +118,20 @@ const opsLoggingEventDeprecation: ConfigDeprecation = (settings, fromPath, log) log( '"logging.events.ops" has been deprecated and will be removed ' + 'in 8.0. To access ops data moving forward, please enable debug logs for the ' + - '"metrics.ops" context in your logging configuration.' + '"metrics.ops" context in your logging configuration. For more details, see ' + + 'https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md' + ); + } + return settings; +}; + +const requestLoggingEventDeprecation: ConfigDeprecation = (settings, fromPath, log) => { + if (has(settings, 'logging.events.request') || has(settings, 'logging.events.response')) { + log( + '"logging.events.request" and "logging.events.response" have been deprecated and will be removed ' + + 'in 8.0. To access request and/or response data moving forward, please enable debug logs for the ' + + '"http.server.response" context in your logging configuration. For more details, see ' + + 'https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md' ); } return settings; @@ -171,4 +184,5 @@ export const coreDeprecationProvider: ConfigDeprecationProvider = ({ mapManifestServiceUrlDeprecation, serverHostZeroDeprecation, opsLoggingEventDeprecation, + requestLoggingEventDeprecation, ]; diff --git a/src/core/server/http/http_server.ts b/src/core/server/http/http_server.ts index a6842e8d573e82..8435050a238c6c 100644 --- a/src/core/server/http/http_server.ts +++ b/src/core/server/http/http_server.ts @@ -6,7 +6,7 @@ * Side Public License, v 1. */ -import { Server } from '@hapi/hapi'; +import { Server, Request } from '@hapi/hapi'; import HapiStaticFiles from '@hapi/inert'; import url from 'url'; import uuid from 'uuid'; @@ -33,6 +33,7 @@ import { import { IsAuthenticated, AuthStateStorage, GetAuthState } from './auth_state_storage'; import { AuthHeadersStorage, GetAuthHeaders } from './auth_headers_storage'; import { BasePath } from './base_path_service'; +import { getEcsResponseLog } from './logging'; import { HttpServiceSetup, HttpServerInfo } from './types'; /** @internal */ @@ -76,6 +77,7 @@ export class HttpServer { private registeredRouters = new Set(); private authRegistered = false; private cookieSessionStorageCreated = false; + private handleServerResponseEvent?: (req: Request) => void; private stopped = false; private readonly log: Logger; @@ -112,6 +114,7 @@ export class HttpServer { const basePathService = new BasePath(config.basePath, config.publicBaseUrl); this.setupBasePathRewrite(config, basePathService); this.setupConditionalCompression(config); + this.setupResponseLogging(); this.setupRequestStateAssignment(config); return { @@ -216,6 +219,9 @@ export class HttpServer { const hasStarted = this.server.info.started > 0; if (hasStarted) { this.log.debug('stopping http server'); + if (this.handleServerResponseEvent) { + this.server.events.removeListener('response', this.handleServerResponseEvent); + } await this.server.stop(); } } @@ -282,6 +288,24 @@ export class HttpServer { } } + private setupResponseLogging() { + if (this.server === undefined) { + throw new Error('Server is not created yet'); + } + if (this.stopped) { + this.log.warn(`setupResponseLogging called after stop`); + } + + const log = this.logger.get('http', 'server', 'response'); + + this.handleServerResponseEvent = (request) => { + const { message, ...meta } = getEcsResponseLog(request, this.log); + log.debug(message!, meta); + }; + + this.server.events.on('response', this.handleServerResponseEvent); + } + private setupRequestStateAssignment(config: HttpConfig) { this.server!.ext('onRequest', (request, responseToolkit) => { request.app = { diff --git a/src/core/server/http/integration_tests/logging.test.ts b/src/core/server/http/integration_tests/logging.test.ts new file mode 100644 index 00000000000000..ba265c1ff61bc2 --- /dev/null +++ b/src/core/server/http/integration_tests/logging.test.ts @@ -0,0 +1,338 @@ +/* + * 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 { schema } from '@kbn/config-schema'; +import * as kbnTestServer from '../../../test_helpers/kbn_server'; + +describe('request logging', () => { + let mockConsoleLog: jest.SpyInstance; + + beforeAll(() => { + mockConsoleLog = jest.spyOn(global.console, 'log'); + }); + + afterEach(() => { + mockConsoleLog.mockClear(); + }); + + afterAll(() => { + mockConsoleLog.mockRestore(); + }); + + describe('http server response logging', () => { + describe('configuration', () => { + it('does not log with a default config', async () => { + const root = kbnTestServer.createRoot({ plugins: { initialize: false } }); + const { http } = await root.setup(); + + http + .createRouter('/') + .get( + { path: '/ping', validate: false, options: { authRequired: 'optional' } }, + (context, req, res) => res.ok({ body: 'pong' }) + ); + await root.start(); + + await kbnTestServer.request.get(root, '/ping').expect(200, 'pong'); + expect(mockConsoleLog).not.toHaveBeenCalled(); + + await root.shutdown(); + }); + + it('logs at the correct level and with the correct context', async () => { + const root = kbnTestServer.createRoot({ + logging: { + silent: true, + appenders: { + 'test-console': { + kind: 'console', + layout: { + kind: 'pattern', + pattern: '%level|%logger|%message|%meta', + }, + }, + }, + loggers: [ + { + context: 'http.server.response', + appenders: ['test-console'], + level: 'debug', + }, + ], + }, + plugins: { + initialize: false, + }, + }); + const { http } = await root.setup(); + + http + .createRouter('/') + .get( + { path: '/ping', validate: false, options: { authRequired: 'optional' } }, + (context, req, res) => res.ok({ body: 'pong' }) + ); + await root.start(); + + await kbnTestServer.request.get(root, '/ping').expect(200, 'pong'); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [level, logger] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(level).toBe('DEBUG'); + expect(logger).toBe('http.server.response'); + + await root.shutdown(); + }); + }); + + describe('content', () => { + let root: ReturnType; + const config = { + logging: { + silent: true, + appenders: { + 'test-console': { + kind: 'console', + layout: { + kind: 'pattern', + pattern: '%level|%logger|%message|%meta', + }, + }, + }, + loggers: [ + { + context: 'http.server.response', + appenders: ['test-console'], + level: 'debug', + }, + ], + }, + plugins: { + initialize: false, + }, + }; + + beforeEach(() => { + root = kbnTestServer.createRoot(config); + }); + + afterEach(async () => { + await root.shutdown(); + }); + + it('handles a GET request', async () => { + const { http } = await root.setup(); + + http + .createRouter('/') + .get( + { path: '/ping', validate: false, options: { authRequired: 'optional' } }, + (context, req, res) => res.ok({ body: 'pong' }) + ); + await root.start(); + + await kbnTestServer.request.get(root, '/ping').expect(200, 'pong'); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , message, meta] = mockConsoleLog.mock.calls[0][0].split('|'); + // some of the contents of the message are variable based on environment, such as + // response time, so we are only performing assertions against parts of the string + expect(message.includes('GET /ping 200')).toBe(true); + expect(JSON.parse(meta).http.request.method).toBe('GET'); + expect(JSON.parse(meta).url.path).toBe('/ping'); + expect(JSON.parse(meta).http.response.status_code).toBe(200); + }); + + it('handles a POST request', async () => { + const { http } = await root.setup(); + + http.createRouter('/').post( + { + path: '/ping', + validate: { + body: schema.object({ message: schema.string() }), + }, + options: { + authRequired: 'optional', + body: { + accepts: ['application/json'], + }, + timeout: { payload: 100 }, + }, + }, + (context, req, res) => res.ok({ body: { message: req.body.message } }) + ); + await root.start(); + + await kbnTestServer.request + .post(root, '/ping') + .set('Content-Type', 'application/json') + .send({ message: 'hi' }) + .expect(200); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , message] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(message.includes('POST /ping 200')).toBe(true); + }); + + it('handles an error response', async () => { + const { http } = await root.setup(); + + http + .createRouter('/') + .get( + { path: '/a', validate: false, options: { authRequired: 'optional' } }, + (context, req, res) => res.ok({ body: 'pong' }) + ); + await root.start(); + + await kbnTestServer.request.get(root, '/b').expect(404); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , message, meta] = mockConsoleLog.mock.calls[0][0].split('|'); + // some of the contents of the message are variable based on environment, such as + // response time, so we are only performing assertions against parts of the string + expect(message.includes('GET /b 404')).toBe(true); + expect(JSON.parse(meta).http.response.status_code).toBe(404); + }); + + it('handles query strings', async () => { + const { http } = await root.setup(); + + http + .createRouter('/') + .get( + { path: '/ping', validate: false, options: { authRequired: 'optional' } }, + (context, req, res) => res.ok({ body: 'pong' }) + ); + await root.start(); + + await kbnTestServer.request.get(root, '/ping').query({ hey: 'ya' }).expect(200, 'pong'); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , message, meta] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(message.includes('GET /ping?hey=ya 200')).toBe(true); + expect(JSON.parse(meta).url.query).toBe('hey=ya'); + }); + + it('correctly calculates response payload', async () => { + const { http } = await root.setup(); + + http + .createRouter('/') + .get( + { path: '/ping', validate: false, options: { authRequired: 'optional' } }, + (context, req, res) => res.ok({ body: 'pong' }) + ); + await root.start(); + + const response = await kbnTestServer.request.get(root, '/ping').expect(200, 'pong'); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , , meta] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(JSON.parse(meta).http.response.body.bytes).toBe(response.text.length); + }); + + describe('handles request/response headers', () => { + it('includes request/response headers in log entry', async () => { + const { http } = await root.setup(); + + http + .createRouter('/') + .get( + { path: '/ping', validate: false, options: { authRequired: 'optional' } }, + (context, req, res) => res.ok({ headers: { bar: 'world' }, body: 'pong' }) + ); + await root.start(); + + await kbnTestServer.request.get(root, '/ping').set('foo', 'hello').expect(200); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , , meta] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(JSON.parse(meta).http.request.headers.foo).toBe('hello'); + expect(JSON.parse(meta).http.response.headers.bar).toBe('world'); + }); + + it('filters sensitive request headers', async () => { + const { http } = await root.setup(); + + http.createRouter('/').post( + { + path: '/ping', + validate: { + body: schema.object({ message: schema.string() }), + }, + options: { + authRequired: 'optional', + body: { + accepts: ['application/json'], + }, + timeout: { payload: 100 }, + }, + }, + (context, req, res) => res.ok({ body: { message: req.body.message } }) + ); + await root.start(); + + await kbnTestServer.request + .post(root, '/ping') + .set('content-type', 'application/json') + .set('authorization', 'abc') + .send({ message: 'hi' }) + .expect(200); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , , meta] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(JSON.parse(meta).http.request.headers.authorization).toBe('[REDACTED]'); + }); + + it('filters sensitive response headers', async () => { + const { http } = await root.setup(); + + http.createRouter('/').post( + { + path: '/ping', + validate: { + body: schema.object({ message: schema.string() }), + }, + options: { + authRequired: 'optional', + body: { + accepts: ['application/json'], + }, + timeout: { payload: 100 }, + }, + }, + (context, req, res) => + res.ok({ headers: { 'set-cookie': ['123'] }, body: { message: req.body.message } }) + ); + await root.start(); + + await kbnTestServer.request + .post(root, '/ping') + .set('Content-Type', 'application/json') + .send({ message: 'hi' }) + .expect(200); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , , meta] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(JSON.parse(meta).http.response.headers['set-cookie']).toBe('[REDACTED]'); + }); + }); + + it('handles user agent', async () => { + const { http } = await root.setup(); + + http + .createRouter('/') + .get( + { path: '/ping', validate: false, options: { authRequired: 'optional' } }, + (context, req, res) => res.ok({ body: 'pong' }) + ); + await root.start(); + + await kbnTestServer.request.get(root, '/ping').set('user-agent', 'world').expect(200); + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [, , , meta] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(JSON.parse(meta).http.request.headers['user-agent']).toBe('world'); + expect(JSON.parse(meta).user_agent.original).toBe('world'); + }); + }); + }); +}); diff --git a/src/core/server/http/logging/get_payload_size.test.ts b/src/core/server/http/logging/get_payload_size.test.ts new file mode 100644 index 00000000000000..a4ab8919e8b6da --- /dev/null +++ b/src/core/server/http/logging/get_payload_size.test.ts @@ -0,0 +1,204 @@ +/* + * 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 type { Request } from '@hapi/hapi'; +import Boom from '@hapi/boom'; + +import mockFs from 'mock-fs'; +import { createReadStream } from 'fs'; + +import { loggerMock, MockedLogger } from '../../logging/logger.mock'; + +import { getResponsePayloadBytes } from './get_payload_size'; + +type Response = Request['response']; + +describe('getPayloadSize', () => { + let logger: MockedLogger; + + beforeEach(() => (logger = loggerMock.create())); + + test('handles Boom errors', () => { + const boomError = Boom.badRequest(); + const payload = boomError.output.payload; + const result = getResponsePayloadBytes(boomError, logger); + expect(result).toBe(JSON.stringify(payload).length); + }); + + describe('handles Buffers', () => { + test('with ascii characters', () => { + const result = getResponsePayloadBytes( + { + variety: 'buffer', + source: Buffer.from('heya'), + } as Response, + logger + ); + expect(result).toBe(4); + }); + + test('with special characters', () => { + const result = getResponsePayloadBytes( + { + variety: 'buffer', + source: Buffer.from('¡hola!'), + } as Response, + logger + ); + expect(result).toBe(7); + }); + }); + + describe('handles fs streams', () => { + afterEach(() => mockFs.restore()); + + test('with ascii characters', async () => { + mockFs({ 'test.txt': 'heya' }); + const source = createReadStream('test.txt'); + + let data = ''; + for await (const chunk of source) { + data += chunk; + } + + const result = getResponsePayloadBytes( + { + variety: 'stream', + source, + } as Response, + logger + ); + + expect(result).toBe(Buffer.byteLength(data)); + }); + + test('with special characters', async () => { + mockFs({ 'test.txt': '¡hola!' }); + const source = createReadStream('test.txt'); + + let data = ''; + for await (const chunk of source) { + data += chunk; + } + + const result = getResponsePayloadBytes( + { + variety: 'stream', + source, + } as Response, + logger + ); + + expect(result).toBe(Buffer.byteLength(data)); + }); + }); + + describe('handles plain responses', () => { + test('when source is text', () => { + const result = getResponsePayloadBytes( + { + variety: 'plain', + source: 'heya', + } as Response, + logger + ); + expect(result).toBe(4); + }); + + test('when source has special characters', () => { + const result = getResponsePayloadBytes( + { + variety: 'plain', + source: '¡hola!', + } as Response, + logger + ); + expect(result).toBe(7); + }); + + test('when source is object', () => { + const payload = { message: 'heya' }; + const result = getResponsePayloadBytes( + { + variety: 'plain', + source: payload, + } as Response, + logger + ); + expect(result).toBe(JSON.stringify(payload).length); + }); + }); + + describe('handles content-length header', () => { + test('always provides content-length header if available', () => { + const headers = { 'content-length': '123' }; + const result = getResponsePayloadBytes( + ({ + headers, + variety: 'plain', + source: 'abc', + } as unknown) as Response, + logger + ); + expect(result).toBe(123); + }); + + test('uses first value when hapi header is an array', () => { + const headers = { 'content-length': ['123', '456'] }; + const result = getResponsePayloadBytes(({ headers } as unknown) as Response, logger); + expect(result).toBe(123); + }); + + test('returns undefined if length is NaN', () => { + const headers = { 'content-length': 'oops' }; + const result = getResponsePayloadBytes(({ headers } as unknown) as Response, logger); + expect(result).toBeUndefined(); + }); + }); + + test('defaults to undefined', () => { + const result = getResponsePayloadBytes(({} as unknown) as Response, logger); + expect(result).toBeUndefined(); + }); + + test('swallows errors to prevent crashing Kibana', () => { + // intentionally create a circular reference so JSON.stringify fails + const payload = { + get circular() { + return this; + }, + }; + const result = getResponsePayloadBytes( + ({ + variety: 'plain', + source: payload.circular, + } as unknown) as Response, + logger + ); + expect(result).toBeUndefined(); + }); + + test('logs any errors that are caught', () => { + // intentionally create a circular reference so JSON.stringify fails + const payload = { + get circular() { + return this; + }, + }; + getResponsePayloadBytes( + ({ + variety: 'plain', + source: payload.circular, + } as unknown) as Response, + logger + ); + expect(logger.warn.mock.calls[0][0]).toMatchInlineSnapshot( + `"Failed to calculate response payload bytes."` + ); + }); +}); diff --git a/src/core/server/http/logging/get_payload_size.ts b/src/core/server/http/logging/get_payload_size.ts new file mode 100644 index 00000000000000..6dcaf3653d8420 --- /dev/null +++ b/src/core/server/http/logging/get_payload_size.ts @@ -0,0 +1,73 @@ +/* + * 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 type { ReadStream } from 'fs'; +import { isBoom } from '@hapi/boom'; +import type { Request } from '@hapi/hapi'; +import { Logger } from '../../logging'; + +type Response = Request['response']; + +const isBuffer = (src: unknown, res: Response): src is Buffer => { + return !isBoom(res) && res.variety === 'buffer' && res.source === src; +}; +const isFsReadStream = (src: unknown, res: Response): src is ReadStream => { + return !isBoom(res) && res.variety === 'stream' && res.source === src; +}; + +/** + * Attempts to determine the size (in bytes) of a Hapi response + * body based on the payload type. Falls back to `undefined` + * if the size cannot be determined from the response object. + * + * @param response Hapi response object or Boom error + * + * @internal + */ +export function getResponsePayloadBytes(response: Response, log: Logger): number | undefined { + try { + const headers = isBoom(response) + ? (response.output.headers as Record) + : response.headers; + + const contentLength = headers && headers['content-length']; + if (contentLength) { + const val = parseInt( + // hapi response headers can be `string | string[]`, so we need to handle both cases + Array.isArray(contentLength) ? String(contentLength) : contentLength, + 10 + ); + return !isNaN(val) ? val : undefined; + } + + if (isBoom(response)) { + return Buffer.byteLength(JSON.stringify(response.output.payload)); + } + + if (isBuffer(response.source, response)) { + return response.source.byteLength; + } + + if (isFsReadStream(response.source, response)) { + return response.source.bytesRead; + } + + if (response.variety === 'plain') { + return typeof response.source === 'string' + ? Buffer.byteLength(response.source) + : Buffer.byteLength(JSON.stringify(response.source)); + } + } catch (e) { + // We intentionally swallow any errors as this information is + // only a nicety for logging purposes, and should not cause the + // server to crash if it cannot be determined. + log.warn('Failed to calculate response payload bytes.', e); + } + + return undefined; +} diff --git a/src/core/server/http/logging/get_response_log.test.ts b/src/core/server/http/logging/get_response_log.test.ts new file mode 100644 index 00000000000000..46c4f1d95e3be0 --- /dev/null +++ b/src/core/server/http/logging/get_response_log.test.ts @@ -0,0 +1,247 @@ +/* + * 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 type { Request } from '@hapi/hapi'; +import Boom from '@hapi/boom'; +import { loggerMock, MockedLogger } from '../../logging/logger.mock'; +import { getEcsResponseLog } from './get_response_log'; + +jest.mock('./get_payload_size', () => ({ + getResponsePayloadBytes: jest.fn().mockReturnValue(1234), +})); + +import { getResponsePayloadBytes } from './get_payload_size'; + +interface RequestFixtureOptions { + auth?: Record; + body?: Record; + headers?: Record; + info?: Record; + method?: string; + mime?: string; + path?: string; + query?: Record; + response?: Record | Boom.Boom; +} + +function createMockHapiRequest({ + auth = { isAuthenticated: true }, + body = {}, + headers = { 'user-agent': '' }, + info = { referrer: 'localhost:5601/app/home' }, + method = 'get', + mime = 'application/json', + path = '/path', + query = {}, + response = { headers: {}, statusCode: 200 }, +}: RequestFixtureOptions = {}): Request { + return ({ + auth, + body, + headers, + info, + method, + mime, + path, + query, + response, + } as unknown) as Request; +} + +describe('getEcsResponseLog', () => { + let logger: MockedLogger; + + beforeEach(() => { + logger = loggerMock.create(); + jest.clearAllMocks(); + }); + + test('provides correctly formatted message', () => { + const req = createMockHapiRequest({ + info: { + completed: 1610660232000, + received: 1610660231000, + }, + }); + const result = getEcsResponseLog(req, logger); + expect(result.message).toMatchInlineSnapshot(`"GET /path 200 1000ms - 1.2KB"`); + }); + + describe('calculates responseTime', () => { + test('with response.info.completed', () => { + const req = createMockHapiRequest({ + info: { + completed: 1610660232000, + received: 1610660231000, + }, + }); + const result = getEcsResponseLog(req, logger); + expect(result.http.response.responseTime).toBe(1000); + }); + + test('with response.info.responded', () => { + const req = createMockHapiRequest({ + info: { + responded: 1610660233500, + received: 1610660233000, + }, + }); + const result = getEcsResponseLog(req, logger); + expect(result.http.response.responseTime).toBe(500); + }); + + test('excludes responseTime from message if none is provided', () => { + const req = createMockHapiRequest(); + const result = getEcsResponseLog(req, logger); + expect(result.message).toMatchInlineSnapshot(`"GET /path 200 - 1.2KB"`); + expect(result.http.response.responseTime).toBeUndefined(); + }); + }); + + describe('handles request querystring', () => { + test('correctly formats querystring', () => { + const req = createMockHapiRequest({ + query: { + a: 'hello', + b: 'world', + }, + }); + const result = getEcsResponseLog(req, logger); + expect(result.url.query).toMatchInlineSnapshot(`"a=hello&b=world"`); + expect(result.message).toMatchInlineSnapshot(`"GET /path?a=hello&b=world 200 - 1.2KB"`); + }); + + test('correctly encodes querystring', () => { + const req = createMockHapiRequest({ + query: { a: '¡hola!' }, + }); + const result = getEcsResponseLog(req, logger); + expect(result.url.query).toMatchInlineSnapshot(`"a=%C2%A1hola!"`); + expect(result.message).toMatchInlineSnapshot(`"GET /path?a=%C2%A1hola! 200 - 1.2KB"`); + }); + }); + + test('calls getResponsePayloadBytes to calculate payload bytes', () => { + const response = { headers: {}, source: '...' }; + const req = createMockHapiRequest({ response }); + getEcsResponseLog(req, logger); + expect(getResponsePayloadBytes).toHaveBeenCalledWith(response, logger); + }); + + test('excludes payload bytes from message if unavailable', () => { + (getResponsePayloadBytes as jest.Mock).mockReturnValueOnce(undefined); + const req = createMockHapiRequest(); + const result = getEcsResponseLog(req, logger); + expect(result.message).toMatchInlineSnapshot(`"GET /path 200"`); + }); + + test('handles Boom errors in the response', () => { + const req = createMockHapiRequest({ + response: Boom.badRequest(), + }); + const result = getEcsResponseLog(req, logger); + expect(result.http.response.status_code).toBe(400); + }); + + describe('filters sensitive headers', () => { + test('redacts Authorization and Cookie headers by default', () => { + const req = createMockHapiRequest({ + headers: { authorization: 'a', cookie: 'b', 'user-agent': 'hi' }, + response: { headers: { 'content-length': 123, 'set-cookie': 'c' } }, + }); + const result = getEcsResponseLog(req, logger); + expect(result.http.request.headers).toMatchInlineSnapshot(` + Object { + "authorization": "[REDACTED]", + "cookie": "[REDACTED]", + "user-agent": "hi", + } + `); + expect(result.http.response.headers).toMatchInlineSnapshot(` + Object { + "content-length": 123, + "set-cookie": "[REDACTED]", + } + `); + }); + + test('does not mutate original headers', () => { + const reqHeaders = { authorization: 'a', cookie: 'b', 'user-agent': 'hi' }; + const resHeaders = { headers: { 'content-length': 123, 'set-cookie': 'c' } }; + const req = createMockHapiRequest({ + headers: reqHeaders, + response: { headers: resHeaders }, + }); + getEcsResponseLog(req, logger); + expect(reqHeaders).toMatchInlineSnapshot(` + Object { + "authorization": "a", + "cookie": "b", + "user-agent": "hi", + } + `); + expect(resHeaders).toMatchInlineSnapshot(` + Object { + "headers": Object { + "content-length": 123, + "set-cookie": "c", + }, + } + `); + }); + }); + + describe('ecs', () => { + test('specifies correct ECS version', () => { + const req = createMockHapiRequest(); + const result = getEcsResponseLog(req, logger); + expect(result.ecs.version).toBe('1.7.0'); + }); + + test('provides an ECS-compatible response', () => { + const req = createMockHapiRequest(); + const result = getEcsResponseLog(req, logger); + expect(result).toMatchInlineSnapshot(` + Object { + "client": Object { + "ip": undefined, + }, + "ecs": Object { + "version": "1.7.0", + }, + "http": Object { + "request": Object { + "headers": Object { + "user-agent": "", + }, + "method": "GET", + "mime_type": "application/json", + "referrer": "localhost:5601/app/home", + }, + "response": Object { + "body": Object { + "bytes": 1234, + }, + "headers": Object {}, + "responseTime": undefined, + "status_code": 200, + }, + }, + "message": "GET /path 200 - 1.2KB", + "url": Object { + "path": "/path", + "query": "", + }, + "user_agent": Object { + "original": "", + }, + } + `); + }); + }); +}); diff --git a/src/core/server/http/logging/get_response_log.ts b/src/core/server/http/logging/get_response_log.ts new file mode 100644 index 00000000000000..f75acde93bf405 --- /dev/null +++ b/src/core/server/http/logging/get_response_log.ts @@ -0,0 +1,92 @@ +/* + * 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 querystring from 'querystring'; +import { isBoom } from '@hapi/boom'; +import type { Request } from '@hapi/hapi'; +import numeral from '@elastic/numeral'; +import { LogMeta } from '@kbn/logging'; +import { EcsEvent, Logger } from '../../logging'; +import { getResponsePayloadBytes } from './get_payload_size'; + +const ECS_VERSION = '1.7.0'; +const FORBIDDEN_HEADERS = ['authorization', 'cookie', 'set-cookie']; +const REDACTED_HEADER_TEXT = '[REDACTED]'; + +// We are excluding sensitive headers by default, until we have a log filtering mechanism. +function redactSensitiveHeaders( + headers?: Record +): Record { + const result = {} as Record; + if (headers) { + for (const key of Object.keys(headers)) { + result[key] = FORBIDDEN_HEADERS.includes(key) ? REDACTED_HEADER_TEXT : headers[key]; + } + } + return result; +} + +/** + * Converts a hapi `Request` into ECS-compliant `LogMeta` for logging. + * + * @internal + */ +export function getEcsResponseLog(request: Request, log: Logger): LogMeta { + const { path, response } = request; + const method = request.method.toUpperCase(); + + const query = querystring.stringify(request.query); + const pathWithQuery = query.length > 0 ? `${path}?${query}` : path; + + // eslint-disable-next-line @typescript-eslint/naming-convention + const status_code = isBoom(response) ? response.output.statusCode : response.statusCode; + const responseHeaders = isBoom(response) ? response.output.headers : response.headers; + + // borrowed from the hapi/good implementation + const responseTime = (request.info.completed || request.info.responded) - request.info.received; + const responseTimeMsg = !isNaN(responseTime) ? ` ${responseTime}ms` : ''; + + const bytes = getResponsePayloadBytes(response, log); + const bytesMsg = bytes ? ` - ${numeral(bytes).format('0.0b')}` : ''; + + const meta: EcsEvent = { + ecs: { version: ECS_VERSION }, + message: `${method} ${pathWithQuery} ${status_code}${responseTimeMsg}${bytesMsg}`, + client: { + ip: request.info.remoteAddress, + }, + http: { + request: { + method, + mime_type: request.mime, + referrer: request.info.referrer, + // @ts-expect-error Headers are not yet part of ECS: https://github.com/elastic/ecs/issues/232. + headers: redactSensitiveHeaders(request.headers), + }, + response: { + body: { + bytes, + }, + status_code, + // @ts-expect-error Headers are not yet part of ECS: https://github.com/elastic/ecs/issues/232. + headers: redactSensitiveHeaders(responseHeaders), + // responseTime is a custom non-ECS field + responseTime: !isNaN(responseTime) ? responseTime : undefined, + }, + }, + url: { + path, + query, + }, + user_agent: { + original: request.headers['user-agent'], + }, + }; + + return meta; +} diff --git a/src/core/server/http/logging/index.ts b/src/core/server/http/logging/index.ts new file mode 100644 index 00000000000000..1ce7c37a64c858 --- /dev/null +++ b/src/core/server/http/logging/index.ts @@ -0,0 +1,9 @@ +/* + * 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. + */ + +export { getEcsResponseLog } from './get_response_log'; diff --git a/src/core/server/logging/README.md b/src/core/server/logging/README.md index cc2b6230d2d332..b0759defb88039 100644 --- a/src/core/server/logging/README.md +++ b/src/core/server/logging/README.md @@ -347,6 +347,8 @@ logging.root.level: off ``` ### Dedicated loggers +**Metrics Logs** + The `metrics.ops` logger is configured with `debug` level and will automatically output sample system and process information at a regular interval. The metrics that are logged are a subset of the data collected and are formatted in the log message as follows: @@ -364,6 +366,28 @@ ops.interval: 5000 ``` The minimum interval is 100ms and defaults to 5000ms. + +**Request and Response Logs** + +The `http.server.response` logger is configured with `debug` level and will automatically output +data about http requests and responses occurring on the Kibana server. +The message contains some high-level information, and the corresponding log meta contains the following: + +| Meta property | Description | Format +| :------------------------- | :-------------------------- | :-------------------------- | +| client.ip | IP address of the requesting client | ip | +| http.request.method | http verb for the request (uppercase) | string | +| http.request.mime_type | (optional) mime as specified in the headers | string | +| http.request.referrer | (optional) referrer | string | +| http.request.headers | request headers | object | +| http.response.body.bytes | (optional) Calculated response payload size in bytes | number | +| http.response.status_code | status code returned | number | +| http.response.headers | response headers | object | +| http.response.responseTime | (optional) Calculated response time in ms | number | +| url.path | request path | string | +| url.query | (optional) request query string | string | +| user_agent.original | raw user-agent string provided in request headers | string | + ## Usage Usage is very straightforward, one should just get a logger for a specific context and use it to log messages with @@ -479,6 +503,26 @@ logging: #### logging.events Define a custom logger for a specific context. +**`logging.events.ops`** outputs sample system and process information at a regular interval. +With the new logging config, these are provided by a dedicated [context](#logger-hierarchy), +and you can enable them by adjusting the minimum required [logging level](#log-level) to `debug`: +```yaml + loggers: + - context: metrics.ops + appenders: [console] + level: debug +``` + +**`logging.events.request` and `logging.events.response`** provide logs for each request handled +by the http service. With the new logging config, these are provided by a dedicated [context](#logger-hierarchy), +and you can enable them by adjusting the minimum required [logging level](#log-level) to `debug`: +```yaml + loggers: + - context: http.server.response + appenders: [console] + level: debug +``` + #### logging.filter TBD diff --git a/src/core/server/logging/ecs.ts b/src/core/server/logging/ecs.ts index cdb548abedcca5..f6db79819d819c 100644 --- a/src/core/server/logging/ecs.ts +++ b/src/core/server/logging/ecs.ts @@ -14,8 +14,7 @@ * * @internal */ - -export interface EcsOpsMetricsEvent { +export interface EcsEvent { /** * These typings were written as of ECS 1.7.0. * Don't change this value without checking the rest @@ -30,21 +29,17 @@ export interface EcsOpsMetricsEvent { labels?: Record; message?: string; tags?: string[]; + // other fields - process?: EcsProcessField; + client?: EcsClientField; event?: EcsEventField; + http?: EcsHttpField; + process?: EcsProcessField; + url?: EcsUrlField; + user_agent?: EcsUserAgentField; } -interface EcsProcessField { - uptime?: number; -} - -export interface EcsEventField { - kind?: EcsEventKind; - category?: EcsEventCategory[]; - type?: EcsEventType; -} - +/** @internal */ export enum EcsEventKind { ALERT = 'alert', EVENT = 'event', @@ -54,6 +49,7 @@ export enum EcsEventKind { SIGNAL = 'signal', } +/** @internal */ export enum EcsEventCategory { AUTHENTICATION = 'authentication', CONFIGURATION = 'configuration', @@ -70,6 +66,7 @@ export enum EcsEventCategory { WEB = 'web', } +/** @internal */ export enum EcsEventType { ACCESS = 'access', ADMIN = 'admin', @@ -88,3 +85,45 @@ export enum EcsEventType { START = 'start', USER = 'user', } + +interface EcsEventField { + kind?: EcsEventKind; + category?: EcsEventCategory[]; + type?: EcsEventType; +} + +interface EcsProcessField { + uptime?: number; +} + +interface EcsClientField { + ip?: string; +} + +interface EcsHttpFieldRequest { + body?: { bytes?: number; content?: string }; + method?: string; + mime_type?: string; + referrer?: string; +} + +interface EcsHttpFieldResponse { + body?: { bytes?: number; content?: string }; + bytes?: number; + status_code?: number; +} + +interface EcsHttpField { + version?: string; + request?: EcsHttpFieldRequest; + response?: EcsHttpFieldResponse; +} + +interface EcsUrlField { + path?: string; + query?: string; +} + +interface EcsUserAgentField { + original?: string; +} diff --git a/src/core/server/logging/index.ts b/src/core/server/logging/index.ts index f565d3db1407e5..9b3d7747fc5601 100644 --- a/src/core/server/logging/index.ts +++ b/src/core/server/logging/index.ts @@ -17,13 +17,7 @@ export { LogLevelId, LogLevel, } from '@kbn/logging'; -export { - EcsOpsMetricsEvent, - EcsEventField, - EcsEventKind, - EcsEventCategory, - EcsEventType, -} from './ecs'; +export { EcsEvent, EcsEventKind, EcsEventCategory, EcsEventType } from './ecs'; export { config, LoggingConfigType, diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts index 723fc50bd8392e..02c3ad312c7dd2 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -7,7 +7,7 @@ */ import numeral from '@elastic/numeral'; -import { EcsOpsMetricsEvent, EcsEventKind, EcsEventCategory, EcsEventType } from '../../logging'; +import { EcsEvent, EcsEventKind, EcsEventCategory, EcsEventType } from '../../logging'; import { OpsMetrics } from '..'; const ECS_VERSION = '1.7.0'; @@ -16,7 +16,7 @@ const ECS_VERSION = '1.7.0'; * * @internal */ -export function getEcsOpsMetricsLog(metrics: OpsMetrics): EcsOpsMetricsEvent { +export function getEcsOpsMetricsLog(metrics: OpsMetrics): EcsEvent { const { process, os } = metrics; const processMemoryUsedInBytes = process?.memory?.heap?.used_in_bytes; const processMemoryUsedInBytesMsg = processMemoryUsedInBytes