encountering NoMethodError: undefined method `map' for nil:NilClass #516

rhuang · 2021-07-06T18:11:09Z

I have a piece of code that sometimes throws the exception:

 NoMethodError: undefined method `map' for nil:NilClass

My code is this: MyModel.where(id: id)&.any? { ... }, where id is a GSI.

Any idea what might be the problem?

The stacktrace is below:

1
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb" line 499 in block (2 levels) in query
2
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 35 in <<
3
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 35 in block (3 levels) in call
4
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 34 in tap
5
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 34 in block (2 levels) in call
6
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/middleware/limit.rb" line 42 in call
7
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/middleware/start_key.rb" line 14 in call
8
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/middleware/backoff.rb" line 15 in call
9
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 47 in block (3 levels) in call
10
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 46 in loop
11
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 46 in block (2 levels) in call
12
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 45 in catch
13
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3/query.rb" line 45 in block in call
14
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb" line 497 in each
15
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb" line 497 in each
16
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb" line 497 in block in query
17
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 546 in each
18
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 546 in each
19
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 546 in block in raw_pages_via_query
20
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 407 in each
21
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 407 in each
22
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 407 in each
23
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 407 in each
24
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 407 in each
25
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 407 in each
26
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 407 in each
27
File "/opt/rubies/ruby-2.5.9/lib/ruby/gems/2.5.0/gems/dynamoid-3.7.0/lib/dynamoid/criteria/chain.rb" line 407 in each
28
File "/var/app/current/app/models/client.rb", line 173 in any?

The text was updated successfully, but these errors were encountered:

rhuang · 2023-09-21T20:56:49Z

@andrykonchin

hello, any idea why this is happening? it happens occasionally, not all the time. it seems like page.items is nil?

dynamoid/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb

Line 519 in b2103d9

page.items.map { |item| item_to_hash(item) },

andrykonchin · 2023-09-25T09:12:04Z

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.

andrykonchin · 2023-09-25T16:43:45Z

Could you please specify a version of the aws-sdk-dynamodb gem?

rhuang · 2023-09-25T16:50:01Z

1.80.0, thanks.

rhuang · 2023-09-25T16:56:24Z

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

andrykonchin · 2023-09-26T11:28:27Z

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.

rhuang · 2023-09-26T15:12:16Z

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?

andrykonchin · 2023-09-26T15:33:44Z

Will do. Will use the mentioned above release (3.8.0)

Is the issue reproducible on some non-production environment?

rhuang · 2023-09-26T15:45:09Z

Yes, it happens for both my test and prod env, so I will try to observe my test env for it. Thanks.

andrykonchin · 2023-09-26T22:50:49Z

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

rhuang · 2023-09-26T23:01:01Z

Thanks. I will report back in a few days.

rhuang · 2023-10-02T19:37:11Z

@andrykonchin aws/aws-sdk-ruby#2914 (comment)

andrykonchin · 2023-10-02T22:03:35Z

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.

rhuang · 2023-10-17T17:18:40Z

@andrykonchin Do you mind plugging this into a separate branch like the wire trace debug? aws/aws-sdk-ruby#2914 (comment)

mullermp · 2023-10-17T17:57:23Z

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.

andrykonchin · 2023-10-17T18:13:50Z

Updated the https://github.com/Dynamoid/dynamoid/tree/add-http-wire-trace-config-option branch to print HTTP request body

andrykonchin · 2023-10-17T18:33:00Z

@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?

mullermp · 2023-10-17T18:37:43Z

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.

andrykonchin · 2023-10-17T18:41:08Z

Thank you!

rhuang · 2023-10-17T18:43:25Z

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.

alextwoods · 2023-10-17T18:58:59Z

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.

mullermp · 2023-10-19T12:54:14Z

@andrykonchin Could you please review the snippets from @rhuang here and check the original stack trace for potential issues? aws/aws-sdk-ruby#2914 (comment) 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.

andrykonchin · 2023-10-19T20:31:05Z

Yes, I will investigate the issue further on the Dynamoid's side. It's great that the issue could be reproduced.

andrykonchin · 2023-10-23T21:31:07Z

@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:

add config.log_formatter = Dynamoid::Log::Formatter::Debug.new
add Dynamoid.logger.level = Logger::DEBUG

So this way request body/headers + response body will be printed together.

rhuang · 2023-10-23T21:32:19Z

@andrykonchin I will do this. Will report back in a few days.

rhuang · 2023-11-01T23:52:46Z

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

andrykonchin · 2023-11-02T00:05:36Z

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'

andrykonchin · 2023-11-22T14:52:59Z

@rhuang Did have a chance to check with extended logging?

rhuang · 2023-11-22T23:17:35Z

@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.

andrykonchin mentioned this issue Sep 25, 2023

DynamoDB #query method returns response with items = nil aws/aws-sdk-ruby#2914

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

encountering NoMethodError: undefined method `map' for nil:NilClass #516

encountering NoMethodError: undefined method `map' for nil:NilClass #516

rhuang commented Jul 6, 2021 •

edited

Loading

rhuang commented Sep 21, 2023

andrykonchin commented Sep 25, 2023 •

edited

Loading

andrykonchin commented Sep 25, 2023

rhuang commented Sep 25, 2023

rhuang commented Sep 25, 2023

andrykonchin commented Sep 26, 2023

rhuang commented Sep 26, 2023

andrykonchin commented Sep 26, 2023

rhuang commented Sep 26, 2023

andrykonchin commented Sep 26, 2023

rhuang commented Sep 26, 2023

rhuang commented Oct 2, 2023

andrykonchin commented Oct 2, 2023 •

edited

Loading

rhuang commented Oct 17, 2023

mullermp commented Oct 17, 2023

andrykonchin commented Oct 17, 2023

andrykonchin commented Oct 17, 2023 •

edited

Loading

mullermp commented Oct 17, 2023

andrykonchin commented Oct 17, 2023

rhuang commented Oct 17, 2023

alextwoods commented Oct 17, 2023

mullermp commented Oct 19, 2023

andrykonchin commented Oct 19, 2023

andrykonchin commented Oct 23, 2023 •

edited

Loading

rhuang commented Oct 23, 2023

rhuang commented Nov 1, 2023

andrykonchin commented Nov 2, 2023 •

edited

Loading

andrykonchin commented Nov 22, 2023

rhuang commented Nov 22, 2023 •

edited

Loading

encountering NoMethodError: undefined method `map' for nil:NilClass #516

encountering NoMethodError: undefined method `map' for nil:NilClass #516

Comments

rhuang commented Jul 6, 2021 • edited Loading

rhuang commented Sep 21, 2023

andrykonchin commented Sep 25, 2023 • edited Loading

andrykonchin commented Sep 25, 2023

rhuang commented Sep 25, 2023

rhuang commented Sep 25, 2023

andrykonchin commented Sep 26, 2023

rhuang commented Sep 26, 2023

andrykonchin commented Sep 26, 2023

rhuang commented Sep 26, 2023

andrykonchin commented Sep 26, 2023

rhuang commented Sep 26, 2023

rhuang commented Oct 2, 2023

andrykonchin commented Oct 2, 2023 • edited Loading

rhuang commented Oct 17, 2023

mullermp commented Oct 17, 2023

andrykonchin commented Oct 17, 2023

andrykonchin commented Oct 17, 2023 • edited Loading

mullermp commented Oct 17, 2023

andrykonchin commented Oct 17, 2023

rhuang commented Oct 17, 2023

alextwoods commented Oct 17, 2023

mullermp commented Oct 19, 2023

andrykonchin commented Oct 19, 2023

andrykonchin commented Oct 23, 2023 • edited Loading

rhuang commented Oct 23, 2023

rhuang commented Nov 1, 2023

andrykonchin commented Nov 2, 2023 • edited Loading

andrykonchin commented Nov 22, 2023

rhuang commented Nov 22, 2023 • edited Loading

rhuang commented Jul 6, 2021 •

edited

Loading

andrykonchin commented Sep 25, 2023 •

edited

Loading

andrykonchin commented Oct 2, 2023 •

edited

Loading

andrykonchin commented Oct 17, 2023 •

edited

Loading

andrykonchin commented Oct 23, 2023 •

edited

Loading

andrykonchin commented Nov 2, 2023 •

edited

Loading

rhuang commented Nov 22, 2023 •

edited

Loading