Skip to content

Commit 396f8a5

Browse files
committed
fix(telemetry): cap the printed LambdaLogExporter line, escaping included
maxRecordSizeBytes was measured on the rendered record, but the record is escaped again inside the envelope's message, so an escape-heavy record that fit the budget could print a line of about twice the limit (300,000 backslashes with new LambdaLogExporter(1_000_000) printed about 1.2 MB). export now checks the final line and, when it is over the limit, truncates the record again with the escaped envelope as the measured rendering, so the printed line is at most maxRecordSizeBytes.
1 parent 9d1e06d commit 396f8a5

3 files changed

Lines changed: 67 additions & 43 deletions

File tree

‎telemetry-exporter/README.md‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -205,12 +205,12 @@ one event per record to `{logStreamPrefix}YYYY/MM/DD` (IAM: `logs:CreateLogStrea
205205
`{"timestamp":"<UTC, 3 fraction digits>Z","level":"INFO","message":"<compact record JSON>"}`,
206206
because the JS readers of this destination filter on `level` and parse `message`. The Node
207207
runtime adds this envelope around `console.log`; Java `System.out` is not wrapped, and Lambda
208-
does not re-wrap a line that is already JSON. `maxRecordSizeBytes` is measured on the record
209-
(`render`), not on the printed line. The record is embedded in `message` as a JSON string, so
210-
every `"` and `\` in it is escaped again: the line is the record plus 68 bytes plus one byte
211-
per quote or backslash in the record, and can be up to about twice the record size
212-
(`2 × maxRecordSizeBytes + 68` in the worst case, about 512 KB with the default 256,000). That
213-
is within the CloudWatch Logs limit of 1 MB per log event.
208+
does not re-wrap a line that is already JSON. `maxRecordSizeBytes` caps the printed line,
209+
envelope included. The record is embedded in `message` as a JSON string, so every `"` and `\`
210+
in it is escaped again and the line can be up to about twice the record. When the line is over
211+
the limit, the exporter truncates the record again, measuring the escaped envelope, until the
212+
line fits. With the default 256,000, or any limit up to 1 MB, every line is within the
213+
CloudWatch Logs limit of 1 MB per log event.
214214
`LambdaLogExporter` lines are INFO; an application log level of WARN or above drops them.
215215
This line shape is a breaking change: 2.3.0 printed the bare record JSON, so a reader that
216216
parsed each stdout line as a record must now parse `message`.

‎telemetry-exporter/src/main/java/software/amazon/lambda/durable/telemetry/exporters/LambdaLogExporter.java‎

Lines changed: 28 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22
// SPDX-License-Identifier: Apache-2.0
33
package software.amazon.lambda.durable.telemetry.exporters;
44

5+
import java.nio.charset.StandardCharsets;
56
import java.time.Instant;
67
import java.time.ZoneOffset;
78
import java.time.format.DateTimeFormatter;
@@ -11,6 +12,7 @@
1112
import software.amazon.lambda.durable.telemetry.DurableExecutionTelemetryRecord;
1213
import software.amazon.lambda.durable.telemetry.Json;
1314
import software.amazon.lambda.durable.telemetry.TelemetryExporter;
15+
import software.amazon.lambda.durable.telemetry.Truncation;
1416

1517
/**
1618
* Exports workflow telemetry records to CloudWatch Logs via {@code System.out.println} (Lambda captures stdout to the
@@ -22,11 +24,11 @@
2224
* runtime adds that envelope around {@code console.log}, but Java {@code System.out} is not wrapped, so this exporter
2325
* writes it itself; Lambda does not re-wrap a line that is already JSON.
2426
*
25-
* <p><b>Line size.</b> {@link #maxRecordSizeBytes()} is measured on the record ({@link #render}), not on the printed
26-
* line. The record is embedded in {@code message} as a JSON string, so every {@code "} and {@code \} in it is escaped
27-
* again: the line is the record plus 68 bytes of envelope plus one byte per quote or backslash in the record, so it can
28-
* be up to about twice the record size ({@code 2 × maxRecordSizeBytes + 68} in the worst case). With the default
29-
* 256,000-byte limit that is about 512 KB, within the CloudWatch Logs limit of 1 MB per log event.
27+
* <p><b>Line size.</b> {@link #maxRecordSizeBytes()} caps the printed line, envelope included. The record is embedded
28+
* in {@code message} as a JSON string, so every {@code "} and {@code \} in it is escaped again and the line can be up
29+
* to about twice the record. When the line is over the limit, {@link #export} truncates the record again, measuring the
30+
* escaped envelope, until the line fits. With the default 256,000-byte limit every line stays well within the
31+
* CloudWatch Logs limit of 1 MB per log event, and so does any limit up to 1 MB.
3032
*
3133
* <p>Lines are written with {@code "level":"INFO"}. With the Lambda JSON log format and an application log level of
3234
* {@code WARN} or above, Lambda drops them.
@@ -37,10 +39,7 @@ public final class LambdaLogExporter implements TelemetryExporter {
3739
private static final DateTimeFormatter TIMESTAMP =
3840
DateTimeFormatter.ofPattern("uuuu-MM-dd'T'HH:mm:ss.SSS'Z'").withZone(ZoneOffset.UTC);
3941

40-
/**
41-
* Budget for the rendered record, not the printed line (see the class documentation). The default 256,000 keeps the
42-
* worst-case escaped line (about 512 KB) under the CloudWatch Logs limit of 1 MB per log event.
43-
*/
42+
/** Budget for the printed line, envelope included (see the class documentation). */
4443
private final Integer maxRecordSizeBytes;
4544

4645
public LambdaLogExporter() {
@@ -63,15 +62,33 @@ public Object render(DurableExecutionTelemetryRecord record) {
6362

6463
@Override
6564
public void export(DurableExecutionTelemetryRecord record) {
66-
System.out.println(logLine(Json.stringify(render(record)), Instant.now()));
65+
System.out.println(fittedLine(record, maxRecordSizeBytes, Instant.now()));
66+
}
67+
68+
/**
69+
* Returns the envelope line for {@code record}, truncated so that the line, escaping included, is at most
70+
* {@code maxBytes} bytes. The record passed in was truncated against {@link #render}, which does not count the
71+
* second escaping of {@code message}, so it is truncated again here with the envelope as the measured rendering.
72+
*/
73+
String fittedLine(DurableExecutionTelemetryRecord record, Integer maxBytes, Instant now) {
74+
String line = logLine(Json.stringify(render(record)), now);
75+
if (maxBytes == null || maxBytes <= 0 || line.getBytes(StandardCharsets.UTF_8).length <= maxBytes) {
76+
return line;
77+
}
78+
var fitted = Truncation.truncateRecord(record, maxBytes, r -> envelope(Json.stringify(render(r)), now));
79+
return logLine(Json.stringify(render(fitted)), now);
6780
}
6881

6982
/** Builds the one-line Lambda JSON log envelope; keys in the shared cross-SDK order. */
7083
static String logLine(String recordJson, Instant now) {
84+
return Json.stringify(envelope(recordJson, now));
85+
}
86+
87+
private static Map<String, Object> envelope(String recordJson, Instant now) {
7188
Map<String, Object> line = new LinkedHashMap<>();
7289
line.put("timestamp", TIMESTAMP.format(now));
7390
line.put("level", "INFO");
7491
line.put("message", recordJson);
75-
return Json.stringify(line);
92+
return line;
7693
}
7794
}

‎telemetry-exporter/src/test/java/software/amazon/lambda/durable/telemetry/exporters/LambdaLogExporterTest.java‎

Lines changed: 33 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -33,11 +33,15 @@ class LambdaLogExporterTest {
3333
private static final Pattern READER_MESSAGE_FILTER = Pattern.compile("DurableExecutionTelemetry");
3434

3535
private static String exportAndCapture(DurableExecutionTelemetryRecord record) {
36+
return exportAndCapture(new LambdaLogExporter(), record);
37+
}
38+
39+
private static String exportAndCapture(LambdaLogExporter exporter, DurableExecutionTelemetryRecord record) {
3640
PrintStream original = System.out;
3741
ByteArrayOutputStream buffer = new ByteArrayOutputStream();
3842
try (PrintStream capture = new PrintStream(buffer, true, StandardCharsets.UTF_8)) {
3943
System.setOut(capture);
40-
new LambdaLogExporter().export(record);
44+
exporter.export(record);
4145
} finally {
4246
System.setOut(original);
4347
}
@@ -84,21 +88,16 @@ void timestampAlwaysHasThreeFractionDigitsInUtc() {
8488
}
8589

8690
@Test
87-
void truncationIsMeasuredOnTheRecordNotTheEnvelope() {
91+
void lineThatFitsIsPrintedWhole() {
8892
var record = RecordFactory.sample();
8993
var exporter = new LambdaLogExporter();
90-
int recordBytes = Json.byteSize(exporter.render(record));
91-
92-
// A limit equal to the rendered record keeps it whole, even though the printed envelope line is larger.
93-
var shaped = Truncation.truncateRecord(record, recordBytes, exporter::render);
94-
assertSame(record, shaped);
95-
assertFalse(shaped.toWireMap().containsKey("truncated"));
96-
String line = exportAndCapture(shaped).strip();
97-
String recordJson = Json.stringify(exporter.render(shaped));
94+
String line = exportAndCapture(record).strip();
95+
String recordJson = Json.stringify(exporter.render(record));
9896
assertEquals(
99-
recordBytes + ENVELOPE_BYTES + escapedChars(recordJson),
97+
Json.byteSize(exporter.render(record)) + ENVELOPE_BYTES + escapedChars(recordJson),
10098
line.getBytes(StandardCharsets.UTF_8).length,
10199
"line = record + 68-byte envelope + one byte per quote or backslash in the record");
100+
assertFalse(line.contains("\\\"truncated\\\""), "not truncated: " + line);
102101
}
103102

104103
/** Bytes the envelope adds around an empty {@code message}. */
@@ -115,23 +114,31 @@ void envelopeAddsSixtyEightBytes() {
115114
}
116115

117116
/**
118-
* An escape-heavy record just under the default 256,000-byte budget is not truncated, and its printed line is about
119-
* twice the record: at most {@code 2 × maxRecordSizeBytes + 68}, and under the 1 MB CloudWatch Logs event limit.
117+
* The limit caps the printed line, escaping included. An escape-heavy record that fits the record budget but whose
118+
* line does not (300,000 backslashes are about 600 KB of record and 1.2 MB of line) is truncated again until the
119+
* line fits; its message still parses and says it was truncated.
120120
*/
121121
@Test
122-
void escapeHeavyRecordNearTheLimitDoublesButStaysUnderOneMegabyte() {
123-
var exporter = new LambdaLogExporter();
124-
int limit = exporter.maxRecordSizeBytes();
125-
for (char ch : new char[] {'"', '\\'}) {
126-
var record = RecordFactory.sampleWithInput(String.valueOf(ch).repeat(127_000));
127-
int recordBytes = Json.byteSize(exporter.render(record));
128-
assertTrue(recordBytes <= limit && recordBytes > limit - 2_000, "record near the limit: " + recordBytes);
129-
var shaped = Truncation.truncateRecord(record, limit, exporter::render);
130-
assertSame(record, shaped, "not truncated");
131-
int lineBytes = exportAndCapture(shaped).strip().getBytes(StandardCharsets.UTF_8).length;
132-
assertTrue(lineBytes > 2 * recordBytes - 1_000, "line about twice the record: " + lineBytes);
133-
assertTrue(lineBytes <= 2 * limit + ENVELOPE_BYTES, "line within 2 x limit + 68: " + lineBytes);
134-
assertTrue(lineBytes < 1_048_576, "line under the 1 MB CloudWatch Logs event limit: " + lineBytes);
122+
@SuppressWarnings("unchecked")
123+
void escapeHeavyRecordIsTruncatedUntilThePrintedLineFits() throws Exception {
124+
for (int limit : new int[] {256_000, 1_000_000}) {
125+
var exporter = new LambdaLogExporter(limit);
126+
for (char ch : new char[] {'"', '\\'}) {
127+
int count = limit == 1_000_000 ? 300_000 : 127_000;
128+
var record = RecordFactory.sampleWithInput(String.valueOf(ch).repeat(count));
129+
int recordBytes = Json.byteSize(exporter.render(record));
130+
assertTrue(recordBytes <= limit, "record fits the record budget: " + recordBytes);
131+
var shaped = Truncation.truncateRecord(record, limit, exporter::render);
132+
assertSame(record, shaped, "record-level truncation keeps it whole");
133+
134+
String line = exportAndCapture(exporter, shaped).strip();
135+
int lineBytes = line.getBytes(StandardCharsets.UTF_8).length;
136+
assertTrue(lineBytes <= limit, limit + ": printed line within the limit: " + lineBytes);
137+
Map<String, Object> envelope = MAPPER.readValue(line, Map.class);
138+
Map<String, Object> parsed = MAPPER.readValue((String) envelope.get("message"), Map.class);
139+
assertEquals(Boolean.TRUE, parsed.get("truncated"), "record says it was truncated");
140+
assertEquals(record.executionArn(), parsed.get("executionArn"));
141+
}
135142
}
136143
}
137144
}

0 commit comments

Comments
 (0)