Connecting to database specified by database.yml
   (0.5ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
BentoSearch::SearchEngine failed results: #<Exception: I am a horrible engine>
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:183:in `search_implementation'
    /home/rochkind/bento_search/app/models/bento_search/search_engine.rb:89:in `search'
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:189:in `test_rescues_exceptions'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:36:in `block in run'
    activesupport (3.2.8) lib/active_support/callbacks.rb:425:in `_run__2886462068739794106__setup__4058406264532479739__callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `__run_callback'
    activesupport (3.2.8) lib/active_support/callbacks.rb:385:in `_run_setup_callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:81:in `run_callbacks'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:35:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun'
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
Connecting to database specified by database.yml
   (0.4ms)  begin transaction
Processing by BentoSearch::SearchControllerTest::CustomSearchController#search as HTML
  Parameters: {"engine_id"=>"mock", "query"=>"my search"}
  Rendered text template (0.0ms)
Completed 403 Forbidden in 43ms (Views: 42.2ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_existing"}
Completed 404 Not Found in 1ms (Views: 0.6ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_routable"}
Completed 403 Forbidden in 1ms (Views: 0.2ms | ActiveRecord: 0.0ms)
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"mock"}
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.2ms)
Completed 200 OK in 41ms (Views: 40.6ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.0ms)
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_search_error.html.erb (0.7ms)
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.3ms)
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.3ms)
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.078106s
EDS timing GET: 0.005008:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=n
EDS timing GET: 0.006394:http://eds-api.ebscohost.com/edsapi/rest/search?view=detailed&query=AND%2Ccancer&searchmode=all&highlight=y&resultsperpage=10
EDS timing GET: 0.006792:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=26cf851d-9a36-435b-a50a-14a5aea15338.KErj2NrKZC8UxoZu2SfB28G2%2Fw9Gjg%2BwmkWnBdUv3As%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.009413s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.007506s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.011699s
EDS timing GET: 0.004569:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.003736:http://eds-api.ebscohost.com/edsapi/rest/info
EDS timing GET: 0.005847:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=c6f7d532-8726-47a7-8e75-b3851a615c68.lS%2FLBviHYcah4372jECVTkM%2Fb4%2FDpExjKLExBuNU0eA%3D
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.014803s
EDS timing GET: 0.002677:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.00258:http://eds-api.ebscohost.com/edsapi/rest/info
EDS auth failed, getting auth again
EDS timing AUTH: 0.002711s
EDS timing GET: 0.005764:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=d389e524-95ea-4518-bd4a-6b0eb7c0af44.kEvPxolRdsxALTno8ChwQHJ3j2LNLih2ApF64T4yK4w%3D
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
BentoSearch::SearchEngine failed results: #<Exception: I am a horrible engine>
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:183:in `search_implementation'
    /home/rochkind/bento_search/app/models/bento_search/search_engine.rb:89:in `search'
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:189:in `test_rescues_exceptions'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:36:in `block in run'
    activesupport (3.2.8) lib/active_support/callbacks.rb:425:in `_run__4029929672233217244__setup__1248707290308868027__callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `__run_callback'
    activesupport (3.2.8) lib/active_support/callbacks.rb:385:in `_run_setup_callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:81:in `run_callbacks'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:35:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun'
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.2ms)
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.2ms)
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_link.html.erb (0.4ms)
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (3.6ms)
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.2ms)
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
Connecting to database specified by database.yml
   (0.6ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
Connecting to database specified by database.yml
   (0.6ms)  begin transaction
Processing by BentoSearch::SearchControllerTest::CustomSearchController#search as HTML
  Parameters: {"engine_id"=>"mock", "query"=>"my search"}
  Rendered text template (0.0ms)
Completed 403 Forbidden in 50ms (Views: 49.6ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_existing"}
Completed 404 Not Found in 2ms (Views: 0.8ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_routable"}
Completed 403 Forbidden in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"mock"}
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.8ms)
Completed 200 OK in 49ms (Views: 48.3ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_search_error.html.erb (0.9ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.117406s
EDS timing GET: 0.007868:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=n
EDS timing GET: 0.009791:http://eds-api.ebscohost.com/edsapi/rest/search?view=detailed&query=AND%2Ccancer&searchmode=all&highlight=y&resultsperpage=10
EDS timing GET: 0.010209:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=26cf851d-9a36-435b-a50a-14a5aea15338.KErj2NrKZC8UxoZu2SfB28G2%2Fw9Gjg%2BwmkWnBdUv3As%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.014126s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.008935s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.015443s
EDS timing GET: 0.005282:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.004674:http://eds-api.ebscohost.com/edsapi/rest/info
EDS timing GET: 0.007372:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=c6f7d532-8726-47a7-8e75-b3851a615c68.lS%2FLBviHYcah4372jECVTkM%2Fb4%2FDpExjKLExBuNU0eA%3D
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.016862s
EDS timing GET: 0.002832:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.002659:http://eds-api.ebscohost.com/edsapi/rest/info
EDS auth failed, getting auth again
EDS timing AUTH: 0.002879s
EDS timing GET: 0.010923:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=d389e524-95ea-4518-bd4a-6b0eb7c0af44.kEvPxolRdsxALTno8ChwQHJ3j2LNLih2ApF64T4yK4w%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
BentoSearch::SearchEngine failed results: #<Exception: I am a horrible engine>
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:183:in `search_implementation'
    /home/rochkind/bento_search/app/models/bento_search/search_engine.rb:89:in `search'
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:189:in `test_rescues_exceptions'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:36:in `block in run'
    activesupport (3.2.8) lib/active_support/callbacks.rb:425:in `_run__2079895681877932289__setup__2619043652292814868__callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `__run_callback'
    activesupport (3.2.8) lib/active_support/callbacks.rb:385:in `_run_setup_callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:81:in `run_callbacks'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:35:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun'
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.5ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_link.html.erb (0.6ms)
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (5.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
Connecting to database specified by database.yml
   (0.6ms)  begin transaction
Processing by BentoSearch::SearchControllerTest::CustomSearchController#search as HTML
  Parameters: {"engine_id"=>"mock", "query"=>"my search"}
  Rendered text template (0.0ms)
Completed 403 Forbidden in 58ms (Views: 57.2ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_existing"}
Completed 404 Not Found in 2ms (Views: 0.8ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_routable"}
Completed 403 Forbidden in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"mock"}
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.9ms)
Completed 200 OK in 57ms (Views: 55.9ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (3.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_search_error.html.erb (0.9ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.077074s
EDS timing GET: 0.004982:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=n
EDS timing GET: 0.006347:http://eds-api.ebscohost.com/edsapi/rest/search?view=detailed&query=AND%2Ccancer&searchmode=all&highlight=y&resultsperpage=10
EDS timing GET: 0.006829:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=26cf851d-9a36-435b-a50a-14a5aea15338.KErj2NrKZC8UxoZu2SfB28G2%2Fw9Gjg%2BwmkWnBdUv3As%3D
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.009381s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.007484s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.011696s
EDS timing GET: 0.00455:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.003848:http://eds-api.ebscohost.com/edsapi/rest/info
EDS timing GET: 0.005859:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=c6f7d532-8726-47a7-8e75-b3851a615c68.lS%2FLBviHYcah4372jECVTkM%2Fb4%2FDpExjKLExBuNU0eA%3D
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.014784s
EDS timing GET: 0.002692:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.002586:http://eds-api.ebscohost.com/edsapi/rest/info
EDS auth failed, getting auth again
EDS timing AUTH: 0.002719s
EDS timing GET: 0.005805:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=d389e524-95ea-4518-bd4a-6b0eb7c0af44.kEvPxolRdsxALTno8ChwQHJ3j2LNLih2ApF64T4yK4w%3D
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
BentoSearch::SearchEngine failed results: #<Exception: I am a horrible engine>
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:183:in `search_implementation'
    /home/rochkind/bento_search/app/models/bento_search/search_engine.rb:95:in `search'
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:189:in `test_rescues_exceptions'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:36:in `block in run'
    activesupport (3.2.8) lib/active_support/callbacks.rb:425:in `_run__2269524022906288665__setup__2247867715169516960__callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `__run_callback'
    activesupport (3.2.8) lib/active_support/callbacks.rb:385:in `_run_setup_callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:81:in `run_callbacks'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:35:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun'
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.9ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.6ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.4ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_link.html.erb (0.7ms)
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (5.6ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
Connecting to database specified by database.yml
   (0.6ms)  begin transaction
Processing by BentoSearch::SearchControllerTest::CustomSearchController#search as HTML
  Parameters: {"engine_id"=>"mock", "query"=>"my search"}
  Rendered text template (0.0ms)
Completed 403 Forbidden in 52ms (Views: 51.5ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_existing"}
Completed 404 Not Found in 2ms (Views: 0.8ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_routable"}
Completed 403 Forbidden in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"mock"}
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.7ms)
Completed 200 OK in 14ms (Views: 12.6ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.7ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_search_error.html.erb (1.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.2ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.114534s
EDS timing GET: 0.00752:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=n
EDS timing GET: 0.00934:http://eds-api.ebscohost.com/edsapi/rest/search?view=detailed&query=AND%2Ccancer&searchmode=all&highlight=y&resultsperpage=10
EDS timing GET: 0.010051:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=26cf851d-9a36-435b-a50a-14a5aea15338.KErj2NrKZC8UxoZu2SfB28G2%2Fw9Gjg%2BwmkWnBdUv3As%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.013759s
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.011291s
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.018216s
EDS timing GET: 0.006731:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.005505:http://eds-api.ebscohost.com/edsapi/rest/info
EDS timing GET: 0.008787:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=c6f7d532-8726-47a7-8e75-b3851a615c68.lS%2FLBviHYcah4372jECVTkM%2Fb4%2FDpExjKLExBuNU0eA%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.022271s
EDS timing GET: 0.003924:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.003742:http://eds-api.ebscohost.com/edsapi/rest/info
EDS auth failed, getting auth again
EDS timing AUTH: 0.004073s
EDS timing GET: 0.008721:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=d389e524-95ea-4518-bd4a-6b0eb7c0af44.kEvPxolRdsxALTno8ChwQHJ3j2LNLih2ApF64T4yK4w%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.5ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_link.html.erb (0.6ms)
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (5.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
Connecting to database specified by database.yml
   (0.5ms)  begin transaction
Processing by BentoSearch::SearchControllerTest::CustomSearchController#search as HTML
  Parameters: {"engine_id"=>"mock", "query"=>"my search"}
  Rendered text template (0.0ms)
Completed 403 Forbidden in 52ms (Views: 51.8ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_existing"}
Completed 404 Not Found in 1ms (Views: 0.8ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_routable"}
Completed 403 Forbidden in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"mock"}
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.2ms)
Completed 200 OK in 11ms (Views: 10.3ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.2ms)
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_search_error.html.erb (0.9ms)
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.4ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.4ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.086025s
EDS timing GET: 0.005316:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=n
EDS timing GET: 0.006612:http://eds-api.ebscohost.com/edsapi/rest/search?view=detailed&query=AND%2Ccancer&searchmode=all&highlight=y&resultsperpage=10
EDS timing GET: 0.007108:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=26cf851d-9a36-435b-a50a-14a5aea15338.KErj2NrKZC8UxoZu2SfB28G2%2Fw9Gjg%2BwmkWnBdUv3As%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.009966s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.007636s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.011923s
EDS timing GET: 0.004743:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.003808:http://eds-api.ebscohost.com/edsapi/rest/info
EDS timing GET: 0.006032:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=c6f7d532-8726-47a7-8e75-b3851a615c68.lS%2FLBviHYcah4372jECVTkM%2Fb4%2FDpExjKLExBuNU0eA%3D
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.015207s
EDS timing GET: 0.002758:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.002669:http://eds-api.ebscohost.com/edsapi/rest/info
EDS auth failed, getting auth again
EDS timing AUTH: 0.002789s
EDS timing GET: 0.005928:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=d389e524-95ea-4518-bd4a-6b0eb7c0af44.kEvPxolRdsxALTno8ChwQHJ3j2LNLih2ApF64T4yK4w%3D
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
BentoSearch::SearchEngine failed results: #<Timeout::Error: I am a horrible engine>
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:183:in `search_implementation'
    /home/rochkind/bento_search/app/models/bento_search/search_engine.rb:101:in `search'
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:189:in `test_rescues_exceptions'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:36:in `block in run'
    activesupport (3.2.8) lib/active_support/callbacks.rb:425:in `_run__2927298851373187549__setup__1905595697193905917__callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `__run_callback'
    activesupport (3.2.8) lib/active_support/callbacks.rb:385:in `_run_setup_callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:81:in `run_callbacks'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:35:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun'
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.5ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_link.html.erb (0.6ms)
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (5.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
Connecting to database specified by database.yml
   (0.6ms)  begin transaction
Processing by BentoSearch::SearchControllerTest::CustomSearchController#search as HTML
  Parameters: {"engine_id"=>"mock", "query"=>"my search"}
  Rendered text template (0.0ms)
Completed 403 Forbidden in 52ms (Views: 51.0ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_existing"}
Completed 404 Not Found in 2ms (Views: 0.8ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"not_routable"}
Completed 403 Forbidden in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
Processing by BentoSearch::SearchController#search as HTML
  Parameters: {"query"=>"my search", "engine_id"=>"mock"}
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.7ms)
Completed 200 OK in 13ms (Views: 12.4ms | ActiveRecord: 0.0ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (2.7ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_search_error.html.erb (0.9ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.8ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
EDS timing AUTH: 0.078203s
EDS timing GET: 0.005192:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=n
EDS timing GET: 0.006392:http://eds-api.ebscohost.com/edsapi/rest/search?view=detailed&query=AND%2Ccancer&searchmode=all&highlight=y&resultsperpage=10
EDS timing GET: 0.006761:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=26cf851d-9a36-435b-a50a-14a5aea15338.KErj2NrKZC8UxoZu2SfB28G2%2Fw9Gjg%2BwmkWnBdUv3As%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.009677s
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.007724s
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.011688s
EDS timing GET: 0.00463:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.003752:http://eds-api.ebscohost.com/edsapi/rest/info
EDS timing GET: 0.005909:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=c6f7d532-8726-47a7-8e75-b3851a615c68.lS%2FLBviHYcah4372jECVTkM%2Fb4%2FDpExjKLExBuNU0eA%3D
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
EDS timing AUTH: 0.015047s
EDS timing GET: 0.002669:http://eds-api.ebscohost.com/edsapi/rest/createsession?profile=edsapi&guest=y
EDS timing GET: 0.002573:http://eds-api.ebscohost.com/edsapi/rest/info
EDS auth failed, getting auth again
EDS timing AUTH: 0.002704s
EDS timing GET: 0.005807:http://eds-api.ebscohost.com/edsapi/rest/endsession?sessiontoken=d389e524-95ea-4518-bd4a-6b0eb7c0af44.kEvPxolRdsxALTno8ChwQHJ3j2LNLih2ApF64T4yK4w%3D
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
BentoSearch::SearchEngine failed results: #<Timeout::Error: I am a horrible engine>
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:183:in `search_implementation'
    /home/rochkind/bento_search/app/models/bento_search/search_engine.rb:95:in `search'
    /home/rochkind/bento_search/test/unit/search_engine_base_test.rb:189:in `test_rescues_exceptions'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:949:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit/testcase.rb:17:in `run'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:36:in `block in run'
    activesupport (3.2.8) lib/active_support/callbacks.rb:425:in `_run__4341096706219397571__setup__437050511900262550__callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:405:in `__run_callback'
    activesupport (3.2.8) lib/active_support/callbacks.rb:385:in `_run_setup_callbacks'
    activesupport (3.2.8) lib/active_support/callbacks.rb:81:in `run_callbacks'
    activesupport (3.2.8) lib/active_support/testing/setup_and_teardown.rb:35:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:787:in `block in _run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `map'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:780:in `_run_suite'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:565:in `block in _run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:563:in `_run_suites'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:746:in `_run_anything'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:909:in `run_tests'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:896:in `block in _run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `each'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:895:in `_run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/minitest/unit.rb:884:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:21:in `run'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:326:in `block (2 levels) in autorun'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:27:in `run_once'
    /home/rochkind/.rvm/rubies/ruby-1.9.3-p194/lib/ruby/1.9.1/test/unit.rb:325:in `block in autorun'
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (1.3ms)
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.3ms)
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.2ms)
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_link.html.erb (0.4ms)
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (3.7ms)
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
  Rendered /home/rochkind/bento_search/app/views/bento_search/_std_item.html.erb (0.2ms)
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.1ms)  begin transaction
   (0.0ms)  rollback transaction
   (0.0ms)  begin transaction
   (0.1ms)  rollback transaction