Skip to content

Commit

Permalink
feat(middleware-logger): log clientName, commandName, input, output (#…
Browse files Browse the repository at this point in the history
  • Loading branch information
trivikr authored Dec 16, 2020
1 parent 04d9cf2 commit 4f9e56f
Show file tree
Hide file tree
Showing 6 changed files with 132 additions and 147 deletions.
156 changes: 101 additions & 55 deletions packages/middleware-logger/src/loggerMiddleware.spec.ts
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,16 @@ describe("loggerMiddleware", () => {
},
};

const mockOutput = {
$metadata: {
statusCode: 200,
requestId: "requestId",
attempts: 2,
totalRetryDelay: 350,
},
outputKey: "outputValue",
};

const mockResponse = {
response: {
statusCode: 200,
Expand All @@ -40,9 +50,7 @@ describe("loggerMiddleware", () => {
"x-amz-cf-id": "cfId",
},
},
output: {
outputKey: "outputValue",
},
output: mockOutput,
};

afterEach(() => {
Expand All @@ -64,61 +72,99 @@ describe("loggerMiddleware", () => {
expect(response).toStrictEqual(mockResponse);
});

it("logs metadata if context.logger has info function", async () => {
mockNext.mockResolvedValueOnce(mockResponse);
const logger = ({ info: jest.fn() } as unknown) as Logger;

const context = {
logger,
};

const response = await loggerMiddleware()(mockNext, context)(mockArgs);
expect(mockNext).toHaveBeenCalledTimes(1);
expect(response).toStrictEqual(mockResponse);

expect(logger.info).toHaveBeenCalledTimes(1);

expect(logger.info).toHaveBeenCalledWith({
metadata: {
statusCode: mockResponse.response.statusCode,
requestId: mockResponse.response.headers["x-amzn-requestid"],
extendedRequestId: mockResponse.response.headers["x-amz-id-2"],
cfId: mockResponse.response.headers["x-amz-cf-id"],
},
describe("logs if context.logger has info function", () => {
it("success case with clientName, commandName, input, metadata", async () => {
mockNext.mockResolvedValueOnce(mockResponse);

const logger = ({ info: jest.fn() } as unknown) as Logger;
const clientName = "mockClientName";
const commandName = "mockCommandName";

const mockInputLog = { inputKey: "inputKey", inputSensitiveKey: "SENSITIVE_VALUE" };
const inputFilterSensitiveLog = jest.fn().mockReturnValueOnce(mockInputLog);
const mockOutputLog = { outputKey: "outputKey", outputSensitiveKey: "SENSITIVE_VALUE" };
const outputFilterSensitiveLog = jest.fn().mockReturnValueOnce(mockOutputLog);

const context = {
logger,
clientName,
commandName,
inputFilterSensitiveLog,
outputFilterSensitiveLog,
};

const response = await loggerMiddleware()(mockNext, context)(mockArgs);
expect(mockNext).toHaveBeenCalledTimes(1);
expect(response).toStrictEqual(mockResponse);

expect(inputFilterSensitiveLog).toHaveBeenCalledTimes(1);
expect(inputFilterSensitiveLog).toHaveBeenCalledWith(mockArgs.input);

const { $metadata, ...outputWithoutMetadata } = mockOutput;
expect(outputFilterSensitiveLog).toHaveBeenCalledTimes(1);
expect(outputFilterSensitiveLog).toHaveBeenCalledWith(outputWithoutMetadata);

expect(logger.info).toHaveBeenCalledTimes(1);
expect(logger.info).toHaveBeenCalledWith({
clientName,
commandName,
input: mockInputLog,
output: mockOutputLog,
metadata: {
statusCode: mockResponse.response.statusCode,
requestId: mockResponse.response.headers["x-amzn-requestid"],
extendedRequestId: mockResponse.response.headers["x-amz-id-2"],
cfId: mockResponse.response.headers["x-amz-cf-id"],
retry: {
attempts: $metadata.attempts,
totalDelay: $metadata.totalRetryDelay,
},
},
});
});
});

it("logs header x-amzn-request-id as requestId if x-amzn-requestid is not present", async () => {
const requestIdBackup = "requestIdBackup";
const customResponse = {
...mockResponse,
response: {
...mockResponse.response,
headers: {
"x-amzn-request-id": requestIdBackup,
it("header x-amzn-request-id as requestId if x-amzn-requestid is not present", async () => {
const requestIdBackup = "requestIdBackup";
const customResponse = {
...mockResponse,
response: {
...mockResponse.response,
headers: {
"x-amzn-request-id": requestIdBackup,
},
},
},
};
mockNext.mockResolvedValueOnce(customResponse);
const logger = ({ info: jest.fn() } as unknown) as Logger;

const context = {
logger,
};

const response = await loggerMiddleware()(mockNext, context)(mockArgs);
expect(mockNext).toHaveBeenCalledTimes(1);
expect(response).toStrictEqual(customResponse);

expect(logger.info).toHaveBeenCalledTimes(1);

expect(logger.info).toHaveBeenCalledWith({
metadata: {
statusCode: customResponse.response.statusCode,
requestId: requestIdBackup,
extendedRequestId: undefined,
cfId: undefined,
},
};
mockNext.mockResolvedValueOnce(customResponse);
const logger = ({ info: jest.fn() } as unknown) as Logger;
const inputFilterSensitiveLog = jest.fn().mockImplementationOnce((input) => input);
const outputFilterSensitiveLog = jest.fn().mockImplementationOnce((output) => output);

const context = {
logger,
inputFilterSensitiveLog,
outputFilterSensitiveLog,
};

const response = await loggerMiddleware()(mockNext, context)(mockArgs);
expect(mockNext).toHaveBeenCalledTimes(1);
expect(response).toStrictEqual(customResponse);

const { $metadata, ...outputWithoutMetadata } = mockOutput;
expect(logger.info).toHaveBeenCalledTimes(1);
expect(logger.info).toHaveBeenCalledWith({
input: mockArgs.input,
output: outputWithoutMetadata,
metadata: {
statusCode: customResponse.response.statusCode,
requestId: requestIdBackup,
extendedRequestId: undefined,
cfId: undefined,
retry: {
attempts: $metadata.attempts,
totalDelay: $metadata.totalRetryDelay,
},
},
});
});
});
});
14 changes: 11 additions & 3 deletions packages/middleware-logger/src/loggerMiddleware.ts
Original file line number Diff line number Diff line change
Expand Up @@ -16,23 +16,31 @@ export const loggerMiddleware = () => <Output extends MetadataBearer = MetadataB
): InitializeHandler<any, Output> => async (
args: InitializeHandlerArguments<any>
): Promise<InitializeHandlerOutput<Output>> => {
const { logger } = context;
const { clientName, commandName, inputFilterSensitiveLog, logger, outputFilterSensitiveLog } = context;

const response = await next(args);

if (!logger) {
return response;
}

const httpResponse = response.response as HttpResponse;

if (typeof logger.info === "function") {
const httpResponse = response.response as HttpResponse;
const { $metadata, ...outputWithoutMetadata } = response.output;
logger.info({
clientName,
commandName,
input: inputFilterSensitiveLog(args.input),
output: outputFilterSensitiveLog(outputWithoutMetadata),
metadata: {
statusCode: httpResponse.statusCode,
requestId: httpResponse.headers["x-amzn-requestid"] ?? httpResponse.headers["x-amzn-request-id"],
extendedRequestId: httpResponse.headers["x-amz-id-2"],
cfId: httpResponse.headers["x-amz-cf-id"],
retry: {
attempts: $metadata.attempts,
totalDelay: $metadata.totalRetryDelay,
},
},
});
}
Expand Down
39 changes: 8 additions & 31 deletions packages/middleware-serde/src/deserializerMiddleware.spec.ts
Original file line number Diff line number Diff line change
@@ -1,5 +1,3 @@
import { Logger } from "@aws-sdk/types";

import { deserializerMiddleware } from "./deserializerMiddleware";

describe("deserializerMiddleware", () => {
Expand Down Expand Up @@ -51,38 +49,17 @@ describe("deserializerMiddleware", () => {
});

afterEach(() => {
expect(mockNext).toHaveBeenCalledTimes(1);
expect(mockNext).toHaveBeenCalledWith(mockArgs);
expect(mockDeserializer).toHaveBeenCalledTimes(1);
expect(mockDeserializer).toHaveBeenCalledWith(mockNextResponse.response, mockOptions);
jest.clearAllMocks();
});

it("returns without logging if context.logger is not defined", async () => {
const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, {})(mockArgs);
expect(response).toStrictEqual(mockResponse);
});

it("returns without logging if context.logger doesn't have debug/info function", async () => {
const logger = {} as Logger;
const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, { logger })(mockArgs);
expect(response).toStrictEqual(mockResponse);
});

it("logs output if context.logger has info function", async () => {
const logger = ({ info: jest.fn() } as unknown) as Logger;
it("calls deserializer and populates response object", async () => {
await expect(deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, {})(mockArgs)).resolves.toStrictEqual(
mockResponse
);

const outputFilterSensitiveLog = jest.fn().mockImplementationOnce((output) => output);
const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, {
logger,
outputFilterSensitiveLog: outputFilterSensitiveLog,
})(mockArgs);

const { $metadata, ...outputWithoutMetadata } = mockOutput;
expect(response).toStrictEqual(mockResponse);
expect(outputFilterSensitiveLog).toHaveBeenCalledTimes(1);
expect(outputFilterSensitiveLog).toHaveBeenCalledWith(outputWithoutMetadata);
expect(logger.info).toHaveBeenCalledTimes(1);
expect(logger.info).toHaveBeenCalledWith({ output: outputWithoutMetadata });
expect(mockNext).toHaveBeenCalledTimes(1);
expect(mockNext).toHaveBeenCalledWith(mockArgs);
expect(mockDeserializer).toHaveBeenCalledTimes(1);
expect(mockDeserializer).toHaveBeenCalledWith(mockNextResponse.response, mockOptions);
});
});
13 changes: 0 additions & 13 deletions packages/middleware-serde/src/deserializerMiddleware.ts
Original file line number Diff line number Diff line change
Expand Up @@ -16,21 +16,8 @@ export const deserializerMiddleware = <Input extends object, Output extends obje
): DeserializeHandler<Input, Output> => async (
args: DeserializeHandlerArguments<Input>
): Promise<DeserializeHandlerOutput<Output>> => {
const { logger, outputFilterSensitiveLog } = context;

const { response } = await next(args);

const parsed = await deserializer(response, options);

// Log parsed after $metadata is removed in https://github.com/aws/aws-sdk-js-v3/issues/1490
const { $metadata, ...outputWithoutMetadata } = parsed;

if (typeof logger?.info === "function") {
logger.info({
output: outputFilterSensitiveLog(outputWithoutMetadata),
});
}

return {
response,
output: parsed as Output,
Expand Down
48 changes: 12 additions & 36 deletions packages/middleware-serde/src/serializerMiddleware.spec.ts
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
import { Logger } from "@aws-sdk/types";
import { EndpointBearer } from "@aws-sdk/types";

import { serializerMiddleware } from "./serializerMiddleware";

Expand All @@ -15,12 +15,6 @@ describe("serializerMiddleware", () => {
}),
};

const mockArgs = {
input: {
inputKey: "inputValue",
},
};

const mockRequest = {
method: "GET",
headers: {},
Expand All @@ -44,43 +38,25 @@ describe("serializerMiddleware", () => {
output: mockOutput,
};

const mockArgs = {
input: {
inputKey: "inputValue",
},
};

beforeEach(() => {
mockNext.mockResolvedValueOnce(mockReturn);
mockSerializer.mockResolvedValueOnce(mockRequest);
});

afterEach(() => {
it("calls serializer and populates request object", async () => {
await expect(serializerMiddleware(mockOptions, mockSerializer)(mockNext, {})(mockArgs)).resolves.toStrictEqual(
mockReturn
);

expect(mockSerializer).toHaveBeenCalledTimes(1);
expect(mockSerializer).toHaveBeenCalledWith(mockArgs.input, mockOptions);
expect(mockNext).toHaveBeenCalledTimes(1);
expect(mockNext).toHaveBeenCalledWith({ ...mockArgs, request: mockRequest });
jest.clearAllMocks();
});

it("returns without logging if context.logger is not defined", async () => {
const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, {})(mockArgs);
expect(response).toStrictEqual(mockReturn);
});

it("returns without logging if context.logger doesn't have debug/info function", async () => {
const logger = {} as Logger;
const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, { logger })(mockArgs);
expect(response).toStrictEqual(mockReturn);
});

it("logs input if context.logger has info function", async () => {
const logger = ({ info: jest.fn() } as unknown) as Logger;

const inputFilterSensitiveLog = jest.fn().mockImplementationOnce((input) => input);
const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, {
logger,
inputFilterSensitiveLog,
})(mockArgs);

expect(response).toStrictEqual(mockReturn);
expect(inputFilterSensitiveLog).toHaveBeenCalledTimes(1);
expect(inputFilterSensitiveLog).toHaveBeenCalledWith(mockArgs.input);
expect(logger.info).toHaveBeenCalledTimes(1);
expect(logger.info).toHaveBeenCalledWith({ input: mockArgs.input });
});
});
9 changes: 0 additions & 9 deletions packages/middleware-serde/src/serializerMiddleware.ts
Original file line number Diff line number Diff line change
Expand Up @@ -17,16 +17,7 @@ export const serializerMiddleware = <Input extends object, Output extends object
): SerializeHandler<Input, Output> => async (
args: SerializeHandlerArguments<Input>
): Promise<SerializeHandlerOutput<Output>> => {
const { logger, inputFilterSensitiveLog } = context;

if (typeof logger?.info === "function") {
logger.info({
input: inputFilterSensitiveLog(args.input),
});
}

const request = await serializer(args.input, options);

return next({
...args,
request,
Expand Down

0 comments on commit 4f9e56f

Please sign in to comment.