search

alexcasalboni / aws-lambda-power-tuning

AWS Lambda Power Tuning is an open-source tool that can help you visualize and fine-tune the memory/power configuration of Lambda functions. It runs in your own AWS account - powered by AWS Step Functions - and it supports three optimization strategies: cost, speed, and balanced.
Apache License 2.0
5.27k stars 362 forks source link

Bug: Support JSON logging #232

Closed ryancausey closed 2 months ago

ryancausey commented 4 months ago

I attempted to run this using the serverless application repository deployment, which appears to be at version 4.3.3. The tags are as follows:

When it gets to the analyze step, the analyze lambda fails with the following error:

{
  "errorType": "TypeError",
  "errorMessage": "Cannot set properties of undefined (setting 'stateMachine')",
  "trace": [
    "TypeError: Cannot set properties of undefined (setting 'stateMachine')",
    "    at findOptimalConfiguration (/var/task/analyzer.js:54:26)",
    "    at Runtime.module.exports.handler (/var/task/analyzer.js:28:12)",
    "    at Runtime.handleOnceNonStreaming (file:///var/runtime/index.mjs:1173:29)"
  ]
}

I noticed that it appears that the executors failed to calculate any statistics, as all the results were 0 cost and 0 duration. Here is the full analyze step input:

{
  "lambdaARN": "arn:aws:lambda:us-west-2:12345:function:asdf",
  "powerValues": [
    128,
    256,
    512,
    1024,
    1536,
    2048,
    3008
  ],
  "num": 100,
  "payload": {
    "version": "2.0",
    "routeKey": "$default",
    "rawPath": "/",
    "rawQueryString": "",
    "headers": {
      "svix-signature": "v1,asdf=",
      "content-length": "926",
      "x-amzn-tls-version": "TLSv1.2",
      "x-forwarded-proto": "https",
      "x-forwarded-port": "443",
      "x-forwarded-for": "1.2.3.4",
      "accept": "*/*",
      "svix-id": "msg_asdf",
      "x-amzn-tls-cipher-suite": "ECDHE-RSA-AES128-GCM-SHA256",
      "svix-timestamp": "1707441209",
      "x-amzn-trace-id": "Root=1-asdf",
      "host": "asdf.lambda-url.us-west-2.on.aws",
      "content-type": "application/json",
      "user-agent": "Svix-Webhooks/1.17.0"
    },
    "requestContext": {
      "accountId": "anonymous",
      "apiId": "asdf",
      "domainName": "asdf.lambda-url.us-west-2.on.aws",
      "domainPrefix": "asdf",
      "http": {
        "method": "POST",
        "path": "/",
        "protocol": "HTTP/1.1",
        "sourceIp": "1.2.3.4",
        "userAgent": "Svix-Webhooks/1.17.0"
      },
      "requestId": "asdf",
      "routeKey": "$default",
      "stage": "$default",
      "time": "09/Feb/2024:01:13:30 +0000",
      "timeEpoch": 1707441210405
    },
    "body": "{\"data\":{\"birthday\":\"\",\"created_at\":1654012591514,\"email_addresses\":[{\"email_address\":\"example@example.org\",\"id\":\"idn_29w83yL7CwVlJXylYLxcslromF1\",\"linked_to\":[],\"object\":\"email_address\",\"reserved\":true,\"verification\":{\"attempts\":null,\"expire_at\":null,\"status\":\"verified\",\"strategy\":\"admin\"}}],\"external_accounts\":[],\"external_id\":null,\"first_name\":\"Example\",\"gender\":\"\",\"id\":\"user_29w83sxmDNGwOuEthce5gg56FcC\",\"image_url\":\"https://img.clerk.com/xxxxxx\",\"last_name\":null,\"last_sign_in_at\":null,\"object\":\"user\",\"password_enabled\":true,\"phone_numbers\":[],\"primary_email_address_id\":\"idn_29w83yL7CwVlJXylYLxcslromF1\",\"primary_phone_number_id\":null,\"primary_web3_wallet_id\":null,\"private_metadata\":{},\"profile_image_url\":\"https://www.gravatar.com/avatar?d=mp\",\"public_metadata\":{},\"two_factor_enabled\":false,\"unsafe_metadata\":{},\"updated_at\":1654012824306,\"username\":null,\"web3_wallets\":[]},\"object\":\"event\",\"type\":\"user.updated\"}",
    "isBase64Encoded": false
  },
  "parallelInvocation": true,
  "strategy": "cost",
  "stats": [
    {
      "averagePrice": 0,
      "averageDuration": 0,
      "totalCost": 0,
      "value": 128
    },
    {
      "averagePrice": 0,
      "averageDuration": 0,
      "totalCost": 0,
      "value": 256
    },
    {
      "averagePrice": 0,
      "averageDuration": 0,
      "totalCost": 0,
      "value": 512
    },
    {
      "averagePrice": 0,
      "averageDuration": 0,
      "totalCost": 0,
      "value": 1024
    },
    {
      "averagePrice": 0,
      "averageDuration": 0,
      "totalCost": 0,
      "value": 1536
    },
    {
      "averagePrice": 0,
      "averageDuration": 0,
      "totalCost": 0,
      "value": 2048
    },
    {
      "averagePrice": 0,
      "averageDuration": 0,
      "totalCost": 0,
      "value": 3008
    }
  ]
}

I pulled this interesting snippet of logs from the end of one of the executor logs:

2024-02-09T04:41:41.956Z    asdf    INFO    us-west-2 not found in base price map, using default: 2.1e-9
2024-02-09T04:41:41.958Z    asdf    INFO    Average duration:  0
2024-02-09T04:41:42.015Z    asdf    INFO    Stats:  { averagePrice: 0, averageDuration: 0, totalCost: 0, value: 1536 }

I can see all of the target lambda invocations ended successfully, so I'm not sure why this is happening. Any ideas?

ryancausey commented 4 months ago

I suspect this may be due to using the new JSON logging type for Lambda. I instrumented the executor's parseLogAndExtractDurations function like so:

module.exports.parseLogAndExtractDurations = (data) => {
    return data.map(log => {
        const logString = utils.base64decode(log.LogResult || '');
        console.log("===========================================");
        console.log(log.logR);
        console.log("===========================================");
        return utils.extractDuration(logString);
    });
};

And it showed that the log.LogResult was always undefined.

2024-02-09T05:56:19.727Z    9b29def9-f9e6-42f6-a3d4-5673095e9406    INFO    ===========================================
2024-02-09T05:56:19.727Z    9b29def9-f9e6-42f6-a3d4-5673095e9406    INFO    undefined
2024-02-09T05:56:19.727Z    9b29def9-f9e6-42f6-a3d4-5673095e9406    INFO    ===========================================

When I turned the logging back to Text, it no longer has this issue.

alexcasalboni commented 4 months ago

@ryancausey thanks for sharing! This does look like a bug (or at least a missing support for JSON logging).

When you did this:

console.log(log.logR);

Shouldn't it be as follows?

console.log(log.LogResult);

log.logR is expected to be undefined, isn't it?

I would expect utils.extractDuration to throw an exception (or return nothing) with structured logs since it's expecting just text. But log.LogResult should be defined in both cases.

I'll need to run some more tests. Could you please share with me a basic Lambda function to deploy for this setup?

alexcasalboni commented 4 months ago

Nevermind, I managed to run some tests already :)

log.LogResult is defined as a base64-encoded string and it does contain multiple JSON objects (multi-line).

I'm going to work on a quick fix to make sure utils.extractDuration can handle JSON logging too.

alexcasalboni commented 4 months ago

I've created a PR here: https://github.com/alexcasalboni/aws-lambda-power-tuning/pull/233

It will need some new unit tests, but I've deployed and tested it in my AWS Account and it seems to work fine :)

Should be able to merge it next week!

alexcasalboni commented 4 months ago

@ryancausey this is now merged :)

I haven't published to SAR yet, but will do asap later this week (quite a few updates to document in the latest SAR version).

Let me know in case you encounter any issues or edge cases!

ryancausey commented 4 months ago

Thanks for the quick turnaround! I optimized the lambda by switching it to text logs temporarily, but next time I run the optimizer I will double check.

ryancausey commented 4 months ago

@alexcasalboni I attempted to use the power tuner today using the SAR, but it didn't work. I was using this ARN: arn:aws:serverlessrepo:us-east-1:451282441545:applications/aws-lambda-power-tuning

It looks like the SAR hasn't been updated? The serverlessrepo:semanticVersion tag still shows as 4.3.3.

alexcasalboni commented 4 months ago

@ryancausey apologies, I have not published a new version to SAR yet. Will do asap this week :)

alexcasalboni commented 4 months ago

@ryancausey done 👌 🚀

ryancausey commented 4 months ago

@alexcasalboni when I attempted to use it I received this error:

2024-03-01T04:06:02.008Z    f992f187-78f5-4ef4-aade-453dad360bd8    ERROR   Invoke Error    {
    "errorType": "SyntaxError",
    "errorMessage": "Unexpected end of JSON input",
    "stack": [
        "SyntaxError: Unexpected end of JSON input",
        "    at JSON.parse (<anonymous>)",
        "    at /var/task/utils.js:551:54",
        "    at Array.map (<anonymous>)",
        "    at module.exports.extractDurationFromJSON (/var/task/utils.js:551:35)",
        "    at module.exports.extractDuration (/var/task/utils.js:528:22)",
        "    at /var/task/utils.js:472:22",
        "    at Array.map (<anonymous>)",
        "    at module.exports.parseLogAndExtractDurations (/var/task/utils.js:470:17)",
        "    at computeStatistics (/var/task/executor.js:180:29)",
        "    at module.exports.handler (/var/task/executor.js:71:12)"
    ]
}

I noticed in the logs that there are non-JSON formatted logs from the AWS Secrets Manager extension:

[AWS Parameters and Secrets Lambda Extension] 2024/03/01 04:29:30 PARAMETERS_SECRETS_EXTENSION_LOG_LEVEL is ERROR. Log level set to error.

I'm guessing the issue is that it is somehow parsing this non-JSON value? Should I open a new issue?

alexcasalboni commented 4 months ago

Ouch 😞

Yes, the current implementation assumes that all logs are either text or JSON (not a mix of both).

I think this is worth fixing, so I'm going to reopen this issue and jump on it next week.

In the meantime, I have reached out to the extension's maintainers to figure out whether this is the expected behaviour or not (my guess is that it should align with the function's logging type).

thereallori commented 3 months ago

I attempted to run this using the serverless application repository deployment, which appears to be at version 4.3.3. The tags are as follows:

  • serverlessrepo:applicationId: arn:aws:serverlessrepo:us-east-1:451282441545:applications/aws-lambda-power-tuning

  • serverlessrepo:semanticVersion: 4.3.3

When it gets to the analyze step, the analyze lambda fails with the following error:


{

  "errorType": "TypeError",

  "errorMessage": "Cannot set properties of undefined (setting 'stateMachine')",

  "trace": [

    "TypeError: Cannot set properties of undefined (setting 'stateMachine')",

    "    at findOptimalConfiguration (/var/task/analyzer.js:54:26)",

    "    at Runtime.module.exports.handler (/var/task/analyzer.js:28:12)",

    "    at Runtime.handleOnceNonStreaming (file:///var/runtime/index.mjs:1173:29)"

  ]

}

I noticed that it appears that the executors failed to calculate any statistics, as all the results were 0 cost and 0 duration. Here is the full analyze step input:


{

  "lambdaARN": "arn:aws:lambda:us-west-2:12345:function:asdf",

  "powerValues": [

    128,

    256,

    512,

    1024,

    1536,

    2048,

    3008

  ],

  "num": 100,

  "payload": {

    "version": "2.0",

    "routeKey": "$default",

    "rawPath": "/",

    "rawQueryString": "",

    "headers": {

      "svix-signature": "v1,asdf=",

      "content-length": "926",

      "x-amzn-tls-version": "TLSv1.2",

      "x-forwarded-proto": "https",

      "x-forwarded-port": "443",

      "x-forwarded-for": "1.2.3.4",

      "accept": "*/*",

      "svix-id": "msg_asdf",

      "x-amzn-tls-cipher-suite": "ECDHE-RSA-AES128-GCM-SHA256",

      "svix-timestamp": "1707441209",

      "x-amzn-trace-id": "Root=1-asdf",

      "host": "asdf.lambda-url.us-west-2.on.aws",

      "content-type": "application/json",

      "user-agent": "Svix-Webhooks/1.17.0"

    },

    "requestContext": {

      "accountId": "anonymous",

      "apiId": "asdf",

      "domainName": "asdf.lambda-url.us-west-2.on.aws",

      "domainPrefix": "asdf",

      "http": {

        "method": "POST",

        "path": "/",

        "protocol": "HTTP/1.1",

        "sourceIp": "1.2.3.4",

        "userAgent": "Svix-Webhooks/1.17.0"

      },

      "requestId": "asdf",

      "routeKey": "$default",

      "stage": "$default",

      "time": "09/Feb/2024:01:13:30 +0000",

      "timeEpoch": 1707441210405

    },

    "body": "{\"data\":{\"birthday\":\"\",\"created_at\":1654012591514,\"email_addresses\":[{\"email_address\":\"example@example.org\",\"id\":\"idn_29w83yL7CwVlJXylYLxcslromF1\",\"linked_to\":[],\"object\":\"email_address\",\"reserved\":true,\"verification\":{\"attempts\":null,\"expire_at\":null,\"status\":\"verified\",\"strategy\":\"admin\"}}],\"external_accounts\":[],\"external_id\":null,\"first_name\":\"Example\",\"gender\":\"\",\"id\":\"user_29w83sxmDNGwOuEthce5gg56FcC\",\"image_url\":\"https://img.clerk.com/xxxxxx\",\"last_name\":null,\"last_sign_in_at\":null,\"object\":\"user\",\"password_enabled\":true,\"phone_numbers\":[],\"primary_email_address_id\":\"idn_29w83yL7CwVlJXylYLxcslromF1\",\"primary_phone_number_id\":null,\"primary_web3_wallet_id\":null,\"private_metadata\":{},\"profile_image_url\":\"https://www.gravatar.com/avatar?d=mp\",\"public_metadata\":{},\"two_factor_enabled\":false,\"unsafe_metadata\":{},\"updated_at\":1654012824306,\"username\":null,\"web3_wallets\":[]},\"object\":\"event\",\"type\":\"user.updated\"}",

    "isBase64Encoded": false

  },

  "parallelInvocation": true,

  "strategy": "cost",

  "stats": [

    {

      "averagePrice": 0,

      "averageDuration": 0,

      "totalCost": 0,

      "value": 128

    },

    {

      "averagePrice": 0,

      "averageDuration": 0,

      "totalCost": 0,

      "value": 256

    },

    {

      "averagePrice": 0,

      "averageDuration": 0,

      "totalCost": 0,

      "value": 512

    },

    {

      "averagePrice": 0,

      "averageDuration": 0,

      "totalCost": 0,

      "value": 1024

    },

    {

      "averagePrice": 0,

      "averageDuration": 0,

      "totalCost": 0,

      "value": 1536

    },

    {

      "averagePrice": 0,

      "averageDuration": 0,

      "totalCost": 0,

      "value": 2048

    },

    {

      "averagePrice": 0,

      "averageDuration": 0,

      "totalCost": 0,

      "value": 3008

    }

  ]

}

I pulled this interesting snippet of logs from the end of one of the executor logs:


2024-02-09T04:41:41.956Z  asdf    INFO    us-west-2 not found in base price map, using default: 2.1e-9

2024-02-09T04:41:41.958Z  asdf    INFO    Average duration:  0

2024-02-09T04:41:42.015Z  asdf    INFO    Stats:  { averagePrice: 0, averageDuration: 0, totalCost: 0, value: 1536 }

I can see all of the target lambda invocations ended successfully, so I'm not sure why this is happening. Any ideas?

MarcosDanielTorres-UALA commented 2 months ago

Hi. Facing a similar issue using the latest version of SAR. Input:

{
  "lambdaARN": "my_lambda_arn",
  "powerValues": [
    2048
  ],
  "num": 50,
  "payload": {}
}

Output of the executor:

{
  "errorType": "SyntaxError",
  "errorMessage": "Unexpected end of JSON input",
  "trace": [
    "SyntaxError: Unexpected end of JSON input",
    "    at JSON.parse (<anonymous>)",
    "    at /var/task/utils.js:551:54",
    "    at Array.map (<anonymous>)",
    "    at module.exports.extractDurationFromJSON (/var/task/utils.js:551:35)",
    "    at module.exports.extractDuration (/var/task/utils.js:528:22)",
    "    at /var/task/utils.js:472:22",
    "    at Array.map (<anonymous>)",
    "    at module.exports.parseLogAndExtractDurations (/var/task/utils.js:470:17)",
    "    at computeStatistics (/var/task/executor.js:180:29)",
    "    at module.exports.handler (/var/task/executor.js:71:12)"
  ]
}
alexcasalboni commented 2 months ago

Thanks for sharing!

This looks like a bug, indeed. And it probably cause by a recent update to support Lambda JSON logging.

Could you please confirm that you’re using the new JSON logging? Are you also using any Lambda Extension?

On Wed, 10 Apr 2024 at 20:32, MarcosDanielTorres-UALA < @.***> wrote:

Hi. Facing a similar issue using the latest version of SAR. Input:

{ "lambdaARN": "my_lambda_arn", "powerValues": [ 2048 ], "num": 50, "payload": {} }

Output of the executor:

{ "errorType": "SyntaxError", "errorMessage": "Unexpected end of JSON input", "trace": [ "SyntaxError: Unexpected end of JSON input", " at JSON.parse ()", " at /var/task/utils.js:551:54", " at Array.map ()", " at module.exports.extractDurationFromJSON (/var/task/utils.js:551:35)", " at module.exports.extractDuration (/var/task/utils.js:528:22)", " at /var/task/utils.js:472:22", " at Array.map ()", " at module.exports.parseLogAndExtractDurations (/var/task/utils.js:470:17)", " at computeStatistics (/var/task/executor.js:180:29)", " at module.exports.handler (/var/task/executor.js:71:12)" ] }

— Reply to this email directly, view it on GitHub https://github.com/alexcasalboni/aws-lambda-power-tuning/issues/232#issuecomment-2048203151, or unsubscribe https://github.com/notifications/unsubscribe-auth/AASX75AZNDTCPUWAQQ2MQXDY4WAUBAVCNFSM6AAAAABDA4FO5CVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDANBYGIYDGMJVGE . You are receiving this because you modified the open/close state.Message ID: @.*** com>

Malanius commented 2 months ago

Hello there, I have the same issue from the CDK install from this repo,
(ref acbcf36bf4b33907cdb051b8de7aa118f53dd8ae ) as this. This is tied to JSON logging enabled on the lambda log group. When I switched back to text logging, everything was working OK, returning to JSON logs breaks things again.

I'm also using lambda insights extensions, but didn't try running without it.

Hi. Facing a similar issue using the latest version of SAR. Input:

{
  "lambdaARN": "my_lambda_arn",
  "powerValues": [
    2048
  ],
  "num": 50,
  "payload": {}
}

Output of the executor:

{
  "errorType": "SyntaxError",
  "errorMessage": "Unexpected end of JSON input",
  "trace": [
    "SyntaxError: Unexpected end of JSON input",
    "    at JSON.parse (<anonymous>)",
    "    at /var/task/utils.js:551:54",
    "    at Array.map (<anonymous>)",
    "    at module.exports.extractDurationFromJSON (/var/task/utils.js:551:35)",
    "    at module.exports.extractDuration (/var/task/utils.js:528:22)",
    "    at /var/task/utils.js:472:22",
    "    at Array.map (<anonymous>)",
    "    at module.exports.parseLogAndExtractDurations (/var/task/utils.js:470:17)",
    "    at computeStatistics (/var/task/executor.js:180:29)",
    "    at module.exports.handler (/var/task/executor.js:71:12)"
  ]
}
alexcasalboni commented 2 months ago

Thank you all 🙏

We're currently working on a fix!

FYI @Lavanya0513

MarcosDanielTorres-UALA commented 2 months ago

Thanks for sharing! This looks like a bug, indeed. And it probably cause by a recent update to support Lambda JSON logging. Could you please confirm that you’re using the new JSON logging? Are you also using any Lambda Extension? … On Wed, 10 Apr 2024 at 20:32, MarcosDanielTorres-UALA < @.> wrote: Hi. Facing a similar issue using the latest version of SAR. Input: { "lambdaARN": "my_lambda_arn", "powerValues": [ 2048 ], "num": 50, "payload": {} } Output of the executor: { "errorType": "SyntaxError", "errorMessage": "Unexpected end of JSON input", "trace": [ "SyntaxError: Unexpected end of JSON input", " at JSON.parse ()", " at /var/task/utils.js:551:54", " at Array.map ()", " at module.exports.extractDurationFromJSON (/var/task/utils.js:551:35)", " at module.exports.extractDuration (/var/task/utils.js:528:22)", " at /var/task/utils.js:472:22", " at Array.map ()", " at module.exports.parseLogAndExtractDurations (/var/task/utils.js:470:17)", " at computeStatistics (/var/task/executor.js:180:29)", " at module.exports.handler (/var/task/executor.js:71:12)" ] } — Reply to this email directly, view it on GitHub <#232 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/AASX75AZNDTCPUWAQQ2MQXDY4WAUBAVCNFSM6AAAAABDA4FO5CVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDANBYGIYDGMJVGE . You are receiving this because you modified the open/close state.Message ID: @. com>

Thanks for reaching back out! Yes I can confirm I'm using the new json logging and no lambda extension.

I actually modified the code a bit and got it working on my own branch. I was going to commit but I saw there is a PR from 2 hours ago with the fix

alexcasalboni commented 2 months ago

@ryancausey @MarcosDanielTorres-UALA @Malanius the fix has been merged to master. Could you please confirm that it runs without errors now? (it's not deployed to SAR yet, you'll need to fork & deploy "manually").

Malanius commented 2 months ago

I've sucesfully testeed this fom 61acc54e0f4d23c4ad9d8ae8ed49cb5199afd3cf using manual SAM install and running it against same lambda with JSON logging enabled as before.

No issues with Unexpected end of JSON input or any other encountered. Given me the result as expected in execution output as well (was empty with that JSON issue). :+1:

alexcasalboni commented 2 months ago

Amazing 🚀

I'm closing this issue, please feel free to reopen it in case you're still facing the problem.