Bug: idempotency dynamoDB cache doesn't read correct value

[mrerichoffman]

Expected Behavior

When using the Idempotency utility with ddb persistence, the utility should return the result of a previous operation from cache provided that the request is handled by the same execution environment.

Current Behavior

When using ddb persistence the utility doesn't return the correct value from the cache, but instead causes a runtime error. If I revert from v2.1.0 to v1.17.0 the bug goes away.

Code snippet

import { IdempotencyConfig } from "@aws-lambda-powertools/idempotency";
import { DynamoDBPersistenceLayer } from "@aws-lambda-powertools/idempotency/dynamodb";
import { makeHandlerIdempotent } from "@aws-lambda-powertools/idempotency/middleware";
import middy from "@middy/core";

export interface ProcessResult {
  processResult: "processed" | "rejected";
}

const getDefaultIdempotencyConfigs = (eventKeyJmesPath = '["correlationId"]') => {
  const persistenceStore = new DynamoDBPersistenceLayer({
    tableName: process.env.IDEMPOTENCY_TABLE_NAME || "IdempotencyTable",
    sortKeyAttr: "sortKey"
  });
  const idempotencyConfig = new IdempotencyConfig({
    throwOnNoIdempotencyKey: true,
    eventKeyJmesPath
  });
  return {
    persistenceStore,
    idempotencyConfig
  };
};

const { persistenceStore, idempotencyConfig } = getDefaultIdempotencyConfigs();

const lambdaHandler = async (event: Record<"string", unknown>): Promise<ProcessResult> => {
  console.info("event", event);
  const processResult: ProcessResult = {
    processResult: "processed"
  };

  return processResult;
};

export const processLambda = middy(lambdaHandler).use(
  makeHandlerIdempotent({
    persistenceStore,
    config: idempotencyConfig
  })
);

Steps to Reproduce

Then run the function with the same event payload, { "correlationId": "abc-123-def-456" }, twice and observe the error (shown below) being thrown at the second execution.

Possible Solution

No response

Powertools for AWS Lambda (TypeScript) version

latest

AWS Lambda function runtime

20.x

Packaging format used

npm

Execution logs

2024-05-10T22:01:01.282Z	8034ee17-fd14-4244-8603-79500af0f7cb	ERROR	{
    "_logLevel": "error",
    "msg": "Failed to save in progress record to idempotency store. This error was caused by: Failed to put record for already existing idempotency key: svc-quick-list-name-dev-callListenerNameRules#7Hd4wd4mD/EQSj89aUna6A==.",
    "stack": "Error: Failed to save in progress record to idempotency store. This error was caused by: Failed to put record for already existing idempotency key: svc-quick-list-name-dev-callListenerNameRules#7Hd4wd4mD/EQSj89aUna6A==.\n    at IdempotencyHandler.<anonymous> (/node_modules/@aws-lambda-powertools/idempotency/lib/esm/IdempotencyHandler.js:92:27)\n    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n    at IdempotencyHandler.handleMiddyBefore (/node_modules/@aws-lambda-powertools/idempotency/lib/esm/IdempotencyHandler.js:242:32)\n    at runMiddlewares (/node_modules/@middy/core/index.js:160:21)\n    at runRequest (/node_modules/@middy/core/index.js:114:9)",
    "_tags": []
}

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #typescript channel on our Powertools for AWS Lambda Discord: Invite link

[dreamorosi]

Hi @mrerichoffman - thank you for opening the issue & providing the example.

I'm going to try to reproduce the issue on my end and will be back to you!

[dreamorosi]

Hi, I have been looking at reproducing this and I was not able to do so.

Running your exact code on a function backed by a DynamoDB table using composite primary key I was able to execute the function more than once using the same payload and observe that subsequent requests are being considered idempotent (see screenshot below):

In the sentence above I specifically called out that the DynamoDB table uses composite primary key, meaning the configuration provided to the DynamoDBPersistenceLayer class expects a partition key of type string and with name id (default), and a sort key also of type string but with name sortKey (as specified in your code using the sortKeyAttr option).

This is a non standard setup, and if you have deployed a Table using the configuration suggested in our docs, then the key schema would be with a partition key named id only. If I run your code using the default configuration I get a different runtime error Failed to update success record to idempotency store. This error was caused by: The provided key element does not match the schema, which is still the not the one you're seeing.

---

With this in mind, is there any other info that you think could be relevant in helping me reproduce the error consistently?

Alternatively, I also want to call out that this error is expected when two concurrent identical in-flight requests are being handled. As the error states, if a request arrives while a previously received identical one is still in progress, any subsequent one is rejected. This flow is detailed in this diagram in the docs and is also explained here.

If your first request failed to process and the idempotency record remained in an "in progress" state, subsequent requests made within what we call "in progress expiration" time are also rejected. This time is set to the remaining time in milliseconds before the invocation will timeout. In other words, if a request starts being processed while the function has 100 seconds remaining, the corresponding idempotency record will be placed as "in progress" with an in_progress_expiration equal to that. Any identical request that comes in that time frame while the item is still marked as "in progress" will be considered as "in flight".

This locking mechanism is necessary due to the distributed nature of Lambda, since subsequent identical requests have no way of knowing whether the first original request is still being processed (i.e. long running process) or has failed/timed out. After that in_progress_expiration has passed however, we can safely assume that if the item is still marked as "in progress", then it must have failed since by that time the Lambda function that was processing would have definitely timed out.

After that, if a new identical request comes it will be accepted and processed accordingly.

[mrerichoffman]

Sorry, I must have tested the provided sample code before I ripped out additional code to simplify testing. As it turns out the bug is reproducable when getDefaultIdempotencyConfigs is externalized into a separate npm package which is bundled to commonjs. To fix I removed the idempotency utility from the npm package and exported json configurations instead.

[dreamorosi]

Thanks for letting me know.

Just to make sure I understand, could you share an example of how to reproduce the issue?

I'd like to see if there's anything that we can either improve in the code or docs to avoid others experiencing the same problem.

Thanks!

[mrerichoffman]

Sure, I externalized the idempotency configs into an example npm package that can be installed from the attached tarball.

Updated lambda handler:

import { makeHandlerIdempotent } from "@aws-lambda-powertools/idempotency/middleware";
import middy from "@middy/core";
import { getDefaultIdempotencyConfigs } from "example-config-package";

export interface ProcessResult {
  processResult: "processed" | "rejected";
}

const { persistenceStore, idempotencyConfig } = getDefaultIdempotencyConfigs();

const lambdaHandler = async (event: Record<"string", unknown>): Promise<ProcessResult> => {
  console.info(`event`, { event });
  const processResult: ProcessResult = {
    processResult: "processed"
  };

  return processResult;
};

export const testingPowertool = middy(lambdaHandler).use(
  makeHandlerIdempotent({
    persistenceStore,
    config: idempotencyConfig
  })
);

npm package example-config-package referenced in import { getDefaultIdempotencyConfigs } from "example-config-package";

import { IdempotencyConfig } from "@aws-lambda-powertools/idempotency";
import { DynamoDBPersistenceLayer } from "@aws-lambda-powertools/idempotency/dynamodb";

export const getDefaultIdempotencyConfigs = (eventKeyJmesPath = '["correlationId"]') => {
  const persistenceStore = new DynamoDBPersistenceLayer({
    tableName: process.env.IDEMPOTENCY_TABLE_NAME || "IdempotencyTable",
    sortKeyAttr: "sortKey"
  });
  const idempotencyConfig = new IdempotencyConfig({
    throwOnNoIdempotencyKey: true,
    eventKeyJmesPath
  });
  return {
    persistenceStore,
    idempotencyConfig
  };
};

Place the tgz packed library in the root of the project.
example-config-package-v1.0.0.tgz

Reference the tzg file in package.json dependencies like this - "example-config-package": "file:./example-config-package-v1.0.0.tgz"

[dreamorosi]

Hi, I have been looking into this and I am able to reproduce the issue when I use the tarball you provided but not when I bundle/build the same utility on my end.

When deploying my function using your example-config-package and bundle it with esbuild I noticed that the Idempotency package gets included twice, once because it's pulled in by the handler, and once more because it's pulled in by the config package. This is kind of strange.

Despite this, I haven't been able to pinpoint the issue yet and due to the fact that it appears only under these specific conditions I am not sure how to troubleshoot it properly.

I'll still give it a try and get back to you.