Merge pull request #233 from alexcasalboni/232-json-logging-support

Support JSON logging
alexcasalboni · Feb 13, 2024 · 93e7cf2 · 93e7cf2
2 parents bb8795f + 7dd4689
commit 93e7cf2
Show file tree

Hide file tree

Showing 2 changed files with 53 additions and 4 deletions.
diff --git a/lambda/utils.js b/lambda/utils.js
@@ -523,13 +523,42 @@ module.exports.computeAverageDuration = (durations, discardTopBottom) => {
  * Extract duration (in ms) from a given Lambda's CloudWatch log.
  */
 module.exports.extractDuration = (log) => {
+    if (log.charAt(0) === '{') {
+        // extract from JSON (multi-line)
+        return utils.extractDurationFromJSON(log);
+    } else {
+        // extract from text
+        return utils.extractDurationFromText(log);
+    }
+};
+
+/**
+ * Extract duration (in ms) from a given text log.
+ */
+module.exports.extractDurationFromText = (log) => {
     const regex = /\tBilled Duration: (\d+) ms/m;
     const match = regex.exec(log);
 
     if (match == null) return 0;
     return parseInt(match[1], 10);
 };
 
+/**
+ * Extract duration (in ms) from a given JSON log (multi-line).
+ */
+module.exports.extractDurationFromJSON = (log) => {
+    // extract each line and parse it to JSON object
+    const lines = log.split('\n').map((line) => JSON.parse(line));
+
+    // find the log corresponding to the invocation report
+    const durationLine = lines.find((line) => line.type === 'platform.report');
+    if (durationLine){
+        return durationLine.record.metrics.billedDurationMs;
+    }
+
+    throw new Error('Unrecognized JSON log');
+};
+
 /**
  * Encode a given string to base64.
  */
@@ -591,7 +620,7 @@ module.exports.buildVisualizationURL = (stats, baseURL) => {
     ].join(';');
 
     if (process.env.AWS_REGION.startsWith('cn-')) {
-        baseURL += "?currency=CNY";
+        baseURL += '?currency=CNY';
     }
 
     return baseURL + '#' + hash;

diff --git a/test/unit/test-utils.js b/test/unit/test-utils.js
@@ -166,19 +166,39 @@ describe('Lambda Utils', () => {
     });
 
     describe('extractDuration', () => {
-        const log =
+        const textLog =
             'START RequestId: 55bc566d-1e2c-11e7-93e6-6705ceb4c1cc Version: $LATEST\n' +
             'END RequestId: 55bc566d-1e2c-11e7-93e6-6705ceb4c1cc\n' +
             'REPORT RequestId: 55bc566d-1e2c-11e7-93e6-6705ceb4c1cc\tDuration: 469.40 ms\tBilled Duration: 500 ms\tMemory Size: 1024 MB\tMax Memory Used: 21 MB'
             ;
-        it('should extract the duration from a Lambda log', () => {
-            expect(utils.extractDuration(log)).to.be(500);
+
+        // JSON logs contain multiple objects, seperated by a newline
+        const jsonLog =
+            '{"timestamp":"2024-02-09T08:42:44.078Z","level":"INFO","requestId":"d661f7cf-9208-46b9-85b0-213b04a91065","message":"Just some logs here =)"}\n' +
+            '{"time":"2024-02-09T08:42:44.078Z","type":"platform.start","record":{"requestId":"d661f7cf-9208-46b9-85b0-213b04a91065","version":"8"}}\n' +
+            '{"time":"2024-02-09T08:42:44.079Z","type":"platform.runtimeDone","record":{"requestId":"d661f7cf-9208-46b9-85b0-213b04a91065","status":"success","spans":[{"name":"responseLatency","start":"2024-02-09T08:42:44.078Z","durationMs":0.677},{"name":"responseDuration","start":"2024-02-09T08:42:44.079Z","durationMs":0.035},{"name":"runtimeOverhead","start":"2024-02-09T08:42:44.079Z","durationMs":0.211}],"metrics":{"durationMs":1.056,"producedBytes":50}}}\n' +
+            '{"time":"2024-02-09T08:42:44.080Z","type":"platform.report","record":{"requestId":"d661f7cf-9208-46b9-85b0-213b04a91065","status":"success","metrics":{"durationMs":1.317,"billedDurationMs":2,"memorySizeMB":1024,"maxMemoryUsedMB":68}}}'
+            ;
+
+        it('should extract the duration from a Lambda log (text format)', () => {
+            expect(utils.extractDuration(textLog)).to.be(500);
         });
+
         it('should return 0 if duration is not found', () => {
             expect(utils.extractDuration('hello world')).to.be(0);
             const partialLog = 'START RequestId: 55bc566d-1e2c-11e7-93e6-6705ceb4c1cc Version: $LATEST\n';
             expect(utils.extractDuration(partialLog)).to.be(0);
         });
+
+        it('should extract the duration from a Lambda log (json format)', () => {
+            expect(utils.extractDuration(jsonLog)).to.be(2);
+        });
+
+        it('should explode if invalid json format document is provided', () => {
+            const invalidJSONLog = '{"timestamp":"2024-02-09T08:42:44.078Z","level":"INFO","requestId":"d661f7cf-9208-46b9-85b0-213b04a91065","message":"Just some logs here =)"}';
+            expect(() => utils.extractDuration(invalidJSONLog)).to.throwError();
+        });
+
     });
 
     describe('computePrice', () => {