Repository: alexcasalboni/aws-lambda-power-tuning
Pull request #243 (2024-04-11 12:55:27)

Fix for issue #232


Patch:
diff --git a/lambda/utils.js b/lambda/utils.js
index fb2ba7b..e83603c 100644
--- a/lambda/utils.js
+++ b/lambda/utils.js
@@ -554,8 +554,14 @@ module.exports.extractDurationFromText = (log) => {
  */
 module.exports.extractDurationFromJSON = (log) => {
     // extract each line and parse it to JSON object
-    const lines = log.split('\n').map((line) => JSON.parse(line));
-
+    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 '';
+       }
+    });
     // find the log corresponding to the invocation report
     const durationLine = lines.find((line) => line.type === 'platform.report');
     if (durationLine){


Test patch:
diff --git a/test/unit/test-utils.js b/test/unit/test-utils.js
index 6a42a12..ae590e1 100644
--- a/test/unit/test-utils.js
+++ b/test/unit/test-utils.js
@@ -179,7 +179,23 @@ describe('Lambda Utils', () => {
             '{"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}}}'
             ;
+        
+        const jsonMixedLog =
+            '{"timestamp":"2024-02-09T08:42:44.078Z","level":"INFO","requestId":"d661f7cf-9208-46b9-85b0-213b04a91065","message":"Just some logs here =)"}\n' +
+            '[AWS Parameters and Secrets Lambda Extension] 2024/04/11 02:14:17 PARAMETERS_SECRETS_EXTENSION_LOG_LEVEL is info. Log level set to info.' +
+            '{"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":4,"memorySizeMB":1024,"maxMemoryUsedMB":68}}}'
+            ;
 
+        const jsonMixedLogWithInvalidJSON =
+            '{"timestamp":"2024-02-09T08:42:44.078Z","level":"INFO","requestId":"d661f7cf-9208-46b9-85b0-213b04a91065","message":"Just some logs here =)"\n' + // missing } here
+            '[AWS Parameters and Secrets Lambda Extension] 2024/04/11 02:14:17 PARAMETERS_SECRETS_EXTENSION_LOG_LEVEL is info. Log level set to info.' +
+            '{"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":8,"memorySizeMB":1024,"maxMemoryUsedMB":68}}}'
+            ;
+        
         it('should extract the duration from a Lambda log (text format)', () => {
             expect(utils.extractDuration(textLog)).to.be(500);
         });
@@ -194,6 +210,14 @@ describe('Lambda Utils', () => {
             expect(utils.extractDuration(jsonLog)).to.be(2);
         });
 
+        it('should extract the duration from a Lambda log (json text mixed format)', () => {
+            expect(utils.extractDuration(jsonMixedLog)).to.be(4);
+        });
+
+        it('should extract the duration from a Lambda log (json text mixed format with invalid JSON)', () => {
+            expect(utils.extractDuration(jsonMixedLogWithInvalidJSON)).to.be(8);
+        });
+
         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();