Skip to content

Commit 4f9e56f

Browse files
trivikrtrivikr
authored
feat(middleware-logger): log clientName, commandName, input, output (#1788)
1 parent 04d9cf2 commit 4f9e56f

File tree

6 files changed

+132
-147
lines changed

6 files changed

+132
-147
lines changed

‎packages/middleware-logger/src/loggerMiddleware.spec.ts

+101-55
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,16 @@ describe("loggerMiddleware", () => {
3131
},
3232
};
3333

34+
const mockOutput = {
35+
$metadata: {
36+
statusCode: 200,
37+
requestId: "requestId",
38+
attempts: 2,
39+
totalRetryDelay: 350,
40+
},
41+
outputKey: "outputValue",
42+
};
43+
3444
const mockResponse = {
3545
response: {
3646
statusCode: 200,
@@ -40,9 +50,7 @@ describe("loggerMiddleware", () => {
4050
"x-amz-cf-id": "cfId",
4151
},
4252
},
43-
output: {
44-
outputKey: "outputValue",
45-
},
53+
output: mockOutput,
4654
};
4755

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

67-
it("logs metadata if context.logger has info function", async () => {
68-
mockNext.mockResolvedValueOnce(mockResponse);
69-
const logger = ({ info: jest.fn() } as unknown) as Logger;
70-
71-
const context = {
72-
logger,
73-
};
74-
75-
const response = await loggerMiddleware()(mockNext, context)(mockArgs);
76-
expect(mockNext).toHaveBeenCalledTimes(1);
77-
expect(response).toStrictEqual(mockResponse);
78-
79-
expect(logger.info).toHaveBeenCalledTimes(1);
80-
81-
expect(logger.info).toHaveBeenCalledWith({
82-
metadata: {
83-
statusCode: mockResponse.response.statusCode,
84-
requestId: mockResponse.response.headers["x-amzn-requestid"],
85-
extendedRequestId: mockResponse.response.headers["x-amz-id-2"],
86-
cfId: mockResponse.response.headers["x-amz-cf-id"],
87-
},
75+
describe("logs if context.logger has info function", () => {
76+
it("success case with clientName, commandName, input, metadata", async () => {
77+
mockNext.mockResolvedValueOnce(mockResponse);
78+
79+
const logger = ({ info: jest.fn() } as unknown) as Logger;
80+
const clientName = "mockClientName";
81+
const commandName = "mockCommandName";
82+
83+
const mockInputLog = { inputKey: "inputKey", inputSensitiveKey: "SENSITIVE_VALUE" };
84+
const inputFilterSensitiveLog = jest.fn().mockReturnValueOnce(mockInputLog);
85+
const mockOutputLog = { outputKey: "outputKey", outputSensitiveKey: "SENSITIVE_VALUE" };
86+
const outputFilterSensitiveLog = jest.fn().mockReturnValueOnce(mockOutputLog);
87+
88+
const context = {
89+
logger,
90+
clientName,
91+
commandName,
92+
inputFilterSensitiveLog,
93+
outputFilterSensitiveLog,
94+
};
95+
96+
const response = await loggerMiddleware()(mockNext, context)(mockArgs);
97+
expect(mockNext).toHaveBeenCalledTimes(1);
98+
expect(response).toStrictEqual(mockResponse);
99+
100+
expect(inputFilterSensitiveLog).toHaveBeenCalledTimes(1);
101+
expect(inputFilterSensitiveLog).toHaveBeenCalledWith(mockArgs.input);
102+
103+
const { $metadata, ...outputWithoutMetadata } = mockOutput;
104+
expect(outputFilterSensitiveLog).toHaveBeenCalledTimes(1);
105+
expect(outputFilterSensitiveLog).toHaveBeenCalledWith(outputWithoutMetadata);
106+
107+
expect(logger.info).toHaveBeenCalledTimes(1);
108+
expect(logger.info).toHaveBeenCalledWith({
109+
clientName,
110+
commandName,
111+
input: mockInputLog,
112+
output: mockOutputLog,
113+
metadata: {
114+
statusCode: mockResponse.response.statusCode,
115+
requestId: mockResponse.response.headers["x-amzn-requestid"],
116+
extendedRequestId: mockResponse.response.headers["x-amz-id-2"],
117+
cfId: mockResponse.response.headers["x-amz-cf-id"],
118+
retry: {
119+
attempts: $metadata.attempts,
120+
totalDelay: $metadata.totalRetryDelay,
121+
},
122+
},
123+
});
88124
});
89-
});
90125

91-
it("logs header x-amzn-request-id as requestId if x-amzn-requestid is not present", async () => {
92-
const requestIdBackup = "requestIdBackup";
93-
const customResponse = {
94-
...mockResponse,
95-
response: {
96-
...mockResponse.response,
97-
headers: {
98-
"x-amzn-request-id": requestIdBackup,
126+
it("header x-amzn-request-id as requestId if x-amzn-requestid is not present", async () => {
127+
const requestIdBackup = "requestIdBackup";
128+
const customResponse = {
129+
...mockResponse,
130+
response: {
131+
...mockResponse.response,
132+
headers: {
133+
"x-amzn-request-id": requestIdBackup,
134+
},
99135
},
100-
},
101-
};
102-
mockNext.mockResolvedValueOnce(customResponse);
103-
const logger = ({ info: jest.fn() } as unknown) as Logger;
104-
105-
const context = {
106-
logger,
107-
};
108-
109-
const response = await loggerMiddleware()(mockNext, context)(mockArgs);
110-
expect(mockNext).toHaveBeenCalledTimes(1);
111-
expect(response).toStrictEqual(customResponse);
112-
113-
expect(logger.info).toHaveBeenCalledTimes(1);
114-
115-
expect(logger.info).toHaveBeenCalledWith({
116-
metadata: {
117-
statusCode: customResponse.response.statusCode,
118-
requestId: requestIdBackup,
119-
extendedRequestId: undefined,
120-
cfId: undefined,
121-
},
136+
};
137+
mockNext.mockResolvedValueOnce(customResponse);
138+
const logger = ({ info: jest.fn() } as unknown) as Logger;
139+
const inputFilterSensitiveLog = jest.fn().mockImplementationOnce((input) => input);
140+
const outputFilterSensitiveLog = jest.fn().mockImplementationOnce((output) => output);
141+
142+
const context = {
143+
logger,
144+
inputFilterSensitiveLog,
145+
outputFilterSensitiveLog,
146+
};
147+
148+
const response = await loggerMiddleware()(mockNext, context)(mockArgs);
149+
expect(mockNext).toHaveBeenCalledTimes(1);
150+
expect(response).toStrictEqual(customResponse);
151+
152+
const { $metadata, ...outputWithoutMetadata } = mockOutput;
153+
expect(logger.info).toHaveBeenCalledTimes(1);
154+
expect(logger.info).toHaveBeenCalledWith({
155+
input: mockArgs.input,
156+
output: outputWithoutMetadata,
157+
metadata: {
158+
statusCode: customResponse.response.statusCode,
159+
requestId: requestIdBackup,
160+
extendedRequestId: undefined,
161+
cfId: undefined,
162+
retry: {
163+
attempts: $metadata.attempts,
164+
totalDelay: $metadata.totalRetryDelay,
165+
},
166+
},
167+
});
122168
});
123169
});
124170
});

‎packages/middleware-logger/src/loggerMiddleware.ts

+11-3
Original file line numberDiff line numberDiff line change
@@ -16,23 +16,31 @@ export const loggerMiddleware = () => <Output extends MetadataBearer = MetadataB
1616
): InitializeHandler<any, Output> => async (
1717
args: InitializeHandlerArguments<any>
1818
): Promise<InitializeHandlerOutput<Output>> => {
19-
const { logger } = context;
19+
const { clientName, commandName, inputFilterSensitiveLog, logger, outputFilterSensitiveLog } = context;
2020

2121
const response = await next(args);
2222

2323
if (!logger) {
2424
return response;
2525
}
2626

27-
const httpResponse = response.response as HttpResponse;
28-
2927
if (typeof logger.info === "function") {
28+
const httpResponse = response.response as HttpResponse;
29+
const { $metadata, ...outputWithoutMetadata } = response.output;
3030
logger.info({
31+
clientName,
32+
commandName,
33+
input: inputFilterSensitiveLog(args.input),
34+
output: outputFilterSensitiveLog(outputWithoutMetadata),
3135
metadata: {
3236
statusCode: httpResponse.statusCode,
3337
requestId: httpResponse.headers["x-amzn-requestid"] ?? httpResponse.headers["x-amzn-request-id"],
3438
extendedRequestId: httpResponse.headers["x-amz-id-2"],
3539
cfId: httpResponse.headers["x-amz-cf-id"],
40+
retry: {
41+
attempts: $metadata.attempts,
42+
totalDelay: $metadata.totalRetryDelay,
43+
},
3644
},
3745
});
3846
}

‎packages/middleware-serde/src/deserializerMiddleware.spec.ts

+8-31
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,3 @@
1-
import { Logger } from "@aws-sdk/types";
2-
31
import { deserializerMiddleware } from "./deserializerMiddleware";
42

53
describe("deserializerMiddleware", () => {
@@ -51,38 +49,17 @@ describe("deserializerMiddleware", () => {
5149
});
5250

5351
afterEach(() => {
54-
expect(mockNext).toHaveBeenCalledTimes(1);
55-
expect(mockNext).toHaveBeenCalledWith(mockArgs);
56-
expect(mockDeserializer).toHaveBeenCalledTimes(1);
57-
expect(mockDeserializer).toHaveBeenCalledWith(mockNextResponse.response, mockOptions);
5852
jest.clearAllMocks();
5953
});
6054

61-
it("returns without logging if context.logger is not defined", async () => {
62-
const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, {})(mockArgs);
63-
expect(response).toStrictEqual(mockResponse);
64-
});
65-
66-
it("returns without logging if context.logger doesn't have debug/info function", async () => {
67-
const logger = {} as Logger;
68-
const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, { logger })(mockArgs);
69-
expect(response).toStrictEqual(mockResponse);
70-
});
71-
72-
it("logs output if context.logger has info function", async () => {
73-
const logger = ({ info: jest.fn() } as unknown) as Logger;
55+
it("calls deserializer and populates response object", async () => {
56+
await expect(deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, {})(mockArgs)).resolves.toStrictEqual(
57+
mockResponse
58+
);
7459

75-
const outputFilterSensitiveLog = jest.fn().mockImplementationOnce((output) => output);
76-
const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, {
77-
logger,
78-
outputFilterSensitiveLog: outputFilterSensitiveLog,
79-
})(mockArgs);
80-
81-
const { $metadata, ...outputWithoutMetadata } = mockOutput;
82-
expect(response).toStrictEqual(mockResponse);
83-
expect(outputFilterSensitiveLog).toHaveBeenCalledTimes(1);
84-
expect(outputFilterSensitiveLog).toHaveBeenCalledWith(outputWithoutMetadata);
85-
expect(logger.info).toHaveBeenCalledTimes(1);
86-
expect(logger.info).toHaveBeenCalledWith({ output: outputWithoutMetadata });
60+
expect(mockNext).toHaveBeenCalledTimes(1);
61+
expect(mockNext).toHaveBeenCalledWith(mockArgs);
62+
expect(mockDeserializer).toHaveBeenCalledTimes(1);
63+
expect(mockDeserializer).toHaveBeenCalledWith(mockNextResponse.response, mockOptions);
8764
});
8865
});

‎packages/middleware-serde/src/deserializerMiddleware.ts

-13
Original file line numberDiff line numberDiff line change
@@ -16,21 +16,8 @@ export const deserializerMiddleware = <Input extends object, Output extends obje
1616
): DeserializeHandler<Input, Output> => async (
1717
args: DeserializeHandlerArguments<Input>
1818
): Promise<DeserializeHandlerOutput<Output>> => {
19-
const { logger, outputFilterSensitiveLog } = context;
20-
2119
const { response } = await next(args);
22-
2320
const parsed = await deserializer(response, options);
24-
25-
// Log parsed after $metadata is removed in https://github.com/aws/aws-sdk-js-v3/issues/1490
26-
const { $metadata, ...outputWithoutMetadata } = parsed;
27-
28-
if (typeof logger?.info === "function") {
29-
logger.info({
30-
output: outputFilterSensitiveLog(outputWithoutMetadata),
31-
});
32-
}
33-
3421
return {
3522
response,
3623
output: parsed as Output,

‎packages/middleware-serde/src/serializerMiddleware.spec.ts

+12-36
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
import { Logger } from "@aws-sdk/types";
1+
import { EndpointBearer } from "@aws-sdk/types";
22

33
import { serializerMiddleware } from "./serializerMiddleware";
44

@@ -15,12 +15,6 @@ describe("serializerMiddleware", () => {
1515
}),
1616
};
1717

18-
const mockArgs = {
19-
input: {
20-
inputKey: "inputValue",
21-
},
22-
};
23-
2418
const mockRequest = {
2519
method: "GET",
2620
headers: {},
@@ -44,43 +38,25 @@ describe("serializerMiddleware", () => {
4438
output: mockOutput,
4539
};
4640

41+
const mockArgs = {
42+
input: {
43+
inputKey: "inputValue",
44+
},
45+
};
46+
4747
beforeEach(() => {
4848
mockNext.mockResolvedValueOnce(mockReturn);
4949
mockSerializer.mockResolvedValueOnce(mockRequest);
5050
});
5151

52-
afterEach(() => {
52+
it("calls serializer and populates request object", async () => {
53+
await expect(serializerMiddleware(mockOptions, mockSerializer)(mockNext, {})(mockArgs)).resolves.toStrictEqual(
54+
mockReturn
55+
);
56+
5357
expect(mockSerializer).toHaveBeenCalledTimes(1);
5458
expect(mockSerializer).toHaveBeenCalledWith(mockArgs.input, mockOptions);
5559
expect(mockNext).toHaveBeenCalledTimes(1);
5660
expect(mockNext).toHaveBeenCalledWith({ ...mockArgs, request: mockRequest });
57-
jest.clearAllMocks();
58-
});
59-
60-
it("returns without logging if context.logger is not defined", async () => {
61-
const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, {})(mockArgs);
62-
expect(response).toStrictEqual(mockReturn);
63-
});
64-
65-
it("returns without logging if context.logger doesn't have debug/info function", async () => {
66-
const logger = {} as Logger;
67-
const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, { logger })(mockArgs);
68-
expect(response).toStrictEqual(mockReturn);
69-
});
70-
71-
it("logs input if context.logger has info function", async () => {
72-
const logger = ({ info: jest.fn() } as unknown) as Logger;
73-
74-
const inputFilterSensitiveLog = jest.fn().mockImplementationOnce((input) => input);
75-
const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, {
76-
logger,
77-
inputFilterSensitiveLog,
78-
})(mockArgs);
79-
80-
expect(response).toStrictEqual(mockReturn);
81-
expect(inputFilterSensitiveLog).toHaveBeenCalledTimes(1);
82-
expect(inputFilterSensitiveLog).toHaveBeenCalledWith(mockArgs.input);
83-
expect(logger.info).toHaveBeenCalledTimes(1);
84-
expect(logger.info).toHaveBeenCalledWith({ input: mockArgs.input });
8561
});
8662
});

‎packages/middleware-serde/src/serializerMiddleware.ts

-9
Original file line numberDiff line numberDiff line change
@@ -17,16 +17,7 @@ export const serializerMiddleware = <Input extends object, Output extends object
1717
): SerializeHandler<Input, Output> => async (
1818
args: SerializeHandlerArguments<Input>
1919
): Promise<SerializeHandlerOutput<Output>> => {
20-
const { logger, inputFilterSensitiveLog } = context;
21-
22-
if (typeof logger?.info === "function") {
23-
logger.info({
24-
input: inputFilterSensitiveLog(args.input),
25-
});
26-
}
27-
2820
const request = await serializer(args.input, options);
29-
3021
return next({
3122
...args,
3223
request,

0 commit comments

Comments
 (0)