Dynamoid のスレッドセーフではない実装を直しました

こんにちは。インフラエンジニアの id:tsub511 です。

私は Dynamoid のメンテナではないのですが、弊社内で今回それなりに大きい問題が起きて、得た知見も大きかったため記事にしました。

TL;DR

Dynamoid にスレッドセーフではない実装があったが PR をマージしてもらって修正済み。

2019/08/13 時点ではまだリリースされていないようなので、エラーで困っている方は master ブランチをお使いください。

今回起きた問題

弊サービスでは Sidekiq 上で Dynamoid を使っています。

github.com

基本的に問題なく稼働していたのですが、デプロイ時に Sidekiq を再起動した後、Bugsnag に以下のような二種類のエラーが継続的に飛んできました。

f:id:tsub511:20190809182531p:plain — undefined method `[]' for nil:NilClass

f:id:tsub511:20190809182800p:plain — undefined method `query' for #<Dynamoid::AdapterPlugin::AwsSdkV3:0x00000000078dc1b8> Did you mean? to_query

このエラーが起きると、自然には回復しないため、Sidekiq のワーカーを再起動する必要があります。

また、NoMethodError という一般的な例外クラスのため ActiveJob の retry_on によるリトライ処理の考慮はしておらず、大事なジョブが実行されないままになってしまうのも問題です。

エラーをパッと見ただけでは、キャッシュの実装に考慮漏れがあるのかな？とか、インスタンスが生成されていてコード上ではメソッドが実装されているのになんで undefined method エラーが起きるんだ？などと、不思議なエラーが出ていて調査が難航しそうな印象でした。

何が原因だったのか

Sidekiq + Dynamoid でピンと来る方もいると思いますが、エラーの原因は Dynamoid にスレッドセーフではない実装があったことでした。

スレッドセーフではない実装がどこにあったのか探すために、ここで発生していたエラーをもう一度見てみます。

undefined method `' for nil:NilClass

まず 1 つ目のエラーは nil に対して #[] を呼び出そうとしてエラーになっていますが、nil になっている変数は table_cache です。

table_cache は以下で初期化されています。

# https://github.com/Dynamoid/dynamoid/blob/v3.2.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb#L66-L69
def connect!
  @client = Aws::DynamoDB::Client.new(connection_config)
  @table_cache = {}
end

そして、この初期化のための Dynamoid::AdapterPlugin::AwsSdkV3#connect! を呼び出しているのは Dynamoid::Adapter#adapter です。

adapter.connect! の部分に if adapter.respond_to?(:connect!) という条件がありますが、ここが false になっていて adapter.connect! が実行されていないため、table_cache の初期化処理が動いていないようです。

# https://github.com/Dynamoid/dynamoid/blob/v3.2.0/lib/dynamoid/adapter.rb#L29-L37
def adapter
  unless @adapter_.value
    adapter = self.class.adapter_plugin_class.new
    adapter.connect! if adapter.respond_to?(:connect!)
    @adapter_.compare_and_set(nil, adapter)
    clear_cache!
  end
  @adapter_.value
end

2 つ目のエラーも見てみます。

undefined method `query' for #<Dynamoid::AdapterPlugin::AwsSdkV3:0x00000000078dc1b8> Did you mean? to_query

こちらは Dynamoid::AdapterPlugin::AwsSdkV3 のインスタンス adapter に対して query を実行しようとしてメソッドが定義されていないというエラーです。

しかし、実際のコードにはメソッドが定義されています。

https://github.com/Dynamoid/dynamoid/blob/v3.2.0/lib/dynamoid/adapter_plugin/aws_sdk_v3.rb#L489-L500
 def query(table_name, options = {})
  Enumerator.new do |yielder|
    table = describe_table(table_name)

    Query.new(client, table, options).call.each do |page|
      yielder.yield(
        page.items.map { |row| result_item_to_hash(row) },
        last_evaluated_key: page.last_evaluated_key
      )
    end
  end
 end

視点を変えて、adapter インスタンスを定義しているコードを見てみると、やはり Dynamoid::Adapter#adapter に行き着きます。

# https://github.com/Dynamoid/dynamoid/blob/v3.2.0/lib/dynamoid/adapter.rb#L29-L37
def adapter
  unless @adapter_.value
    adapter = self.class.adapter_plugin_class.new
    adapter.connect! if adapter.respond_to?(:connect!)
    @adapter_.compare_and_set(nil, adapter)
    clear_cache!
  end
  @adapter_.value
end

self.class.adapter_plugin_class.new で生成したものをメモ化しています。

メモ化には concurrent-ruby を使っていて、過去に対策されたようなのでそこは問題なさそうです。

self.class.adapter_plugin_class.new の先が怪しそうなのでコードを見てみると、なにやら動的に require しています。

# https://github.com/Dynamoid/dynamoid/blob/v3.2.0/lib/dynamoid/adapter.rb#L181-L187
def self.adapter_plugin_class
  unless Dynamoid.const_defined?(:AdapterPlugin) && Dynamoid::AdapterPlugin.const_defined?(Dynamoid::Config.adapter.camelcase)
    require "dynamoid/adapter_plugin/#{Dynamoid::Config.adapter}"
  end

  Dynamoid::AdapterPlugin.const_get(Dynamoid::Config.adapter.camelcase)
end

実はスレッドセーフではない実装はこの require する条件の Dynamoid.const_defined?(:AdapterPlugin) && Dynamoid::AdapterPlugin.const_defined?(Dynamoid::Config.adapter.camelcase) の部分です。

エラーを再現できるコードを Gist に用意しましたのでそちらを使って確認していきます。

Test codes to reproduce not thread-safe errors of Dynamoid · GitHub

Dynamoid に以下のような変更を加えて、unless の中に入らず require が実行されなかった時の状態を見てみます。

diff --git a/lib/dynamoid/adapter.rb b/lib/dynamoid/adapter.rb
index f390ecf..df2a58c 100644
--- a/lib/dynamoid/adapter.rb
+++ b/lib/dynamoid/adapter.rb
@@ -181,6 +181,13 @@ module Dynamoid
     def self.adapter_plugin_class
       unless Dynamoid.const_defined?(:AdapterPlugin) && Dynamoid::AdapterPlugin.const_defined?(Dynamoid::Config.adapter.camelcase)
         require "dynamoid/adapter_plugin/#{Dynamoid::Config.adapter}"
+      else
+        tmp_adapter = Dynamoid::AdapterPlugin.const_get(Dynamoid::Config.adapter.camelcase).new
+        puts <<~EOS
+          respond_to?(:connect!): #{tmp_adapter.respond_to?(:connect!)},
+          respond_to?(:query): #{tmp_adapter.respond_to?(:query)},
+          require: #{require "dynamoid/adapter_plugin/#{Dynamoid::Config.adapter}"}
+        EOS
       end
 
       Dynamoid::AdapterPlugin.const_get(Dynamoid::Config.adapter.camelcase)

すると、スレッドによっては const_defined? の結果が true で、require の結果も false (コードがロード済み) なのに、実際のメソッドが存在しないという現象が起きていることが分かりました。

$ bundle exec ruby main.rb
...
respond_to?(:connect!): false,
respond_to?(:query): false,
require: false
...

ここからは Ruby の require の実装を知らないため推測になります。

おそらくマルチスレッド環境下で require を実行すると、require を実行したスレッド内では全てのコードがロードされた状態になりますが、別のスレッドではクラス定義などの「ガワ」だけがロードされた状態になっているのではないかと思いました。

そのため、ロードが不十分なスレッドでインスタンスを生成できるが、メソッドが定義されていない、という状態になっているのかと思われます。

解決方法

よって、全てのスレッドで確実に require を実行することで今回のエラーが解決するという結論に至りました。

diff --git a/lib/dynamoid/adapter.rb b/lib/dynamoid/adapter.rb
index f390ecf..8449e34 100644
--- a/lib/dynamoid/adapter.rb
+++ b/lib/dynamoid/adapter.rb
@@ -179,9 +179,7 @@ module Dynamoid
     end
 
     def self.adapter_plugin_class
-      unless Dynamoid.const_defined?(:AdapterPlugin) && Dynamoid::AdapterPlugin.const_defined?(Dynamoid::Config.adapter.camelcase)
-        require "dynamoid/adapter_plugin/#{Dynamoid::Config.adapter}"
-      end
+      require "dynamoid/adapter_plugin/#{Dynamoid::Config.adapter}"
 
       Dynamoid::AdapterPlugin.const_get(Dynamoid::Config.adapter.camelcase)
     end

エラーの原因と解決方法が判明したため、既に Dynamoid に PR を作りマージまでしてもらいました。

github.com

2019/08/13 時点ではまだリリースされていないようなので、エラーで困っている方は master ブランチをお使いください。

調査に苦労した点

マルチスレッドプログラミングの経験が浅いため、まずスレッドセーフではない実装があるということに気づくまでに時間がかかりました。

そして、エラーを再現しようとした時になかなか再現出来なかったのもハマりポイントでした。

エラーの再現コードを読むと分かりますが、Dynamoid のメソッドを呼ぶ直前に puts を実行しています。

# https://gist.github.com/tsub/72e60233ed82a8a453428ea7441e6017#file-main-rb
100.times do |i|
  safe_thread(i.to_s) do
    puts 'debug' # To unlock Ruby's GVL
    Document.where(identifier: 'hoge').first
  end
end

この puts が重要で、Ruby は GVL (Giant VM Lock) という仕組みを使って、実行されるネイティブスレッドが 1 つになるように排他制御をしています。

ただし、IO 関連のメソッドを実行する際は GVL が一時的に解放されてスレッドが同時に実行されます。

ネイティブスレッドを用いて実装されていますが、現在の実装では Ruby VM は Giant VM lock (GVL) を有しており、同時に実行されるネイティブスレッドは常にひとつです。ただし、IO 関連のブロックする可能性があるシステムコールを行う場合には GVL を解放します。その場合にはスレッドは同時に実行され得ます。また拡張ライブラリから GVL を操作できるので、複数のスレッドを同時に実行するような拡張ライブラリは作成可能です。

docs.ruby-lang.org

つまりスレッドセーフではない実装があった場合に、それを再現させるためには単純にスレッドセーフではないコードを書くだけではダメで、IO 関連のメソッドを実行して GVL を解放しないといけません。

少し古い記事ではありますが、こちらが参考になりました。

moyomot.hatenablog.com

実際の本番環境ではログ出力などにより、IO 関連のメソッドは普通に実行されていることが多いかと思いますので、エラーが起きるのも納得です。