ちょっと前にハマったのでメモ。
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 が使われているためです。 この辺の仕組みは前に書きました。
Sequel の transaction はブロックを例外で抜けた時はROLLBACKし、そうでないとCOMMITするようになっているため、例外ではなく throw で抜けた場合には COMMIT されてしまうのでした。
例外だけでなく throw でもブロックを抜け得ることを考慮していない Sequel の問題なような気もするのですが、とりあえず Sequel を使用している場合は Timeout を使用しない方が無難なようです。
追記
Sequelの開発者的には、SequelのバグではなくてTimeoutのバグって見解のようです。