Crash while "vagrant up" in read_state

[hsmanninen]

Vcenter plugin started crashing while trying to create a new virtual machine. Box: gosddc/centos65-x64. The virtual machine is not created, only the template exists at that time.

Uploading the box, deploying OVF and marking it as template work fine but then fails at read_state:

INFO warden: Calling IN action: #VagrantPlugins::VCenter::Action::InventoryCheck:0x000000024655f8 DEBUG inventory_check: This is the box we're looking for: Folder/gosddc-centos65-x64 DEBUG inventory_check: Template found at Folder/gosddc-centos65-x64 INFO warden: Calling IN action: #Vagrant::Action::Builtin::Call:0x000000025247f0 INFO runner: Preparing hooks for middleware sequence... INFO runner: 4 hooks defined. INFO runner: Running action: #Vagrant::Action::Builder:0x00000002489610 INFO warden: Calling IN action: #VagrantPlugins::VCenter::Action::IsCreated:0x000000024b5c10 INFO is_created: VM has been created and ID is: [42341f3a-2993-d643-a832-da9148db3bee] INFO warden: Calling OUT action: #VagrantPlugins::VCenter::Action::IsCreated:0x000000024b5c10 INFO runner: Preparing hooks for middleware sequence... INFO runner: 4 hooks defined. INFO runner: Running action: #Vagrant::Action::Warden:0x000000026329d0 INFO warden: Calling IN action: #<Proc:0x000000026edd98@/opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:94 (lambda)> INFO warden: Calling IN action: #<Proc:0x000000026326d8@/opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:94 (lambda)> INFO warden: Calling IN action: #Vagrant::Action::Builtin::ConfigValidate:0x00000002524638 INFO warden: Calling IN action: #VagrantPlugins::VCenter::Action::ConnectvCenter:0x000000025245e8 INFO warden: Calling IN action: #Vagrant::Action::Builtin::Call:0x000000025e18c8 INFO runner: Preparing hooks for middleware sequence... INFO runner: 4 hooks defined. INFO runner: Running action: #Vagrant::Action::Builder:0x00000002867340 INFO warden: Calling IN action: #VagrantPlugins::VCenter::Action::IsRunning:0x00000002874b58 INFO machine: Calling action: read_state on provider vCenter (42341f3a-2993-d643-a832-da9148db3bee) INFO runner: Preparing hooks for middleware sequence... INFO runner: 3 hooks defined. INFO runner: Running action: #Vagrant::Action::Builder:0x000000029216c8 INFO warden: Calling IN action: #Vagrant::Action::Builtin::ConfigValidate:0x00000002961390 INFO warden: Calling IN action: #VagrantPlugins::VCenter::Action::ConnectvCenter:0x00000002961340 INFO warden: Calling IN action: #VagrantPlugins::VCenter::Action::ReadState:0x00000002a07d80 ERROR warden: Error occurred: undefined method runtime' for nil:NilClass INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. ERROR warden: Error occurred: undefined methodruntime' for nil:NilClass INFO warden: Beginning recovery process... INFO warden: Recovery complete. ERROR warden: Error occurred: undefined method runtime' for nil:NilClass INFO warden: Beginning recovery process... INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x000000025e18c8> INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x000000025247f0> INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x00000001ae29b8> INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. ERROR warden: Error occurred: undefined methodruntime' for nil:NilClass INFO warden: Beginning recovery process... INFO warden: Recovery complete. ERROR warden: Error occurred: undefined method runtime' for nil:NilClass INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. ERROR warden: Error occurred: undefined methodruntime' for nil:NilClass INFO warden: Beginning recovery process... INFO warden: Recovery complete. ERROR warden: Error occurred: undefined method runtime' for nil:NilClass INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO warden: Beginning recovery process... INFO warden: Recovery complete. INFO environment: Released process lock: machine-action-82b3ca4ee03afa4921d3fd8b8512905c INFO environment: Running hook: environment_unload INFO runner: Preparing hooks for middleware sequence... INFO runner: 3 hooks defined. INFO runner: Running action: #<Vagrant::Action::Builder:0x007f20c4b39930> /.../.vagrant.d/gems/gems/vagrant-vcenter-0.2.1/lib/vagrant-vcenter/action/read_state.rb:38:inread_state': undefined method runtime' for nil:NilClass (NoMethodError) from /.../.vagrant.d/gems/gems/vagrant-vcenter-0.2.1/lib/vagrant-vcenter/action/read_state.rb:14:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:in call' from /.../.vagrant.d/gems/gems/vagrant-vcenter-0.2.1/lib/vagrant-vcenter/action/connect_vcenter.rb:32:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builtin/config_validate.rb:25:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builder.rb:116:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:in block in run' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/util/busy.rb:19:inbusy' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:in run' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:196:inaction_raw' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:173:in block in action' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/environment.rb:403:inlock' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:161:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:161:inaction' from /.../.vagrant.d/gems/gems/vagrant-vcenter-0.2.1/lib/vagrant-vcenter/provider.rb:28:in state' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:432:instate' from /.../.vagrant.d/gems/gems/vagrant-vcenter-0.2.1/lib/vagrant-vcenter/action/is_running.rb:14:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builder.rb:116:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:inblock in run' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/util/busy.rb:19:in busy' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:inrun' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builtin/call.rb:43:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /.../.vagrant.d/gems/gems/vagrant-vcenter-0.2.1/lib/vagrant-vcenter/action/connect_vcenter.rb:32:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builtin/config_validate.rb:25:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:95:in block in finalize_action' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:95:inblock in finalize_action' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builder.rb:116:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:inblock in run' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/util/busy.rb:19:in busy' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:inrun' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builtin/call.rb:53:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /.../.vagrant.d/gems/gems/vagrant-vcenter-0.2.1/lib/vagrant-vcenter/action/inventory_check.rb:22:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /.../.vagrant.d/gems/gems/vagrant-vcenter-0.2.1/lib/vagrant-vcenter/action/connect_vcenter.rb:32:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:95:in block in finalize_action' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:95:inblock in finalize_action' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builder.rb:116:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:inblock in run' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/util/busy.rb:19:in busy' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:inrun' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builtin/call.rb:53:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builtin/config_validate.rb:25:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/warden.rb:34:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/builder.rb:116:in call' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:inblock in run' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/util/busy.rb:19:in busy' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/action/runner.rb:66:inrun' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:196:in action_raw' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:173:inblock in action' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/environment.rb:434:in lock' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:161:incall' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/machine.rb:161:in action' from /opt/vagrant/embedded/gems/gems/vagrant-1.6.3/lib/vagrant/batch_action.rb:82:inblock (2 levels) in run'

[frapposelli]

Looks like a known bug, targeting for the next release.

[hsmanninen]

Ok, thanks! Any workaround ideas? I mean, it used to work for a while but now I'm running out of ideas to find out what broke it...

[frapposelli]

@hsmanninen try this:

diff --git a/lib/vagrant-vcenter/action/read_state.rb b/lib/vagrant-vcenter/action/read_state.rb
index 1cd7820..920c4da 100644
--- a/lib/vagrant-vcenter/action/read_state.rb
+++ b/lib/vagrant-vcenter/action/read_state.rb
@@ -16,6 +16,11 @@ module VagrantPlugins
         end

         def read_state(env)
+          if env[:machine].id.nil?
+            @logger.info('VM is not created yet')
+            return :not_created
+          end
+
           # FIXME: this part needs some cleanup
           config = env[:machine].provider_config

@@ -27,14 +32,9 @@ module VagrantPlugins

           vm = root_vm_folder.findByUuid(env[:machine].id)

-          #@logger.debug("Current power state: #{vm.runtime.powerState}")
+          # @logger.debug("Current power state: #{vm.runtime.powerState}")
           vm_name = env[:machine].name

-          if env[:machine].id.nil?
-            @logger.info("VM [#{vm_name}] is not created yet")
-            return :not_created
-          end
-
           if vm.runtime.powerState == 'poweredOff'
             @logger.info("VM [#{vm_name}] is stopped")
             return :stopped

[hsmanninen]

Same error:

INFO warden: Calling IN action: #VagrantPlugins::VCenter::Action::ReadState:0x007f3b748aed30 ERROR warden: Error occurred: undefined method runtime' for nil:NilClass ... lib/vagrant-vcenter/action/read_state.rb:35:inread_state': undefined method `runtime' for nil:NilClass (NoMethodError)

[hsmanninen]

Ok, I changed vm.hostname in Vagrantfile to create a new prefix for the generated VM and it started working.

[hsmanninen]

Ok I found out how to reproduce this situation:

1. Create a new machine with (vagrant up --provider=vcenter)
2. Halt the newly created machine (vagrant halt)
3. Delete the powered off VM from within vCenter
4. Try to start the machine again (vagrant up)
5. The above error happens

[frapposelli]

Thanks, I will add an exception for that.