Unrecognized JSON log error

[guillaume-gc]

I'm experimenting with this tool, which is amazing! Unfortunately, I'm getting this error:

2024-10-03T15:20:17.838Z	e6ffdb72-1be8-4e9d-90f4-b66850933570	ERROR	Invoke Error 	
{
    "errorType": "Error",
    "errorMessage": "Unrecognized JSON log",
    "stack": [
        "Error: Unrecognized JSON log",
        "    at module.exports.extractDurationFromJSON (/var/task/utils.js:673:11)",
        "    at module.exports.extractDuration (/var/task/utils.js:616:22)",
        "    at /var/task/utils.js:544:22",
        "    at Array.map (<anonymous>)",
        "    at module.exports.parseLogAndExtractDurations (/var/task/utils.js:538:17)",
        "    at computeStatistics (/var/task/executor.js:197:34)",
        "    at module.exports.handler (/var/task/executor.js:77:12)",
        "    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)"
    ]
}

Here is some context, with all information redacted:

2024-10-03T15:20:17.837Z	e6ffdb72-1be8-4e9d-90f4-b66850933570	ERROR	Detected invalid JSON line: 
{
    "PutRequest": {
        "Item": {
            "PK": "REDACTED",
            "SK": "REDACTED",
            "ResourceType": "REDACTED",
            "ResourceId": "REDACTED",
            "ResourceSubject": "REDACTED",
            "VersionId": "REDACTED,
            "ChannelType": "REDACTED",
            "TeamId": "REDACTED",
            "CreatedAt": -1,
            "CreatedBy": "REDACTED",
            "InternalVersionId": "REDACTED"
        }
    }
}
]}}}

I assume the issue is caused by the ] character?

Here is log that appears to be causing the issue:

{
    "cold_start": false,
    "function_arn": "REDACTED:RAM8182",
    "function_memory_size": "8182",
    "function_name": "REDACTED",
    "function_request_id": "REDACTED",
    "level": "DEBUG",
    "message": "REDACTED",
    "sampling_rate": 0,
    "service": "REDACTED",
    "timestamp": "REDACTED",
    "xray_trace_id": "REDACTED",
    "teamId": "REDACTED",
    "resourceId": "REDACTED",
    "resourceType": "REDACTED",
    "env": "REDACTED",
    "gitBranch": "REDACTED",
    "tenant": "REDACTED",
    "input": {
        "RequestItems": {
            "REDACTED": [
                {
                    "PutRequest": {
                        "Item": {
                            "PK": "REDACTED",
                            "SK": "REDACTED",
                            "ResourceType": "REDACTED",
                            "ResourceId": "REDACTED",
                            "ResourceSubject": "REDACTED",
                            "VersionId": "REDACTED",
                            "ChannelType": "REDACTED",
                            "TeamId": "REDACTED",
                            "CreatedAt": -1,
                            "CreatedBy": "REDACTED",
                            "InternalVersionId": "REDACTED"
                        }
                    }
                },
                {
                    "PutRequest": {
                        "Item": {
                            "PK": "REDACTED",
                            "SK": "REDACTED",
                            "ResourceType": "REDACTED",
                            "ResourceId": "REDACTED",
                            "ResourceSubject": "REDACTED",
                            "VersionId": "REDACTED",
                            "ChannelType": "REDACTED",
                            "TeamId": "REDACTED",
                            "CreatedAt": -1,
                            "CreatedBy": "REDACTED",
                            "InternalVersionId": "REDACTED"
                        }
                    }
                }
            ]
        }
    }
}

Here is the Step Functions input, without the payload key:

{
  "lambdaARN": "REDACTED",
  "num": 25,
  "powerValues": [
    "128",
    "256",
    "512",
    "1024",
    "2048",
    "4096",
    "8182"
  ],
  "parallelInvocation": false,
  "dryRun": false,
  "onlyColdStarts": false,
  "discardTopBottom": 0.2
}

[alexcasalboni]

Hi @guillaume-gc 👋 thanks for sharing!

This is probably a duplicate of #253 :)

Thanks for sharing the logs as well! There seems to be some kind of problem with the JSON formatting (is it multi-line?). What kind of logger are you using? Is it Lambda Power Tools?

Could you please share the raw logs? (without formatting or multi-line)

Context: Lambda Power Tuning assumes that there is one log per line (separated by \n), which is what CloudWatch does by default. If the log is "prettified" or split into multiple lines, it becomes problematic.

[guillaume-gc]

Hi @alexcasalboni! You're welcome! Apologies if it's a duplicate, it seems the error message is a bit different so I couldn't find it.

I'm using Lambda Power Tools with TypeScript to manage logs. In the CloudWatch console, the logs have the same format as in this issue. I'm unsure whether Lambda Power Tools formats the logs in this manner before sending them to CloudWatch, or if the CloudWatch console automatically formats all JSON logs to improve user experience. I've viewed the logs in plain text, and nothing changed, which suggests that it may be the former. 🤷

One important detail is that I've successfully used your tool on some of my lambda functions before, which also have Lambda Power Tools with (I believe) the same configuration for logging. If the issue is only caused by sending logs with line breaks inside, which is something Lambda Power Tools seems to do, I suppose it would have occurred sooner? I've also ""solved"" this issue by adjusting the logging level to INFO, as the log that seems to be causing the issue was set to DEBUG.

[alexcasalboni]

@guillaume-gc ah, that's interesting! is it possible that DEBUG logs are prettified intentionally to improve the debugging experience? 🤔

[guillaume-gc]

@alexcasalboni as far as I know, no this is not the case.

Here is an example of a INFO log, still in plain text:

{
    "cold_start": true,
    "function_arn": "REDACTED",
    "function_memory_size": "128",
    "function_name": "REDACTED",
    "function_request_id": "REDACTED",
    "level": "INFO",
    "message": "Query is authorized",
    "sampling_rate": 0,
    "service": "REDACTED",
    "timestamp": "REDACTED",
    "xray_trace_id": "REDACTED"
}

As you can see, it's also prettified. Same with ERROR or WARNING log message.

The only difference I see between logs that are causing the issue and those who are not is the prettified array, and the error message also only included an array closing bracket (and no opening bracket). It could just be coincidental of course, I don't have enough examples to check for a real pattern.

[patmeiler]

Hey @alexcasalboni and @guillaume-gc , the error has nothing to do with the log format. The problem seems to be that the actual durationMs is missing in the JSON log.

[alexcasalboni]

@patmeiler mmm and why would that happen? Is there an alternative field on its place? Or it's just missing entirely?

[patmeiler]

@alexcasalboni in the code, we invoke the Lambda by using the Invoke action (duh, right?!). Part of the response is LogResult, the last 4 KB of base64-encoded execution log. My hypothesis is, that in some cases, the durationMs is not part of the 4KB anymore.
I am currently working on improved JSON handling and better error logs. But I'm also researching how to mitigate the issue.