Vagrant::Driver::VirtualBox.read_version failing on second call (JRuby)

[jkutner]

With JRuby only, any vagrant command that invokes the Vagrant::Driver::VirtualBox.read_version twice gets nil back when executing:

VBoxManage --version

The resulting error is:

$ vagrant up
[default] Importing base box 'torquebox'...
NoMethodError: private method `split' called for nil:NilClass
     read_version at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/driver/virtualbox.rb:117
       initialize at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/driver/virtualbox.rb:36
          reload! at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/vm.rb:129
            uuid= at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/vm.rb:124
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/vm/import.rb:15
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/warden.rb:33
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/vm/check_box.rb:28
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/warden.rb:33
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/vm/check_accessible.rb:18
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/warden.rb:33
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/general/validate.rb:14
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/warden.rb:33
             call at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/builder.rb:92
              run at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/runner.rb:49
             busy at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/util/busy.rb:19
              run at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/action/runner.rb:49
       run_action at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/vm.rb:192
               up at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/vm.rb:143
          execute at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/command/up.rb:46
  with_target_vms at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/command/base.rb:100
             each at org/jruby/RubyArray.java:1612
  with_target_vms at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/command/base.rb:95
          execute at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/command/up.rb:39
          execute at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/cli.rb:38
              cli at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/lib/vagrant/environment.rb:156
           (root) at ~/.rvm/gems/jruby-1.6.5/gems/vagrant-0.9.1/bin/vagrant:43
             load at org/jruby/RubyKernel.java:1063
           (root) at ~/.rvm/gems/jruby-1.6.5/bin/vagrant:19

This only happens on the second invocation of Vagrant::Driver::VirtualBox.read_version. Commands that only invoke it once -- such as vagrant status work fine.

SYSTEM INFO:

$ vagrant -v
Vagrant version 0.9.1

$ uname -a
Darwin largo.local 11.2.0 Darwin Kernel Version 11.2.0: Tue Aug  9 20:54:00 PDT 2011; root:xnu-1699.24.8~1/RELEASE_X86_64 x86_64

$ ruby -v
jruby 1.6.5 (ruby-1.8.7-p330) (2011-10-25 9dcd388) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_29) [darwin-x86_64-java]

$ VBoxManage --version
4.1.8r75467

[jkutner]

This may be a dup of:
#657

[mitchellh]

Yeah probably. The one curious thing about this issue is that it fails on the second time, which is odd. can you try this with VAGRANT_LOG=debug and gist that here.

[jkutner]

Yup:
https://gist.github.com/1643194

[mitchellh]

Hm, that is really strange. I wonder why the second time is empty. I think
that is a big issue, whereas my issue doesn't see this behavior. I'll try
to mimic it on this end.

Mitchell

On Thu, Jan 19, 2012 at 2:10 PM, Joe Kutner <
reply@reply.github.com

wrote:

Yup:
https://gist.github.com/1643194

---

Reply to this email directly or view it on GitHub:
#658 (comment)

[jkutner]

Let me know if/how I can help.

-Joe

On Jan 19, 2012, at 5:13 PM, Mitchell Hashimotoreply@reply.github.com wrote:

Hm, that is really strange. I wonder why the second time is empty. I think
that is a big issue, whereas my issue doesn't see this behavior. I'll try
to mimic it on this end.

Mitchell

On Thu, Jan 19, 2012 at 2:10 PM, Joe Kutner <
reply@reply.github.com

wrote:

Yup:
https://gist.github.com/1643194

---

Reply to this email directly or view it on GitHub:
#658 (comment)

---

Reply to this email directly or view it on GitHub:
#658 (comment)

[mitchellh]

Fixed!

[mitchellh]

Actually, I still don't know why its blank the second time, so YOUR specific case may not be fixed :-\ But the NoMethodError will definitely be gone.

I'll still play with JRuby tonight.

[jkutner]

I get a nicer error message now:
https://gist.github.com/1644498

But it doesn't work. I'm not sure if this should really be closed.

I'll keep investigating myself.

[jkutner]

This may be a JRuby or ChildProcess bug.

I've created this issue with JRuby:
http://jira.codehaus.org/browse/JRUBY-6362

And started this thread:
http://markmail.org/thread/e7rmwy4jp53e3wjj

[mitchellh]

Yeah based on the behavior I believe it is. It looks like Nick Sieger verified it as well, which is great news.