Fix #58 Improve logging and error handling

source/lib/vagrant-openstack-provider/action/connect_openstack.rb

@@ -7,9 +7,6 @@
 module VagrantPlugins
   module Openstack
     module Action
-      # This action connects to Openstack, verifies credentials work, and
-      # puts the Openstack connection object into the `:openstack_compute` key
-      # in the environment.
       class ConnectOpenstack
         def initialize(app, _env)
           @app = app

source/lib/vagrant-openstack-provider/action/create_server.rb

@@ -16,46 +16,24 @@ def initialize(app, _env)
         end
 
         def call(env)
+          @logger.info 'Start create server action'
+
           config = env[:machine].provider_config
           nova = env[:openstack_client].nova
 
           flavor = resolve_flavor(env)
           image = resolve_image(env)
           networks = resolve_networks(env)
-          server_name = config.server_name || env[:machine].name
-
-          env[:ui].info(I18n.t('vagrant_openstack.launching_server'))
-          env[:ui].info(" -- Tenant         : #{config.tenant_name}")
-          env[:ui].info(" -- Name           : #{server_name}")
-          env[:ui].info(" -- Flavor         : #{flavor.name}")
-          env[:ui].info(" -- FlavorRef      : #{flavor.id}")
-          env[:ui].info(" -- Image          : #{image.name}")
-          env[:ui].info(" -- ImageRef       : #{image.id}")
-          env[:ui].info(" -- KeyPair        : #{config.keypair_name}")
-          unless networks.empty?
-            if networks.size == 1
-              env[:ui].info(" -- Network        : #{config.networks[0]}")
-            else
-              env[:ui].info(" -- Networks       : #{config.networks}")
-            end
-          end
-
-          server_id = nova.create_server(env, server_name, image.id, flavor.id, networks, config.keypair_name)
+          server_id = create_server(env, flavor, image, networks)
 
           # Store the ID right away so we can track it
           env[:machine].id = server_id
 
-          # Wait for the server to finish building
-          env[:ui].info(I18n.t('vagrant_openstack.waiting_for_build'))
-          timeout(200) do
-            while nova.get_server_details(env, server_id)['status'] != 'ACTIVE'
-              sleep 3
-              @logger.debug('Waiting for server to be ACTIVE')
-            end
-          end
+          waiting_for_server_to_be_build(env, server_id)
 
           if config.floating_ip
-            env[:ui].info("Using floating IP #{config.floating_ip}")
+            @logger.info "Using floating IP #{config.floating_ip}"
+            env[:ui].info(I18n.t('vagrant_openstack.using_floating_ip', floating_ip: config.floating_ip))
             nova.add_floating_ip(env, server_id, config.floating_ip)
           end
 
@@ -71,6 +49,7 @@ def call(env)
               fail Errors::SshUnavailable, host: host, timeout: ssh_timeout
             end
 
+            @logger.info 'The server is ready'
             env[:ui].info(I18n.t('vagrant_openstack.ready'))
           end
 
@@ -80,26 +59,31 @@ def call(env)
         private
 
         def resolve_flavor(env)
+          @logger.info 'Resolving flavor'
           config = env[:machine].provider_config
           nova = env[:openstack_client].nova
           env[:ui].info(I18n.t('vagrant_openstack.finding_flavor'))
           flavors = nova.get_all_flavors(env)
+          @logger.info "Finding flavor matching name '#{config.flavor}'"
           flavor = find_matching(flavors, config.flavor)
           fail Errors::NoMatchingFlavor unless flavor
           flavor
         end
 
         def resolve_image(env)
+          @logger.info 'Resolving image'
           config = env[:machine].provider_config
           nova = env[:openstack_client].nova
           env[:ui].info(I18n.t('vagrant_openstack.finding_image'))
           images = nova.get_all_images(env)
+          @logger.info "Finding image matching name '#{config.image}'"
           image = find_matching(images, config.image)
           fail Errors::NoMatchingImage unless image
           image
         end
 
         def resolve_networks(env)
+          @logger.info 'Resolving network(s)'
           config = env[:machine].provider_config
           return [] if config.networks.nil? || config.networks.empty?
           env[:ui].info(I18n.t('vagrant_openstack.finding_networks'))
@@ -125,16 +109,64 @@ def resolve_networks(env)
           networks
         end
 
+        def create_server(env, flavor, image, networks)
+          config = env[:machine].provider_config
+          nova = env[:openstack_client].nova
+          server_name = config.server_name || env[:machine].name
+
+          env[:ui].info(I18n.t('vagrant_openstack.launching_server'))
+          env[:ui].info(" -- Tenant         : #{config.tenant_name}")
+          env[:ui].info(" -- Name           : #{server_name}")
+          env[:ui].info(" -- Flavor         : #{flavor.name}")
+          env[:ui].info(" -- FlavorRef      : #{flavor.id}")
+          env[:ui].info(" -- Image          : #{image.name}")
+          env[:ui].info(" -- ImageRef       : #{image.id}")
+          env[:ui].info(" -- KeyPair        : #{config.keypair_name}")
+          unless networks.empty?
+            if networks.size == 1
+              env[:ui].info(" -- Network        : #{config.networks[0]}")
+            else
+              env[:ui].info(" -- Networks       : #{config.networks}")
+            end
+          end
+
+          log = "Lauching server '#{server_name}' in project '#{config.tenant_name}' "
+          log << "with flavor '#{flavor.name}' (#{flavor.id}), "
+          log << "image '#{image.name}' (#{image.id}) "
+          log << "and keypair '#{config.keypair_name}'"
+
+          @logger.info(log)
+
+          nova.create_server(env, server_name, image.id, flavor.id, networks, config.keypair_name)
+        end
+
+        def waiting_for_server_to_be_build(env, server_id)
+          @logger.info 'Waiting for the server to be built...'
+          env[:ui].info(I18n.t('vagrant_openstack.waiting_for_build'))
+          nova = env[:openstack_client].nova
+          timeout(200) do
+            while nova.get_server_details(env, server_id)['status'] != 'ACTIVE'
+              sleep 3
+              @logger.debug('Waiting for server to be ACTIVE')
+            end
+          end
+        end
+
         def port_open?(env, ip, port, timeout)
           start_time = Time.now
           current_time = start_time
           nb_retry = 0
           while (current_time - start_time) <= timeout
             begin
-              env[:ui].info(I18n.t('vagrant_openstack.waiting_for_ssh')) if nb_retry % 5 == 0
+              @logger.debug "Checking if SSH port is open... Attempt number #{nb_retry}"
+              if nb_retry % 5 == 0
+                @logger.info 'Waiting for SSH to become available...'
+                env[:ui].info(I18n.t('vagrant_openstack.waiting_for_ssh'))
+              end
               TCPSocket.new(ip, port)
               return true
             rescue Errno::ECONNREFUSED, Errno::EHOSTUNREACH, Errno::ETIMEDOUT
+              @logger.debug 'SSH port is not open... new retry in in 1 second'
               nb_retry += 1
               sleep 1
             end
@@ -153,7 +185,7 @@ def find_matching(collection, name)
             return single if single.name == name
             return single if name.is_a?(Regexp) && name =~ single.name
           end
-
+          @logger.error "Flavor '#{name}' not found"
           nil
         end
       end

source/lib/vagrant-openstack-provider/action/delete_server.rb

@@ -12,6 +12,7 @@ def initialize(app, _env)
 
         def call(env)
           if env[:machine].id
+            @logger.info "Deleting server #{env[:machine].id}..."
             env[:ui].info(I18n.t('vagrant_openstack.deleting_server'))
             env[:openstack_client].nova.delete_server(env, env[:machine].id)
             env[:machine].id = nil

source/lib/vagrant-openstack-provider/action/read_ssh_info.rb

@@ -12,6 +12,7 @@ def initialize(app, _env)
         end
 
         def call(env)
+          @loger.info 'Reading SSH info'
           env[:machine_ssh_info] = read_ssh_info(env)
 
           @app.call(env)

source/lib/vagrant-openstack-provider/action/resume.rb

@@ -4,10 +4,12 @@ module Action
       class Resume
         def initialize(app, _env)
           @app = app
+          @logger = Log4r::Logger.new('vagrant_openstack::action::resume_server')
         end
 
         def call(env)
           if env[:machine].id
+            @logger.info "Resuming suspended VM #{env[:machine].id}..."
             env[:ui].info I18n.t('vagrant.actions.vm.resume.resuming')
             env[:openstack_client].nova.resume_server(env, env[:machine].id)
           end

source/lib/vagrant-openstack-provider/action/stop_server.rb

@@ -11,6 +11,7 @@ def initialize(app, _env)
 
         def call(env)
           if env[:machine].id
+            @logger.info "Stopping server #{env[:machine].id}..."
             env[:ui].info(I18n.t('vagrant_openstack.stopping_server'))
             env[:openstack_client].nova.stop_server(env, env[:machine].id)
           end

source/lib/vagrant-openstack-provider/action/suspend.rb

@@ -4,10 +4,12 @@ module Action
       class Suspend
         def initialize(app, _env)
           @app = app
+          @logger = Log4r::Logger.new('vagrant_openstack::action::suspend_server')
         end
 
         def call(env)
           if env[:machine].id
+            @logger.info "Saving VM #{env[:machine].id} state and suspending execution..."
             env[:ui].info I18n.t('vagrant.actions.vm.suspend.suspending')
             env[:openstack_client].nova.suspend_server(env, env[:machine].id)
           end

source/lib/vagrant-openstack-provider/action/wait_stop.rb

@@ -17,7 +17,7 @@ def call(env)
             timeout(200) do
               while client.get_server_details(env, env[:machine].id)['status'] != 'SHUTOFF'
                 sleep 3
-                @logger.debug('Waiting for server to stop')
+                @logger.info('Waiting for server to stop')
               end
             end
           end

source/lib/vagrant-openstack-provider/client/keystone.rb

@@ -2,10 +2,13 @@
 require 'restclient'
 require 'json'
 
+require 'vagrant-openstack-provider/client/request_logger'
+
 module VagrantPlugins
   module Openstack
     class KeystoneClient
       include Singleton
+      include VagrantPlugins::Openstack::Utils::RequestLogger
 
       def initialize
         @logger = Log4r::Logger.new('vagrant_openstack::keystone')
@@ -17,21 +20,38 @@ def authenticate(env)
         config = env[:machine].provider_config
         @logger.info(I18n.t('vagrant_openstack.client.authentication', project: config.tenant_name, user: config.username))
 
-        authentication = RestClient.post(
-            config.openstack_auth_url,
-            {
-              auth:
+        post_body =
+          {
+            auth:
               {
                 tenantName: config.tenant_name,
                 passwordCredentials:
                   {
                     username: config.username,
-                    password: config.password
+                    password: '****'
                   }
               }
-            }.to_json,
-            content_type: :json,
-            accept: :json)
+          }
+
+        log_request(:POST, config.openstack_auth_url, post_body.to_json)
+
+        post_body[:auth][:passwordCredentials][:password] = config.password
+
+        authentication = RestClient.post(config.openstack_auth_url, post_body.to_json,
+                                         content_type: :json,
+                                         accept: :json) do |response|
+          log_response(response)
+          case response.code
+          when 200
+            response
+          when 401
+            fail Errors::AuthenticationFailed
+          when 404
+            fail Errors::BadAuthenticationEndpoint
+          else
+            fail Errors::VagrantOpenstackError, message: response.to_s
+          end
+        end
 
         access = JSON.parse(authentication)['access']
 

source/lib/vagrant-openstack-provider/client/neutron.rb

@@ -16,16 +16,12 @@ def initialize
       end
 
       def get_private_networks(env)
-        authenticated(env) do
-          networks_json = RestClient.get("#{@session.endpoints[:network]}/networks",
-                                         'X-Auth-Token' => @session.token,
-                                         :accept => :json) { |res| handle_response(res) }
-          networks = []
-          JSON.parse(networks_json)['networks'].each do |n|
-            networks << Item.new(n['id'], n['name']) if n['tenant_id'].eql? @session.project_id
-          end
-          networks
+        networks_json = get(env, "#{@session.endpoints[:network]}/networks")
+        networks = []
+        JSON.parse(networks_json)['networks'].each do |n|
+          networks << Item.new(n['id'], n['name']) if n['tenant_id'].eql? @session.project_id
         end
+        networks
       end
     end
   end