sporkrb/spork-testunit — Issue #42: recycled object error
Author: aspiers
Created: 2012-01-29 13:11:02+00:00
State: open

I am using MRI 1.9.3, Rails 3.2.1, spork 0.9.0, test-unit 2.4.5, and spork-testunit. Regardless of whether I use spork-testunit 0.0.7 or the latest git master, I get this 'recycled object' error from `bundle exec testdrb`:

Error executing -Itest ./test/functional/admin/assignments_controller_test.rb ./test/functional/admin/availabilities_controller_test.rb ./test/functional/admin/events_controller_test.rb ./test/functional/admin/people_controller_test.rb ./test/functional/admin/roles_controller_test.rb ./test/functional/events_controller_test.rb ./test/functional/people_controller_test.rb ./test/functional/replies_controller_test.rb ./test/functional/routes_test.rb ./test/functional/sessions_controller_test.rb
0x474231e is recycled object
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:375:in `_id2ref'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:375:in `to_obj'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1410:in `to_obj'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1708:in `to_obj'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:613:in `recv_request'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:908:in `recv_request'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1523:in `init_with_client'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1535:in `setup_message'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1487:in `perform'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop'
(druby://127.0.0.1:8988) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop'
(druby://127.0.0.1:59689) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1548:in `write'
(druby://127.0.0.1:59689) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1548:in `perform_without_block'
(druby://127.0.0.1:59689) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1508:in `perform'
(druby://127.0.0.1:59689) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop'
(druby://127.0.0.1:59689) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop'
(druby://127.0.0.1:59689) /home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/console/testrunner.rb:348:in `output_single'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/console/testrunner.rb:337:in `output'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/console/testrunner.rb:265:in `output_statistics'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/console/testrunner.rb:106:in `block in finished'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/console/testrunner.rb:53:in `change_output_level'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/console/testrunner.rb:105:in `finished'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/util/observable.rb:78:in `call'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/util/observable.rb:78:in `block in notify_listeners'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/util/observable.rb:78:in `each'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/util/observable.rb:78:in `notify_listeners'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/testrunnermediator.rb:64:in `run_suite'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/testrunner.rb:40:in `start_mediator'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/testrunner.rb:25:in `start'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/ui/testrunnerutilities.rb:24:in `run'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/test-unit-2.4.5/lib/test/unit/autorunner.rb:368:in `run'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/spork-testunit-0.0.6/lib/spork/test_framework/test_unit.rb:49:in `run_tests'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/spork-0.9.0/lib/spork/run_strategy/forking.rb:13:in `block in run'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/spork-0.9.0/lib/spork/forker.rb:21:in `block in initialize'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/spork-0.9.0/lib/spork/forker.rb:18:in `fork'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/spork-0.9.0/lib/spork/forker.rb:18:in `initialize'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/spork-0.9.0/lib/spork/run_strategy/forking.rb:9:in `new'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/spork-0.9.0/lib/spork/run_strategy/forking.rb:9:in `run'
/home/adam/.rvm/gems/ruby-1.9.3-p0@rails-3.2/gems/spork-0.9.0/lib/spork/server.rb:48:in `run'
/home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1548:in `perform_without_block'
/home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1508:in `perform'
/home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1586:in `block (2 levels) in main_loop'
/home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1582:in `loop'
/home/adam/.rvm/rubies/ruby-1.9.3-p0/lib/ruby/1.9.1/drb/drb.rb:1582:in `block in main_loop'
------------------------------
Done.

I experimented with trimming the list of tests run, and found that it is triggered by any test which has an error (not a failure). When triggered, one of two things happen: (1) the above stack trace, or (2) what should be the summary line in the output (e.g. something like `20 tests, 106 assertions, 0 failures, 0 errors, 0 pendings, 0 omissions, 0 notifications`) actually ends up being complete garbage, e.g.

$ bundle exec testdrb -Itest ./test/functional/admin/roles_controller_test.rb
Loaded suite Admin::RolesControllerTest
Started
E
===================================================================================================
Error:
test_should_get_index(Admin::RolesControllerTest):
ActionView::Template::Error: wrong number of arguments (4 for 5)
lib/admin/controller_tests.rb:60:in `block in '
===================================================================================================

Finished in 0.972404894 seconds.
Ie:ptionParser::Arguable[ I"
-Itest:ETI"5./test/functional/admin/roles_controller_test.rb;TI"0./test/functional/people_controller_test.rb;TI"1./test/functional/replies_controller_test.rb;T:@optparse0
0% passed

3.09 tests/s, 11.31 assertions/s

So it looks to me like some memory pointer has gone AWOL and this string just gets plucked from a random memory area. Ouch!

Given that it is the summary line which goes FUBAR, I strongly suspect that this is related to issue #33. However, this happens even after I manually edited `testdrb` to prevent it getting confused by the presence of the `minitest` gem.

This is the final straw for me. I've had endless woes trying to get Spork and Guard to play nice with both test-unit and minitest, so I'm going to switch to RSpec which is hopefully a more well-trodden and reliable path.