diff --git a/lambda/utils.js b/lambda/utils.js index 745c58d..dc73556 100644 --- a/lambda/utils.js +++ b/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; }; diff --git a/test/unit/test-utils.js b/test/unit/test-utils.js index f70c19a..90b871d 100644 --- a/test/unit/test-utils.js +++ b/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(); + }); + }); });