読者です 読者をやめる 読者になる 読者になる

Sequelのトランザクション内でタイムアウトするとCOMMITされてしまう

Ruby Sequel

ちょっと前にハマったのでメモ。

Sequelでトランザクションを使う時は次のように transaction メソッドにブロックを渡します。

require 'sequel'
require 'logger'

db = Sequel.connect('mysql2://user:passwd@localhost/test')
db.loggers = [Logger.new($stdout)]
db.transaction do
  db[:test].insert(id: 123)
end
I, [2017-03-12T22:34:51.946849 #27932]  INFO -- : (0.000119s) SET @@wait_timeout = 2147483
I, [2017-03-12T22:34:51.947047 #27932]  INFO -- : (0.000133s) SET SQL_AUTO_IS_NULL=0
I, [2017-03-12T22:34:51.947182 #27932]  INFO -- : (0.000039s) BEGIN
I, [2017-03-12T22:34:51.947517 #27932]  INFO -- : (0.000149s) INSERT INTO `test` (`id`) VALUES (123)
I, [2017-03-12T22:34:51.955289 #27932]  INFO -- : (0.007675s) COMMIT

ブロックを抜ける時に自動的にCOMMITされます。

ブロック内で例外が発生した場合は、ROLLBACKされます。

require 'sequel'
require 'logger'

db = Sequel.connect('mysql2://user:passwd@localhost/test')
db.loggers = [Logger.new($stdout)]
db.transaction do
  db[:test].insert(id: 123)
  raise 'hoge'
end
I, [2017-03-12T22:36:10.121107 #27942]  INFO -- : (0.000191s) SET @@wait_timeout = 2147483
I, [2017-03-12T22:36:10.121317 #27942]  INFO -- : (0.000110s) SET SQL_AUTO_IS_NULL=0
I, [2017-03-12T22:36:10.121454 #27942]  INFO -- : (0.000043s) BEGIN
I, [2017-03-12T22:36:10.121834 #27942]  INFO -- : (0.000149s) INSERT INTO `test` (`id`) VALUES (123)
I, [2017-03-12T22:36:10.152997 #27942]  INFO -- : (0.031052s) ROLLBACK
test-2.rb:8:in `block in <main>': hoge (RuntimeError)

ですが、Timeout を使っていてトランザクション中でタイムアウトが発生した場合は

require 'timeout'
require 'sequel'
require 'logger'

db = Sequel.connect('mysql2://user:passwd@localhost/test')
db.loggers = [Logger.new($stdout)]
Timeout.timeout(1) do
  db.transaction do
    db[:test].insert(id: 123)
    sleep 2
  end
end
I, [2017-03-12T22:37:57.026693 #27953]  INFO -- : (0.000084s) SET @@wait_timeout = 2147483
I, [2017-03-12T22:37:57.026803 #27953]  INFO -- : (0.000047s) SET SQL_AUTO_IS_NULL=0
I, [2017-03-12T22:37:57.026924 #27953]  INFO -- : (0.000041s) BEGIN
I, [2017-03-12T22:37:57.027223 #27953]  INFO -- : (0.000119s) INSERT INTO `test` (`id`) VALUES (123)
I, [2017-03-12T22:37:58.034292 #27953]  INFO -- : (0.007787s) COMMIT
test-3.rb:10:in `sleep': execution expired (Timeout::Error)

なんとCOMMITされてしまいます!こわい!

ちなみに、タイムアウト時に発生する例外を指定した場合はちゃんとROLLBACKされます。

require 'timeout'
require 'sequel'
require 'logger'

db = Sequel.connect('mysql2://user:passwd@localhost/test')
db.loggers = [Logger.new($stdout)]
Timeout.timeout(1, Timeout::Error) do
  db.transaction do
    db[:test].insert(id: 123)
    sleep 2
  end
end
I, [2017-03-12T22:40:50.531245 #27979]  INFO -- : (0.000166s) SET @@wait_timeout = 2147483
I, [2017-03-12T22:40:50.531455 #27979]  INFO -- : (0.000106s) SET SQL_AUTO_IS_NULL=0
I, [2017-03-12T22:40:50.531820 #27979]  INFO -- : (0.000222s) BEGIN
I, [2017-03-12T22:40:50.532302 #27979]  INFO -- : (0.000240s) INSERT INTO `test` (`id`) VALUES (123)
I, [2017-03-12T22:40:51.540196 #27979]  INFO -- : (0.009461s) ROLLBACK
test-4.rb:10:in `sleep': execution expired (Timeout::Error)

さっきの例と発生する例外も発生箇所も同じなのに、Sequelの振る舞いが異なっています。

これは、Timeout.timeout の引数で例外を指定しない場合は、実際には例外ではなく throw - catch が使われているためです。 この辺の仕組みは前に書きました。

tmtms.hatenablog.com

Sequel の transaction はブロックを例外で抜けた時はROLLBACKし、そうでないとCOMMITするようになっているため、例外ではなく throw で抜けた場合には COMMIT されてしまうのでした。

例外だけでなく throw でもブロックを抜け得ることを考慮していない Sequel の問題なような気もするのですが、とりあえず Sequel を使用している場合は Timeout を使用しない方が無難なようです。

追記

Sequelの開発者的には、SequelのバグではなくてTimeoutのバグって見解のようです。

github.com