Skip to content

Commit dc18ce2

Browse files
vip-amznvip-amzn
committed
refactor: Emit worker pool event via byte[] path
1 parent 5dd520e commit dc18ce2

7 files changed

Lines changed: 64 additions & 157 deletions

File tree

‎aws-lambda-java-runtime-interface-client/src/main/java/com/amazonaws/services/lambda/runtime/api/client/AWSLambda.java‎

Lines changed: 28 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,11 @@
3535
import java.io.PrintStream;
3636
import java.lang.reflect.Constructor;
3737
import java.net.URLClassLoader;
38+
import java.nio.charset.StandardCharsets;
3839
import java.security.Security;
40+
import java.time.Instant;
41+
import java.time.ZoneId;
42+
import java.time.format.DateTimeFormatter;
3943
import java.util.Properties;
4044
import java.util.concurrent.ExecutorService;
4145
import java.util.concurrent.Executors;
@@ -251,11 +255,14 @@ protected static void startRuntimeLoops(LambdaRequestHandler lambdaRequestHandle
251255
if (concurrencyConfig.isMultiConcurrent()) {
252256
lambdaLogger.log(concurrencyConfig.getConcurrencyConfigMessage(), lambdaLogger.getLogFormat() == LogFormat.JSON ? LogLevel.INFO : LogLevel.UNDEFINED);
253257
ExecutorService platformThreadExecutor = Executors.newFixedThreadPool(concurrencyConfig.getNumberOfPlatformThreads());
254-
lambdaLogger.logStructuredEvent(
255-
new WorkerPoolInitializedEvent(
256-
concurrencyConfig.getNumberOfPlatformThreads(),
257-
concurrencyConfig.getNumberOfPlatformThreads()),
258-
LogLevel.DEBUG);
258+
// Emitted once during INIT. The byte[] log path applies level filtering but no
259+
// formatting, so the hand-built line keeps "message" as a nested JSON object.
260+
if (lambdaLogger.getLogFormat() == LogFormat.JSON) {
261+
WorkerPoolInitializedEvent event = new WorkerPoolInitializedEvent(
262+
concurrencyConfig.getNumberOfPlatformThreads(),
263+
concurrencyConfig.getNumberOfPlatformThreads());
264+
lambdaLogger.log(event.toJsonLogLine().getBytes(StandardCharsets.UTF_8), LogLevel.DEBUG);
265+
}
259266
try {
260267
for (int i = 0; i < concurrencyConfig.getNumberOfPlatformThreads(); i++) {
261268
startRuntimeLoopWithExecutor(lambdaRequestHandler, lambdaLogger, platformThreadExecutor, runtimeClient);
@@ -380,13 +387,28 @@ protected static URLClassLoader getCustomerClassLoader() {
380387
}
381388

382389
static class WorkerPoolInitializedEvent {
383-
final String event = "runtime_worker_pool_initializing";
390+
static final String EVENT_NAME = "runtime_worker_pool_initializing";
391+
private static final DateTimeFormatter TIMESTAMP_FORMAT =
392+
DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSS'Z'").withZone(ZoneId.of("UTC"));
393+
384394
final int workerCount;
385395
final int executionEnvironmentMaxConcurrency;
386396

387397
WorkerPoolInitializedEvent(int workerCount, int executionEnvironmentMaxConcurrency) {
388398
this.workerCount = workerCount;
389399
this.executionEnvironmentMaxConcurrency = executionEnvironmentMaxConcurrency;
390400
}
401+
402+
/**
403+
* Complete JSON log line with "message" as a nested object (queryable in CloudWatch
404+
* Logs Insights). Hand-built safely: all values are constants or ints, no escaping needed.
405+
*/
406+
String toJsonLogLine() {
407+
return "{\"timestamp\":\"" + TIMESTAMP_FORMAT.format(Instant.now())
408+
+ "\",\"message\":{\"event\":\"" + EVENT_NAME
409+
+ "\",\"workerCount\":" + workerCount
410+
+ ",\"executionEnvironmentMaxConcurrency\":" + executionEnvironmentMaxConcurrency
411+
+ "},\"level\":\"DEBUG\"}\n";
412+
}
391413
}
392414
}

‎aws-lambda-java-runtime-interface-client/src/main/java/com/amazonaws/services/lambda/runtime/api/client/logging/AbstractLambdaLogger.java‎

Lines changed: 0 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -64,12 +64,6 @@ public void log(byte[] message) {
6464
this.log(message, LogLevel.UNDEFINED);
6565
}
6666

67-
public void logStructuredEvent(Object event, LogLevel logLevel) {
68-
if (logFiltering.isEnabled(logLevel)) {
69-
this.logMessage(logFormatter.format(event, logLevel), logLevel);
70-
}
71-
}
72-
7367
public void setLambdaContext(LambdaContext lambdaContext) {
7468
this.logFormatter.setLambdaContext(lambdaContext);
7569
}

‎aws-lambda-java-runtime-interface-client/src/main/java/com/amazonaws/services/lambda/runtime/api/client/logging/JsonLogFormatter.java‎

Lines changed: 2 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -26,22 +26,14 @@ public class JsonLogFormatter implements LogFormatter {
2626

2727
@Override
2828
public String format(String message, LogLevel logLevel) {
29-
return serialize(createLogMessage(message, logLevel));
30-
}
31-
32-
@Override
33-
public String format(Object message, LogLevel logLevel) {
34-
return serialize(createLogMessage(message, logLevel));
35-
}
36-
37-
private String serialize(StructuredLogMessage msg) {
3829
ByteArrayOutputStream stream = new ByteArrayOutputStream();
30+
StructuredLogMessage msg = createLogMessage(message, logLevel);
3931
serializer.toJson(msg, stream);
4032
stream.write('\n');
4133
return new String(stream.toByteArray(), StandardCharsets.UTF_8);
4234
}
4335

44-
private StructuredLogMessage createLogMessage(Object message, LogLevel logLevel) {
36+
private StructuredLogMessage createLogMessage(String message, LogLevel logLevel) {
4537
StructuredLogMessage msg = new StructuredLogMessage();
4638
msg.timestamp = dateFormatter.format(LocalDateTime.now());
4739
msg.message = message;

‎aws-lambda-java-runtime-interface-client/src/main/java/com/amazonaws/services/lambda/runtime/api/client/logging/LogFormatter.java‎

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -11,10 +11,6 @@
1111
public interface LogFormatter {
1212
String format(String message, LogLevel logLevel);
1313

14-
default String format(Object message, LogLevel logLevel) {
15-
return format(String.valueOf(message), logLevel);
16-
}
17-
1814
default void setLambdaContext(LambdaContext context) {
1915
}
2016
}

‎aws-lambda-java-runtime-interface-client/src/main/java/com/amazonaws/services/lambda/runtime/api/client/logging/StructuredLogMessage.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,7 @@
99

1010
class StructuredLogMessage {
1111
public String timestamp;
12-
public Object message;
12+
public String message;
1313
public LogLevel level;
1414
public String AWSRequestId;
1515
public String tenantId;

‎aws-lambda-java-runtime-interface-client/src/test/java/com/amazonaws/services/lambda/runtime/api/client/AWSLambdaTest.java‎

Lines changed: 33 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -579,6 +579,7 @@ void testSequentialWithVirtualMachineErrorStopsLoop() throws Throwable {
579579
@Test
580580
@Timeout(value = 1, unit = TimeUnit.MINUTES)
581581
void testWorkerPoolInitializedEventEmittedOnceInMultiConcurrentMode() throws Throwable {
582+
when(lambdaLogger.getLogFormat()).thenReturn(LogFormat.JSON);
582583
when(concurrencyConfig.isMultiConcurrent()).thenReturn(true);
583584
when(concurrencyConfig.getNumberOfPlatformThreads()).thenReturn(4);
584585

@@ -587,13 +588,32 @@ void testWorkerPoolInitializedEventEmittedOnceInMultiConcurrentMode() throws Thr
587588

588589
AWSLambda.startRuntimeLoops(lambdaRequestHandler, lambdaLogger, concurrencyConfig, runtimeClient);
589590

590-
org.mockito.ArgumentCaptor<Object> eventCaptor = org.mockito.ArgumentCaptor.forClass(Object.class);
591-
verify(lambdaLogger, times(1)).logStructuredEvent(eventCaptor.capture(), eq(LogLevel.DEBUG));
591+
org.mockito.ArgumentCaptor<byte[]> lineCaptor = org.mockito.ArgumentCaptor.forClass(byte[].class);
592+
verify(lambdaLogger, times(1)).log(lineCaptor.capture(), eq(LogLevel.DEBUG));
593+
594+
com.amazonaws.lambda.thirdparty.org.json.JSONObject parsed =
595+
new com.amazonaws.lambda.thirdparty.org.json.JSONObject(
596+
new String(lineCaptor.getValue(), java.nio.charset.StandardCharsets.UTF_8));
597+
com.amazonaws.lambda.thirdparty.org.json.JSONObject message = parsed.getJSONObject("message");
598+
assertEquals("runtime_worker_pool_initializing", message.getString("event"));
599+
assertEquals(4, message.getInt("workerCount"));
600+
assertEquals(4, message.getInt("executionEnvironmentMaxConcurrency"));
601+
}
602+
603+
@Test
604+
@Timeout(value = 1, unit = TimeUnit.MINUTES)
605+
void testWorkerPoolInitializedEventNotEmittedInNonJsonLogFormat() throws Throwable {
606+
// Guard: no emission when the log format is not JSON, even in multi-concurrent mode
607+
when(lambdaLogger.getLogFormat()).thenReturn(LogFormat.TEXT);
608+
when(concurrencyConfig.isMultiConcurrent()).thenReturn(true);
609+
when(concurrencyConfig.getNumberOfPlatformThreads()).thenReturn(2);
610+
611+
when(runtimeClient.nextInvocationWithExponentialBackoff(lambdaLogger))
612+
.thenThrow(fakelambdaRuntimeClientMaxRetriesExceededException);
613+
614+
AWSLambda.startRuntimeLoops(lambdaRequestHandler, lambdaLogger, concurrencyConfig, runtimeClient);
592615

593-
AWSLambda.WorkerPoolInitializedEvent event = (AWSLambda.WorkerPoolInitializedEvent) eventCaptor.getValue();
594-
assertEquals("runtime_worker_pool_initializing", event.event);
595-
assertEquals(4, event.workerCount);
596-
assertEquals(4, event.executionEnvironmentMaxConcurrency);
616+
verify(lambdaLogger, never()).log(any(byte[].class), any(LogLevel.class));
597617
}
598618

599619
@Test
@@ -607,24 +627,23 @@ void testWorkerPoolInitializedEventNotEmittedInSequentialMode() throws Throwable
607627

608628
AWSLambda.startRuntimeLoops(lambdaRequestHandler, lambdaLogger, concurrencyConfig, runtimeClient);
609629

610-
verify(lambdaLogger, never()).logStructuredEvent(any(), any());
630+
verify(lambdaLogger, never()).log(any(byte[].class), any(LogLevel.class));
611631
}
612632

613633
/*
614-
* Pins the exact wire format of the event through the real JSON formatter (Gson),
615-
* proving the Object-typed StructuredLogMessage.message serializes the event as a
616-
* nested JSON object with exactly the documented schema.
634+
* Pins the exact wire format of the hand-built log line: "message" must be a nested
635+
* JSON object with exactly the documented schema, inside a valid envelope.
617636
*/
618637
@Test
619638
void testWorkerPoolInitializedEventJsonWireFormat() {
620-
com.amazonaws.services.lambda.runtime.api.client.logging.JsonLogFormatter formatter =
621-
new com.amazonaws.services.lambda.runtime.api.client.logging.JsonLogFormatter();
622-
String output = formatter.format(new AWSLambda.WorkerPoolInitializedEvent(16, 16), LogLevel.DEBUG);
639+
String line = new AWSLambda.WorkerPoolInitializedEvent(16, 16).toJsonLogLine();
640+
org.junit.jupiter.api.Assertions.assertTrue(line.endsWith("\n"));
623641

624642
com.amazonaws.lambda.thirdparty.org.json.JSONObject parsed =
625-
new com.amazonaws.lambda.thirdparty.org.json.JSONObject(output);
643+
new com.amazonaws.lambda.thirdparty.org.json.JSONObject(line);
626644
assertEquals("DEBUG", parsed.getString("level"));
627645
org.junit.jupiter.api.Assertions.assertNotNull(parsed.getString("timestamp"));
646+
assertEquals(3, parsed.length());
628647

629648
com.amazonaws.lambda.thirdparty.org.json.JSONObject message = parsed.getJSONObject("message");
630649
assertEquals("runtime_worker_pool_initializing", message.getString("event"));

‎aws-lambda-java-runtime-interface-client/src/test/java/com/amazonaws/services/lambda/runtime/api/client/logging/JsonLogFormatterTest.java‎

Lines changed: 0 additions & 116 deletions
Original file line numberDiff line numberDiff line change
@@ -1,133 +1,17 @@
11
package com.amazonaws.services.lambda.runtime.api.client.logging;
22

3-
import com.amazonaws.lambda.thirdparty.org.json.JSONObject;
43
import com.amazonaws.services.lambda.runtime.api.client.api.LambdaContext;
54
import com.amazonaws.services.lambda.runtime.serialization.PojoSerializer;
65
import com.amazonaws.services.lambda.runtime.serialization.factories.GsonFactory;
76
import org.junit.jupiter.api.Test;
87

98
import static org.junit.jupiter.api.Assertions.assertEquals;
10-
import static org.junit.jupiter.api.Assertions.assertFalse;
119
import static org.junit.jupiter.api.Assertions.assertNotNull;
12-
import static org.junit.jupiter.api.Assertions.assertTrue;
1310

1411
import com.amazonaws.services.lambda.runtime.logging.LogLevel;
1512

1613
public class JsonLogFormatterTest {
1714

18-
/*
19-
* Gson serialization-neutrality tests for the String -> Object type change of
20-
* StructuredLogMessage.message. These pin the exact serialized behavior so any
21-
* future regression (e.g. from a Gson upgrade changing runtime-type adapter
22-
* resolution) is caught here rather than in customers' log pipelines.
23-
*/
24-
25-
@Test
26-
void testStringMessageStillSerializesAsJsonStringWithObjectDeclaredField() {
27-
JsonLogFormatter formatter = new JsonLogFormatter();
28-
String output = formatter.format("test log", LogLevel.INFO);
29-
30-
JSONObject parsed = new JSONObject(output);
31-
// message must be a JSON string value, not an object or anything else
32-
assertTrue(parsed.get("message") instanceof String);
33-
assertEquals("test log", parsed.getString("message"));
34-
assertEquals("INFO", parsed.getString("level"));
35-
}
36-
37-
@Test
38-
void testStringMessageEscapingUnchangedWithObjectDeclaredField() {
39-
// quotes, backslashes, newlines, unicode and HTML-sensitive chars must
40-
// round-trip exactly as before the field type change
41-
String tricky = "quote\" backslash\\ newline\n tab\t unicode\u00e9 html<>&";
42-
JsonLogFormatter formatter = new JsonLogFormatter();
43-
String output = formatter.format(tricky, LogLevel.WARN);
44-
45-
JSONObject parsed = new JSONObject(output);
46-
assertEquals(tricky, parsed.getString("message"));
47-
}
48-
49-
@Test
50-
void testNullStringMessageOmittedExactlyAsBefore() {
51-
// serializeNulls(false) omitted a null String message before the change;
52-
// a null Object message must behave identically
53-
JsonLogFormatter formatter = new JsonLogFormatter();
54-
String output = formatter.format((String) null, LogLevel.INFO);
55-
56-
JSONObject parsed = new JSONObject(output);
57-
assertFalse(parsed.has("message"));
58-
assertNotNull(parsed.getString("timestamp"));
59-
}
60-
61-
static class SampleStructuredEvent {
62-
final String event = "sample_event";
63-
final int intValue;
64-
final String textValue;
65-
66-
SampleStructuredEvent(int intValue, String textValue) {
67-
this.intValue = intValue;
68-
this.textValue = textValue;
69-
}
70-
}
71-
72-
@Test
73-
void testObjectMessageSerializesAsNestedJsonObject() {
74-
JsonLogFormatter formatter = new JsonLogFormatter();
75-
String output = formatter.format(new SampleStructuredEvent(42, "abc"), LogLevel.DEBUG);
76-
77-
JSONObject parsed = new JSONObject(output);
78-
JSONObject message = parsed.getJSONObject("message");
79-
assertEquals("sample_event", message.getString("event"));
80-
assertEquals(42, message.getInt("intValue"));
81-
assertEquals("abc", message.getString("textValue"));
82-
assertEquals(3, message.length());
83-
assertEquals("DEBUG", parsed.getString("level"));
84-
assertNotNull(parsed.getString("timestamp"));
85-
}
86-
87-
@Test
88-
void testObjectMessageWithLambdaContextKeepsEnvelopeFields() {
89-
JsonLogFormatter formatter = new JsonLogFormatter();
90-
formatter.setLambdaContext(new LambdaContext(
91-
0, 0, "request-id", null, null, "function-name",
92-
null, null, "function-arn", "tenant-id", null, null));
93-
String output = formatter.format(new SampleStructuredEvent(1, "x"), LogLevel.DEBUG);
94-
95-
JSONObject parsed = new JSONObject(output);
96-
assertEquals("request-id", parsed.getString("AWSRequestId"));
97-
assertEquals("tenant-id", parsed.getString("tenantId"));
98-
assertEquals(1, parsed.getJSONObject("message").getInt("intValue"));
99-
}
100-
101-
@Test
102-
void testReflectiveStringAccessToMessageFieldStillWorks() throws Exception {
103-
// StructuredLogMessage is internal, but be conservative about reflective
104-
// consumers: setting and reading a String through the field must not break.
105-
StructuredLogMessage msg = new StructuredLogMessage();
106-
java.lang.reflect.Field field = StructuredLogMessage.class.getDeclaredField("message");
107-
field.set(msg, "reflective string");
108-
assertEquals("reflective string", (String) field.get(msg));
109-
110-
PojoSerializer<StructuredLogMessage> serializer =
111-
GsonFactory.getInstance().getSerializer(StructuredLogMessage.class);
112-
java.io.ByteArrayOutputStream stream = new java.io.ByteArrayOutputStream();
113-
serializer.toJson(msg, stream);
114-
JSONObject parsed = new JSONObject(stream.toString("UTF-8"));
115-
assertEquals("reflective string", parsed.getString("message"));
116-
}
117-
118-
@Test
119-
void testStringMessageDeserializationRoundTripUnchanged() {
120-
// fromJson of a string-message log line must still yield a String in the field
121-
JsonLogFormatter formatter = new JsonLogFormatter();
122-
String output = formatter.format("round trip", LogLevel.INFO);
123-
124-
PojoSerializer<StructuredLogMessage> serializer =
125-
GsonFactory.getInstance().getSerializer(StructuredLogMessage.class);
126-
StructuredLogMessage result = serializer.fromJson(output);
127-
assertTrue(result.message instanceof String);
128-
assertEquals("round trip", result.message);
129-
}
130-
13115
@Test
13216
void testFormattingWithoutLambdaContext() {
13317
assertFormatsString("test log", LogLevel.WARN, null);

0 commit comments

Comments
 (0)