DynamoDB #query method returns response with items = nil
andrykonchin opened this issue · 18 comments
Describe the bug
Initial issue (Dynamoid/dynamoid#516) was reported in Dynamoid project. It seems the #query (link) method may return sometimes response with #items equal nil.
Expected Behavior
I would expect QueryOutput#items to return Array of items or at least an empty Array if there are no items to fetch as the documentation states.
https://docs.aws.amazon.com/sdk-for-ruby/v3/api/Aws/DynamoDB/Client.html#query-instance_method
Current Behavior
QueryOutput#items returns nil
Reproduction Steps
There is no way to constantly reproduce the issue. The issue is being reproduced occasionally.
Possible Solution
No response
Additional Information/Context
A GSI is used in the query
Gem name ('aws-sdk', 'aws-sdk-resources' or service gems like 'aws-sdk-s3') and its version
aws-sdk-dynamodb 1.80.0
Environment details (Version of Ruby, OS environment)
Ruby 3.0
That member should always be present. Can you try to reproduce and get a wire trace with http_wire_trace: true as a Client config option?
Thank you! We will try to get the logs.
Hi, I believe I managed to reproduce and find the wire trace logs for this:
<- \"POST / HTTP/1.1\\r\\nAccept-Encoding: \\r\\nUser-Agent: aws-sdk-ruby3/3.168.4 ruby/3.0.6 aarch64-linux aws-sdk-dynamodb/1.80.0\\r\\nContent-Type: application/x-amz-json-1.0\\r\\nX-Amz-Target: DynamoDB_20120810.Query\\r\\nHost: dynamodb.us-west-2.amazonaws.com\\r\\nX-Amz-Date: 20231002T185533Z\\r\\nX-Amz-Content-Sha256: 936f1fa1f673dd94776a3e122dbdb15f6db26ecfa032f8be5e93554a83972e8b\\r\\nAuthorization: AWS4-HMAC-SHA256 Credential=AKIAJGVPQQR46W7CRMPA/20231002/us-west-2/dynamodb/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-target, Signature=fa09d4979a5dcb8c782274012c065eccc9ccf03ce642e46c356c0cd79a863ed1\\r\\nContent-Length: 449\\r\\nAccept: */*\\r\\n\\r\\n\"
-> \"HTTP/1.1 200 OK\\r\\n\"
-> \"Server: Server\\r\\n\"
-> \"Date: Mon, 02 Oct 2023 18:55:33 GMT\\r\\n\"
-> \"Content-Type: application/x-amz-json-1.0\\r\\n\"
-> \"Content-Length: 2\\r\\n\"
-> \"Connection: keep-alive\\r\\n\"
-> \"x-amzn-RequestId: BRBGGA6F0MJKJ7B9KO1LUPT31JVV4KQNSO5AEMVJF66Q9ASUAAJG\\r\\n\"
-> \"x-amz-crc32: 2745614147\\r\\n\"
-> \"\\r\\n\"
reading 2 bytes...
-> \"{}\"
From what I understand, it should log -> \"{\\\"Count\\\":0,\\\"Items\\\":[],\\\"ScannedCount\\\":0}\" if there are 0 items returned.
I did notice the content length in the header is only 2, which seems incorrect.
Wow! Thanks. We will forward this request Id to the DynamoDB team and have them investigate. This is either an undocumented behavior or just a bug (probably the latter).
FWIW content length is correct assuming the body is {}
Thanks!
Hi @rhuang, while we wait for the service team to respond, could you please let me know if you use any proxy that may be in the middle of the request?
Thanks!
No, there is no proxy.
@rhuang Can you share any surrounding code? DynamoDb is still investigating, and somehow this is being treated as a PutItem request (hence empty response), but the Ruby SDK looks to correctly set the target header to be a query operation.
@andrykonchin Might be better suited to answer since I'm using his Dynamoid gem to make the request. I believe it breaks here, where page.items returns nil: https://github.com/Dynamoid/dynamoid/blob/f8fb70c51188b566496eff3d6fbc068a1b0875dc/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb#L519
I had pasted the backtrace here as well: Dynamoid/dynamoid#516 (comment)
On my end, Questionnaire.where(client_id: client_id) is a query against a GSI on the "QUESTIONNAIRES" table, where the client_id is the hash key of the GSI.
My app makes this call all the time, and it only sometimes throws the nil error from inside Dynamoid.
DynamoDB team is asking for us to reproduce again, not just with that wire trace option, but also if we can output the body of the request. Ruby's Net::HTTP http debug option doesn't do this by default unfortunately.
Can you add this plugin to your DynamoDB client (once before initialization) and try to reproduce? It prints out the body and then rewinds, and continues calling SDK code.
class PrintHttpBody < Seahorse::Client::Plugin
class Handler < Seahorse::Client::Handler
def call(context)
puts "HTTP REQUEST BODY:"
puts context.http_request.body.read
context.http_request.body.rewind
@handler.call(context)
end
end
def add_handlers(handlers, cfg)
handlers.add(Handler, step: :sign, priority: 99)
end
end
Aws::DynamoDB::Client.add_plugin(PrintHttpBody)
Is your application multi threaded or have multiple connections or use multiple dynamodb clients in any way?
I found 2 requests. I might have gotten the "HTTP REQUEST BODY" logs mixed up between the 2 requests. They are very close in time proximity so I can't tell which is which. Let me know if you need more information.
-> "HTTP/1.1 200 OK\r\n"
-> "Server: Server\r\n"
-> "Date: Wed, 18 Oct 2023 07:04:45 GMT\r\n"
-> "Content-Type: application/x-amz-json-1.0\r\n"
-> "Content-Length: 2\r\n"
-> "Connection: keep-alive\r\n"
-> "x-amzn-RequestId: BMDREEJBMN0D51Q169LP9LLQONVV4KQNSO5AEMVJF66Q9ASUAAJG\r\n"
-> "x-amz-crc32: 2745614147\r\n"
-> "\r\n"
reading 2 bytes...
-> "{}"
read 2 bytes
HTTP REQUEST BODY: {"ConsistentRead":false,"ScanIndexForward":true,"IndexName":"INDEX_FOR_CLIENT_ID_AND_CASE_ID","TableName":"STAGING_QUESTIONNAIRES","KeyConditions":{"client_id":{"ComparisonOperator":"EQ","AttributeValueList":[{"S":"fb66433e2ac2837ef741"}]},"case_id":{"ComparisonOperator":"EQ","AttributeValueList":[{"S":"55eb47"}]}},"QueryFilter":{}}
<- "POST / HTTP/1.1\r\nAccept-Encoding: \r\nUser-Agent: aws-sdk-ruby3/3.168.4 ruby/3.0.6 aarch64-linux aws-sdk-dynamodb/1.80.0\r\nContent-Type: application/x-amz-json-1.0\r\nX-Amz-Target: DynamoDB_20120810.PutItem\r\nHost: dynamodb.us-west-2.amazonaws.com\r\nX-Amz-Date: 20231018T070445Z\r\nX-Amz-Content-Sha256: 739b30c5771bc7757223d29dc303591278af15c58a10a33102e1d37fd72d103f\r\nAuthorization: AWS4-HMAC-SHA256 Credential=AKIAJGVPQQR46W7CRMPA/20231018/us-west-2/dynamodb/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-target, Signature=ea8a8e2f05230263a94884bee7704caadfae6360f0368ce541e415e978d98fd2\r\nContent-Length: 769\r\nAccept: */*\r\n\r\n"
-> "HTTP/1.1 200 OK\r\n"
-> "Server: Server\r\n"
-> "Date: Wed, 18 Oct 2023 07:04:45 GMT\r\n"
-> "Content-Type: application/x-amz-json-1.0\r\n"
-> "Content-Length: 2\r\n"
-> "Connection: keep-alive\r\n"
-> "x-amzn-RequestId: 039BO0LGCOP8NCTDDH9JA1HD7BVV4KQNSO5AEMVJF66Q9ASUAAJG\r\n"
-> "x-amz-crc32: 2745614147\r\n"
-> "\r\n"
reading 2 bytes...
-> "{}"
Conn keep-alive
HTTP REQUEST BODY: {"ConsistentRead":false,"ScanIndexForward":true,"IndexName":"INDEX_FOR_CLIENT_ID_AND_CASE_ID","TableName":"STAGING_QUESTIONNAIRES","KeyConditions":{"client_id":{"ComparisonOperator":"EQ","AttributeValueList":[{"S":"697283f3e3b8a172154a"}]},"case_id":{"ComparisonOperator":"EQ","AttributeValueList":[{"S":"6f182c"}]}},"QueryFilter":{}}
The second snippet looks to be a PutItem with X-Amz-Target: DynamoDB_20120810.PutItem
Do you have the request headers for the first snippet?
In both cases, the body is intended for query. Dynamoid may not be forwarding arguments to the correct client calls in some cases.
DynamoDB team pulled the request ids and found that they are both put item requests getting query request body (query params). Common sense would say that if this were an issue with the SDK, more than one customer would be affected.. I am thinking this is an issue in dynamoid or usage of it.
Thank you! I will close the issue for now.
⚠️ COMMENT VISIBILITY WARNING⚠️
Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.