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

Add truncation to all serializers #143

Merged
merged 8 commits into from
Jul 28, 2024
Merged
Show file tree
Hide file tree
Changes from 7 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
5 changes: 5 additions & 0 deletions .changeset/smooth-ties-look.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
---
'@seek/logger': major
---

Adds trimming to log fields with dedicated serializers
zbrydon marked this conversation as resolved.
Show resolved Hide resolved
4 changes: 3 additions & 1 deletion src/formatters/index.ts
Original file line number Diff line number Diff line change
@@ -1,6 +1,8 @@
import { trimmer } from 'dtrim';
import type { LoggerOptions } from 'pino';

export const DEFAULT_MAX_OBJECT_DEPTH = 4;
Copy link
Contributor Author

@zbrydon zbrydon Jul 17, 2024

Choose a reason for hiding this comment

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

Looking for suggestions on this default value, given this potential usecase.


export interface FormatterOptions {
/**
* Maximum property depth of objects being logged. Default: 4
Expand All @@ -17,7 +19,7 @@ export const createFormatters = (
opts: FormatterOptions & Required<Pick<LoggerOptions, 'serializers'>>,
): LoggerOptions['formatters'] => {
const trim = trimmer({
depth: opts.maxObjectDepth ?? 4,
depth: opts.maxObjectDepth ?? DEFAULT_MAX_OBJECT_DEPTH,
retain: new Set(Object.keys(opts.serializers)),
});

Expand Down
113 changes: 60 additions & 53 deletions src/index.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -441,10 +441,7 @@ testLog(
request: {
_options: {
method: 'get',
headers: {
Accept: 'application/json, text/plain, */*',
authorization: '[Redacted]',
},
Comment on lines -444 to -447
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This is now truncated as a result of fixing the max object depth.

Copy link
Member

Choose a reason for hiding this comment

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

Random stream of consciousness thought, do we know if the trimming impacts a potentially deep err.stack trace? Perhaps we could pull some (non-sensitive) ones out of Splunk and have a test case around it? The stack trace tends to be the highest value field in an error log, so retaining a long stack may be a safer default.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I've excluded the stack field from being trimmed, though the sharing of a trimmer between serializers means that its not just the top level fields of err and errWithCause that are affected by this exclusion.

Copy link
Member

Choose a reason for hiding this comment

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

I was poking around with this, do you have thoughts on 7b1f2a1?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Sure do that's way cleaner I like it!!
Cleaned up and condensed all the bits of spread out logic that I implemented and didn't like 😆 🙏

Copy link
Member

Choose a reason for hiding this comment

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

Thanks for the change, refactoring is the easy part 😉

headers: '[Object]',
},
domain: null,
},
Expand Down Expand Up @@ -632,48 +629,36 @@ test('should log customized timestamp if timestamp logger option is supplied', a
expect(log.timestamp).toBe(mockTimestamp);
});

class Req {
get socket() {
return {
remoteAddress: 'localhost',
remotePort: '4000',
};
}
}
testLog(
'should not truncate objects with a non error serializer',
'should trim default serializers',
{
req: new Req(),
notSerialized: {
errWithCause: {
a: {
b: {},
},
anyField: 'a'.repeat(555),
stack: 'a'.repeat(555),
},
},
{
req: {
remoteAddress: 'localhost',
remotePort: '4000',
},
notSerialized: {
a: '[Object]',
},
},
'info',
{
maxObjectDepth: 2,
},
);

testLog(
'should truncate objects with error serializers',
{
errWithCause: {
err: {
a: {
b: {},
},
anyField: 'a'.repeat(555),
stack: 'a'.repeat(555),
},
err: {
req: {
method: 'GET',
url: 'a'.repeat(555),
headers: [],
socket: { remoteAddress: 'localhost', remotePort: '4000' },
},
res: {
headers: { Origin: 'a'.repeat(555) },
status: 500,
foo: 'baz',
},
headers: {
'test-header': 'a'.repeat(555),
a: {
b: {},
},
Expand All @@ -684,44 +669,66 @@ testLog(
a: {
b: '[Object]',
},
anyField: `${'a'.repeat(512)}...`,
stack: 'a'.repeat(555),
},
err: {
a: {
b: '[Object]',
},
anyField: `${'a'.repeat(512)}...`,
stack: 'a'.repeat(555),
},
req: {
method: 'GET',
url: `${'a'.repeat(512)}...`,
headers: [],
remoteAddress: 'localhost',
remotePort: '4000',
},
res: {
headers: { Origin: `${'a'.repeat(512)}...` },
statusCode: 500,
},
headers: {
'test-header': `${'a'.repeat(512)}...`,
a: {
b: '[Object]',
},
},
},
'info',
{
maxObjectDepth: 2,
maxObjectDepth: 3,
},
);

testLog(
'should truncate strings longer than 512 characters with error serializers',
'should trim custom serializer',
{
err: {
anyField: {
anyField: 'a'.repeat(555),
},
},
errWithCause: {
anyField: {
anyField: 'a'.repeat(555),
serialize: {
a: {
b: {
c: {},
},
},
anyField: 'a'.repeat(555),
},
},
{
err: {
anyField: {
anyField: `${'a'.repeat(512)}...`,
serialize: {
a: {
b: '[Object]',
},
anyField: `${'a'.repeat(512)}...`,
},
errWithCause: {
anyField: {
anyField: `${'a'.repeat(512)}...`,
},
},
'info',
{
serializers: {
serialize: (input: unknown) => input,
},
maxObjectDepth: 3,
},
);

Expand Down
5 changes: 1 addition & 4 deletions src/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -29,10 +29,7 @@ export default (
): Logger => {
opts.redact = redact.addDefaultRedactPathStrings(opts.redact);

const serializers = {
...createSerializers(opts),
...opts.serializers,
};
const serializers = createSerializers(opts);

opts.serializers = serializers;

Expand Down
74 changes: 52 additions & 22 deletions src/serializers/index.ts
Original file line number Diff line number Diff line change
@@ -1,11 +1,11 @@
import { trimmer } from 'dtrim';
import type pino from 'pino';
import { type SerializedError, err, errWithCause } from 'pino-std-serializers';
import type { pino } from 'pino';
import { err, errWithCause } from 'pino-std-serializers';

import type { FormatterOptions } from '../formatters';
import { DEFAULT_MAX_OBJECT_DEPTH } from '../formatters';

import { createOmitPropertiesSerializer } from './omitPropertiesSerializer';
import type { SerializerFn } from './types';
import type { SerializerFn, TrimmerFn } from './types';

export const DEFAULT_OMIT_HEADER_NAMES = Object.freeze([
'x-envoy-attempt-count',
Expand All @@ -32,6 +32,10 @@ export interface SerializerOptions {
* and can be disabled by supplying an empty array `[]`.
*/
omitHeaderNames?: readonly string[];

maxObjectDepth?: number;

serializers?: pino.LoggerOptions['serializers'];
}

interface Socket {
Expand Down Expand Up @@ -80,30 +84,56 @@ const res = (response: Response) =>
}
: response;

const createErrSerializer =
(
serializer: (error: Error) => SerializedError,
opts: FormatterOptions,
): SerializerFn =>
(error: unknown): unknown =>
trimmer({
depth: opts.maxObjectDepth ?? 4,
})(serializer(error as Error));

export const createSerializers = (
opts: SerializerOptions & FormatterOptions,
) => {
export const trimSerializerOutput =
(serializer: SerializerFn, trim: TrimmerFn): SerializerFn =>
(input) =>
trim(serializer(input));

export const createSerializers = (opts: SerializerOptions) => {
const serializeHeaders = createOmitPropertiesSerializer(
opts.omitHeaderNames ?? DEFAULT_OMIT_HEADER_NAMES,
);

// We are trimming inside one level of property nesting.
const depth = Math.max(
0,
(opts.maxObjectDepth ?? DEFAULT_MAX_OBJECT_DEPTH) - 1,
);

const errSerializers = trimSerializers(
{
err,
errWithCause,
},
// Retain long stack traces for troubleshooting purposes.
trimmer({ depth, retain: new Set(['stack']) }),
);

const restSerializers = trimSerializers(
{
req: createReqSerializer(serializeHeaders),
res,
headers: serializeHeaders,
...opts.serializers,
},
trimmer({ depth }),
);

const serializers = {
err: createErrSerializer(err, opts),
errWithCause: createErrSerializer(errWithCause, opts),
req: createReqSerializer(serializeHeaders),
res,
headers: serializeHeaders,
...errSerializers,
...restSerializers,
} satisfies pino.LoggerOptions['serializers'];

return serializers;
};

const trimSerializers = <T extends string>(
serializers: Record<T, SerializerFn>,
trim: TrimmerFn,
) =>
Object.fromEntries(
Object.entries<SerializerFn>(serializers).map(
([property, serializer]) =>
[property, trimSerializerOutput(serializer, trim)] as const,
),
) as Record<T, SerializerFn>;
2 changes: 1 addition & 1 deletion src/serializers/omitPropertiesSerializer.ts
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,7 @@ export const createOmitPropertiesSerializer = (
const uniquePropertySet = new Set(properties);

if (uniquePropertySet.size === 0) {
return (input) => input;
return (input): unknown => input;
}

const uniqueProperties = Array.from(uniquePropertySet);
Expand Down
4 changes: 3 additions & 1 deletion src/serializers/types.ts
Original file line number Diff line number Diff line change
@@ -1 +1,3 @@
export type SerializerFn = (input: unknown) => unknown;
export type TrimmerFn = (input: unknown) => unknown;
// eslint-disable-next-line @typescript-eslint/no-explicit-any
export type SerializerFn = (input: any) => unknown;