[Bug Fix] Improved JSON parsing for statistics (#268)

* improved JSON parse for statistics

* fixed linting issues

* added test to fix coverage

* Minor error message fix

* Minor refactor to avoid JSON parsing multiple times

---------

Co-authored-by: Patrick Meiler <pameiler@amazon.de>
Co-authored-by: Alex Casalboni <alexsaxmib@gmail.com>

Author: 3 people

lambda/utils.js

@@ -653,24 +653,33 @@ module.exports.extractDurationFromText = (log, durationType) => {
  * Extract duration (in ms) from a given JSON log (multi-line)  and duration type.
  */
 module.exports.extractDurationFromJSON = (log, durationType) => {
-    // extract each line and parse it to JSON object
-    const lines = log.split('\n').filter((line) => line.startsWith('{')).map((line) => {
-        try {
-            return JSON.parse(line);
-        } catch (e) {
-            console.error(`Detected invalid JSON line: ${line}`);
-            return '';
+    // Check occurance of platform.report in log
+    if (!log.includes('platform.report')) {
+        throw new Error('Invalid JSON log does not contain platform.report');
+    }
+
+    if (!log.includes(durationType)) {
+        throw new Error(`Invalid JSON log does not contain ${durationType}`);
+    }
+
+    let lines = [];
+    try {
+        const parsedLog = JSON.parse(log); // this might throw an Error (because of multi-line)
+        if (Array.isArray(parsedLog)) {
+            lines = parsedLog; // we already have a list of lines
+        } else {
+            lines.push(parsedLog); // we only have 1 line
         }
-    });
-    // find the log corresponding to the invocation report
-    const durationLine = lines.find((line) => line.type === 'platform.report');
-    if (durationLine){
-        let field = durationType;
-        // Default to 0 if the specific duration is not found in the log line
-        return durationLine.record.metrics[field] || 0;
+    } catch (e) {
+        // in case the log is not pretty printed, the string needs to be transformed first
+        console.log('Json Log not pretty printed');
+        lines = log.split('\n').filter((line) => line.includes('platform.report')).map((line) => {
+            return JSON.parse(line);
+        });
     }
 
-    throw new Error('Unrecognized JSON log');
+    const durationLine = lines.find((line) => line.type === 'platform.report');
+    return durationLine.record.metrics[durationType] || 0;
 };
 
 

test/unit/test-utils.js

@@ -1337,4 +1337,121 @@ describe('Lambda Utils', () => {
             expect(value).to.be('RAM128-1');
         });
     });
+
+    describe('extractDurationFromJSON', () => {
+        it('should handle pretty-printed logs from Powertools', () => {
+            const prettyPrintedLog = `
+            {
+            "cold_start": true,
+            "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:TestFunction",
+            "function_memory_size": "128",
+            "function_name": "TestFunction",
+            "function_request_id": "test-id",
+            "level": "INFO",
+            "message": "Lambda invocation event",
+            "timestamp": "2024-12-12T17:00:03.173Z",
+            "type": "platform.report",
+            "record": {
+                "metrics": {
+                "durationMs": 100.0,
+                "initDurationMs": 200.0
+                }
+            }
+            }`;
+            const duration = utils.extractDurationFromJSON(prettyPrintedLog, utils.DURATIONS.durationMs);
+            expect(duration).to.be(100.0);
+        });
+        it('should handle multiline pretty printed logs', () => {
+            const logLine = `
+            [{
+                "cold_start": true,
+                "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:TestFunction",
+                "function_memory_size": "128",
+                "function_name": "TestFunction",
+                "function_request_id": "test-id",
+                "level": "INFO",
+                "message": "Lambda invocation event",
+                "timestamp": "2024-12-12T17:00:03.173Z",
+                "type": "platform.report",
+                "record": {
+                    "metrics": {
+                    "durationMs": 100.0,
+                    "initDurationMs": 200.0
+                    }
+                }
+                },{
+                "cold_start": true,
+                "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:TestFunction",
+                "function_memory_size": "128",
+                "function_name": "TestFunction",
+                "function_request_id": "test-id",
+                "level": "INFO",
+                "message": "Lambda invocation event",
+                "timestamp": "2024-12-12T17:00:03.173Z",
+                "type": "platform.test",
+                "record": {
+                    "metrics": {
+                    "durationMs": 100.0,
+                    "initDurationMs": 200.0
+                    }
+                }
+            }]`;
+            const duration = utils.extractDurationFromJSON(logLine, utils.DURATIONS.durationMs);
+            expect(duration).to.be(100.0);
+        });
+        it('should handle empty lines in logs pretty printed', () => {
+            const logWithEmptyLines = `
+
+            [
+        
+        {
+        "type": "platform.report",
+        "record": {
+            "metrics": {
+            "durationMs": 100.0
+            }
+        }
+        }
+        ,
+        {
+        "some": "other log"
+        }
+        
+            ]
+
+        `;
+            const duration = utils.extractDurationFromJSON(logWithEmptyLines, utils.DURATIONS.durationMs);
+            expect(duration).to.be(100.0);
+        });
+        it('should handle logs with no platform.report', () => {
+            const logWithNoPlatformReport = `
+    {
+      "message": "some log"
+    }
+    {
+      "another": "log"
+    }`;
+            expect(() => utils.extractDurationFromJSON(logWithNoPlatformReport, utils.DURATIONS.durationMs)).to.throwError();
+        });
+        it('should handle logs with no platform.report', () => {
+            const logWithoutDurationMS = `
+            {
+            "cold_start": true,
+            "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:TestFunction",
+            "function_memory_size": "128",
+            "function_name": "TestFunction",
+            "function_request_id": "test-id",
+            "level": "INFO",
+            "message": "Lambda invocation event",
+            "timestamp": "2024-12-12T17:00:03.173Z",
+            "type": "platform.report",
+            "record": {
+                "metrics": {
+                "initDurationMs": 200.0
+                }
+            }
+            }`;
+            expect(() => utils.extractDurationFromJSON(logWithoutDurationMS, utils.DURATIONS.durationMs)).to.throwError();
+        });
+    });
 });