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:
PostConfirmation log entry that says the record was added has the timestamp at 2020-08-24T17:51:06.463Z.createdAt for the added record (createdAt) says the record was created at 2020-08-24T17:51:06.377Z.PostConfirmation lambda "END RequestId: xxxxx" has the timestamp at 2020-08-24T17:51:06.465-05:002020-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.
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.