Unable to provision new instances

[vincenthuynh]

Hello,

Is anyone else experiencing issues provisioning as of 18:00 EST today? We have not been able to provision or destroy instances since this began. The errors we're encountering are as follows:

==> vagrant up base01 --provider=softlayer --debug
INFO global: Vagrant version: 1.6.5
INFO global: Ruby version: 2.0.0
INFO global: RubyGems version: 2.0.14
INFO global: VAGRANT_EXECUTABLE="/opt/vagrant/bin/../embedded/gems/gems/vagrant-1.6.5/bin/vagrant"
...
INFO global: Plugins:
...
INFO global:   - softlayer_api = 3.0.2
INFO global:   - vagrant-hostmanager = 1.5.0
INFO global:   - vagrant-login = 1.0.1
INFO global:   - vagrant-share = 1.1.3
INFO global:   - vagrant-softlayer = 0.4.0
...
==> base01: Creating a new SoftLayer instance...
ERROR warden: Error occurred: Vagrant returned an exception while calling the SoftLayer API.

Exception class: Net::ReadTimeout
Exception message: Net::ReadTimeout
 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.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: Vagrant returned an exception while calling the SoftLayer API.

Exception class: Net::ReadTimeout
Exception message: Net::ReadTimeout
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: Vagrant returned an exception while calling the SoftLayer API.

Exception class: Net::ReadTimeout
Exception message: Net::ReadTimeout
 INFO warden: Beginning recovery process...
 INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x00000002360d10>
 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.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO environment: Released process lock: machine-action-1015591140c1646304638a4008b6f914
 INFO environment: Running hook: environment_unload
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x000000025f4540>
ERROR vagrant: Vagrant experienced an error! Details:
ERROR vagrant: #<VagrantPlugins::SoftLayer::Errors::SLApiError: Vagrant returned an exception while calling the SoftLayer API.

Exception class: Net::ReadTimeout
Exception message: Net::ReadTimeout>
ERROR vagrant: Vagrant returned an exception while calling the SoftLayer API.

Exception class: Net::ReadTimeout
Exception message: Net::ReadTimeout
ERROR vagrant: /var/lib/jenkins/.vagrant.d/gems/gems/vagrant-softlayer-0.4.0/lib/vagrant-softlayer/util/warden.rb:31:in `rescue in sl_warden'
/var/lib/jenkins/.vagrant.d/gems/gems/vagrant-softlayer-0.4.0/lib/vagrant-softlayer/util/warden.rb:17:in `sl_warden'
/var/lib/jenkins/.vagrant.d/gems/gems/vagrant-softlayer-0.4.0/lib/vagrant-softlayer/action/create_instance.rb:20:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/builtin/synced_folders.rb:84:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/var/lib/jenkins/.vagrant.d/gems/gems/vagrant-hostmanager-1.5.0/lib/vagrant-hostmanager/action/update_all.rb:33:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/builtin/config_validate.rb:25:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/builtin/provision.rb:80:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/var/lib/jenkins/.vagrant.d/gems/gems/vagrant-softlayer-0.4.0/lib/vagrant-softlayer/action/setup_softlayer.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/builder.rb:116:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/runner.rb:66:in `block in run'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/util/busy.rb:19:in `busy'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/runner.rb:66:in `run'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/builtin/call.rb:53:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/var/lib/jenkins/.vagrant.d/gems/gems/vagrant-softlayer-0.4.0/lib/vagrant-softlayer/action/setup_softlayer.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/builtin/config_validate.rb:25:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/builtin/handle_box.rb:56:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/warden.rb:34:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/builder.rb:116:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/runner.rb:66:in `block in run'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/util/busy.rb:19:in `busy'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/action/runner.rb:66:in `run'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/machine.rb:196:in `action_raw'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/machine.rb:173:in `block in action'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/environment.rb:474:in `lock'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/machine.rb:161:in `call'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/machine.rb:161:in `action'
/opt/vagrant/embedded/gems/gems/vagrant-1.6.5/lib/vagrant/batch_action.rb:82:in `block (2 levels) in run'
 INFO interface: error: Vagrant returned an exception while calling the SoftLayer API.

Exception class: Net::ReadTimeout
Exception message: Net::ReadTimeout
Vagrant returned an exception while calling the SoftLayer API.

Exception class: Net::ReadTimeout
Exception message: Net::ReadTimeout
 INFO interface: Machine: error-exit ["VagrantPlugins::SoftLayer::Errors::SLApiError", "Vagrant returned an exception while calling the SoftLayer API.\n\nException class: Net::ReadTimeout\nException message: Net::ReadTimeout"]

Other errors we're also seeing:

==> Creating a new SoftLayer instance...
Vagrant returned an exception while calling the SoftLayer API.
   Exception class: VagrantPlugins::SoftLayer::Errors::SLApiError
   Exception message: Vagrant returned an exception while calling the SoftLayer API.
   Exception class: Net::ReadTimeout
   Exception message: Net::ReadTimeout

==> Creating a new SoftLayer instance...
Vagrant returned an exception while calling the SoftLayer API.
  Exception class: Errno::ECONNRESET
  Exception message: Connection reset by peer

 ==> Destroying the SoftLayer instance...
   Vagrant returned an exception while calling the SoftLayer API.
   Exception class: XMLRPC::FaultException
   Exception message: This cancellation could not be processed please contact support.This cancellation could not be processed. Please contact support. There is currently an active transaction.

==> Waiting for instance provisioning. This may take a few minutes...
  /opt/vagrant/embedded/lib/ruby/2.0.0/net/protocol.rb:158:in `rescue in rbuf_fill': Net::ReadTimeout (Net::ReadTimeout)

Executing API calls directly seem to be working fine.

Paging...@SLsthompson, @underscorephil

Thanks!
Vincent-

[SLsthompson]

If executing the API calls directly doesn't cause a problem, if the problem exists at the vagrant level, then there's not much that Phil or I can to to help.

The calls appear to be timeout issues which could be a problem at our end, but it could also very well be a problem anywhere in the network between you client and our servers.

[vincenthuynh]

At about 22:00 EST, the timeout issues look to have been resolved upstream and we have been able to provision using vagrant again.

@SLsthompson: Do you know if there was an upgrade happening yesterday based on the timing that might explain this?

Thanks,
Vincent-

[SLsthompson]

I do not know. I'm not directly tied into the release schedules for the main system.