Open rhuang opened 3 years ago
@andrykonchin
hello, any idea why this is happening? it happens occasionally, not all the time. it seems like page.items
is nil
?
Yes, it seems so. DynamoDB Query response doesn't contain the Items
attribute.
I haven't found in the DynamoDB documentation any statement that items
/Items
could be missing at all - it should be Array anyway. There is no any similar issue reported in the AWS Ruby SDK repository, so it isn't a bug that was fixed. Will ask there a question. As a workaround we can treat items' nil
value as []
but it's important to understand what happens and why.
Could you please specify a version of the aws-sdk-dynamodb
gem?
1.80.0
, thanks.
Here is a more recent stacktrace with ruby 3.0 and latest version of dynamoid. aws-sdk 3.0, aws-sdk-dynamodb 1.80.0.
undefined method `map' for nil:NilClass
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb:492:in `block (2 levels) in query'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb:35:in `<<'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb:35:in `block (3 levels) in call'
<internal:kernel>:90:in `tap'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb:34:in `block (2 levels) in call'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/middleware/limit.rb:42:in `call'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/middleware/start_key.rb:14:in `call'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/middleware/backoff.rb:15:in `call'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb:47:in `block (3 levels) in call'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb:46:in `loop'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb:46:in `block (2 levels) in call'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb:45:in `catch'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb:45:in `block in call'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb:490:in `each'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb:490:in `each'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb:490:in `block in query'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/criteria/chain.rb:549:in `each'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/criteria/chain.rb:549:in `each'
/var/app/current/vendor/bundle/ruby/3.0.0/gems/dynamoid-3.8.0/lib/dynamoid/criteria/chain.rb:549:in `block in raw_pages_via_query'
/var/app/current/app/models/client.rb:360:in `each'
This is /var/app/current/app/models/client.rb:360:
Questionnaire.where(client_id: client_id).all.force.sort_by(&:created_at).reverse
Is it possible to reproduce the issue with enabled http_wire_trace
DynamoDB client option (as it was suggested here)? I could prepare a Dynamoid branch with support of this option.
I can try. It happens every few days. My logs are stored in CloudWatch and I'm not sure how noisy http_wire_trace
could be and affect the cost.
Can you prepare the branch?
Will do. Will use the mentioned above release (3.8.0)
Is the issue reproducible on some non-production environment?
Yes, it happens for both my test and prod env, so I will try to observe my test env for it. Thanks.
Please check https://github.com/Dynamoid/dynamoid/tree/add-http-wire-trace-config-option
It should be set this way:
Dynamoid.configure do |config|
# ...
config.http_wire_trace = true
end
The output for one DynamoDB operation may look like the following:
<- "POST / HTTP/1.1\r\nAccept-Encoding: \r\nContent-Type: application/x-amz-json-1.0\r\nX-Amz-Target: DynamoDB_20120810.CreateTable\r\nUser-Agent: aws-sdk-ruby3/3.180.3 ua/2.0 api/dynamodb#1.93.1 os/macos#21 md/x86_64 lang/ruby#3.2.1 md/3.2.1 cfg/retry-mode#legacy\r\nHost: 127.0.0.1:8000\r\nX-Amz-Date: 20230926T224314Z\r\nX-Amz-Content-Sha256: 8ee93af59735becc1f6d7afa3a376c65c3eef8a2dfbf60f7cd0a4b93eb972d99\r\nAuthorization: AWS4-HMAC-SHA256 Credential=abcd/20230926/us-west-2/dynamodb/aws4_request, SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-target, Signature=861cf345d09f0c32d3dabb4e5f4f3ba8a7e4b49f01fdb960870944b035ec5301\r\nContent-Length: 279\r\nAccept: */*\r\n\r\n"
<- "{\"TableName\":\"dynamoid_tests_documents_1695768194_509\",\"KeySchema\":[{\"AttributeName\":\"id\",\"KeyType\":\"HASH\"}],\"AttributeDefinitions\":[{\"AttributeName\":\"id\",\"AttributeType\":\"S\"}],\"BillingMode\":\"PROVISIONED\",\"ProvisionedThroughput\":{\"ReadCapacityUnits\":100,\"WriteCapacityUnits\":20}}"
-> "HTTP/1.1 200 OK\r\n"
-> "Date: Tue, 26 Sep 2023 21:40:14 GMT\r\n"
-> "x-amzn-RequestId: 823a96a4-7274-4d4c-a3e6-a7e93cae8dc7\r\n"
-> "Content-Type: application/x-amz-json-1.0\r\n"
-> "x-amz-crc32: 3323354817\r\n"
-> "Content-Length: 545\r\n"
-> "Server: Jetty(11.0.11)\r\n"
-> "\r\n"
reading 545 bytes...
-> "{\"TableDescription\":{\"AttributeDefinitions\":[{\"AttributeName\":\"id\",\"AttributeType\":\"S\"}],\"TableName\":\"dynamoid_tests_documents_1695768194_509\",\"KeySchema\":[{\"AttributeName\":\"id\",\"KeyType\":\"HASH\"}],\"TableStatus\":\"ACTIVE\",\"CreationDateTime\":1695764414.405,\"ProvisionedThroughput\":{\"LastIncreaseDateTime\":0.000,\"LastDecreaseDateTime\":0.000,\"NumberOfDecreasesToday\":0,\"ReadCapacityUnits\":100,\"WriteCapacityUnits\":20},\"TableSizeBytes\":0,\"ItemCount\":0,\"TableArn\":\"arn:aws:dynamodb:ddblocal:000000000000:table/dynamoid_tests_documents_1695768194_509\"}}"
read 545 bytes
Thanks. I will report back in a few days.
Nice!
I've noticed that provided logs don't contain a request body so we cannot ensure that request is well-formed. So we cannot reproduce the issue in isolation to check whether this request fails every time or occasionally. It would help to understand where is the issue - in Dynamoid, AWS Ruby SDK or on the DynamoDB side.
Ah, there is an x-amzn-RequestId
header so they can get this information on their own.
@andrykonchin Do you mind plugging this into a separate branch like the wire trace debug? https://github.com/aws/aws-sdk-ruby/issues/2914#issuecomment-1766817792
Is there a possibility of a multithreading bug in dynamoid that's causing this? DynamoDB team is saying @rhuang's request ends up being processed as PutItem. It may be possible a PutItem and a Query were happening very close together in a multithreaded way, and Dynamoid may be handling that wrong response.
Updated the https://github.com/Dynamoid/dynamoid/tree/add-http-wire-trace-config-option branch to print HTTP request body
@mullermp
Only one single instance of Aws::DynamoDB::Client
class is instantiated in Dynamoid and access to it isn't synchronised (e.g. with mutex).
So potentially if two threads send requests using the same client object and this client object uses one TCP connection - then it seems possible that threads receive wrong responses.
But I was under the impression that AWS Ruby SDK handles concurrency issues on its own and uses a pool of TCP connections (or HTTP clients) to ensure that any operation (put/query/etc) uses its own dedicated TCP connection/HTTP client. I haven't found any mentioning of thread-safety in the AWS Ruby SDK documentation but have found synchronisation mechanisms in the source code (e.g. here).
Could you or Ruby SDK maintainers please clarify whether Ruby SDK is thread safe by default?
Yes, it should be thread safe to use one client, assuming no bugs. We do use a connection pool and a different connection for each request. We've also not seen any reports of this outside of @rhuang + dynamoid. Hopefully debugging the body will reveal some more information.
Thank you!
Thanks. I will update the Dynamoid client and hopefully report back in a few days when the log is captured. We do use multithreading in the application and DynamoDB is called within threads in various ways, including puts and gets, all from the Dynamoid client.
Just confirming what @mullermp said - I've reviewed the SDK's client + connection pool + net:http client code and agree it should be thread safe and don't see any potential threading issues that could cause this.
@andrykonchin Could you please review the snippets from @rhuang here and check the original stack trace for potential issues? https://github.com/aws/aws-sdk-ruby/issues/2914#issuecomment-1769128036 I am thinking Dynamoid has an issue with forwarding arguments in some cases. The request body is intended for query but it appears to be making a put item call.
Yes, I will investigate the issue further on the Dynamoid's side. It's great that the issue could be reproduced.
@rhuang I would like to check one more time logs to ensure there is an issue with request body.
I have added some debug info in the add-http-wire-trace-config-option
branch. Could you please reproduce the issue using it?
And change configuration a bit:
config.log_formatter = Dynamoid::Log::Formatter::Debug.new
Dynamoid.logger.level = Logger::DEBUG
So this way request body/headers + response body will be printed together.
@andrykonchin I will do this. Will report back in a few days.
Hi @andrykonchin, I'm running into this error:
/Users/raymondhuang/Workspace/juristium-clone/config/initializers/dynamoid.rb:19:in `block in <main>': uninitialized constant Dynamoid::Log (NameError)
from /Users/raymondhuang/.rbenv/versions/3.0.5/lib/ruby/gems/3.0.0/bundler/gems/dynamoid-f89968c4b6c3/lib/dynamoid.rb:49:in `configure'
from /Users/raymondhuang/Workspace/juristium-clone/config/initializers/dynamoid.rb:3:in `<main>'
from /Users/raymondhuang/.rbenv/versions/3.0.5/lib/ruby/gems/3.0.0/gems/railties-6.1.7/lib/rails/engine.rb:681:in `block in load_config_initializer'
...
My code is here:
Dynamoid.configure do |config|
...
if Rails.env.development? || Rails.env.alpha?
config.log_formatter = Dynamoid::Log::Formatter::Debug.new
config.http_wire_trace = true
end
end
Ah, right.
Please add require
before configuring Dynamoid - the formatter is used only in Dynamoid's specs and isn't public:
require 'dynamoid/log/formatter'
@rhuang Did have a chance to check with extended logging?
@andrykonchin Sorry, not yet. We have been busy with some projects, but I can confirm the issue is still happening from my error alerts. I spent some time earlier to find extended logging but it was difficult to match my service request logs to to the correct extended logging.
I have a piece of code that sometimes throws the exception:
My code is this:
MyModel.where(id: id)&.any? { ... }
, whereid
is a GSI.Any idea what might be the problem?
The stacktrace is below: