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 RewriteAppender for filtering LogMeta. #91492

Merged
merged 29 commits into from
Feb 24, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
29 commits
Select commit Hold shift + click to select a range
752bdf1
Add RewriteAppender with a 'meta' rewrite policy.
lukeelmers Feb 16, 2021
71e46ce
Add unit tests.
lukeelmers Feb 16, 2021
e1c6402
Filter sensitive headers using rewrite appender.
lukeelmers Feb 17, 2021
ae5facc
Update generated docs.
lukeelmers Feb 17, 2021
03a0397
Rename policy.transform to policy.rewrite for consistency with log4j.
lukeelmers Feb 17, 2021
61d4450
Address initial feedback.
lukeelmers Feb 18, 2021
0dc0afc
Switch from appenders.update to appenders.addAppender to align with l…
lukeelmers Feb 18, 2021
44d1440
Fix missed transform > rewrite rename.
lukeelmers Feb 18, 2021
524cc31
Shallow clone http request/response headers.
lukeelmers Feb 18, 2021
c72c75b
Test for circular refs between appenders.
lukeelmers Feb 19, 2021
7cbe347
Update README with documentation.
lukeelmers Feb 19, 2021
e9b9bcc
Merge branch 'master' into feat/rewrite-appender
kibanamachine Feb 19, 2021
8fb040e
Take Appender inside addAppender
lukeelmers Feb 19, 2021
88397a5
Clean up policy comments
lukeelmers Feb 19, 2021
a6632ee
Update snapshots
lukeelmers Feb 19, 2021
eabb888
Merge branch 'master' into feat/rewrite-appender
kibanamachine Feb 21, 2021
0516db3
Re-add hardcoded headers filtering to http logs.
lukeelmers Feb 21, 2021
c777305
Use fixed timestamp in meta policy tests.
lukeelmers Feb 21, 2021
e0f4c58
Clean up documentation.
lukeelmers Feb 21, 2021
11b5512
Prevent mutating array headers.
lukeelmers Feb 22, 2021
b46e404
Extract inline types from MetaRewritePolicy.
lukeelmers Feb 22, 2021
f6ae2ea
Clean up unknown appender error message.
lukeelmers Feb 22, 2021
353d8e5
Resolve merge conflicts.
lukeelmers Feb 22, 2021
dcee4b9
Merge branch 'master' into feat/rewrite-appender
lukeelmers Feb 22, 2021
f9f28dd
Remove MetaRewritePolicy 'add' mode.
lukeelmers Feb 23, 2021
3d2a945
Remove default rewrite-appender.
lukeelmers Feb 23, 2021
102d490
Merge branch 'master' into feat/rewrite-appender
kibanamachine Feb 23, 2021
aa5d21e
Merge branch 'master' into feat/rewrite-appender
kibanamachine Feb 24, 2021
fb23cb1
Fix logging system jest tests.
lukeelmers Feb 24, 2021
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
Original file line number Diff line number Diff line change
Expand Up @@ -8,5 +8,5 @@
<b>Signature:</b>

```typescript
export declare type AppenderConfigType = ConsoleAppenderConfig | FileAppenderConfig | LegacyAppenderConfig | RollingFileAppenderConfig;
export declare type AppenderConfigType = ConsoleAppenderConfig | FileAppenderConfig | LegacyAppenderConfig | RewriteAppenderConfig | RollingFileAppenderConfig;
```
18 changes: 18 additions & 0 deletions packages/kbn-logging/src/appenders.ts
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,24 @@ import { LogRecord } from './log_record';
*/
export interface Appender {
append(record: LogRecord): void;
/**
* Appenders can be "attached" to one another so that they are able to act
* as a sort of middleware by calling `append` on a different appender.
*
* As appenders cannot be attached to each other until they are configured,
* the `addAppender` method can be used to pass in a newly configured appender
* to attach.
*/
addAppender?(appenderRef: string, appender: Appender): void;
/**
* For appenders which implement `addAppender`, they should declare a list of
* `appenderRefs`, which specify the names of the appenders that their configuration
* depends on.
*
* Note that these are the appender key names that the user specifies in their
* config, _not_ the names of the appender types themselves.
*/
appenderRefs?: string[];
}

/**
Expand Down
136 changes: 134 additions & 2 deletions src/core/server/http/integration_tests/logging.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -251,7 +251,7 @@ describe('request logging', () => {
expect(JSON.parse(meta).http.response.headers.bar).toBe('world');
});

it('filters sensitive request headers', async () => {
it('filters sensitive request headers by default', async () => {
const { http } = await root.setup();

http.createRouter('/').post(
Expand Down Expand Up @@ -283,7 +283,139 @@ describe('request logging', () => {
expect(JSON.parse(meta).http.request.headers.authorization).toBe('[REDACTED]');
});

it('filters sensitive response headers', async () => {
it('filters sensitive request headers when RewriteAppender is configured', async () => {
root = kbnTestServer.createRoot({
logging: {
silent: true,
appenders: {
'test-console': {
type: 'console',
layout: {
type: 'pattern',
pattern: '%level|%logger|%message|%meta',
},
},
rewrite: {
type: 'rewrite',
appenders: ['test-console'],
policy: {
type: 'meta',
mode: 'update',
properties: [
{ path: 'http.request.headers.authorization', value: '[REDACTED]' },
],
},
},
},
loggers: [
{
name: 'http.server.response',
appenders: ['rewrite'],
level: 'debug',
},
],
},
plugins: {
initialize: false,
},
});
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 by defaut', 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('filters sensitive response headers when RewriteAppender is configured', async () => {
root = kbnTestServer.createRoot({
logging: {
silent: true,
appenders: {
'test-console': {
type: 'console',
layout: {
type: 'pattern',
pattern: '%level|%logger|%message|%meta',
},
},
rewrite: {
type: 'rewrite',
appenders: ['test-console'],
policy: {
type: 'meta',
mode: 'update',
properties: [{ path: 'http.response.headers.set-cookie', value: '[REDACTED]' }],
},
},
},
loggers: [
{
name: 'http.server.response',
appenders: ['rewrite'],
level: 'debug',
},
],
},
plugins: {
initialize: false,
},
});
const { http } = await root.setup();

http.createRouter('/').post(
Expand Down
47 changes: 47 additions & 0 deletions src/core/server/http/logging/get_response_log.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -171,6 +171,53 @@ describe('getEcsResponseLog', () => {
});

test('does not mutate original headers', () => {
const reqHeaders = { a: 'foo', b: ['hello', 'world'] };
const resHeaders = { headers: { c: 'bar' } };
const req = createMockHapiRequest({
headers: reqHeaders,
response: { headers: resHeaders },
});

const responseLog = getEcsResponseLog(req, logger);
expect(reqHeaders).toMatchInlineSnapshot(`
Object {
"a": "foo",
"b": Array [
"hello",
"world",
],
}
`);
expect(resHeaders).toMatchInlineSnapshot(`
Object {
"headers": Object {
"c": "bar",
},
}
`);

responseLog.http.request.headers.a = 'testA';
responseLog.http.request.headers.b[1] = 'testB';
responseLog.http.request.headers.c = 'testC';
expect(reqHeaders).toMatchInlineSnapshot(`
Object {
"a": "foo",
"b": Array [
"hello",
"world",
],
}
`);
expect(resHeaders).toMatchInlineSnapshot(`
Object {
"headers": Object {
"c": "bar",
},
}
`);
});

test('does not mutate original headers when redacting sensitive data', () => {
const reqHeaders = { authorization: 'a', cookie: 'b', 'user-agent': 'hi' };
const resHeaders = { headers: { 'content-length': 123, 'set-cookie': 'c' } };
const req = createMockHapiRequest({
Expand Down
28 changes: 20 additions & 8 deletions src/core/server/http/logging/get_response_log.ts
Original file line number Diff line number Diff line change
Expand Up @@ -18,14 +18,22 @@ const ECS_VERSION = '1.7.0';
const FORBIDDEN_HEADERS = ['authorization', 'cookie', 'set-cookie'];
const REDACTED_HEADER_TEXT = '[REDACTED]';

type HapiHeaders = Record<string, string | string[]>;

// We are excluding sensitive headers by default, until we have a log filtering mechanism.
function redactSensitiveHeaders(
headers?: Record<string, string | string[]>
): Record<string, string | string[]> {
const result = {} as Record<string, string | string[]>;
function redactSensitiveHeaders(key: string, value: string | string[]): string | string[] {
return FORBIDDEN_HEADERS.includes(key) ? REDACTED_HEADER_TEXT : value;
}

// Shallow clone the headers so they are not mutated if filtered by a RewriteAppender.
function cloneAndFilterHeaders(headers?: HapiHeaders) {
const result = {} as HapiHeaders;
if (headers) {
for (const key of Object.keys(headers)) {
result[key] = FORBIDDEN_HEADERS.includes(key) ? REDACTED_HEADER_TEXT : headers[key];
result[key] = redactSensitiveHeaders(
key,
Array.isArray(headers[key]) ? [...headers[key]] : headers[key]
Copy link
Contributor

@mshustov mshustov Feb 23, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

optional: It's good we enforce immutability, but we pay the extra cost when cloning the array. IMO we can assume that no-one mutates the array.

);
}
}
return result;
Expand All @@ -45,7 +53,11 @@ export function getEcsResponseLog(request: Request, log: Logger): LogMeta {

// 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;

const requestHeaders = cloneAndFilterHeaders(request.headers);
const responseHeaders = cloneAndFilterHeaders(
isBoom(response) ? (response.output.headers as HapiHeaders) : response.headers
);

// borrowed from the hapi/good implementation
const responseTime = (request.info.completed || request.info.responded) - request.info.received;
Expand All @@ -66,15 +78,15 @@ export function getEcsResponseLog(request: Request, log: Logger): LogMeta {
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),
headers: requestHeaders,
},
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),
headers: responseHeaders,
// responseTime is a custom non-ECS field
responseTime: !isNaN(responseTime) ? responseTime : undefined,
},
Expand Down
Loading