SQLite3::BusyException thrown when busy_timeout is set

[Krists Ozols]

While working on Rails application which is using SQLite3 I noticed that timeout parameter in database.yml has no effect if pool size is larger than 1.

Application was using Puma in theaded mode and if there were multiple incoming requests one of them succeded and rest got "database is locked" exceptions.

After digging deeper in ActiveRecord SQLite3 adapter i found that timeout config parameter is used in busy_timeout method within SQLite3::Database class.

Here is an example application without ActiveRecord:

require 'bundler/inline'

require "thread"

require "tempfile"

gemfile do

  source 'https://rubygems.org'

  gem 'sqlite3', '1.3.13'

  gem 'pry'

end

puts 'Gems installed and loaded!'

puts "The SQLite3 version #{SQLite3::SQLITE_VERSION}"

begin

  database_path = Tempfile.open("testdb")

  db = SQLite3::Database.new(database_path.path)

  db.transaction do

    db.execute("CREATE TABLE `test_1` (connection_role VARCHAR (255))")

    db.execute("INSERT INTO test_1 VALUES ('main-1')")

  end

  thread = Thread.new do

    begin

      thread_db = SQLite3::Database.new(database_path.path)

      thread_db.transaction(:immediate) do

        puts "puts:bg:1 #{thread_db.execute("SELECT * FROM test_1")}"

        thread_db.execute("INSERT INTO test_1 VALUES ('bg-1')")

        puts "puts:bg:2 #{thread_db.execute("SELECT * FROM test_1")}"

        sleep 2

        thread_db.execute("INSERT INTO test_1 VALUES ('bg-2')")

        puts "puts:bg:3 #{thread_db.execute("SELECT * FROM test_1")}"

      end

      puts "puts:bg:4 transaction closed"

    ensure

      thread_db.close if thread_db

    end

  end

  puts "puts:main:1 #{db.execute("SELECT * FROM test_1")}"

  sleep 1

  puts "puts:main:2 #{db.execute("SELECT * FROM test_1")}"

  db.busy_timeout 3000 # <-- raises: .rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:108:in `step': database is locked (SQLite3::BusyException)

  # busy_handler works as expected

  # db.busy_handler do

  #   true

  # end

  puts "puts:main:3 #{db.execute("SELECT * FROM test_1")}"

  db.execute("INSERT INTO test_1 VALUES ('main-2')")

  puts "puts:main:4 #{db.execute("SELECT * FROM test_1")}"

  thread.join

ensure

  database_path.close

  database_path.unlink

end

It outputs:

Gems installed and loaded!

The SQLite3 version 3.22.0

puts:main:1 [["main-1"]]

puts:bg:1 [["main-1"]]

puts:bg:2 [["main-1"], ["bg-1"]]

puts:main:2 [["main-1"]]

puts:main:3 [["main-1"]]

puts:bg:3 [["main-1"], ["bg-1"], ["bg-2"]]

puts:bg:4 transaction closed

Traceback (most recent call last):

8: from sqlite3_busy_timeout.rb:54:in `<main>'

7: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:137:in `execute'

6: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:95:in `prepare'

5: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:156:in `block in execute'

4: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:156:in `to_a'

3: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:107:in `each'

2: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:107:in `loop'

1: from /home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:108:in `block in each'

/home/krists/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:108:in `step': database is locked (SQLite3::BusyException)

As the busy_timeout is 3000ms which is larger than total time that thread blocks I was not expecting an error.

If you comment out db.busy_timeout call and uncomment lines below with db.busy_handler you can see that it works as expected - insert statement with value main-2 succeeds.

Is this a bug or I havent understood how these methods should be used?

Thanks,
Krists