"provisioned" status not updating in wait_for_ready

[cbreden]

Still tracing the root cause, but I'm finding wait_for_ready to never return true on newly created virtual guests and virtual guests from templates since the provisionedDate never comes in.

https://github.com/softlayer/softlayer-ruby/blob/2aee085c76f43098cdfd9c9e3ee7305ab3de5450/lib/softlayer/VirtualServer.rb#L176

When I inject some debugging output like puts "check - provisioned:#{provisioned ? "T":"F"}|reloading_os:#{reloading_os ? "T":"F"}|wait_for_transactions:#{wait_for_transactions ? "T":"F"}|has_active_transaction:#{has_active_transaction ? "T":"F"}|ready:#{ready ? "T":"F"}", I can see when the active transaction stops, but provisioned never becomes true.

If I stop the thread and re-initialize the VirtualServer object when I know it's finished, it will correctly report it as provisioned though. Therefore I think there might be something off with self.refresh_details() on line 128.

[cbreden]

Also...might be deserving of a new issue, but in the middle of a waiting loop wait_for_ready can sporadically crash. It's a bit suspect that this happens during refresh_details:

check - provisioned:F|reloading_os:F|wait_for_transactions:T|has_active_transaction:T|ready:F
check - provisioned:F|reloading_os:F|wait_for_transactions:T|has_active_transaction:T|ready:F
returned ready: F | ready.nil?: F
check - provisioned:F|reloading_os:F|wait_for_transactions:T|has_active_transaction:T|ready:F
check - provisioned:F|reloading_os:F|wait_for_transactions:T|has_active_transaction:T|ready:F
returned ready: F | ready.nil?: F
C:/Ruby193/lib/ruby/1.9.1/xmlrpc/client.rb:414:in `call': parse error. not well formed (XMLRPC::FaultException)
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/softlayer_api-3.0.2/lib/softlayer/Service.rb:267:in `call_softlayer_api_with_params'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/softlayer_api-3.0.2/lib/softlayer/APIParameterFilter.rb:194:in `method_missing'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/softlayer_api-3.0.2/lib/softlayer/Server.rb:127:in `softlayer_properties'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/softlayer_api-3.0.2/lib/softlayer/ModelBase.rb:66:in `refresh_details'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/softlayer_api-3.0.2/lib/softlayer/VirtualServer.rb:128:in `wait_until_ready'
        from C:/Users/cbreden/workspace/softlayer_api_wrapper/lib/softlayer_api_wrapper/virtual_guest.rb:261:in `check_ready'
        from C:/Users/cbreden/workspace/softlayer_api_wrapper/lib/softlayer_api_wrapper/virtual_guest.rb:301:in `wait_for_ready'
        from C:/Users/cbreden/workspace/softlayer_api_wrapper/bin/sl_cli.rb:492:in `ready'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor/command.rb:27:in `run'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor/invocation.rb:126:in `invoke_command'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor.rb:359:in `dispatch'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor/invocation.rb:115:in `invoke'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor.rb:235:in `block in subcommand'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor/command.rb:27:in `run'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor/invocation.rb:126:in `invoke_command'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor.rb:359:in `dispatch'
        from C:/Ruby193/lib/ruby/gems/1.9.1/gems/thor-0.19.1/lib/thor/base.rb:440:in `start'
        from sl:4:in `<main>'

[SLsthompson]

Is this new behavior that's just started happening in code that was previously working, or is this the first time you're running into the problem? Does it happen every time, or "occasionally"?

[cbreden]

The the second respones about the in-the-middle-of-the-loop failure is very very rare. I've also seen a very strangely formed API and XMLRPC error which led me to think it was just the API server being down.

The provisioned flag not getting updated may have been happening for awhile since we weren't using this gem's wait_until_ready until just recently -- I was using a custom wait function that didn't check the provisionDate attribute. Sorry for not having a clearer answer. Is this replicate-able on your end? Do you need some sample code to isolate this behavior? (it's just create a vg from a template and then wait_until_ready on that vg)

[cbreden]

Well, the original issue might be a false report. Isolated this with just a very clean provision followed by a wait and the flag actually updated as it was supposed to. I'll reopen this if I can distinguish the difference without our code...

require 'rubygems'
require 'softlayer_api'
require 'pp'

begin

  client = SoftLayer::Client.new(
     :username => "",              # enter your username here
     :api_key => ""   # enter your api key here
  )

  server_order = SoftLayer::VirtualServerOrder.new(client)

  server_order.hostname = "testwait01"
  server_order.domain = "softlayer.com"
  server_order.datacenter = SoftLayer::Datacenter.datacenter_named 'dal09', client
  server_order.cores = 2
  server_order.memory = 4 #GB
  server_order.os_reference_code = 'WIN_2008-ENT-R2-SP1_64'
  server_order.max_port_speed = SoftLayer::VirtualServerOrder.max_port_speed_options(client).max  
  server_order.disks = [100]

  begin
    server_order.verify
    puts "The server order is OK"
    server_order.place_order!
  rescue Exception => e
    puts "The server order failed verification :-( -- #{e}"
  end

  sleep 10

  vgs = SoftLayer::VirtualServer.find_servers({:client => client, :hostname => server_order.hostname})

  pp vgs

  vgs.first.wait_until_ready(100000, true, 8)

rescue Exception => exception
  $stderr.puts "An exception occurred while trying to complete the SoftLayer API calls #{exception}"
end

(above code works as it should)