Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[core.logging] Add response logs to the KP logging system. #87939

Merged
merged 19 commits into from
Feb 4, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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.
lukeelmers marked this conversation as resolved.
Show resolved Hide resolved

[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'],
lukeelmers marked this conversation as resolved.
Show resolved Hide resolved
},
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 () => {
lukeelmers marked this conversation as resolved.
Show resolved Hide resolved
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.
lukeelmers marked this conversation as resolved.
Show resolved Hide resolved
*
* @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