Why do I get random errors while executing jest tests that call cognito lambda triggers PostConfirmation and then PreTokenGeneration?

Question

I have one PostConfirmation lambda trigger that adds data to DynamoDB via GraphQL (appsync https call) and then I query for that info in the PreTokenGeneration lambda. When I test manually via my app UI things work. But when executing via Jest tests, 50%+ of the time I get an error due to the supposed record info not being found in DynamoDB. The problem doesn't occur when I test manually via UI app. Only when executing via Jest test.

I checked the Cloudwatch timestamps for the PostConfirmation DynamoDB record addition, PreTokenGeneration and checked the createDate in DynamoDB. The timestamps look ok. For instance:

• The PostConfirmation log entry that says the record was added has the timestamp at 2020-08-24T17:51:06.463Z.
• The DynamoDB createdAt for the added record (createdAt) says the record was created at 2020-08-24T17:51:06.377Z.
• The PostConfirmation lambda "END RequestId: xxxxx" has the timestamp at 2020-08-24T17:51:06.465-05:00
• The PreTokenGeneration lambda starts at 2020-08-24T17:51:12.866Z and at 2020-08-24T17:51:13.680Z the query result says it didn't find any record.

Can someone help me or give me a hint about why this happen and/or how can I troubleshoot this problem? Thank you in advance.

Taking into account the answers from @noel-llevares I modified the VTL template to include the ConsistentRead=true but the problem remains.

Heres is the RequestMapping logged for the save operation

{
    "logType": "RequestMapping",
    "path": [
        "createAccountMember"
    ],
    "fieldName": "createAccountMember",
    "resolverArn": "arn:aws:appsync:xx-xxxx-x:111111111:apis/<redacted>/types/Mutation/resolvers/createAccountMember",
    "requestId": "<redacted>",
    "context": {
        "arguments": {
            "input": {
                "id": "<redacted>",
                "userID": "<redacted>",
                "accountID": "<redacted>",
                "membershipStatus": "active",
                "groupsEnrolledIn": [
                    <redacted>
                ],
                "recordOwner": "<redacted>",
                "createdAt": "2020-08-25T05:11:10.917Z",
                "updatedAt": "2020-08-25T05:11:10.917Z",
                "__typename": "AccountMember"
            }
        },
        "stash": {},
        "outErrors": []
    },
    "fieldInError": false,
    "errors": [],
    "parentType": "Mutation",
    "graphQLAPIId": "<redacted>",
    "transformedTemplate": "\n\n\n\n\n\n\n\n{\n  \"version\": \"2018-05-29\",\n  \"operation\": \"PutItem\",\n  \"key\":  {\n  \"id\":   {\"S\":\"<redacted>\"}\n} ,\n  \"attributeValues\": {\"accountID\":{\"S\":\"<redacted>\"},\"createdAt\":{\"S\":\"2020-08-25T05:11:10.917Z\"},\"recordOwner\":{\"S\":\"<redacted>\"},\"__typename\":{\"S\":\"AccountMember\"},\"id\":{\"S\":\"<redacted>\"},\"membershipStatus\":{\"S\":\"active\"},\"userID\":{\"S\":\"<redacted>\"},\"groupsEnrolledIn\":{\"L\":[{\"S\":\"<redacted>\"},{\"S\":\"<redacted>\"},{\"S\":\"<redacted>\"}]},\"updatedAt\":{\"S\":\"2020-08-25T05:11:10.917Z\"}},\n  \"condition\": {\"expression\":\"attribute_not_exists(#id)\",\"expressionNames\":{\"#id\":\"id\"}}\n}\n"
}

The ResponseMapping logged for the save operation

{
    "logType": "ResponseMapping",
    "path": [
        "createAccountMember"
    ],
    "fieldName": "createAccountMember",
    "resolverArn": "<redacted>",
    "requestId": "<redacted>",
    "context": {
        "arguments": {
            "input": {
                "id": "<redacted>",
                "userID": "<redacted>",
                "accountID": "<redacted>",
                "membershipStatus": "active",
                "groupsEnrolledIn": [
                    "<redacted>",
                    "<redacted>",
                    "<redacted>"
                ],
                "recordOwner": "<redacted>",
                "createdAt": "2020-08-25T05:11:10.917Z",
                "updatedAt": "2020-08-25T05:11:10.917Z",
                "__typename": "AccountMember"
            }
        },
        "result": {
            "accountID": "<redacted>",
            "createdAt": "2020-08-25T05:11:10.917Z",
            "recordOwner": "<redacted>",
            "__typename": "AccountMember",
            "id": "<redacted>",
            "membershipStatus": "active",
            "userID": "<redacted>",
            "groupsEnrolledIn": [
                "<redacted>",
                "<redacted>",
                "<redacted>"
            ],
            "updatedAt": "2020-08-25T05:11:10.917Z"
        },
        "stash": {},
        "outErrors": []
    },
    "fieldInError": false,
    "errors": [],
    "parentType": "Mutation",
    "graphQLAPIId": "<redacted>",
    "transformedTemplate": "{\"accountID\":\"<redacted>\",\"createdAt\":\"2020-08-25T05:11:10.917Z\",\"recordOwner\":\"<redacted>\",\"__typename\":\"AccountMember\",\"id\":\"<redacted>\",\"membershipStatus\":\"active\",\"userID\":\"<redacted>\",\"groupsEnrolledIn\":[\"<redacted>\",\"<redacted>\",\"<redacted>\"],\"updatedAt\":\"2020-08-25T05:11:10.917Z\"}\n"
}

Here's is the Request mapping logged for the list operation. You can see the consistentRead=true

{
    "logType": "RequestMapping",
    "path": [
        "listAccountMembers"
    ],
    "fieldName": "listAccountMembers",
    "resolverArn": "<redacted>",
    "requestId": "<redacted>",
    "context": {
        "arguments": {
            "filter": {
                "userID": {
                    "eq": "<redacted>"
                }
            }
        },
        "stash": {},
        "outErrors": []
    },
    "fieldInError": false,
    "errors": [],
    "parentType": "Query",
    "graphQLAPIId": "<redacted>,
    "transformedTemplate": "  \n{\"version\":\"2018-05-29\",\"limit\":100,\"consistentRead\":true,\"filter\":{\"expression\":\"(#userID = :userID_eq)\",\"expressionNames\":{\"#userID\":\"userID\"},\"expressionValues\":{\":userID_eq\":{\"S\":\"<redacted>\"}}},\"operation\":\"Scan\"}"
}

Here is the responseMapping logged. You can see the result is an empty array (items:[]) even though the record has been added previously and we have specified consistentRead=true for the query.

{
    "logType": "ResponseMapping",
    "path": [
        "listAccountMembers"
    ],
    "fieldName": "listAccountMembers",
    "resolverArn": "<redacted>",
    "requestId": "<redacted>",
    "context": {
        "arguments": {
            "filter": {
                "userID": {
                    "eq": "<redacted>"
                }
            }
        },
        "result": {
            "items": [],
            "nextToken": "<redacted>",
            "scannedCount": 100
        },
        "stash": {},
        "outErrors": []
    },
    "fieldInError": false,
    "errors": [],
    "parentType": "Query",
    "graphQLAPIId": "<redacted>",
    "transformedTemplate": "\n{\"items\":[],\"nextToken\":\"<redacted>",\"scannedCount\":100,\"startedAt\":null}\n"
}

What else could I be missing?

UPDATE02

I found the possible cause. It's beacause I'm new to how DynamoDB works. The query or scan operations get the results by key. In this case there is no key involved, so it gets all the records taking the limit into account. In my case it's 100, and then it applies the filter. So if the record added is not in the first 100 results it can't find it unless I go through the paging (not good for muy specific need).

TL;DR: I changed the query to use a @key directive with userID as the key field and the problem has gone because que field is a GSI and the number of records I expect to retrieve with such partition is much less than the 100 limit. I'll add this as part of the answer as soon as I finish undoing the tweaks i previously made.

Answer 1

DynamoDB is eventually consistent by default.

According to the documentation,

When you read data from a DynamoDB table, the response might not reflect the results of a recently completed write operation. The response might include some stale data. If you repeat your read request after a short time, the response should return the latest data.

If you need to read what you just wrote immediately, you can opt to use strongly consistent reads. This is usually done by specifying ConsistentRead to true in your DynamoDB calls.

Answer 2

I found the root cause. The query or scan operations get the results by key. In this case there is no key involved, so it gets all the records taking the limit into account, in my case it's 100, and then it applies the filter. So if the record added is not in the first 100 results it can't find it unless I go through paging (not good for my specific need). I didn't notice this because I'm new to how DynamoDB works. But thank to @noel-llevares I went through more in-depth research to find a solution.

The solution was to change the query to use a @key directive with name "byUsername" that exists in the AccountMember type with userID as the key field and the problem has gone because que field is a GSI and the number of records I expect to retrieve with such partition is much less than the 100 limit.