Skip to content

Commit 4c57389

Browse files
pankajagrawal16Pankaj Agrawal
andauthored
fix: Log event via object mapper and not depend on toString (#113)
Co-authored-by: Pankaj Agrawal <[email protected]>
1 parent 8001e72 commit 4c57389

File tree

7 files changed

+166
-21
lines changed

7 files changed

+166
-21
lines changed

pom.xml

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -190,6 +190,12 @@
190190
<version>3.17.2</version>
191191
<scope>test</scope>
192192
</dependency>
193+
<dependency>
194+
<groupId>org.skyscreamer</groupId>
195+
<artifactId>jsonassert</artifactId>
196+
<version>1.5.0</version>
197+
<scope>test</scope>
198+
</dependency>
193199
<dependency>
194200
<groupId>org.aspectj</groupId>
195201
<artifactId>aspectjtools</artifactId>

powertools-logging/pom.xml

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -103,6 +103,16 @@
103103
<artifactId>assertj-core</artifactId>
104104
<scope>test</scope>
105105
</dependency>
106+
<dependency>
107+
<groupId>com.amazonaws</groupId>
108+
<artifactId>aws-lambda-java-events</artifactId>
109+
<scope>test</scope>
110+
</dependency>
111+
<dependency>
112+
<groupId>org.skyscreamer</groupId>
113+
<artifactId>jsonassert</artifactId>
114+
<scope>test</scope>
115+
</dependency>
106116
</dependencies>
107117

108118
</project>

powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java

Lines changed: 18 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@
2323
import java.util.Optional;
2424
import java.util.Random;
2525

26+
import com.fasterxml.jackson.core.JsonProcessingException;
2627
import com.fasterxml.jackson.databind.ObjectMapper;
2728
import org.apache.logging.log4j.Level;
2829
import org.apache.logging.log4j.LogManager;
@@ -37,6 +38,7 @@
3738
import software.amazon.lambda.powertools.logging.PowertoolsLogging;
3839

3940
import static java.util.Optional.empty;
41+
import static java.util.Optional.of;
4042
import static java.util.Optional.ofNullable;
4143
import static software.amazon.lambda.powertools.core.internal.LambdaHandlerProcessor.coldStartDone;
4244
import static software.amazon.lambda.powertools.core.internal.LambdaHandlerProcessor.extractContext;
@@ -147,7 +149,8 @@ private Object[] logEvent(final ProceedingJoinPoint pjp) {
147149
if (isHandlerMethod(pjp)) {
148150
if (placedOnRequestHandler(pjp)) {
149151
Logger log = logger(pjp);
150-
log.info(pjp.getArgs()[0]);
152+
asJson(pjp, pjp.getArgs()[0])
153+
.ifPresent(log::info);
151154
}
152155

153156
if (placedOnStreamHandler(pjp)) {
@@ -171,7 +174,9 @@ private Object[] logFromInputStream(final ProceedingJoinPoint pjp) {
171174
args[0] = new ByteArrayInputStream(bytes);
172175

173176
Logger log = logger(pjp);
174-
log.info(MAPPER.readValue(bytes, Map.class));
177+
178+
asJson(pjp, MAPPER.readValue(bytes, Map.class))
179+
.ifPresent(log::info);
175180

176181
} catch (IOException e) {
177182
Logger log = logger(pjp);
@@ -181,14 +186,24 @@ private Object[] logFromInputStream(final ProceedingJoinPoint pjp) {
181186
return args;
182187
}
183188

189+
private Optional<String> asJson(final ProceedingJoinPoint pjp,
190+
final Object target) {
191+
try {
192+
return ofNullable(MAPPER.writeValueAsString(target));
193+
} catch (JsonProcessingException e) {
194+
logger(pjp).error("Failed logging event of type {}", target.getClass(), e);
195+
return empty();
196+
}
197+
}
198+
184199
private Logger logger(final ProceedingJoinPoint pjp) {
185200
return LogManager.getLogger(pjp.getSignature().getDeclaringType());
186201
}
187202

188203
private static Optional<String> getXrayTraceId() {
189204
final String X_AMZN_TRACE_ID = getenv("_X_AMZN_TRACE_ID");
190205
if(X_AMZN_TRACE_ID != null) {
191-
return ofNullable(X_AMZN_TRACE_ID.split(";")[0].replace("Root=", ""));
206+
return of(X_AMZN_TRACE_ID.split(";")[0].replace("Root=", ""));
192207
}
193208
return empty();
194209
}

powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -39,7 +39,7 @@
3939
import static org.assertj.core.api.Assertions.assertThat;
4040
import static org.assertj.core.api.Assertions.fail;
4141
import static org.mockito.Mockito.when;
42-
import static org.mockito.MockitoAnnotations.initMocks;
42+
import static org.mockito.MockitoAnnotations.openMocks;
4343

4444
class LambdaJsonLayoutTest {
4545

@@ -50,7 +50,7 @@ class LambdaJsonLayoutTest {
5050

5151
@BeforeEach
5252
void setUp() throws IOException, IllegalAccessException, NoSuchMethodException, InvocationTargetException {
53-
initMocks(this);
53+
openMocks(this);
5454
setupContext();
5555
//Make sure file is cleaned up before running full stack logging regression
5656
FileChannel.open(Paths.get("target/logfile.json"), StandardOpenOption.WRITE).truncate(0).close();

powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/handlers/PowerLogToolEnabled.java

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,7 @@
2020
import software.amazon.lambda.powertools.logging.PowertoolsLogging;
2121

2222
public class PowerLogToolEnabled implements RequestHandler<Object, Object> {
23-
private final Logger LOG = LogManager.getLogger(PowerToolLogEventEnabled.class);
23+
private final Logger LOG = LogManager.getLogger(PowerLogToolEnabled.class);
2424

2525
@Override
2626
@PowertoolsLogging

powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspectTest.java

Lines changed: 91 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -13,23 +13,33 @@
1313
*/
1414
package software.amazon.lambda.powertools.logging.internal;
1515

16+
import java.io.BufferedReader;
1617
import java.io.ByteArrayInputStream;
1718
import java.io.ByteArrayOutputStream;
1819
import java.io.IOException;
20+
import java.io.InputStreamReader;
21+
import java.lang.reflect.InvocationTargetException;
22+
import java.lang.reflect.Method;
23+
import java.nio.channels.FileChannel;
1924
import java.nio.charset.StandardCharsets;
20-
import java.util.HashMap;
25+
import java.nio.file.Files;
26+
import java.nio.file.Paths;
27+
import java.nio.file.StandardOpenOption;
2128
import java.util.Map;
2229

2330
import com.amazonaws.services.lambda.runtime.Context;
2431
import com.amazonaws.services.lambda.runtime.RequestHandler;
2532
import com.amazonaws.services.lambda.runtime.RequestStreamHandler;
33+
import com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification;
34+
import com.fasterxml.jackson.core.JsonProcessingException;
2635
import com.fasterxml.jackson.databind.ObjectMapper;
36+
import org.apache.logging.log4j.Level;
2737
import org.apache.logging.log4j.ThreadContext;
38+
import org.json.JSONException;
2839
import org.junit.jupiter.api.BeforeEach;
2940
import org.junit.jupiter.api.Test;
3041
import org.mockito.Mock;
3142
import org.mockito.MockedStatic;
32-
import org.mockito.Mockito;
3343
import software.amazon.lambda.powertools.core.internal.LambdaHandlerProcessor;
3444
import software.amazon.lambda.powertools.logging.handlers.PowerLogToolEnabled;
3545
import software.amazon.lambda.powertools.logging.handlers.PowerLogToolEnabledForStream;
@@ -38,11 +48,23 @@
3848
import software.amazon.lambda.powertools.logging.handlers.PowerToolLogEventEnabled;
3949
import software.amazon.lambda.powertools.logging.handlers.PowerToolLogEventEnabledForStream;
4050

51+
import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.RequestParametersEntity;
52+
import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.ResponseElementsEntity;
53+
import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.S3BucketEntity;
54+
import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.S3Entity;
55+
import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.S3EventNotificationRecord;
56+
import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.S3ObjectEntity;
57+
import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.UserIdentityEntity;
58+
import static java.util.Collections.emptyMap;
59+
import static java.util.Collections.singletonList;
60+
import static java.util.stream.Collectors.joining;
4161
import static org.apache.commons.lang3.reflect.FieldUtils.writeStaticField;
4262
import static org.assertj.core.api.Assertions.assertThat;
63+
import static org.assertj.core.api.Assertions.fail;
4364
import static org.mockito.Mockito.mockStatic;
4465
import static org.mockito.Mockito.when;
4566
import static org.mockito.MockitoAnnotations.openMocks;
67+
import static org.skyscreamer.jsonassert.JSONAssert.assertEquals;
4668
import static software.amazon.lambda.powertools.logging.internal.SystemWrapper.getenv;
4769

4870
class LambdaLoggingAspectTest {
@@ -55,13 +77,16 @@ class LambdaLoggingAspectTest {
5577
private Context context;
5678

5779
@BeforeEach
58-
void setUp() throws IllegalAccessException {
80+
void setUp() throws IllegalAccessException, IOException, NoSuchMethodException, InvocationTargetException {
5981
openMocks(this);
6082
ThreadContext.clearAll();
6183
writeStaticField(LambdaHandlerProcessor.class, "IS_COLD_START", null, true);
6284
setupContext();
6385
requestHandler = new PowerLogToolEnabled();
6486
requestStreamHandler = new PowerLogToolEnabledForStream();
87+
//Make sure file is cleaned up before running full stack logging regression
88+
FileChannel.open(Paths.get("target/logfile.json"), StandardOpenOption.WRITE).truncate(0).close();
89+
resetLogLevel(Level.INFO);
6590
}
6691

6792
@Test
@@ -140,30 +165,41 @@ void shouldHaveNoEffectIfNotUsedOnLambdaHandler() {
140165
}
141166

142167
@Test
143-
void shouldLogEventForHandler() {
168+
void shouldLogEventForHandler() throws IOException, JSONException {
144169
requestHandler = new PowerToolLogEventEnabled();
170+
S3EventNotification s3EventNotification = s3EventNotification();
145171

146-
requestHandler.handleRequest(new Object(), context);
172+
requestHandler.handleRequest(s3EventNotification, context);
147173

148-
assertThat(ThreadContext.getImmutableContext())
149-
.hasSize(EXPECTED_CONTEXT_SIZE);
174+
Map<String, Object> log = parseToMap(Files.lines(Paths.get("target/logfile.json")).collect(joining()));
175+
176+
String event = (String) log.get("message");
177+
178+
String expectEvent = new BufferedReader(new InputStreamReader(this.getClass().getResourceAsStream("/s3EventNotification.json")))
179+
.lines().collect(joining("\n"));
180+
181+
assertEquals(expectEvent, event, false);
150182
}
151183

152184
@Test
153-
void shouldLogEventForStreamAndLambdaStreamIsValid() throws IOException {
185+
void shouldLogEventForStreamAndLambdaStreamIsValid() throws IOException, JSONException {
154186
requestStreamHandler = new PowerToolLogEventEnabledForStream();
155187
ByteArrayOutputStream output = new ByteArrayOutputStream();
188+
S3EventNotification s3EventNotification = s3EventNotification();
156189

157-
Map<String, String> testPayload = new HashMap<>();
158-
testPayload.put("test", "payload");
159-
160-
requestStreamHandler.handleRequest(new ByteArrayInputStream(new ObjectMapper().writeValueAsBytes(testPayload)), output, context);
190+
requestStreamHandler.handleRequest(new ByteArrayInputStream(new ObjectMapper().writeValueAsBytes(s3EventNotification)), output, context);
161191

162192
assertThat(new String(output.toByteArray(), StandardCharsets.UTF_8))
163-
.isEqualTo("{\"test\":\"payload\"}");
193+
.isNotEmpty();
164194

165-
assertThat(ThreadContext.getImmutableContext())
166-
.hasSize(EXPECTED_CONTEXT_SIZE);
195+
Map<String, Object> log = parseToMap(Files.lines(Paths.get("target/logfile.json")).collect(joining()));
196+
197+
String event = (String) log.get("message");
198+
199+
String expectEvent = new BufferedReader(new InputStreamReader(this.getClass().getResourceAsStream("/s3EventNotification.json")))
200+
.lines().collect(joining("\n"));
201+
202+
assertEquals(expectEvent, event, false);
167203
}
168204

169205
@Test
@@ -197,4 +233,44 @@ private void setupContext() {
197233
when(context.getFunctionVersion()).thenReturn("1");
198234
when(context.getMemoryLimitInMB()).thenReturn(10);
199235
}
236+
237+
private void resetLogLevel(Level level) throws NoSuchMethodException, IllegalAccessException, InvocationTargetException {
238+
Method resetLogLevels = LambdaLoggingAspect.class.getDeclaredMethod("resetLogLevels", Level.class);
239+
resetLogLevels.setAccessible(true);
240+
resetLogLevels.invoke(null, level);
241+
writeStaticField(LambdaLoggingAspect.class, "LEVEL_AT_INITIALISATION", level, true);
242+
}
243+
244+
private S3EventNotification s3EventNotification() {
245+
S3EventNotificationRecord record = new S3EventNotificationRecord("us-west-2",
246+
"ObjectCreated:Put",
247+
"aws:s3",
248+
null,
249+
"2.1",
250+
new RequestParametersEntity("127.0.0.1"),
251+
new ResponseElementsEntity("C3D13FE58DE4C810", "FMyUVURIY8/IgAtTv8xRjskZQpcIZ9KG4V5Wp6S7S/JRWeUWerMUE5JgHvANOjpD"),
252+
new S3Entity("testConfigRule",
253+
new S3BucketEntity("mybucket",
254+
new UserIdentityEntity("A3NL1KOZZKExample"),
255+
"arn:aws:s3:::mybucket"),
256+
new S3ObjectEntity("HappyFace.jpg",
257+
1024L,
258+
"d41d8cd98f00b204e9800998ecf8427e",
259+
"096fKKXTRTtl3on89fVO.nfljtsv6qko",
260+
"0055AED6DCD90281E5"),
261+
"1.0"),
262+
new UserIdentityEntity("AIDAJDPLRKLG7UEXAMPLE")
263+
);
264+
265+
return new S3EventNotification(singletonList(record));
266+
}
267+
268+
private Map<String, Object> parseToMap(String stringAsJson) {
269+
try {
270+
return new ObjectMapper().readValue(stringAsJson, Map.class);
271+
} catch (JsonProcessingException e) {
272+
fail("Failed parsing logger line " + stringAsJson);
273+
return emptyMap();
274+
}
275+
}
200276
}
Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
{
2+
"records":[
3+
{
4+
"eventVersion":"2.1",
5+
"eventSource":"aws:s3",
6+
"awsRegion":"us-west-2",
7+
"eventName":"ObjectCreated:Put",
8+
"userIdentity":{
9+
"principalId":"AIDAJDPLRKLG7UEXAMPLE"
10+
},
11+
"requestParameters":{
12+
"sourceIPAddress":"127.0.0.1"
13+
},
14+
"responseElements":{
15+
"xAmzId2":"C3D13FE58DE4C810",
16+
"xAmzRequestId":"FMyUVURIY8/IgAtTv8xRjskZQpcIZ9KG4V5Wp6S7S/JRWeUWerMUE5JgHvANOjpD"
17+
},
18+
"s3":{
19+
"s3SchemaVersion":"1.0",
20+
"configurationId":"testConfigRule",
21+
"bucket":{
22+
"name":"mybucket",
23+
"ownerIdentity":{
24+
"principalId":"A3NL1KOZZKExample"
25+
},
26+
"arn":"arn:aws:s3:::mybucket"
27+
},
28+
"object":{
29+
"key":"HappyFace.jpg",
30+
"size":1024,
31+
"eTag":"d41d8cd98f00b204e9800998ecf8427e",
32+
"versionId":"096fKKXTRTtl3on89fVO.nfljtsv6qko",
33+
"sequencer":"0055AED6DCD90281E5"
34+
}
35+
}
36+
}
37+
]
38+
}

0 commit comments

Comments
 (0)