Skip to content

Commit

Permalink
[core.logging] Add response logs to the KP logging system. (#87939)
Browse files Browse the repository at this point in the history
  • Loading branch information
lukeelmers authored Feb 4, 2021
1 parent 1818dd7 commit 72670eb
Show file tree
Hide file tree
Showing 21 changed files with 1,393 additions and 67 deletions.
11 changes: 10 additions & 1 deletion docs/migration/migrate_8_0.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,16 @@ for example, `logstash-*`.
==== Responses are never logged by default
*Details:* Previously responses would be logged if either `logging.json` was true, `logging.dest` was specified, or a `TTY` was detected.

*Impact:* To restore the previous behavior, in kibana.yml set `logging.events.response=*`.
*Impact:* To restore the previous behavior, in kibana.yml enable `debug` logs for the `http.server.response` context under `logging.loggers`:
[source,yaml]
-------------------
logging:
loggers:
- context: http.server.response
appenders: [console]
level: debug
-------------------
See https://github.com/elastic/kibana/pull/87939 for more details.

[float]
==== `xpack.security.authProviders` is no longer valid
Expand Down
13 changes: 7 additions & 6 deletions packages/kbn-legacy-logging/src/get_logging_config.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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, {
Expand Down Expand Up @@ -75,6 +75,7 @@ export function getLoggingConfiguration(config: LegacyLoggingConfig, opsInterval
},
includes: {
request: ['headers', 'payload'],
response: ['headers', 'payload'],
},
reporters: {
logReporter: [loggerStream],
Expand Down
4 changes: 3 additions & 1 deletion packages/kbn-legacy-logging/src/log_events.ts
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
* Side Public License, v 1.
*/

import type { ResponseObject } from '@hapi/hapi';
import { EventData, isEventData } from './metadata';

export interface BaseEvent {
Expand All @@ -21,7 +22,8 @@ export interface ResponseEvent extends BaseEvent {
statusCode: number;
path: string;
headers: Record<string, string | string[]>;
responsePayload: string;
responseHeaders: Record<string, string | string[]>;
responsePayload: ResponseObject['source'];
responseTime: string;
query: Record<string, any>;
}
Expand Down
33 changes: 23 additions & 10 deletions packages/kbn-legacy-logging/src/log_format.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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<string, any>, format?: string) {
const { timezone } = this.config;
const date = moment(data['@timestamp']);
Expand Down Expand Up @@ -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 });
Expand All @@ -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: ');
Expand Down
63 changes: 39 additions & 24 deletions packages/kbn-legacy-logging/src/log_format_json.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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<string>([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<string>([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<string>([createListStream([event]), format]);
expect(JSON.parse(result).message).toBe('GET /path/to/resource 200 12000ms');
});
});

it('ops', async () => {
Expand Down
101 changes: 101 additions & 0 deletions packages/kbn-legacy-logging/src/utils/get_payload_size.test.ts
Original file line number Diff line number Diff line change
@@ -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();
});
});
64 changes: 64 additions & 0 deletions packages/kbn-legacy-logging/src/utils/get_payload_size.ts
Original file line number Diff line number Diff line change
@@ -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<string, unknown> =>
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<string, any> = {}
): 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;
}
1 change: 1 addition & 0 deletions packages/kbn-legacy-logging/src/utils/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -7,3 +7,4 @@
*/

export { applyFiltersToKeys } from './apply_filters_to_keys';
export { getResponsePayloadBytes } from './get_payload_size';
Loading

0 comments on commit 72670eb

Please sign in to comment.